CROM-6894 Logging updates

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 {

CromIAM/src/main/resources/logback.xml

@@ -1,5 +1,15 @@
 <configuration>
 
+    <!-- Enhanced thread and date reporting. -->
+    <conversionRule
+            conversionWord="et"
+            converterClass="cromwell.core.logging.EnhancedThreadConverter"
+    />
+    <conversionRule
+            conversionWord="ed"
+            converterClass="cromwell.core.logging.EnhancedDateConverter"
+    />
+
     <!-- default properties for FILEROLLER need to be set upfront -->
 
     <if condition='property("FILEROLLER_DIR").equals("")'>
@@ -18,7 +28,7 @@
         <then>
             <appender name="STANDARD_APPENDER" class="ch.qos.logback.core.ConsoleAppender">
                 <encoder>
-                    <pattern>%date %X{sourceThread} %-5level - %msg%n</pattern>
+                    <pattern>%ed{yyyy-MM-dd HH:mm:ss,SSS} %et %-5level - %msg%n</pattern>
                 </encoder>
             </appender>
         </then>
@@ -68,7 +78,7 @@
 
                 </rollingPolicy>
                 <encoder>
-                    <pattern>%d{yyyy-MM-dd HH:mm:ss,SSS} [%thread] %-5level %logger{35} - %msg%n</pattern>
+                    <pattern>%ed{yyyy-MM-dd HH:mm:ss,SSS} [%et] %-5level %logger{35} - %msg%n</pattern>
                 </encoder>
             </appender>
         </then>

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)
+    }
+  }
+}

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)
+}

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)
+    }
+  }
+}

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()
+  }
+}

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()

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"),
+  )
 }

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"),

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"
 

server/src/main/resources/logback.xml

@@ -1,5 +1,15 @@
 <configuration>
 
+    <!-- Enhanced thread and date reporting. -->
+    <conversionRule
+            conversionWord="et"
+            converterClass="cromwell.core.logging.EnhancedThreadConverter"
+    />
+    <conversionRule
+            conversionWord="ed"
+            converterClass="cromwell.core.logging.EnhancedDateConverter"
+    />
+
     <!-- default properties for FILEROLLER need to be set upfront -->
 
     <if condition='property("FILEROLLER_DIR").equals("")'>
@@ -18,7 +28,7 @@
         <then>
             <appender name="STANDARD_APPENDER" class="ch.qos.logback.core.ConsoleAppender">
                 <encoder>
-                    <pattern>%date %X{sourceThread} %-5level - %msg%n</pattern>
+                    <pattern>%ed{yyyy-MM-dd HH:mm:ss,SSS} %et %-5level - %msg%n</pattern>
                 </encoder>
             </appender>
         </then>
@@ -68,7 +78,7 @@
 
                 </rollingPolicy>
                 <encoder>
-                    <pattern>%d{yyyy-MM-dd HH:mm:ss,SSS} [%thread] %-5level %logger{35} - %msg%n</pattern>
+                    <pattern>%ed{yyyy-MM-dd HH:mm:ss,SSS} [%et] %-5level %logger{35} - %msg%n</pattern>
                 </encoder>
             </appender>
         </then>

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()
+
     ()
   }