diff --git a/akka-actor-tests/src/test/scala/akka/event/LoggerSpec.scala b/akka-actor-tests/src/test/scala/akka/event/LoggerSpec.scala index aa4a82db0f..aa8217b237 100644 --- a/akka-actor-tests/src/test/scala/akka/event/LoggerSpec.scala +++ b/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) diff --git a/akka-actor/src/main/scala/akka/event/Logging.scala b/akka-actor/src/main/scala/akka/event/Logging.scala index dc35609dee..f3a935797f 100644 --- a/akka-actor/src/main/scala/akka/event/Logging.scala +++ b/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 diff --git a/akka-actor/src/main/scala/akka/util/Helpers.scala b/akka-actor/src/main/scala/akka/util/Helpers.scala index f62724e065..00beae396a 100644 --- a/akka-actor/src/main/scala/akka/util/Helpers.scala +++ b/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 diff --git a/akka-docs/rst/java/logging.rst b/akka-docs/rst/java/logging.rst index c4133b0f46..4483dc5036 100644 --- a/akka-docs/rst/java/logging.rst +++ b/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``:: + + + + %X{akkaTimestamp} %-5level %logger{36} %X{akkaSource} - %msg%n + + diff --git a/akka-docs/rst/scala/logging.rst b/akka-docs/rst/scala/logging.rst index adeea22873..174a53ed7a 100644 --- a/akka-docs/rst/scala/logging.rst +++ b/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``:: + + + + %X{akkaTimestamp} %-5level %logger{36} %X{akkaSource} - %msg%n + + \ No newline at end of file diff --git a/akka-osgi/src/main/scala/akka/osgi/DefaultOSGiLogger.scala b/akka-osgi/src/main/scala/akka/osgi/DefaultOSGiLogger.scala index 3d2973e437..1363c17b8b 100644 --- a/akka-osgi/src/main/scala/akka/osgi/DefaultOSGiLogger.scala +++ b/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 _ ⇒ logService.log(event.level.asInt, messageFormat.format(timestamp, event.thread.getName, event.logSource, event.message)) + case error: Logging.Error if error.cause != NoCause ⇒ + 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)) } } diff --git a/akka-slf4j/src/main/scala/akka/event/slf4j/Slf4jLogger.scala b/akka-slf4j/src/main/scala/akka/event/slf4j/Slf4jLogger.scala index 0354955ef9..7d90e69d71 100644 --- a/akka-slf4j/src/main/scala/akka/event/slf4j/Slf4jLogger.scala +++ b/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) - try { - logStatement - } finally { + MDC.put(mdcThreadAttributeName, logEvent.thread.getName) + MDC.put(mdcAkkaTimestamp, formatTimestamp(logEvent.timestamp)) + try logStatement 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) }