SLF4J - Mapped Diagnostic Context (MDC)

Giriş

Açıklaması şöyle

The basic idea of Mapped Diagnostic Context is to provide a way to enrich log messages with pieces of information that could be not available in the scope where the logging actually occurs, but that can be indeed useful to better track the execution of the program.

In most of the modern client-server applications, servers are made to handle different client requests in separate worker threads. But traditional logging methods are not able to capture the thread/event specific information without doing a complete logging implementation manually.

MDC is introduced to serve this gap. It will help the developers to store thread/event specific information in its internal data structure (Map). And append the information to the log messages according to the configuration.

Simple Logging Facade for Java (SLF4J) APIs supports MDC feature and through Log4j and LOGBack implementations, developers can use the MDC feature.

... developer should clear the MDC context at the execution start point as it will contain garbage values if the threads are being reused. (eg: executer service with reusable threads)

Açıklaması şöyle

Both Logback and Log4j2 support a feature called “Mapped Diagnostic Context”, or MDC, where a dictionary/map of context is attached to each thread, which you can then read from and write to as needed. Data stored in a thread’s MDC can be logged using the %X variable. You can either log all of the MDC, or just specific pieces of information, e.g. if your log pattern included %X{orderNumber}, just the value of the "orderNumber" key from a thread's MDC would be logged.

Örnek

SLF kodunda şöyle yaparız

import org.slf4j.MDC;
...
try {
  MDC.put("field_name", "value");
  log.info("This message will have the field field_name set to value");
  …
  log.info("This one also");
  …
}
finally {
  MDC.remove("field_name");
}

Örnek

Şöyle yaparız. Burada AccountId=%X{accountId} şeklindeki kullanımda MDC içine "accountId" değişkeni yerleştiriliyor. Appender da bunu logluyor.

<configuration>
  <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
      <pattern>%d{YYYY-MM-DD'T'hh:mm:ss} [%thread] %5p %c{1}
         - %m AccountId=%X{accountId}
              CustomerId=%X{customerId}
              RequestId=%X{requestId} %n</pattern>
    </encoder>
  </appender>

  <root level="TRACE">
    <appender-ref ref="stdout" />
  </root>

</configuration>

SLF4J kodu şöyle.

public void run() {
  MDC.put("threadId",String.valueOf(Thread.currentThread().getId()));
  MDC.put("accountId", transfer.getAccount());
  MDC.put("requestId", transfer.getRequest());
  ... 
}

Örnek

Log4J ile şöyle yaparız. Burada ThreadContext sınıfı kullanılıyor

import org.apache.logging.log4j.ThreadContext;

public List<OrderItem> getOrderItems(@PathVariable("orderNumber") @Required
  String orderNumber) {
  ThreadContext.put("orderNumber", orderNumber);
  
  List<OrderItem> orderItems = null;
  try {
    orderItems = d.getItemsForOrder(orderNumber);
  } catch (Exception ex) {
    logger.error("Unable to fetch items from database for order", ex);
  }
  logger.info("Got items, returning");
  ThreadContext.clearAll();
  return orderItems;
}

Burada ise CloseableThreadContext kullanılıyor. Bu sınıf ThreadContext'i otomatik olarak temizler. Şöyle yaparız. 

public List<OrderItem> getOrderItems(...) {
  try (final CloseableThreadContext.Instance ignored = CloseableThreadContext
    .put("orderNumber", orderNumber)
    .put("retailer", retailer)) {
    ...
  }
}

Log4J örneği ama mantık aynı. Şöyle yaparız

<Property name="LOG_PATTERN">
    %d{yyyy-MM-dd HH:mm:ss.SSS} %5p [%15.15t] %-40.40c{1.} : %X : %m%n%ex
</Property>

Çıktı olarak şunu alırız

2021-06-08 12:25:10.774 INFO [nio-8080-exec-1] c.z.s.s.OrderController : {orderNumber=2313} : Getting items
2021-06-08 12:25:10.774 INFO [nio-8080-exec-1] c.z.s.s.OrderController : {orderNumber=2313} : Got items, returning
2021-06-08 12:25:26.732 INFO [nio-8080-exec-2] c.z.s.s.OrderController : {orderNumber=8291} : Getting items
2021-06-08 12:25:26.732 INFO [nio-8080-exec-2] c.z.s.s.OrderController : {orderNumber=8291} : Got items, returning

Örnek

Elimizde şöyle bir appender olsun. %X{key} ile MDC nesnesine "key" isimli bir alan ekleyeceğimizi belirtiriz.

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> 
  <layout>
    <Pattern>%X{key}  - %m%n</Pattern>
  </layout> 
</appender>

Şöyle yaparız.

public String doAnyAction(long key) {
  MDC.put("key", key);
  logger.info(key);
}