Mapped Diagnostic Context(MDC)

MDC is a feature provided by logging frameworks like Logback and Log4j. It allows you to associate contextual information with each thread when it is running in multi-threaded.

To uniquely stamp each request, the user puts contextual information into the MDC.

1. Single Threaded Application

We can easily use MDC in single threaded application. It is using same MDC among all the logs.(output 1)

import com.typesafe.scalalogging.LazyLogging
import org.slf4j.MDC

import java.util.UUID

object SingleThread extends App with LazyLogging {
  val correlationId = UUID.randomUUID().toString
  MDC.put("correlationId", correlationId)

  logger.info("Hello")
  logger.info("My Name is Pramod")
  logger.info("How are you")
}

output 1

2. Multi-Threaded Application

Here you can see, when application is running on multi-threaded environment, MDC is not propagated to all the threads.(output 2)

import com.typesafe.scalalogging.LazyLogging

import java.util.concurrent.Executors
import scala.concurrent.{ExecutionContext, Future}

object NonMDCClass1 extends LazyLogging {
  implicit val nonblocking: ExecutionContext = {
    ExecutionContext.fromExecutor(Executors.newCachedThreadPool())
  }
  def test() : Future[String] = {
    logger.info(s"Calling NonMDCClass1.test function")
      Future.successful("test")
  }

  def test2() : Future[String] = {
    logger.info(s"Calling NonMDCClass1.test2 function")
    Future.successful("test")
  }

  def caller(): Future[Unit] = {
    logger.info(s"Calling NonMDCClass1.caller function")
    for {
      _ <- test()
      _ <- test2()
    } yield()
  }
}

import com.typesafe.scalalogging.LazyLogging

import java.util.concurrent.Executors
import scala.concurrent.{ExecutionContext, Future}

object NonMDCClass2 extends LazyLogging {
  implicit lazy val nonblocking: ExecutionContext = {
    ExecutionContext.fromExecutor(Executors.newWorkStealingPool())
  }
  def test() : Future[String] = {
    logger.info(s"Calling NonMDCClass2.test function")
    Future.successful("test")
  }
}

import org.slf4j.MDC

import java.util.UUID
import java.util.concurrent.Executors
import scala.concurrent.ExecutionContext

object NonMDCMultiThread extends App {
  implicit val nonblocking: ExecutionContext = {
    ExecutionContext.fromExecutor(Executors.newWorkStealingPool())
  }
  val correlationId = UUID.randomUUID().toString
  MDC.put("correlationId", correlationId)
  for {
    _ <- NonMDCClass1.caller()
    _ <- NonMDCClass2.test()
  } yield()
}

output 2

Handle MDC in Multi-Threaded

If we are using multiple threads in the application, we should copy the context from previous thread to new thread.

figure 1

Every time, we should clear the MDC in finally block. This ensures that the finally block is executed even if an unexpected exception occurs. Otherwise we would use wrong MDC information in some logs, somehow if we forgot to clear the MDC context.

import org.slf4j.MDC

import scala.concurrent.ExecutionContext

object MDCExecutionContext {
  def apply(executionContext: ExecutionContext): MDCExecutionContext = {
    new MDCExecutionContext(executionContext)
  }
}

class MDCExecutionContext(executionContext: ExecutionContext) extends ExecutionContext {
  override def execute(runnable: Runnable): Unit = {
    val callerMdc = MDC.getCopyOfContextMap
    executionContext.execute(() => {
      if (callerMdc != null) {
        MDC.setContextMap(callerMdc)
      }
      try {
        runnable.run()
      } finally {
        MDC.clear()
      }
    })
  }

  override def reportFailure(cause: Throwable): Unit = executionContext.reportFailure(cause)
}

import com.typesafe.scalalogging.LazyLogging

import java.util.concurrent.Executors
import scala.concurrent.{ExecutionContext, Future}

object MDCClass2 extends LazyLogging {

  implicit val mdcExecutionContext: MDCExecutionContext = MDCExecutionContext(ExecutionContext.fromExecutor(Executors.newWorkStealingPool()))

  def test() : Future[String] = {
    logger.info(s"Calling NonMDCClass2.test function")
    Future.successful("test")
  }
}

import com.typesafe.scalalogging.LazyLogging

import java.util.concurrent.Executors
import scala.concurrent.{ExecutionContext, Future}

object MDCClass1 extends LazyLogging {

  implicit val mdcExecutionContext: MDCExecutionContext = MDCExecutionContext(ExecutionContext.fromExecutor(Executors.newCachedThreadPool()))

  def test() : Future[String] = {
    logger.info(s"Calling NonMDCClass1.test function")
      Future.successful("test")
  }

  def test2() : Future[String] = {
    logger.info(s"Calling NonMDCClass1.test2 function")
    Future.successful("test")
  }

  def caller(): Future[Unit] = {
    logger.info(s"Calling NonMDCClass1.caller function")
    for {
      _ <- test()
      _ <- test2()
    } yield()
  }
}

import org.slf4j.MDC

import java.util.UUID
import java.util.concurrent.Executors
import scala.concurrent.ExecutionContext

object MDCMultiThread extends App {

  implicit val mdcExecutionContext: MDCExecutionContext =  MDCExecutionContext(ExecutionContext.fromExecutor(Executors.newCachedThreadPool()))

  val correlationId = UUID.randomUUID().toString
  MDC.put("correlationId", correlationId)
  for {
    _ <- MDCClass1.caller()
    _ <- MDCClass2.test()
  } yield()
}

output 3

Here you can see, these four logs are running on 3 different threads. But it has been propegated MDC properly.(output 3)

• This is the logback.xml file for log the thread name and correlation id.

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%date \(%level\) [%thread] [%X{correlationId}]: %message%n</pattern>
        </encoder>
    </appender>

    <root level="debug">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

References

https://logback.qos.ch/manual/mdc.html