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/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/project/Dependencies.scala b/project/Dependencies.scala index 3aab47d94ce..045f1edd544 100644 --- a/project/Dependencies.scala +++ b/project/Dependencies.scala @@ -232,7 +232,13 @@ object Dependencies { "org.codehaus.janino" % "janino" % janinoV, // Replace all log4j usage with slf4j // https://www.slf4j.org/legacy.html#log4j-over-slf4j - "org.slf4j" % "log4j-over-slf4j" % slf4jV + "org.slf4j" % "log4j-over-slf4j" % slf4jV, + // Replace all commons-logging usage with slf4j + // https://www.slf4j.org/legacy.html#jcl-over-slf4j + "org.slf4j" % "jcl-over-slf4j" % slf4jV, + // Enable runtime replacing of java.util.logging usage with slf4j + // https://www.slf4j.org/legacy.html#jul-to-slf4j + "org.slf4j" % "jul-to-slf4j" % slf4jV, ) ++ slf4jFacadeDependencies private val slickDependencies = List( @@ -710,4 +716,12 @@ object Dependencies { nimbusdsOverrides ++ bouncyCastleOverrides ++ protobufJavaOverrides + + /* + Libraries that should be globally excluded. + */ + val cromwellExcludeDependencies: List[ExclusionRule] = List( + // Replaced with jcl-over-slf4j + ExclusionRule("commons-logging", "commons-logging"), + ) } diff --git a/project/Settings.scala b/project/Settings.scala index 79242733583..951b1fc8fe6 100644 --- a/project/Settings.scala +++ b/project/Settings.scala @@ -86,6 +86,7 @@ object Settings { Tags.limit(Tags.Test, 1) ), dependencyOverrides ++= cromwellDependencyOverrides, + excludeDependencies ++= cromwellExcludeDependencies, scalacOptions ++= baseSettings ++ warningSettings ++ consoleHostileSettings, // http://stackoverflow.com/questions/31488335/scaladoc-2-11-6-fails-on-throws-tag-with-unable-to-find-any-member-to-link#31497874 Compile / doc / scalacOptions ++= baseSettings ++ List("-no-link-warnings"), diff --git a/server/src/main/resources/application.conf b/server/src/main/resources/application.conf index e0769277a6b..e80cd716b4e 100644 --- a/server/src/main/resources/application.conf +++ b/server/src/main/resources/application.conf @@ -1,6 +1,6 @@ akka { log-dead-letters = "off" - loggers = ["akka.event.slf4j.Slf4jLogger"] + loggers = ["cromwell.core.logging.EnhancedSlf4jLogger"] logging-filter = "cromwell.server.CromwellAkkaLogFilter" actor.guardian-supervisor-strategy = "cromwell.core.CromwellUserGuardianStrategy" diff --git a/server/src/main/resources/logback.xml b/server/src/main/resources/logback.xml index 4868962f994..b4d4ac4a335 100644 --- a/server/src/main/resources/logback.xml +++ b/server/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/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() + () }