Documentation

MDC in an Asynchronous Environment

What is MDC?

Mapped Diagnostic Context is essentially a map maintained by the logging framework where the application code provides key-value pairs which can then be inserted by the logging framework in log messages. MDC data can also be highly helpful in filtering messages, store useful data to diagnose errors or triggering certain actions.

This context can be used to store values that can be displayed in every Logging statement. For example:

def requestProcessor(request:Request):Unit = {
  MDC.put("X-ApplicationId", request.client)
  try {

    logger.info("processing Request...")

  } finally {
    MDC.remove("X-ApplicationId") //clean up the mdc
  }
}
public void requestProcessor(Request request) {
  MDC.put("X-ApplicationId", request.client);
  try {

    logger.info("processing Request...");

  } finally {
    MDC.remove("X-ApplicationId"); //clean up the mdc
  }
}

logback.xml must be configured to display the X-ApplicationId value as show below:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} %-5level %logger{35} %X{X-ApplicationId} - %msg%n</pattern>
    </encoder>
</appender>

In the Console, the MDC value for X-ApplicationId is now printed out:

16:51:49.605 [info] Logger AwesomeClient - processing Request...

Limitation of the default implementation of the MDC

To record the values in the MDC, Logback uses a ThreadLocal variable in order to manages contextual information on a per thread basis. A child thread automatically inherits a copy of the mapped diagnostic context of its parent.

This strategy works when one thread is used for one request, like in servlet container before the 3.0 specification. In a asynchronous server, the processing of a request could be composed of several function calls, and each call can be run on a different thread for that reason the implementation of the MDC with a ThreadLocal cannot work with this non-blocking asynchronous threading model.

Known Alternatives

Depending of the utilized framework there is some known workaround:

  • a custom Akka Dispatcher. This solution needs minimal change to a current application.
  • a custom ExecutionContext that propagates the MDC from the caller’s thread to the callee’s one.
  • a custom ExecutorService in order to propagate the MDC from the caller’s thread to the callee’s one.

The Kamon Way

Using the TraceLocalStorage with a special type called AvailableToMdc or simply calling to TraceLocal.storeForMdc method, Kamon can propagate the key and value through the current TraceContext.

val ApplicationIdKey = AvailableToMdc("X-ApplicationId")

def tracedRequestProcessor(request:Request):Unit = {
  TraceLocal.store(ApplicationIdKey)(request.client)

  withMdc { // exposes all AvailableToMdc keys in the MDC.
    logger.info("processing Traced Request...")
  }
}
public static final String ApplicationIdKey = "X-ApplicationId";

public void tracedRequestProcessor(Request request) {
  TraceLocal.storeForMdc(ApplicationIdKey, request.client);

  withMdc(() ->  // exposes all AvailableToMdc keys in the MDC.
    logger.info("processing Traced Request...");
  );
}
18:20:27.118 [info] Logger AwesomeClient - processing Traced Request...

Please note that some Kamon modules such as our Akka and Play modules already provide bytecode instrumentation that automatically propagates the AvailableToMdc type and make it availalable when using Akka ActorLogging or Play Logger functionality.