diff --git a/CHANGELOG.md b/CHANGELOG.md index 0c40f47b651..e1158be3ca4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,19 @@ # Cromwell Change Log +## 84 Release Notes + +### CromIAM enabled user checks + +For Cromwell instances utilizing the optional CromIAM identity and access management component, the following endpoints now verify that the calling user is enabled before forwarding the request. +* `/api/workflows/v1/backends` +* `/api/womtool/v1/describe` + +This change makes the above endpoints consistent with the existing behavior of all the other endpoints in the `/api/` path of CromIAM. + +## 83 Release Notes + +* Changes the type of several primary key columns in call caching tables from int to bigint. The database migration may be lengthy if your database contains a large amount of call caching data. + ## 82 Release Notes * Restored missing example configuration file diff --git a/CromIAM/src/main/resources/application.conf b/CromIAM/src/main/resources/application.conf index c809d0daafb..ff1006ab91b 100644 --- a/CromIAM/src/main/resources/application.conf +++ b/CromIAM/src/main/resources/application.conf @@ -24,7 +24,7 @@ swagger_oauth { akka { log-dead-letters = "off" - loggers = ["akka.event.slf4j.Slf4jLogger"] + loggers = ["cromwell.core.logging.EnhancedSlf4jLogger"] http { server { diff --git a/CromIAM/src/main/resources/logback.xml b/CromIAM/src/main/resources/logback.xml index 030868d3259..e9e2b753466 100644 --- a/CromIAM/src/main/resources/logback.xml +++ b/CromIAM/src/main/resources/logback.xml @@ -1,5 +1,15 @@ + + + + @@ -18,7 +28,7 @@ - %date %X{sourceThread} %-5level - %msg%n + %ed{yyyy-MM-dd HH:mm:ss,SSS} %et %-5level - %msg%n @@ -68,7 +78,7 @@ - %d{yyyy-MM-dd HH:mm:ss,SSS} [%thread] %-5level %logger{35} - %msg%n + %ed{yyyy-MM-dd HH:mm:ss,SSS} [%et] %-5level %logger{35} - %msg%n diff --git a/CromIAM/src/main/scala/cromiam/instrumentation/CromIamInstrumentation.scala b/CromIAM/src/main/scala/cromiam/instrumentation/CromIamInstrumentation.scala index 63f48073146..65b164f00f6 100644 --- a/CromIAM/src/main/scala/cromiam/instrumentation/CromIamInstrumentation.scala +++ b/CromIAM/src/main/scala/cromiam/instrumentation/CromIamInstrumentation.scala @@ -20,6 +20,7 @@ trait CromIamInstrumentation extends CromwellInstrumentation { val samPrefix: NonEmptyList[String] = NonEmptyList.one("sam") val getWhitelistPrefix = NonEmptyList.one("get-whitelist") + val getUserEnabledPrefix = NonEmptyList.one("get-user-enabled") val userCollectionPrefix = NonEmptyList.one("user-collection") val authCollectionPrefix = NonEmptyList.one("auth-collection") val registerCollectionPrefix = NonEmptyList.one("register-collection") diff --git a/CromIAM/src/main/scala/cromiam/sam/SamClient.scala b/CromIAM/src/main/scala/cromiam/sam/SamClient.scala index f289251a2fb..d6a315f8241 100644 --- a/CromIAM/src/main/scala/cromiam/sam/SamClient.scala +++ b/CromIAM/src/main/scala/cromiam/sam/SamClient.scala @@ -18,6 +18,7 @@ import cromiam.sam.SamResourceJsonSupport._ import cromiam.server.status.StatusCheckedSubsystem import cromwell.api.model._ import mouse.boolean._ +import spray.json.RootJsonFormat import scala.concurrent.ExecutionContextExecutor @@ -73,6 +74,33 @@ class SamClient(scheme: String, } yield whitelisted } + def isUserEnabledSam(user: User, cromIamRequest: HttpRequest): FailureResponseOrT[Boolean] = { + val request = HttpRequest( + method = HttpMethods.GET, + uri = samUserStatusUri, + headers = List[HttpHeader](user.authorization) + ) + + for { + response <- instrumentRequest( + () => Http().singleRequest(request).asFailureResponseOrT, + cromIamRequest, + instrumentationPrefixForSam(getUserEnabledPrefix) + ) + userEnabled <- response.status match { + case StatusCodes.OK => + val unmarshal: IO[UserStatusInfo] = IO.fromFuture(IO(Unmarshal(response.entity).to[UserStatusInfo])) + FailureResponseOrT.right[HttpResponse](unmarshal).map { userInfo => + if (!userInfo.enabled) log.info("Access denied for user {}", user.userId) + userInfo.enabled + } + case _ => + log.error("Could not verify access with Sam for user {}, error was {} {}", user.userId, response.status, response.toString().take(100)) + FailureResponseOrT.pure[IO, HttpResponse](false) + } + } yield userEnabled + } + def collectionsForUser(user: User, cromIamRequest: HttpRequest): FailureResponseOrT[List[Collection]] = { val request = HttpRequest(method = HttpMethods.GET, uri = samBaseCollectionUri, headers = List[HttpHeader](user.authorization)) @@ -170,6 +198,7 @@ class SamClient(scheme: String, private lazy val samBaseResourceUri = s"$samBaseUri/api/resource" private lazy val samBaseCollectionUri = s"$samBaseResourceUri/workflow-collection" private lazy val samSubmitWhitelistUri = s"$samBaseResourceUri/caas/submit/action/get_whitelist" + private lazy val samUserStatusUri = s"$samBaseUri/register/user/v2/self/info" } @@ -188,4 +217,8 @@ object SamClient { def SamRegisterCollectionExceptionResp(statusCode: StatusCode) = HttpResponse(status = statusCode, entity = SamRegisterCollectionException(statusCode).getMessage) + case class UserStatusInfo(adminEnabled: Boolean, enabled: Boolean, userEmail: String, userSubjectId: String) + + implicit val UserStatusInfoFormat: RootJsonFormat[UserStatusInfo] = jsonFormat4(UserStatusInfo) + } diff --git a/CromIAM/src/main/scala/cromiam/webservice/CromIamApiService.scala b/CromIAM/src/main/scala/cromiam/webservice/CromIamApiService.scala index 63694599476..7a16e5ea797 100644 --- a/CromIAM/src/main/scala/cromiam/webservice/CromIamApiService.scala +++ b/CromIAM/src/main/scala/cromiam/webservice/CromIamApiService.scala @@ -81,7 +81,7 @@ trait CromIamApiService extends RequestSupport def abortRoute: Route = path("api" / "workflows" / Segment / Segment / Abort) { (_, workflowId) => post { - extractUserAndRequest { (user, req) => + extractUserAndStrictRequest { (user, req) => logUserWorkflowAction(user, workflowId, Abort) complete { authorizeAbortThenForwardToCromwell(user, workflowId, req).asHttpResponse @@ -93,7 +93,7 @@ trait CromIamApiService extends RequestSupport //noinspection MutatorLikeMethodIsParameterless def releaseHoldRoute: Route = path("api" / "workflows" / Segment / Segment / ReleaseHold) { (_, workflowId) => post { - extractUserAndRequest { (user, req) => + extractUserAndStrictRequest { (user, req) => logUserWorkflowAction(user, workflowId, ReleaseHold) complete { authorizeUpdateThenForwardToCromwell(user, workflowId, req).asHttpResponse @@ -112,7 +112,7 @@ trait CromIamApiService extends RequestSupport def labelPatchRoute: Route = { path("api" / "workflows" / Segment / Segment / Labels) { (_, workflowId) => patch { - extractUserAndRequest { (user, req) => + extractUserAndStrictRequest { (user, req) => entity(as[String]) { labels => logUserWorkflowAction(user, workflowId, Labels) validateLabels(Option(labels)) { _ => // Not using the labels, just using this to verify they didn't specify labels we don't want them to @@ -130,7 +130,7 @@ trait CromIamApiService extends RequestSupport def callCacheDiffRoute: Route = path("api" / "workflows" / Segment / "callcaching" / "diff") { _ => get { - extractUserAndRequest { (user, req) => + extractUserAndStrictRequest { (user, req) => logUserAction(user, "call caching diff") parameterSeq { parameters => val paramMap = parameters.toMap @@ -150,11 +150,9 @@ trait CromIamApiService extends RequestSupport */ private def workflowGetRoute(urlSuffix: String): Route = path("api" / "workflows" / Segment / urlSuffix) { _ => get { - extractUserAndRequest { (user, req) => + extractUserAndStrictRequest { (user, req) => logUserAction(user, urlSuffix) - complete { - cromwellClient.forwardToCromwell(req).asHttpResponse - } + forwardIfUserEnabled(user, req, cromwellClient, samClient) } } } @@ -166,7 +164,7 @@ trait CromIamApiService extends RequestSupport private def workflowRoute(urlSuffix: String, method: Directive0): Route = path("api" / "workflows" / Segment / Segment / urlSuffix) { (_, workflowId) => method { - extractUserAndRequest { (user, req) => + extractUserAndStrictRequest { (user, req) => logUserWorkflowAction(user, workflowId, urlSuffix) complete { authorizeReadThenForwardToCromwell(user, List(workflowId), req).asHttpResponse diff --git a/CromIAM/src/main/scala/cromiam/webservice/QuerySupport.scala b/CromIAM/src/main/scala/cromiam/webservice/QuerySupport.scala index cddabe74a57..e9397605c6a 100644 --- a/CromIAM/src/main/scala/cromiam/webservice/QuerySupport.scala +++ b/CromIAM/src/main/scala/cromiam/webservice/QuerySupport.scala @@ -55,7 +55,7 @@ trait QuerySupport extends RequestSupport { * directive */ private def preprocessQuery: Directive[(User, List[Collection], HttpRequest)] = { - extractUserAndRequest tflatMap { case (user, cromIamRequest) => + extractUserAndStrictRequest tflatMap { case (user, cromIamRequest) => log.info("Received query " + cromIamRequest.method.value + " request for user " + user.userId) onComplete(samClient.collectionsForUser(user, cromIamRequest).value.unsafeToFuture()) flatMap { diff --git a/CromIAM/src/main/scala/cromiam/webservice/RequestSupport.scala b/CromIAM/src/main/scala/cromiam/webservice/RequestSupport.scala index 12b231485f7..c9b6a196368 100644 --- a/CromIAM/src/main/scala/cromiam/webservice/RequestSupport.scala +++ b/CromIAM/src/main/scala/cromiam/webservice/RequestSupport.scala @@ -6,6 +6,13 @@ import akka.http.scaladsl.server.Directives._ import akka.http.scaladsl.server._ import cromiam.auth.User import org.broadinstitute.dsde.workbench.model.WorkbenchUserId +import akka.http.scaladsl.model.HttpResponse +import akka.http.scaladsl.server.Directives.{authorize, complete, onComplete} +import akka.http.scaladsl.server.Route +import cromiam.cromwell.CromwellClient +import cromiam.sam.SamClient + +import scala.util.{Failure, Success} trait RequestSupport { def extractStrictRequest: Directive1[HttpRequest] = { @@ -26,10 +33,27 @@ trait RequestSupport { } } - def extractUserAndRequest: Directive[(User, HttpRequest)] = { + def extractUserAndStrictRequest: Directive[(User, HttpRequest)] = { for { user <- extractUser request <- extractStrictRequest } yield (user, request) } + + def forwardIfUserEnabled(user: User, req: HttpRequest, cromwellClient: CromwellClient, samClient: SamClient): Route = { + import cromwell.api.model.EnhancedFailureResponseOrHttpResponseT + + onComplete(samClient.isUserEnabledSam(user, req).value.unsafeToFuture()) { + case Success(Left(httpResponse: HttpResponse)) => complete(httpResponse) + case Success(Right(isEnabled: Boolean)) => + authorize(isEnabled) { + complete { + cromwellClient.forwardToCromwell(req).asHttpResponse + } + } + case Failure(e) => + val message = s"Unable to look up enablement status for user ${user.userId}: ${e.getMessage}. Please try again later." + throw new RuntimeException(message, e) + } + } } diff --git a/CromIAM/src/main/scala/cromiam/webservice/SubmissionSupport.scala b/CromIAM/src/main/scala/cromiam/webservice/SubmissionSupport.scala index c1f5477475b..52a05d1cdc7 100644 --- a/CromIAM/src/main/scala/cromiam/webservice/SubmissionSupport.scala +++ b/CromIAM/src/main/scala/cromiam/webservice/SubmissionSupport.scala @@ -31,7 +31,7 @@ trait SubmissionSupport extends RequestSupport { // FIXME - getting pathPrefix to shrink this keeps hosing up, there's gotta be some way to do this def submitRoute: Route = (path("api" / "workflows" / Segment) | path("api" / "workflows" / Segment / "batch")) { _ => post { - extractUserAndRequest { (user, request) => + extractUserAndStrictRequest { (user, request) => log.info("Received submission request from user " + user.userId) onComplete(samClient.isSubmitWhitelisted(user, request).value.unsafeToFuture()) { case Success(Left(httpResponse)) => complete(httpResponse) diff --git a/CromIAM/src/main/scala/cromiam/webservice/WomtoolRouteSupport.scala b/CromIAM/src/main/scala/cromiam/webservice/WomtoolRouteSupport.scala index 671d4a76543..a6098b1fae0 100644 --- a/CromIAM/src/main/scala/cromiam/webservice/WomtoolRouteSupport.scala +++ b/CromIAM/src/main/scala/cromiam/webservice/WomtoolRouteSupport.scala @@ -2,20 +2,18 @@ package cromiam.webservice import akka.http.scaladsl.server.Directives._ import cromiam.cromwell.CromwellClient -import cromwell.api.model._ +import cromiam.sam.SamClient trait WomtoolRouteSupport extends RequestSupport { // When this trait is mixed into `CromIamApiService` the value of `cromwellClient` is the reader (non-abort) address val cromwellClient: CromwellClient + val samClient: SamClient val womtoolRoutes = path("api" / "womtool" / Segment / "describe") { _ => post { - extractStrictRequest { req => - complete { - // This endpoint requires authn which it gets for free from the proxy, does not care about authz - cromwellClient.forwardToCromwell(req).asHttpResponse - } + extractUserAndStrictRequest { (user, req) => + forwardIfUserEnabled(user, req, cromwellClient, samClient) } } } diff --git a/CromIAM/src/test/scala/cromiam/webservice/CromIamApiServiceSpec.scala b/CromIAM/src/test/scala/cromiam/webservice/CromIamApiServiceSpec.scala index 5ad6a976204..89945c5bfcb 100644 --- a/CromIAM/src/test/scala/cromiam/webservice/CromIamApiServiceSpec.scala +++ b/CromIAM/src/test/scala/cromiam/webservice/CromIamApiServiceSpec.scala @@ -4,7 +4,8 @@ import akka.event.NoLogging import akka.http.scaladsl.model.StatusCodes._ import akka.http.scaladsl.model.headers.{Authorization, OAuth2BearerToken, RawHeader} import akka.http.scaladsl.model.{ContentTypes, HttpEntity, HttpHeader} -import akka.http.scaladsl.server.MissingHeaderRejection +import akka.http.scaladsl.server.Route.seal +import akka.http.scaladsl.server.{AuthorizationFailedRejection, MissingHeaderRejection} import akka.http.scaladsl.testkit.ScalatestRouteTest import com.typesafe.config.Config import common.assertion.CromwellTimeoutSpec @@ -303,12 +304,45 @@ class CromIamApiServiceSpec extends AnyFlatSpec with CromwellTimeoutSpec with Ma } } - it should "reject request if it doesn't contain OIDC_CLAIM_user_id in header" in { + it should "reject request if it doesn't contain OIDC_CLAIM_user_id or token" in { Get(s"/api/workflows/$version/backends") ~> allRoutes ~> check { rejection shouldEqual MissingHeaderRejection("OIDC_CLAIM_user_id") } } + it should "return 403 when we request with a disabled user" in { + Get( + s"/api/workflows/$version/backends" + ).withHeaders( + List(Authorization(OAuth2BearerToken("my-token")), RawHeader("OIDC_CLAIM_user_id", "disabled@example.com")) + ) ~> allRoutes ~> check { + rejection shouldEqual AuthorizationFailedRejection + } + } + + it should "reject request if it contains a token and no OIDC_CLAIM_user_id in header" in { + Get( + s"/api/workflows/$version/backends" + ).withHeaders( + List(Authorization(OAuth2BearerToken("my-token"))) + ) ~> allRoutes ~> check { + rejection shouldEqual MissingHeaderRejection("OIDC_CLAIM_user_id") + } + } + + it should "return 404 when no auth token provided" in { + Get( + s"/api/workflows/$version/backends" + ).withHeaders( + List(RawHeader("OIDC_CLAIM_user_id", "enabled@example.com")) + // "[An] explicit call on the Route.seal method is needed in test code, but in your application code it is not necessary." + // https://doc.akka.io/docs/akka-http/current/routing-dsl/testkit.html#testing-sealed-routes + // https://doc.akka.io/docs/akka-http/current/routing-dsl/routes.html#sealing-a-route + ) ~> seal(allRoutes) ~> check { + responseAs[String] shouldEqual "The requested resource could not be found." + status shouldBe NotFound + } + } behavior of "ReleaseHold endpoint" it should "return 200 for authorized user who has collection associated with root workflow" in { diff --git a/CromIAM/src/test/scala/cromiam/webservice/MockClients.scala b/CromIAM/src/test/scala/cromiam/webservice/MockClients.scala index 3fb9689e5cc..59e75347159 100644 --- a/CromIAM/src/test/scala/cromiam/webservice/MockClients.scala +++ b/CromIAM/src/test/scala/cromiam/webservice/MockClients.scala @@ -141,6 +141,15 @@ class MockSamClient(checkSubmitWhitelist: Boolean = true) FailureResponseOrT.pure(!user.userId.value.equalsIgnoreCase(NotWhitelistedUser)) } + override def isUserEnabledSam(user: User, cromIamRequest: HttpRequest): FailureResponseOrT[Boolean] = { + if (user.userId.value == "enabled@example.com" || user.userId.value == MockSamClient.AuthorizedUserCollectionStr) + FailureResponseOrT.pure(true) + else if (user.userId.value == "disabled@example.com") + FailureResponseOrT.pure(false) + else + throw new Exception("Misconfigured test") + } + override def requestAuth(authorizationRequest: CollectionAuthorizationRequest, cromIamRequest: HttpRequest): FailureResponseOrT[Unit] = { authorizationRequest.user.userId.value match { diff --git a/CromIAM/src/test/scala/cromiam/webservice/WomtoolRouteSupportSpec.scala b/CromIAM/src/test/scala/cromiam/webservice/WomtoolRouteSupportSpec.scala index 7ba1c495f23..785c887c374 100644 --- a/CromIAM/src/test/scala/cromiam/webservice/WomtoolRouteSupportSpec.scala +++ b/CromIAM/src/test/scala/cromiam/webservice/WomtoolRouteSupportSpec.scala @@ -2,6 +2,9 @@ package cromiam.webservice import akka.http.scaladsl.model.ContentTypes import akka.http.scaladsl.model.StatusCodes._ +import akka.http.scaladsl.model.headers.{Authorization, OAuth2BearerToken, RawHeader} +import akka.http.scaladsl.server.Route.seal +import akka.http.scaladsl.server.{AuthorizationFailedRejection, MissingHeaderRejection} import akka.http.scaladsl.testkit.ScalatestRouteTest import common.assertion.CromwellTimeoutSpec import org.scalatest.flatspec.AnyFlatSpec @@ -11,15 +14,64 @@ import org.scalatest.matchers.should.Matchers class WomtoolRouteSupportSpec extends AnyFlatSpec with CromwellTimeoutSpec with Matchers with WomtoolRouteSupport with ScalatestRouteTest { override lazy val cromwellClient = new MockCromwellClient() + override lazy val samClient = new MockSamClient() behavior of "Womtool endpoint routes" it should "return 200 when we request to the right path" in { - Post(s"/api/womtool/v1/describe") ~> womtoolRoutes ~> check { + Post( + s"/api/womtool/v1/describe" + ).withHeaders( + List(Authorization(OAuth2BearerToken("my-token")), RawHeader("OIDC_CLAIM_user_id", "enabled@example.com")) + ) ~> womtoolRoutes ~> check { status shouldBe OK responseAs[String] shouldBe "Hey there, workflow describer" contentType should be(ContentTypes.`text/plain(UTF-8)`) } } + it should "return 403 when we request with a disabled user" in { + Post( + s"/api/womtool/v1/describe" + ).withHeaders( + List(Authorization(OAuth2BearerToken("my-token")), RawHeader("OIDC_CLAIM_user_id", "disabled@example.com")) + ) ~> womtoolRoutes ~> check { + rejection shouldEqual AuthorizationFailedRejection + } + } + + it should "bail out with no user ID" in { + Post( + s"/api/womtool/v1/describe" + ).withHeaders( + List(Authorization(OAuth2BearerToken("my-token"))) + ) ~> womtoolRoutes ~> check { + rejection shouldEqual MissingHeaderRejection("OIDC_CLAIM_user_id") + } + } + + it should "return 404 when no auth token provided" in { + Post( + s"/api/womtool/v1/describe" + ).withHeaders( + List(RawHeader("OIDC_CLAIM_user_id", "enabled@example.com")) + // "[An] explicit call on the Route.seal method is needed in test code, but in your application code it is not necessary." + // https://doc.akka.io/docs/akka-http/current/routing-dsl/testkit.html#testing-sealed-routes + // https://doc.akka.io/docs/akka-http/current/routing-dsl/routes.html#sealing-a-route + ) ~> seal(womtoolRoutes) ~> check { + responseAs[String] shouldEqual "The requested resource could not be found." + status shouldBe NotFound + } + } + + it should "bail out with no headers" in { + Post( + s"/api/womtool/v1/describe" + ).withHeaders( + List.empty + ) ~> womtoolRoutes ~> check { + rejection shouldEqual MissingHeaderRejection("OIDC_CLAIM_user_id") + } + } + } diff --git a/core/src/main/scala/cromwell/core/logging/EnhancedDateConverter.scala b/core/src/main/scala/cromwell/core/logging/EnhancedDateConverter.scala new file mode 100644 index 00000000000..dcf62bc0b28 --- /dev/null +++ b/core/src/main/scala/cromwell/core/logging/EnhancedDateConverter.scala @@ -0,0 +1,70 @@ +package cromwell.core.logging + +import ch.qos.logback.classic.pattern.DateConverter +import ch.qos.logback.classic.spi.ILoggingEvent +import ch.qos.logback.core.CoreConstants +import ch.qos.logback.core.util.CachingDateFormatter + +import java.util.TimeZone +import scala.jdk.CollectionConverters._ + +/** + * Log the Akka akkaTimestamp if found in the MDC, otherwise log the original event timestamp. + * + * - https://doc.akka.io/docs/akka/current/logging.html#more-accurate-timestamps-for-log-output-in-mdc + * - https://logback.qos.ch/manual/layouts.html#customConversionSpecifier + * + * NOTE: For proper configuration both this EnhancedDateConverter should be configured into the logback.xml AND the + * configuration file should set akka.loggers = ["cromwell.core.logging.EnhancedSlf4jLogger"]. + */ +class EnhancedDateConverter extends DateConverter { + protected var cachingDateFormatterProtected: CachingDateFormatter = _ + + /* Duplicated from ch.qos.logback.classic.pattern.DateConverter as cachingDateFormatter is package private. */ + override def start(): Unit = { + cachingDateFormatterProtected = Option(getFirstOption) match { + case Some(CoreConstants.ISO8601_STR) | None => new CachingDateFormatter(CoreConstants.ISO8601_PATTERN) + case Some(datePattern) => + try { + new CachingDateFormatter(datePattern) + } catch { + case e: IllegalArgumentException => + addWarn("Could not instantiate SimpleDateFormat with pattern " + datePattern, e) + // default to the ISO8601 format + new CachingDateFormatter(CoreConstants.ISO8601_PATTERN) + } + } + // if the option list contains a TZ option, then set it. + Option(getOptionList) + .toList + .flatMap(_.asScala) + .drop(1) + .headOption + .map(TimeZone.getTimeZone) + .foreach(cachingDateFormatterProtected.setTimeZone) + + // Allow the parent class to start/initialize its private members. + super.start() + } + + /** + * Look for the Akka timestamp and use that to format the date. + * + * Until this (currently 6+ year) issue is resolved, formatting the date as a Long requires using the + * [[EnhancedSlf4jLogger]] versus Akka's basic Slf4jLogger. + * + * - https://github.com/akka/akka/issues/18079#issuecomment-125175884 + */ + override def convert(event: ILoggingEvent): String = { + val mdc = event.getMDCPropertyMap + if (mdc.containsKey("akkaTimestamp")) { + val timestamp = mdc.get("akkaTimestamp") + timestamp.toLongOption match { + case Some(value) => cachingDateFormatterProtected.format(value) + case None => timestamp // Return the original timestamp string. + } + } else { + super.convert(event) + } + } +} diff --git a/core/src/main/scala/cromwell/core/logging/EnhancedSlf4jLogger.scala b/core/src/main/scala/cromwell/core/logging/EnhancedSlf4jLogger.scala new file mode 100644 index 00000000000..0999ec18055 --- /dev/null +++ b/core/src/main/scala/cromwell/core/logging/EnhancedSlf4jLogger.scala @@ -0,0 +1,16 @@ +package cromwell.core.logging + +import akka.event.slf4j.Slf4jLogger + +class EnhancedSlf4jLogger extends Slf4jLogger { + /** + * Format the timestamp as a simple long. Allows the akkaTimestamp to be retrieved later from the MDC by custom + * converters. + * + * NOTE: Should not be necessary once this issue is resolved: + * - https://github.com/akka/akka/issues/18079#issuecomment-125175884 + * + * @see [[EnhancedDateConverter.convert()]] + */ + override protected def formatTimestamp(timestamp: Long): String = String.valueOf(timestamp) +} diff --git a/core/src/main/scala/cromwell/core/logging/EnhancedThreadConverter.scala b/core/src/main/scala/cromwell/core/logging/EnhancedThreadConverter.scala new file mode 100644 index 00000000000..73f5876597b --- /dev/null +++ b/core/src/main/scala/cromwell/core/logging/EnhancedThreadConverter.scala @@ -0,0 +1,21 @@ +package cromwell.core.logging + +import ch.qos.logback.classic.pattern.ThreadConverter +import ch.qos.logback.classic.spi.ILoggingEvent + +/** + * Log the Akka sourceThread if found, otherwise log the event thread. + * + * - https://doc.akka.io/docs/akka/current/logging.html#logging-thread-akka-source-and-actor-system-in-mdc + * - https://logback.qos.ch/manual/layouts.html#customConversionSpecifier + */ +class EnhancedThreadConverter extends ThreadConverter { + override def convert(event: ILoggingEvent): String = { + val mdc = event.getMDCPropertyMap + if (mdc.containsKey("sourceThread")) { + mdc.get("sourceThread") + } else { + super.convert(event) + } + } +} diff --git a/core/src/main/scala/cromwell/core/logging/JavaLoggingBridge.scala b/core/src/main/scala/cromwell/core/logging/JavaLoggingBridge.scala new file mode 100644 index 00000000000..1dc10fab46d --- /dev/null +++ b/core/src/main/scala/cromwell/core/logging/JavaLoggingBridge.scala @@ -0,0 +1,39 @@ +package cromwell.core.logging + +import ch.qos.logback.classic.LoggerContext +import ch.qos.logback.classic.jul.LevelChangePropagator +import org.slf4j.LoggerFactory +import org.slf4j.bridge.SLF4JBridgeHandler + +import scala.jdk.CollectionConverters._ + +object JavaLoggingBridge { + /** + * Replace java.util.logging with SLF4J while ensuring Logback is configured with a LevelChangePropogator. + * + * One likely won't need to do this but just in case: note that any libraries using JUL running BEFORE this + * initialization which require increasing or decreasing verbosity must be configured via JUL not Logback. + * + * See also: + * - https://www.slf4j.org/api/org/slf4j/bridge/SLF4JBridgeHandler.html + * - https://docs.oracle.com/en/java/javase/11/docs/api/java.logging/java/util/logging/LogManager.html + */ + def init(): Unit = { + // Retrieve the Logback context, and as a side effect initialize Logback. + val ctx = LoggerFactory.getILoggerFactory.asInstanceOf[LoggerContext] + + // Ensure that Logback has a LevelChangePropagator, either here or via a logback.xml. + val listeners = ctx.getCopyOfListenerList.asScala + if (!listeners.exists(_.isInstanceOf[LevelChangePropagator])) { + val propagator = new LevelChangePropagator() + propagator.setContext(ctx) + propagator.start() + } + + // Remove all the JUL logging handlers. + SLF4JBridgeHandler.removeHandlersForRootLogger() + + // Send all JUL logging to SLF4J. + SLF4JBridgeHandler.install() + } +} diff --git a/database/migration/src/main/scala/cromwell/database/migration/liquibase/LiquibaseUtils.scala b/database/migration/src/main/scala/cromwell/database/migration/liquibase/LiquibaseUtils.scala index 20a77f58c02..e4823b8b0ac 100644 --- a/database/migration/src/main/scala/cromwell/database/migration/liquibase/LiquibaseUtils.scala +++ b/database/migration/src/main/scala/cromwell/database/migration/liquibase/LiquibaseUtils.scala @@ -1,7 +1,5 @@ package cromwell.database.migration.liquibase -import java.sql.Connection - import liquibase.changelog.{ChangeLogParameters, ChangeSet, DatabaseChangeLog} import liquibase.database.jvm.{HsqlConnection, JdbcConnection} import liquibase.database.{Database, DatabaseConnection, DatabaseFactory, ObjectQuotingStrategy} @@ -10,12 +8,21 @@ import liquibase.diff.{DiffGeneratorFactory, DiffResult} import liquibase.parser.ChangeLogParserFactory import liquibase.resource.ClassLoaderResourceAccessor import liquibase.snapshot.{DatabaseSnapshot, SnapshotControl, SnapshotGeneratorFactory} -import liquibase.{Contexts, LabelExpression, Liquibase} +import liquibase.ui.LoggerUIService +import liquibase.{Contexts, LabelExpression, Liquibase, Scope} import org.hsqldb.persist.HsqlDatabaseProperties +import java.sql.Connection import scala.jdk.CollectionConverters._ object LiquibaseUtils { + + /* + Move liquibase calls to System.out.println to a logger. + Workaround for issue: https://github.com/liquibase/liquibase/issues/1741#issuecomment-853742652 + */ + Scope.enter(Map(Scope.Attr.ui.name -> new LoggerUIService().asInstanceOf[AnyRef]).asJava) + // Paranoia: Create our own mutex. https://stackoverflow.com/questions/442564/avoid-synchronizedthis-in-java private val mutex = new Object private val DefaultContexts = new Contexts() diff --git a/docs/api/RESTAPI.md b/docs/api/RESTAPI.md index b15072f6407..f1713bc831a 100644 --- a/docs/api/RESTAPI.md +++ b/docs/api/RESTAPI.md @@ -1,5 +1,5 @@ + + + @@ -18,7 +28,7 @@ - %date %X{sourceThread} %-5level - %msg%n + %ed{yyyy-MM-dd HH:mm:ss,SSS} %et %-5level - %msg%n @@ -68,7 +78,7 @@ - %d{yyyy-MM-dd HH:mm:ss,SSS} [%thread] %-5level %logger{35} - %msg%n + %ed{yyyy-MM-dd HH:mm:ss,SSS} [%et] %-5level %logger{35} - %msg%n diff --git a/server/src/main/scala/cromwell/CromwellEntryPoint.scala b/server/src/main/scala/cromwell/CromwellEntryPoint.scala index 5acddd75ce9..a1707db6488 100644 --- a/server/src/main/scala/cromwell/CromwellEntryPoint.scala +++ b/server/src/main/scala/cromwell/CromwellEntryPoint.scala @@ -16,6 +16,7 @@ import cromwell.CommandLineArguments.{ValidSubmission, WorkflowSourceOrUrl} import cromwell.CromwellApp._ import cromwell.api.CromwellClient import cromwell.api.model.{Label, LabelsJsonFormatter, WorkflowSingleSubmission} +import cromwell.core.logging.JavaLoggingBridge import cromwell.core.path.{DefaultPathBuilder, Path} import cromwell.core.{WorkflowSourceFilesCollection, WorkflowSourceFilesWithDependenciesZip, WorkflowSourceFilesWithoutImports} import cromwell.engine.workflow.SingleWorkflowRunnerActor @@ -166,6 +167,13 @@ object CromwellEntryPoint extends GracefulStopSupport { Make sure that the next time one uses the ConfigFactory that our updated system properties are loaded. */ ConfigFactory.invalidateCaches() + + /* + Replace java.util.logging with SLF4J. + https://www.slf4j.org/api/org/slf4j/bridge/SLF4JBridgeHandler.html + */ + JavaLoggingBridge.init() + () }