How to make available sourceThread and akkaTimestamp values in log events dispatched by non-Akka parts?

Question

Our Akka project depends on some other non akka code. From within this code our way to get a logger is by calling org.slf4j.LoggerFactory.getLogger(ThisClass.class)

I would like to have the real time and real thread when and where the event took place, included in the log print, so I fetch the values of akkaTimestamp and sourceThread, as following:

log4j.appender.console.layout.ConversionPattern=[%-5p] [%X{akkaTimestamp}] [%X{sourceThread}] %c{5}: %m%n

Problem is that these values, which are extracted from the MDC, are not available in the prints which were dispatched from the non-akka loggers.

Here they say

It will probably be a good idea to use the sourceThread MDC value also in non-Akka parts of the application in order to have this property consistently available in the logs.

But they never say how /:

Pressley

Not sure about the akkaTimestamp, but for sourceThread I just call MDC.put("sourceThread", Thread.currentThread().getName()) either in the actor prior to calling the non-actor code, or is some cases it will be the first thing I do in the non-actor code. If you can access the akkaTimestamp from actor's context then you could set this also. – Vasos

thanks @nickebbitt, but this solution is not good enough. besides our own party's dependencies we also have many 3rd parties, such as spark, hadoop etc.. I don't always have hooks on which I can "hang" the calls on MDC, and even if I did, it doesn't make too much sense - too much maintenance in the long run. I guess what I'm really looking for is a way to tell log4j to check in each event publish if there are values for akkaTimestamp and sourceThread, and in case missing fill in the values from %d and %t respectively. – Pressley

Yes maintenance is a problem, and 3rd party dependencies. For this reason the approach is limited. I've considered an AOP solution but not explored that option as yet. – Vasos

Answer 1

As Konrad says, its not that complicated. This is what worked for me:

import akka.util.Helpers
import ch.qos.logback.core.ConsoleAppender
import org.slf4j.MDC

/**
 * Decorates MDC with same keys as Akka in
 * <a href="https://github.com/akka/akka/blob/master/akka-slf4j/src/main/scala/akka/event/slf4j/Slf4jLogger.scala#L89">Slf4jLogger</a>
 * So that logging messages dispatched from non-akka threads has same data.
 */
class AkkaCompatibleConsoleAppender[E] extends ConsoleAppender[E] {

  val mdcThreadAttributeName = "sourceThread"
  val mdcAkkaTimestamp = "akkaTimestamp"

  override def append(eventObject: E): Unit = {
    try {
      MDC.put(mdcAkkaTimestamp, Helpers.currentTimeMillisToUTCString(System.currentTimeMillis()))
      MDC.put(mdcThreadAttributeName, Thread.currentThread().getName)
      super.append(eventObject)
    } finally {
      MDC.remove(mdcAkkaTimestamp)
      MDC.remove(mdcThreadAttributeName)
    }
  }
}

And then in logback.xml:

<appender name="STDOUT" class="agordo.server.AkkaCompatibleConsoleAppender">
    <encoder>
        <pattern>%X{akkaTimestamp} %-5level %logger{36} %X{sourceThread} %X{akkaSource} - %msg%n</pattern>           
    </encoder>
</appender>

Seep

Haven't tried it yet but it does seem promising. thanks! – Pressley

The point of akkaTimestamp is that it's recorded at the time an event happened, not when it was logged. The latter information is readily available from Logback as %date. I don't know of a way to get the source timestamp in user code. – Bassoon

Small addition: if you're using the same appender for both Akka and non-Akka-generated logs, unconditional MDC.put will overwrite values provided by Akka, basically reverting to using %d and %thread. So check if (MDC.get(mdcAkkaTimestamp) == null || MDC.put(mdcThreadAttributeName) == null) before adding them. – Inferior

I'm trying to do this on the play framework. The problem is class loading. How can I set this class up to let the play know? – Gree

It's not correct! The threadName is not equal to the real sourceThread which processed messages in actor. – Notorious

@VasiliyIvashin : It would be better if you updated the code snippet itself. – Bedraggled

Answer 2

You could set up your non-akka loggers to use the same style of MDC. It's not very complicated and you can look at Akka's Slf4jLogger class to see how it is done.

For the current thread you can simply use Thread.currentThread.getName and for the time (in order to be 1:1 with the Akka impl) you can have a look at the Helpers.currentTimeMillisToUTCString method in Akka (see here for currentTimeMillisToUTCString)

Happy hakking!

Worry

If I understand you correctly, what you offer me is to go to all my non-akka own party dependencies and replace all calls to LoggerFactory.getLogger with MyLoggeFactory.getLogger which will manually put the date and thread under akkaTimestamp and sourceThread keys into the MDC, is that correct? Not good enough. I still have many 3rd parties such as spark and hadoop which I have no access to points in the life cycle in which their log events are dispatched. – Pressley

Yes and no. If you want to add information in places (3rd party code) where they do not provide it, you could use your own Appender there, which would wrap an existing slf4j appender, inject the MDC data and call the underlying logger (think "manual AOP"). It's not fun, but also not really an akka or scala issue - it's how SLF4J works. – Semanteme

@konrad-ktoso-malawski what you say sounds interesting, but with the absence of (just a little bit of) code examples I have no idea how to implement it /: – Pressley

It's a bit researchy and hacky, I do not have a ready solution, just ideas which should work :) – Semanteme