Implement a standard way of supporting MDC in an async application.

[Kreinoee]

MDC is currently pretty hard to use in async applications, and it would therefore maybe be help for many, if scala-logging supported a way, that would make it more easy to use MDC in an async application.

MDC in slf4j saves the key/value pairs in threadlocal, so to work in an async application scala-logging would need to supply a way of making it easy to set all MDC values before each log statement, and clear them again after the logging statement has been sent to slf4j.

My own solution to this, has been to create a class named RequestLogger, that takes an Map[MDC_KEY, MDC_VALUE] at initialization, and then provides logging methods identical to what sfl4j provides, but with an extra implict param of type Logger. Each method sets the MDC values, use the implicit logger to perform the logging, and then clears the MDC values again. I then pass arround a RequestLogger instance, and use it to perform all logging. My current implementation is based directly on slf4j and not scala-logging as the macros would not be very helpfull anyway in this case (the string would be evaluated before it reaches the code where the macro wrappes in in an if statement). But a coresponding class provided by scala-logging, with the same macros as the Logger class has, could be one suggestion.

There could very well be others and better solutions, and it should be researched and discussed before chosing a solution, but I would like no if there is a possibility that such systems could be a part of scala-logging, before I dive into it.

[pwliwanow]

I forked this repository and implemented new class that I think would solve your issue (https://github.com/pwliwanow/scala-logging/).

Here is the relevant part of the code describes the idea:

trait CanLog[A] {
  def logMessage(originalMsg: String, a: A): String
  def afterLog(a: A): Unit = ()
}

class LoggerTakingImplicit[A] (val underlying: Underlying)(implicit val canLogEv: CanLog[A]) { 
  def error(message: String)(implicit a: A): Unit
}

In the README I added examples how it can be used with MDC. I would love to hear your feedback and if maintainers of this repository like this change, I am more than happy to merge it here :)

[AlexITC]

As I understand, the problem with that approach is that now, you need to propagate the implicit argument, while on thread-based MDC, you could set the value of interest once and then remove it when the flow is completed, one example is setting this value in a request filter.

I have even created a plugin that tries to solve this in the case of play-framework using request-scoped objects, sadly, it is not good enough (see https://github.com/AlexITC/play-request-tracer).

EDIT: This post might be useful: http://yanns.github.io/blog/2014/05/04/slf4j-mapped-diagnostic-context-mdc-with-play-framework/

[jsw]

I'm guessing this issue can be closed based on #83 and release 3.8.0?

One question I have is if the example of incorporating MDC in the README works with logback's AsyncAppender. I think that would depend on whether the appender renders the final message including conversions in the same thread and before afterLog is called.

case class CorrelationId(value: String)
implicit case object CanLogCorrelationId extends CanLog[CorrelationId] {
  override def logMessage(originalMsg: String, a: CorrelationId): String = {
    MDC.put("correlationId", a.value)
    originalMsg
  }
  
  override def afterLog(a: A): Unit = {
    MDC.remove("correlationId")
  }
}

[pwliwanow]

@jsw looking at ch.qos.logback.core.AsyncAppenderBase I think it should work fine. These things happen on the calling thread (unless I missed something): first append method is being called, which calls preprocess(eventObject), where eventObject sets its message, and MDC property map (MDC map is copied from MDC adapter), and finally event object is being put on the blockingQueue. On another thread worker reads event objects (which have already set MDC map) from the queue and renders them.

[jsw]

@pwliwanow Thanks!

Relevant to this thread is a recent post I made to scala contributor's group. I'm looking for the community to advocate a standard mechanism for propagating context across threads.

https://contributors.scala-lang.org/t/locals-in-scala-concurrent/1785

I'm familiar with all the solutions mentioned in this thread, and they all have their pros/cons. If anyone is interested in chatting about this with me, you can contact me on gitter.

[girishsubramanyam]

Hi All,

Are you guys planning to implement this ?

Thanks
Girish

[Kreinoee]

As @pwliwanow mentioned, most of it has already been implemented in #83, and works well. The only thing missing for completing this issue, is an implementation of a MDCMap class, and a default implementation of CanLog[MDCMap]. I said I would create a pull request for this, but I have been busy sinces, and not worked on projects where I needed it. However these classes, are just for having a default bridge to the java world, where MDC is a well known concept, and thereby making it easy to use scala-logging in an application, where MDC is already in use. If you are creating a new app, or just want to start use MDC in you scala app, you may be better of, creating you own class holding the values that should be included in the log, and creating you own implementation of CanLog that able to include them, it will provide better typesafty than using a Map[String,String].

[IainHull]

I really like the ideas behind CanLog And it works really well with MDC if it is the only thing appending to the MDC. What if other code could also be adding to the MDC (for example an interceptor on a typed actor)? Then afterLog could remove a value from the MDC that was added by a previous scope.

It would be much nicer to allow for the conditional removal in afterLog. The code below does not compile because cleanup is not accessible in afterLog.

case class CorrelationId(value: String)
implicit case object CanLogCorrelationId extends CanLog[CorrelationId] {
  override def logMessage(originalMsg: String, a: CorrelationId): String = {
    val cleanup = if (MDC.contains("correlationId")) {
      false
    } else {
      MDC.put("correlationId", a.value)
      true
    }
    originalMsg
  }
  
  override def afterLog(a: A): Unit = {
    if (cleanup) MDC.remove("correlationId")
  }
}

However if CanLog.afterLog was implemented with a function instead of a method cleanup would be much easier.

trait CanLog2[A] {
  override def logMessage(originalMsg: String, a: A): (String, () => Unit)
}

Now conditional clean up is straight forward.

implicit case object CanLogCorrelationId extends CanLog2[CorrelationId] {
  override def logMessage(originalMsg: String, a: CorrelationId): (String, ()=>Unit) = {
    val cleanup = if (MDC.contains("correlationId")) {
      originalMsg -> ()=>()
    } else {
      MDC.put("correlationId", a.value)
      originalMsg -> () => MDC.remove("correlationId"): Unit
    }
  }
}

The old CanLog can produce the more powerful CanLog2

object CanLog2 {
  implicit def fromCanLog[A](implicit canLog: CanLog[A]) = new CanLog2 {
    override def logMessage(originalMsg: String, a: A): (String, ()=>Unit) = {
      canLog.logMessage(originalMsg, a) -> () => afterLog(a)
    }
  }
}

[gabrieljones]

Is this relevant?
https://logging.apache.org/log4j/2.x/manual/extending.html#Custom_ContextDataProvider

[deantray]

Twitter's futures have a context which has a ThreadLocal to transfer everything trhouhg. logback just needs a weay to override the MDC and leave it up to the frameworks to replace the MDC. Twitter finatra replaces the MDCAdapter somehow(reflection maybe) to use Twitters Promise Local.scala instead of ThreadLocal.

[deantray]

Had to do LOTS of reflection to swap out ThreadLocal for Context.java :( in an XFutureMDCAdapter ->

https://github.com/deanhiller/webpieces/pull/213/files#diff-cfa9505f151c50437505e6cb79f17549bd973387fd92ff894ce112bc5205f7a3

Anyway we can have a non-reflective way of adding async MDCAdapter going forward?

[deantray]

MDC.put("key", "value"); works for all keys, values across the CompletableFutures (shamelessly copied from Twitter's version of Promise/Future ;) ).