#3080 - Including a timestamp in LogEvent and in the MDC

akka-actor-tests/src/test/scala/akka/event/LoggerSpec.scala

@@ -7,10 +7,12 @@ import akka.testkit._
 import scala.concurrent.duration._
 import com.typesafe.config.{ Config, ConfigFactory }
 import akka.actor.{ ActorRef, Actor, ActorSystem }
+import java.util.{ Date, GregorianCalendar, TimeZone, Calendar }
 import org.scalatest.WordSpec
 import org.scalatest.matchers.MustMatchers
 import akka.serialization.SerializationExtension
 import akka.event.Logging.{ Warning, LogEvent, LoggerInitialized, InitializeLogger }
+import akka.util.Helpers
 
 object LoggerSpec {
 
@@ -144,6 +146,19 @@ class LoggerSpec extends WordSpec with MustMatchers {
     }
   }
 
+  "Ticket 3080" must {
+    "format currentTimeMillis to a valid UTC String" in {
+      val timestamp = System.currentTimeMillis
+      val c = new GregorianCalendar(TimeZone.getTimeZone("UTC"))
+      c.setTime(new Date(timestamp))
+      val hours = c.get(Calendar.HOUR_OF_DAY)
+      val minutes = c.get(Calendar.MINUTE)
+      val seconds = c.get(Calendar.SECOND)
+      val ms = c.get(Calendar.MILLISECOND)
+      Helpers.currentTimeMillisToUTCString(timestamp) must be(f"$hours%02d:$minutes%02d:$seconds%02d.$ms%03dUTC")
+    }
+  }
+
   "Ticket 3165 - serialize-messages and dual-entry serialization of LogEvent" must {
     "not cause StackOverflowError" in {
       implicit val s = ActorSystem("foo", ticket3165Config)

akka-actor/src/main/scala/akka/event/Logging.scala

@@ -577,6 +577,11 @@ object Logging {
     @transient
     val thread: Thread = Thread.currentThread
 
+    /**
+     * When this LogEvent was created according to System.currentTimeMillis
+     */
+    val timestamp: Long = System.currentTimeMillis
+
     /**
      * The LogLevel of this LogEvent
      */
@@ -675,6 +680,7 @@ object Logging {
     import java.text.SimpleDateFormat
     import java.util.Date
 
+    private val date = new Date()
     private val dateFormat = new SimpleDateFormat("MM/dd/yyyy HH:mm:ss.SSS")
     private val errorFormat = "[ERROR] [%s] [%s] [%s] %s%s".intern
     private val errorFormatWithoutCause = "[ERROR] [%s] [%s] [%s] %s".intern
@@ -682,7 +688,10 @@ object Logging {
     private val infoFormat = "[INFO] [%s] [%s] [%s] %s".intern
     private val debugFormat = "[DEBUG] [%s] [%s] [%s] %s".intern
 
-    def timestamp(): String = synchronized { dateFormat.format(new Date) } // SDF isn't threadsafe
+    def timestamp(event: LogEvent): String = synchronized {
+      date.setTime(event.timestamp)
+      dateFormat.format(date)
+    } // SDF isn't threadsafe
 
     def print(event: Any): Unit = event match {
       case e: Error   ⇒ error(e)
@@ -695,7 +704,7 @@ object Logging {
     def error(event: Error): Unit = {
       val f = if (event.cause == Error.NoCause) errorFormatWithoutCause else errorFormat
       println(f.format(
-        timestamp,
+        timestamp(event),
         event.thread.getName,
         event.logSource,
         event.message,
@@ -704,21 +713,21 @@ object Logging {
 
     def warning(event: Warning): Unit =
       println(warningFormat.format(
-        timestamp,
+        timestamp(event),
         event.thread.getName,
         event.logSource,
         event.message))
 
     def info(event: Info): Unit =
       println(infoFormat.format(
-        timestamp,
+        timestamp(event),
         event.thread.getName,
         event.logSource,
         event.message))
 
     def debug(event: Debug): Unit =
       println(debugFormat.format(
-        timestamp,
+        timestamp(event),
         event.thread.getName,
         event.logSource,
         event.message))
@@ -735,10 +744,9 @@ object Logging {
     val path: ActorPath = new RootActorPath(Address("akka", "all-systems"), "/StandardOutLogger")
     def provider: ActorRefProvider = throw new UnsupportedOperationException("StandardOutLogger does not provide")
     override val toString = "StandardOutLogger"
-    override def !(message: Any)(implicit sender: ActorRef = Actor.noSender): Unit = {
+    override def !(message: Any)(implicit sender: ActorRef = Actor.noSender): Unit =
       if (message == null) throw new InvalidMessageException("Message is null")
-      print(message)
+      else print(message)
-    }
   }
 
   val StandardOutLogger = new StandardOutLogger

akka-actor/src/main/scala/akka/util/Helpers.scala

@@ -37,6 +37,21 @@ object Helpers {
     }
   }
 
+  /**
+   * Converts a "currentTimeMillis"-obtained timestamp accordingly:
+   *   "$hours%02d:$minutes%02d:$seconds%02d.$ms%03dUTC"
+   * @param timestamp a "currentTimeMillis"-obtained timestamp
+   * @return A String formatted like: $hours%02d:$minutes%02d:$seconds%02d.$ms%03dUTC
+   */
+  def currentTimeMillisToUTCString(timestamp: Long): String = {
+    val timeOfDay = timestamp % 86400000L
+    val hours = timeOfDay / 3600000L
+    val minutes = timeOfDay / 60000L % 60
+    val seconds = timeOfDay / 1000L % 60
+    val ms = timeOfDay % 1000
+    f"$hours%02d:$minutes%02d:$seconds%02d.$ms%03dUTC"
+  }
+
   final val base64chars = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789+~"
 
   @tailrec

akka-docs/rst/java/logging.rst

@@ -284,3 +284,16 @@ information is available in the MDC with attribute name ``akkaSource``::
 
 For more details on what this attribute contains—also for non-actors—please see
 `How to Log`_.
+
+More accurate timestamps for log output in MDC
+------------------------------------------------
+
+Akka's logging is asynchronous which means that the timestamp of a log entry is taken from
+when the underlying logger implementation is called, which can be surprising at first.
+If you want to more accurately output the timestamp, use the MDC attribute ``akkaTimestamp``::
+
+  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
+    <encoder>
+      <pattern>%X{akkaTimestamp} %-5level %logger{36} %X{akkaSource} - %msg%n</pattern>
+    </encoder>
+  </appender>

akka-docs/rst/scala/logging.rst

@@ -322,3 +322,17 @@ information is available in the MDC with attribute name ``akkaSource``::
 
 For more details on what this attribute contains—also for non-actors—please see
 `How to Log`_.
+
+
+More accurate timestamps for log output in MDC
+------------------------------------------------
+
+Akka's logging is asynchronous which means that the timestamp of a log entry is taken from
+when the underlying logger implementation is called, which can be surprising at first.
+If you want to more accurately output the timestamp, use the MDC attribute ``akkaTimestamp``::
+
+  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
+    <encoder>
+      <pattern>%X{akkaTimestamp} %-5level %logger{36} %X{akkaSource} - %msg%n</pattern>
+    </encoder>
+  </appender>

akka-osgi/src/main/scala/akka/osgi/DefaultOSGiLogger.scala

@@ -69,8 +69,10 @@ class DefaultOSGiLogger extends DefaultLogger {
    */
   def logMessage(logService: LogService, event: LogEvent) {
     event match {
-      case error: Logging.Error if error.cause != NoCause ⇒ logService.log(event.level.asInt, messageFormat.format(timestamp, event.thread.getName, event.logSource, event.message), error.cause)
+      case error: Logging.Error if error.cause != NoCause ⇒
-      case _ ⇒ logService.log(event.level.asInt, messageFormat.format(timestamp, event.thread.getName, event.logSource, event.message))
+        logService.log(event.level.asInt, messageFormat.format(timestamp(event), event.thread.getName, event.logSource, event.message), error.cause)
+      case _ ⇒
+        logService.log(event.level.asInt, messageFormat.format(timestamp(event), event.thread.getName, event.logSource, event.message))
     }
   }
 

akka-slf4j/src/main/scala/akka/event/slf4j/Slf4jLogger.scala

@@ -9,6 +9,7 @@ import org.slf4j.MDC
 import akka.event.Logging._
 import akka.actor._
 import akka.event.DummyClassForStringSources
+import akka.util.Helpers
 
 /**
  * Base trait for all classes that wants to be able use the SLF4J logging infrastructure.
@@ -54,11 +55,12 @@ class Slf4jLogger extends Actor with SLF4JLogging {
 
   val mdcThreadAttributeName = "sourceThread"
   val mdcAkkaSourceAttributeName = "akkaSource"
+  val mdcAkkaTimestamp = "akkaTimestamp"
 
   def receive = {
 
     case event @ Error(cause, logSource, logClass, message) ⇒
-      withMdc(logSource, event.thread.getName) {
+      withMdc(logSource, event) {
         cause match {
           case Error.NoCause | null ⇒ Logger(logClass, logSource).error(if (message != null) message.toString else null)
           case cause                ⇒ Logger(logClass, logSource).error(if (message != null) message.toString else cause.getLocalizedMessage, cause)
@@ -66,13 +68,13 @@ class Slf4jLogger extends Actor with SLF4JLogging {
       }
 
     case event @ Warning(logSource, logClass, message) ⇒
-      withMdc(logSource, event.thread.getName) { Logger(logClass, logSource).warn("{}", message.asInstanceOf[AnyRef]) }
+      withMdc(logSource, event) { Logger(logClass, logSource).warn("{}", message.asInstanceOf[AnyRef]) }
 
     case event @ Info(logSource, logClass, message) ⇒
-      withMdc(logSource, event.thread.getName) { Logger(logClass, logSource).info("{}", message.asInstanceOf[AnyRef]) }
+      withMdc(logSource, event) { Logger(logClass, logSource).info("{}", message.asInstanceOf[AnyRef]) }
 
     case event @ Debug(logSource, logClass, message) ⇒
-      withMdc(logSource, event.thread.getName) { Logger(logClass, logSource).debug("{}", message.asInstanceOf[AnyRef]) }
+      withMdc(logSource, event) { Logger(logClass, logSource).debug("{}", message.asInstanceOf[AnyRef]) }
 
     case InitializeLogger(_) ⇒
       log.info("Slf4jLogger started")
@@ -80,16 +82,23 @@ class Slf4jLogger extends Actor with SLF4JLogging {
   }
 
   @inline
-  final def withMdc(logSource: String, thread: String)(logStatement: ⇒ Unit) {
+  final def withMdc(logSource: String, logEvent: LogEvent)(logStatement: ⇒ Unit) {
     MDC.put(mdcAkkaSourceAttributeName, logSource)
-    MDC.put(mdcThreadAttributeName, thread)
+    MDC.put(mdcThreadAttributeName, logEvent.thread.getName)
-    try {
+    MDC.put(mdcAkkaTimestamp, formatTimestamp(logEvent.timestamp))
-      logStatement
+    try logStatement finally {
-    } finally {
       MDC.remove(mdcAkkaSourceAttributeName)
       MDC.remove(mdcThreadAttributeName)
+      MDC.remove(mdcAkkaTimestamp)
     }
   }
 
+  /**
+   * Override this method to provide a differently formatted timestamp
+   * @param timestamp a "currentTimeMillis"-obtained timestamp
+   * @return the given timestamp as a UTC String
+   */
+  protected def formatTimestamp(timestamp: Long): String =
+    Helpers.currentTimeMillisToUTCString(timestamp)
 }