Slf4j MDC 使用和基於 Logback 的實現分析

前言

如今，在 Java 開發中，日誌的打印輸出是必不可少的， Slf4j + LogBack 的組合是最通用的方式。

關於 Slf4j 的介紹，請參考本博客 http://ketao1989.github.io/posts/Java-slf4j-Introduce.html

有了日誌之後，我們就可以追蹤各種線上問題。但是，在分布式系統中，各種無關日誌穿行其中，導致我們可能無法直接定位整個操作流程。因此，我們可能需要對一個用戶的操作流程進行歸類標記，比如使用 線程+時間戳 ，或者用戶身份標識等；如此，我們可以從大量日誌信息中grep出某個用戶的操作流程，或者某個時間的流轉記錄。

因此，這就有了 Slf4j MDC 方法。

Slf4j MDC 介紹

MDC ( Mapped Diagnostic Contexts )，顧名思義，其目的是為了便於我們診斷線上問題而出現的方法工具類。雖然，Slf4j 是用來適配其他的日誌具體實現包的，但是針對 MDC功能，目前只有logback 以及 log4j 支持，或者說由於該功能的重要性，slf4j 專門為logback系列包裝接口提供外部調用(玩笑～：）)。

logback 和 log4j 的作者為同一人，所以這裏統稱logback系列。

先來看看 MDC 對外提高的接口：

public class MDC {
  //Put a context value as identified by key
  //into the current thread's context map.
  public static void put(String key, String val);

  //Get the context identified by the key parameter.
  public static String get(String key);

  //Remove the context identified by the key parameter.
  public static void remove(String key);

  //Clear all entries in the MDC.
  public static void clear();
}

接口定義非常簡單，此外，其使用也非常簡單。

如上代碼所示，一般，我們在代碼中，只需要將指定的值put到線程上下文的Map中，然後，在對應的地方使用 get方法獲取對應的值。此外，對於一些線程池使用的應用場景，可能我們在最後使用結束時，需要調用clear方法來清洗將要丟棄的數據。

然後，看看一個MDC使用的簡單示例。

public class LogTest {
    private static final Logger logger = LoggerFactory.getLogger(LogTest.class);

    public static void main(String[] args) {

        MDC.put("THREAD_ID", String.valueOf(Thread.currentThread().getId()));

        logger.info("純字符串信息的info級別日誌");

    }

}

然後看看logback的輸出模板配置：

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <property name="log.base" value="http://ju.outofmemory.cn/entry/${catalina.base}/logs" />

    <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
        <resetJUL>true</resetJUL>
    </contextListener>

    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder charset="UTF-8">
            <pattern>[%d{yyyy-MM-dd HH:mm:ss} %highlight(%-5p) %logger.%M\(%F:%L\)] %X{THREAD_ID} %msg%n</pattern>
        </encoder>
    </appender>
    <root level="INFO">
        <appender-ref ref="console" />
    </root>
</configuration>

於是，就有了輸出：

[2015-04-30 15:34:35 INFO  io.github.ketao1989.log4j.LogTest.main(LogTest.java:29)] 1 純字符串信息的info級別日誌

當我們在web應用中，對服務的所有請求前進行filter攔截，然後加上自定義的唯一標識到MDC中，就可以在所有日誌輸出中，清楚看到某用戶的操作流程。關於web MDC，會單獨一遍博客介紹。

此外，關於logback 是如何將模板中的變量替換成具體的值，會在下一節分析。

在日誌模板logback.xml 中，使用 %X{ } 來占位，替換到對應的 MDC 中 key 的值。

前置知識介紹

InheritableThreadLocal 介紹

在代碼開發中，經常使用 ThreadLocal 來保證在同一個線程中共享變量。在 ThreadLocal 中，每個線程都擁有了自己獨立的一個變量，線程間不存在共享競爭發生，並且它們也能最大限度的由CPU調度，並發執行。顯然這是一種以空間來換取線程安全性的策略。

但是， ThreadLocal 有一個問題，就是它只保證在同一個線程間共享變量，也就是說如果這個線程起了一個新線程，那麽新線程是不會得到父線程的變量信息的。因此，為了保證子線程可以擁有父線程的某些變量視圖，JDK提供了一個數據結構， InheritableThreadLocal 。

javadoc 文檔對 InheritableThreadLocal 說明：

該類擴展了 ThreadLocal，為子線程提供從父線程那裏繼承的值：在創建子線程時，子線程會接收所有可繼承的線程局部變量的初始值，以獲得父線程所具有的值。通常，子線程的值與父線程的值是一致的；但是，通過重寫這個類中的 childValue 方法，子線程的值可以作為父線程值的一個任意函數。

當必須將變量（如用戶 ID 和事務 ID）中維護的每線程屬性（per-thread-attribute）自動傳送給創建的所有子線程時，應盡可能地采用可繼承的線程局部變量，而不是采用普通的線程局部變量。

代碼對比可以看出兩者區別：

ThreadLocal:

public class ThreadLocal<T> {

    /**
     * Method childValue is visibly defined in subclass
     * InheritableThreadLocal, but is internally defined here for the
     * sake of providing createInheritedMap factory method without
     * needing to subclass the map class in InheritableThreadLocal.
     * This technique is preferable to the alternative of embedding
     * instanceof tests in methods.
     */
    T childValue(T parentValue) {
        throw new UnsupportedOperationException();
    }

}

InheritableThreadLocal:

public class InheritableThreadLocal<T> extends ThreadLocal<T> {
    /**
     * Computes the child's initial value for this inheritable thread-local
     * variable as a function of the parent's value at the time the child
     * thread is created.  This method is called from within the parent
     * thread before the child is started.
     * <p>
     * This method merely returns its input argument, and should be overridden
     * if a different behavior is desired.
     *
     * @param parentValue the parent thread's value
     * @return the child thread's initial value
     */
    protected T childValue(T parentValue) {
        return parentValue;
    }

    /**
     * Get the map associated with a ThreadLocal.
     *
     * @param t the current thread
     */
    ThreadLocalMap getMap(Thread t) {
       return t.inheritableThreadLocals;
    }

    /**
     * Create the map associated with a ThreadLocal.
     *
     * @param t the current thread
     * @param firstValue value for the initial entry of the table.
     * @param map the map to store.
     */
    void createMap(Thread t, T firstValue) {
        t.inheritableThreadLocals = new ThreadLocalMap(this, firstValue);
    }
}

// 這個是開發時一般使用的類，直接copy父線程的變量
public class CopyOnInheritThreadLocal extends
    InheritableThreadLocal<HashMap<String, String>> {

  /**
   * Child threads should get a copy of the parent's hashmap.
   */
  @Override
  protected HashMap<String, String> childValue(
      HashMap<String, String> parentValue) {
    if (parentValue =http://ju.outofmemory.cn/entry/= null) {
      return null;
    } else {
      return new HashMap(parentValue);
    }
  }

}

為了支持InheritableThreadLocal的父子線程傳遞變量，JDK在Thread中，定義了 ThreadLocal.ThreadLocalMap inheritableThreadLocals 屬性。該屬性變量在線程初始化的時候，如果父線程的該變量不為null，則會把其值復制到ThreadLocal。

從上面的代碼實現，還可以看到，如果我們使用原生的 InheritableThreadLocal 類則在子線程中修改變量，可能會影響到父線程的變量值，及其他子線程的值。因此，一般我們推薦沒有特殊情況，最好使用 CopyOnInheritThreadLocal 類，該實現是新建一個map來保持值，而不是直接使用父線程的引用。

Log MDC 實現分析

Slf4j MDC 實現分析

Slf4j 的實現原則就是調用底層具體實現類，比如logback,logging等包；而不會去實現具體的輸出打印等操作。因此，除了前文中介紹的門面(Facade)模式外，提供這種功能的還有適配器(Adapter)模式和裝飾(Decorator)模式。

MDC 使用的就是 Decorator 模式，雖然，其類命名為M MDCAdapter 。

Slf4j MDC 內部實現很簡單。實現一個單例對應實例，獲取具體的MDC實現類，然後其對外接口，就是對參數進行校驗，然後調用 MDCAdapter 的方法實現。

實現源碼如下：

public class MDC {

  static MDCAdapter mdcAdapter;

  private MDC() {
  }

  static {
    try {
      mdcAdapter = StaticMDCBinder.SINGLETON.getMDCA();
    } catch (NoClassDefFoundError ncde) {
      //......
  }


  public static void put(String key, String val)
      throws IllegalArgumentException {
    if (key == null) {
      throw new IllegalArgumentException("key parameter cannot be null");
    }
    if (mdcAdapter == null) {
      throw new IllegalStateException("MDCAdapter cannot be null. See also "
          + NULL_MDCA_URL);
    }
    mdcAdapter.put(key, val);
  }

  public static String get(String key) throws IllegalArgumentException {
    if (key == null) {
      throw new IllegalArgumentException("key parameter cannot be null");
    }

    if (mdcAdapter == null) {
      throw new IllegalStateException("MDCAdapter cannot be null. See also "
          + NULL_MDCA_URL);
    }
    return mdcAdapter.get(key);
  }
}  }

對於Slf4j的MDC 部分非常簡單，MDC的核心實現是在logback方法中的。

在 logback 中，提供了 LogbackMDCAdapter 類，其實現了 MDCAdapter 接口。基於性能的考慮，logback 對於InheritableThreadLocal的使用做了一些優化工作。

Logback MDC 實現分析

Logback 中基於 MDC 實現了 LogbackMDCAdapter 類，其 get 方法實現很簡單，但是 put 方法會做一些優化操作。

關於 put 方法，主要有：

使用原始的 InheritableThreadLocal<Map<String, String>> 類，而不是使用子線程復制類 CopyOnInheritThreadLocal 。這樣，運行時可以大量避免不必要的copy操作，節省CPU消耗，畢竟在大量log操作中，子線程會很少去修改父線程中的 key-value 值。
由於上一條的優化，所以代碼實現上實現了一個 寫時復制版本的 InheritableThreadLocal 。實現會根據上一次操作來確定是否需要copy一份新的引用map，而不是去修改老的父線程的map引用。
此外，和 log4j 不同，其map中的val可以為null。

下面給出，get 和 put 的代碼實現：

public final class LogbackMDCAdapter implements MDCAdapter {

  final InheritableThreadLocal<Map<String, String>> copyOnInheritThreadLocal = new InheritableThreadLocal<Map<String, String>>();

  private static final int WRITE_OPERATION = 1;
  private static final int READ_OPERATION = 2;

  // keeps track of the last operation performed
  final ThreadLocal<Integer> lastOperation = new ThreadLocal<Integer>();

  private Integer getAndSetLastOperation(int op) {
    Integer lastOp = lastOperation.get();
    lastOperation.set(op);
    return lastOp;
  }

  private boolean wasLastOpReadOrNull(Integer lastOp) {
    return lastOp == null || lastOp.intValue() == READ_OPERATION;
  }

  private Map<String, String> duplicateAndInsertNewMap(Map<String, String> oldMap) {
    Map<String, String> newMap = Collections.synchronizedMap(new HashMap<String, String>());
    if (oldMap != null) {
        // we don't want the parent thread modifying oldMap while we are
        // iterating over it
        synchronized (oldMap) {
          newMap.putAll(oldMap);
        }
    }

    copyOnInheritThreadLocal.set(newMap);
    return newMap;
  }


  public void put(String key, String val) throws IllegalArgumentException {
    if (key == null) {
      throw new IllegalArgumentException("key cannot be null");
    }

    Map<String, String> oldMap = copyOnInheritThreadLocal.get();
    Integer lastOp = getAndSetLastOperation(WRITE_OPERATION);

    if (wasLastOpReadOrNull(lastOp) || oldMap == null) {
      // 當上一次操作是read時，這次write，則需要new
      Map<String, String> newMap = duplicateAndInsertNewMap(oldMap);
      newMap.put(key, val);
    } else {
      // 寫的話，已經new了就不需要再new
      oldMap.put(key, val);
    }
  }

  /**
   * Get the context identified by the <code>key</code> parameter.
   * <p/>
   */
  public String get(String key) {
    Map<String, String> map = getPropertyMap();
    if ((map != null) && (key != null)) {
      return map.get(key);
    } else {
      return null;
    }
  }
}

需要註意，在上面的代碼中，write操作即put會去修改 lastOperation ，而get操作則不會。這樣就保證了，只會在第一次寫時復制。

MDC clear 操作

Notes：對於涉及到ThreadLocal相關使用的接口，都需要去考慮在使用完上下文對象時，清除掉對應的數據，以避免內存泄露問題。

因此，下面來分析下在MDC中如何清除掉不在需要的對象。

在MDC中提供了 clear 方法，該方法完成對象的清除工作，使用logback時，則調用的是 LogbackMDCAdapter#clear() 方法，繼而調用 copyOnInheritThreadLocal.remove() 。

在ThreadLocal中，實現 remove() 方法：

public void remove() {
    ThreadLocalMap m = getMap(Thread.currentThread());
    if (m != null)
        m.remove(this);
}

這裏，就是調用 ThreadLocal#remove 方法完成對象清理工作。

所有線程的ThreadLocal都是以 ThreadLocalMap 來維護的，也就是，我們獲取threadLocal對象時，實際上是根據當前線程去該Map中獲取之前的設置。在清除的時候，從這個Map中獲取對應的對象，然後移除map.

Logback 日誌輸出實現

MDC 的功能實現很簡單，就是在線程上下文中，維護一個 Map<String,String> 屬性來支持日誌輸出的時候，當我們在配置文件 logback.xml 中配置了 %X{key} ，則後臺日誌打印出對應的 key 的值。

同樣， logback.xml 配置文件支持了多種格式的日誌輸出，比如 %highlight 、 %d 等等，這些標誌，在 PatternLayout.java 中維護。

public class PatternLayout extends PatternLayoutBase<ILoggingEvent> {

  public static final Map<String, String> defaultConverterMap = new HashMap<String, String>();
  public static final String HEADER_PREFIX = "#logback.classic pattern: ";
  
  static {
    defaultConverterMap.putAll(Parser.DEFAULT_COMPOSITE_CONVERTER_MAP);
    // 按照{}配置輸出時間
    defaultConverterMap.put("d", DateConverter.class.getName());
    defaultConverterMap.put("date", DateConverter.class.getName());
    // 輸出應用啟動到日誌時間觸發時候的毫秒數
    defaultConverterMap.put("r", RelativeTimeConverter.class.getName());
    defaultConverterMap.put("relative", RelativeTimeConverter.class.getName());
    // 輸出日誌級別的信息
    defaultConverterMap.put("level", LevelConverter.class.getName());
    defaultConverterMap.put("le", LevelConverter.class.getName());
    defaultConverterMap.put("p", LevelConverter.class.getName());
    // 輸出產生日誌事件的線程名
    defaultConverterMap.put("t", ThreadConverter.class.getName());
    defaultConverterMap.put("thread", ThreadConverter.class.getName());
    // 輸出產生log事件的原點的日誌名=我們創建logger的時候設置的
    defaultConverterMap.put("lo", LoggerConverter.class.getName());
    defaultConverterMap.put("logger", LoggerConverter.class.getName());
    defaultConverterMap.put("c", LoggerConverter.class.getName());
    // 輸出 提供日誌事件的對應的應用信息
    defaultConverterMap.put("m", messageConverter.class.getName());
    defaultConverterMap.put("msg", MessageConverter.class.getName());
    defaultConverterMap.put("message", MessageConverter.class.getName());
    // 輸出調用方發布日誌事件的完整類名
    defaultConverterMap.put("C", ClassOfCallerConverter.class.getName());
    defaultConverterMap.put("class", ClassOfCallerConverter.class.getName());
    // 輸出發布日誌請求的方法名
    defaultConverterMap.put("M", MethodOfCallerConverter.class.getName());
    defaultConverterMap.put("method", MethodOfCallerConverter.class.getName());
    // 輸出log請求的行數
    defaultConverterMap.put("L", LineOfCallerConverter.class.getName());
    defaultConverterMap.put("line", LineOfCallerConverter.class.getName());
    // 輸出發布日誌請求的java源碼的文件名
    defaultConverterMap.put("F", FileOfCallerConverter.class.getName());
    defaultConverterMap.put("file", FileOfCallerConverter.class.getName());
    // 輸出和發布日誌事件關聯的線程的MDC
    defaultConverterMap.put("X", MDCConverter.class.getName());
    defaultConverterMap.put("mdc", MDCConverter.class.getName());
    // 輸出和日誌事件關聯的異常的堆棧信息
    defaultConverterMap.put("ex", ThrowableProxyConverter.class.getName());
    defaultConverterMap.put("exception", ThrowableProxyConverter.class
        .getName());
    defaultConverterMap.put("rEx", RootCauseFirstThrowableProxyConverter.class.getName());
    defaultConverterMap.put("rootException", RootCauseFirstThrowableProxyConverter.class
        .getName());
    defaultConverterMap.put("throwable", ThrowableProxyConverter.class
        .getName());
    // 和上面一樣，此外增加類的包信息
    defaultConverterMap.put("xEx", ExtendedThrowableProxyConverter.class.getName());
    defaultConverterMap.put("xException", ExtendedThrowableProxyConverter.class
        .getName());
    defaultConverterMap.put("xThrowable", ExtendedThrowableProxyConverter.class
        .getName());
    // 當我們想不輸出異常信息時，使用這個。其假裝處理異常，其實無任何輸出
    defaultConverterMap.put("nopex", NopThrowableInformationConverter.class
        .getName());
    defaultConverterMap.put("nopexception",
        NopThrowableInformationConverter.class.getName());
    // 輸出在類附加到日誌上的上下文名字. 
    defaultConverterMap.put("cn", ContextNameConverter.class.getName());
    defaultConverterMap.put("contextName", ContextNameConverter.class.getName());
    // 輸出產生日誌事件的調用者的位置信息
    defaultConverterMap.put("caller", CallerDataConverter.class.getName());
    // 輸出和日誌請求關聯的marker
    defaultConverterMap.put("marker", MarkerConverter.class.getName());
    // 輸出屬性對應的值，一般為system.properties中的屬性
    defaultConverterMap.put("property", PropertyConverter.class.getName());
    // 輸出依賴系統的行分隔符
    defaultConverterMap.put("n", LineSeparatorConverter.class.getName());
    // 相關的顏色格式設置
    defaultConverterMap.put("black", BlackCompositeConverter.class.getName());
    defaultConverterMap.put("red", RedCompositeConverter.class.getName());
    defaultConverterMap.put("green", GreenCompositeConverter.class.getName());
    defaultConverterMap.put("yellow", YellowCompositeConverter.class.getName());
    defaultConverterMap.put("blue", BlueCompositeConverter.class.getName());
    defaultConverterMap.put("magenta", MagentaCompositeConverter.class.getName());
    defaultConverterMap.put("cyan", CyanCompositeConverter.class.getName());
    defaultConverterMap.put("white", WhiteCompositeConverter.class.getName());
    defaultConverterMap.put("gray", GrayCompositeConverter.class.getName());
    defaultConverterMap.put("boldRed", BoldRedCompositeConverter.class.getName());
    defaultConverterMap.put("boldGreen", BoldGreenCompositeConverter.class.getName());
    defaultConverterMap.put("boldYellow", BoldYellowCompositeConverter.class.getName());
    defaultConverterMap.put("boldBlue", BoldBlueCompositeConverter.class.getName());
    defaultConverterMap.put("boldMagenta", BoldMagentaCompositeConverter.class.getName());
    defaultConverterMap.put("boldCyan", BoldCyanCompositeConverter.class.getName());
    defaultConverterMap.put("boldWhite", BoldWhiteCompositeConverter.class.getName());
    defaultConverterMap.put("highlight", HighlightingCompositeConverter.class.getName());
  }
}

Notes：日誌模板配置，使用 % 為前綴讓解析器識別特殊輸出模式，然後以 {} 後綴結尾，內部指定相應的參數設置。

初始化

所謂初始化，就是我們構建 logger 的時候。在 LoggerFactory.getLogger() ，調用的是 slf4j 的方法，而底層使用的是 logback 的實現。因此，初始化的重點就是找到底層具體的實現接口，然後構建具體類。

public static Logger getLogger(String name) {
    ILoggerFactory iLoggerFactory = getILoggerFactory();
    return iLoggerFactory.getLogger(name);
  }

  public static ILoggerFactory getILoggerFactory() {
    if (INITIALIZATION_STATE == UNINITIALIZED) {
      INITIALIZATION_STATE = ONGOING_INITIALIZATION;
      performInitialization();
    }
    switch (INITIALIZATION_STATE) {
      case SUCCESSFUL_INITIALIZATION:
        return StaticLoggerBinder.getSingleton().getLoggerFactory();
      // ......
      case ONGOING_INITIALIZATION:
        // support re-entrant behavior.
        // See also http://bugzilla.slf4j.org/show_bug.cgi?id=106
        return TEMP_FACTORY;
    }
    // .....
  }
}

  private final static void bind() {
    try {
      Set staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
      // the next line does the binding
      // 這裏並沒有使用上面的返回set進行反射構建類，這裏實際上才是各種初始化的地方
      StaticLoggerBinder.getSingleton();
      INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
      // ......
    } catch (Exception e) {
      // ......
    }
  }

  private static Set findPossibleStaticLoggerBinderPathSet() {
    // use Set instead of list in order to deal with  bug #138
    // LinkedHashSet appropriate here because it preserves insertion order during iteration
    Set staticLoggerBinderPathSet = new LinkedHashSet();
    try {
      ClassLoader loggerFactoryClassLoader = LoggerFactory.class
              .getClassLoader();
      Enumeration paths;
      if (loggerFactoryClassLoader == null) {
        paths = ClassLoader.getSystemResources(STATIC_LOGGER_BINDER_PATH);
      } else {
        paths = loggerFactoryClassLoader
                .getResources(STATIC_LOGGER_BINDER_PATH);
      }
      while (paths.hasMoreElements()) {
        URL path = (URL) paths.nextElement();
        staticLoggerBinderPathSet.add(path);
      }
    } catch (IOException ioe) {
      Util.report("Error getting resources from path", ioe);
    }
    return staticLoggerBinderPathSet;
  }

上面的部分代碼，可以很明顯看出，slf4j 會去調用classloader獲取當前加載的類中，實現了指定的接口 org/slf4j/impl/StaticLoggerBinder.class 的類，如果多余1個，則會拋出異常。

以上，依然可以從代碼中看出這個只是檢測是否存在符合接口的實現類，而沒有像正常情況那樣，通過反射構建類，返回給調用方。如何實現呢？

直接在自己的包中實現一個和 slf4j 要求路徑一樣的類，實現對應的接口，然後就可以調用了。不明白，看代碼吧。:)

package org.slf4j.impl;

import ch.qos.logback.core.status.StatusUtil;
import org.slf4j.ILoggerFactory;
import org.slf4j.LoggerFactory;
import org.slf4j.helpers.Util;
import org.slf4j.spi.LoggerFactoryBinder;

import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.util.ContextInitializer;
import ch.qos.logback.classic.util.ContextSelectorStaticBinder;
import ch.qos.logback.core.CoreConstants;

public class StaticLoggerBinder implements LoggerFactoryBinder {

  private static StaticLoggerBinder SINGLETON = new StaticLoggerBinder();

  static {
    SINGLETON.init();
  }

  // 這裏就是創建logback的LoggerContext實例， 包含了log所需的環境配置
  private LoggerContext defaultLoggerContext = new LoggerContext();
  private final ContextSelectorStaticBinder contextSelectorBinder = ContextSelectorStaticBinder
      .getSingleton();

  private StaticLoggerBinder() {
    defaultLoggerContext.setName(CoreConstants.DEFAULT_CONTEXT_NAME);
  }

  public static StaticLoggerBinder getSingleton() {
    return SINGLETON;
  }

    void init() {
    try {
      try {
        // 這裏會初始化配置文件和對應的模板，logback.xml解析
        new ContextInitializer(defaultLoggerContext).autoConfig();
      } 
      // ......
  }
  }}

從 package 和 import 的信息，可以看出，logback 中實現了一個 org.slf4j.impl.StaticLoggerBinder 類，而這個類，在slf4j 的 API 包中直接使用，所以使用slf4j時，必須還要引入其他具體的第三方包來實現相應的接口方法。

此外，接下來的核心邏輯就是解析logback下各種配置文件信息，以及初始化配置。

輸出日誌模板解析

如上所見，其實關於logback.xml的解析工作，也是在初始化的時候完成的。但是，由於其重要性，所以這裏重點介紹下。

在 logback 中，解析xml的工作，都是交給 Action 和其繼承類來完成。在 Action 類中提供了三個方法 begin 、 body 和 end 三個方法，這三個抽象方法中：

begin 方法負責處理ElementSelector元素的解析；
body 方法，一般為空，處理文本的；
end 方法則是處理模板解析的，所以我們的logback.xml的模板解析實在end方法中。具體是在 NestedComplexPropertyIA 類中來解析。其繼承Action類，並且其會調用具體的模板解析工具類： PatternLayoutEncoder 類和 PatternLayout 類。

PatternLayoutEncoder 會創建一個 PatternLayout 對象，然後獲取到logback.xml中配置的模板字符串，即 [%d{yyyy-MM-dd HH:mm:ss} %highlight(%-5p) %logger.%M\(%F:%L\)] %X{THREAD_ID} %msg%n ，如配置的節點名一樣，其在代碼中同樣賦值給pattern變量。

接下來，PatternLayoutEncoder 會調用相關方法對pattern進行解析，然後構建一個節點鏈表，保存這個鏈表會在日誌輸出的時使用到。

public Parser(String pattern, IEscapeUtil escapeUtil) throws ScanException {
    try {
      TokenStream ts = new TokenStream(pattern, escapeUtil);
      this.tokenList = ts.tokenize();
    } catch (IllegalArgumentException npe) {
      throw new ScanException("Failed to initialize Parser", npe);
    }
  }

  enum TokenizerState { LITERAL_STATE,  FORMAT_MODIFIER_STATE, KEYWORD_STATE, OPTION_STATE,  RIGHT_PARENTHESIS_STATE}


  List tokenize() throws ScanException {
    List<Token> tokenList = new ArrayList<Token>();
    StringBuffer buf = new StringBuffer();

    while (pointer < patternLength) {
      char c = pattern.charAt(pointer);
      pointer++;

      switch (state) {
        case LITERAL_STATE:
          handleLiteralState(c, tokenList, buf);
          break;
        case FORMAT_MODIFIER_STATE:
          handleFormatModifierState(c, tokenList, buf);
          break;
        // ......

        default:
      }
    }

    // EOS
    switch (state) {
      case LITERAL_STATE:
        addValuedToken(Token.LITERAL, buf, tokenList);
        break;
     // ......

      case FORMAT_MODIFIER_STATE:
      case OPTION_STATE:
        throw new ScanException("Unexpected end of pattern string");
    }

    return tokenList;
  }

// 構建head鏈表
  Converter<E> compile() {
    head = tail = null;
    for (Node n = top; n != null; n = n.next) {
      switch (n.type) {
        case Node.LITERAL:
          addToList(new LiteralConverter<E>((String) n.getValue()));
          break;
        case Node.COMPOSITE_KEYWORD:
          CompositeNode cn = (CompositeNode) n;
          CompositeConverter<E> compositeConverter = createCompositeConverter(cn);
          if(compositeConverter == null) {
            addError("Failed to create converter for [%"+cn.getValue()+"] keyword");
            addToList(new LiteralConverter<E>("%PARSER_ERROR["+cn.getValue()+"]"));
            break;
          }
          compositeConverter.setFormattingInfo(cn.getFormatInfo());
          compositeConverter.setOptionList(cn.getOptions());
          Compiler<E> childCompiler = new Compiler<E>(cn.getChildNode(),
                  converterMap);
          childCompiler.setContext(context);
          Converter<E> childConverter = childCompiler.compile();
          compositeConverter.setChildConverter(childConverter);
          addToList(compositeConverter);
          break;
        case Node.SIMPLE_KEYWORD:
          SimpleKeywordNode kn = (SimpleKeywordNode) n;
          DynamicConverter<E> dynaConverter = createConverter(kn);
          if (dynaConverter != null) {
            dynaConverter.setFormattingInfo(kn.getFormatInfo());
            dynaConverter.setOptionList(kn.getOptions());
            addToList(dynaConverter);
          } else {
            // if the appropriate dynaconverter cannot be found, then replace
            // it with a dummy LiteralConverter indicating an error.
            Converter<E> errConveter = new LiteralConverter<E>("%PARSER_ERROR["
                    + kn.getValue() + "]");
            addStatus(new ErrorStatus("[" + kn.getValue()
                    + "] is not a valid conversion word", this));
            addToList(errConveter);
          }

      }
    }
    return head;
  }

代碼很簡單，就是依次遍歷pattern字符串，然後把符合要求的字符串放進tokenList中，這個list就維護了我們最終需要輸出的模板的格式化模式了。

在每個case裏面，都會對字符串進行特定的處理，匹配具體的字符。

在隨後的處理中，會將這個tokenList進行轉換，成為我們需要的Node類型的擁有head 和 tail 的鏈表。

日誌輸出分析

構建了各種需要的環境參數，打印日誌就很簡單了。在需要輸出日誌的時候，根據初始化得到的Node鏈表head來解析，遇到%X的時候，從MDC中獲取對應的key值，然後append到日誌字符串中，然後輸出。

在配置文件中，我們使用Appender模式，在日誌輸出類中，顯然會調用append類似的方法了。:)

其調用流程

public class OutputStreamAppender<E> extends UnsynchronizedAppenderBase<E> {
  @Override
  protected void append(E eventObject) {
    if (!isStarted()) {
      return;
    }

    subAppend(eventObject);
  }

  // 這裏就是日誌輸出實際的操作，一般如果有需要，可以重寫這個方法。
  protected void subAppend(E event) {
    if (!isStarted()) {
      return;
    }
    try {
      // this step avoids LBCLASSIC-139
      if (event instanceof DeferredProcessingAware) {
        // 這裏雖然是為輸出準備，在檢查的同時，把把必要的信息解析出來放到變量中
        ((DeferredProcessingAware) event).prepareForDeferredProcessing();
      }
      // the synchronization prevents the OutputStream from being closed while we
      // are writing. It also prevents multiple threads from entering the same
      // converter. Converters assume that they are in a synchronized block.
      synchronized (lock) {
        // 避免多線程的問題，這裏加了鎖。而寫日誌的核心也是在這裏
        writeOut(event);
      }
    } catch (IOException ioe) {
      // as soon as an exception occurs, move to non-started state
      // and add a single ErrorStatus to the SM.
      this.started = false;
      addStatus(new ErrorStatus("IO failure in appender", this, ioe));
    }
  }
  // 這裏將會調用前面我們提到過的模板類，有該類對解析出來的模板按照當前環境進行輸出
  protected void writeOut(E event) throws IOException {
    this.encoder.doEncode(event);
  }
}

Notes：在 prepareForDeferredProcessing 中，查詢了一些常用值，比如當前線程名，比如mdc設置賦值到Map中。而這些信息，當準備結束沒有出現問題時，則會給後面的輸出日誌時公用。

這種方式，其實在我們的代碼中，也可以參考。一般我們可能對當前上下文的入參檢查會去查詢數據庫等耗費CPU或者IO的操作，然後check ok的時候，又會在正常的業務中再次做相同的重復工作，導致不必要的性能損失。

接下來看看，針對模板進行按需獲取屬性值，然後輸出日誌的邏輯：

// 這裏的邏輯就是按照模板獲取值然後轉換成字節流輸出到後臺
public void doEncode(E event) throws IOException {
  String txt = layout.doLayout(event);
  outputStream.write(convertToBytes(txt));
  if (immediateFlush)
    outputStream.flush();
}

public String doLayout(ILoggingEvent event) {
  if (!isStarted()) {
    return CoreConstants.EMPTY_STRING;
  }
  return writeLoopOnConverters(event);
}

// 初始化的時候，就介紹過最後會構建一個head鏈表，
// 這裏輸出就是按照解析後的鏈表進行分析輸出的。然後根據c類型不同，獲取字符串方法也不同
protected String writeLoopOnConverters(E event) {
  StringBuilder buf = new StringBuilder(128);
  Converter<E> c = head;
  while (c != null) {
    c.write(buf, event);
    c = c.getNext();
  }
  return buf.toString();
}

在 writeLoopOnConverters 方法中，獲取對應字符串是不同的，其根據不同的Converter，輸出也不同。而Converter的判斷，時就是根據我們配置的map映射來的，在初始化一節的時候，介紹的 PatternLayout 就包含各種映射關系。至於具體的convert方法，看看mdc的實現：

public class MDCConverter extends ClassicConverter {

  private String key;
  private String defaultValuehttp://ju.outofmemory.cn/entry/= "";

  @Override
  public void start() {
    String[] keyInfo = extractDefaultReplacement(getFirstOption());
    key = keyInfo[0];
    if (keyInfo[1] != null) {
      defaultValue = http://ju.outofmemory.cn/entry/keyInfo[1];
    }
    super.start();
  }

  @Override
  public void stop() {
    key = null;
    super.stop();
  }

  @Override
  public String convert(ILoggingEvent event) {
    Map mdcPropertyMap = event.getMDCPropertyMap();

    if (mdcPropertyMap == null) {
      return defaultValue;
    }

    if (key == null) {
      return outputMDCForAllKeys(mdcPropertyMap);
    } else {

      String value = event.getMDCPropertyMap().get(key);//獲取key的值
      if (value != null) {
        return value;
      } else {
        return defaultValue;
      }
    }
  }

  /**
   * if no key is specified, return all the values present in the MDC, in the format"k1=v1, k2=v2, ..."
   */
  private String outputMDCForAllKeys(Map<String, String> mdcPropertyMap) {
    StringBuilder buf = new StringBuilder();
    boolean first = true;
    for (Map.Entry<String, String> entry : mdcPropertyMap.entrySet()) {
      if (first) {
        first = false;
      } else {
        buf.append(", ");
      }
      //format: key0=value0, key1=value1
      buf.append(entry.getKey()).append('=').append(entry.getValue());
    }
    return buf.toString();
  }
}

我們在MDC實現的時候看到的get方法，在這裏就使用了。我們將key:value鍵值對存放到MDC之後，在logback.xml中配置%X{key}，沒有直接調用get方法，logback會根據 X 判斷是MDC類型，然後根據 key 拿到MDC中對應的value，然後返回給buf中，最後append到後臺日誌上。

後記

其實，本身的 MDC 使用很簡單，實現原理也很簡單。但是，這裏為了分析從將 key:value put 進MDC，然後怎麽獲取，怎麽打印到後臺的邏輯，對整個從 SLF4J 到 logback 的運行流程進場了大體解析。而對不影響理解的一些枝節，進行了刪減。因此，如果需要完全弄清楚整個邏輯，還需要進行詳細分析源碼。

在目前的代碼中，我們在web.xml 中配置了 filter 來將一些用戶個人訪問特征存入了MDC中，這樣可以獲取一個用戶的操作流程，根據某一個訪問特征去grep的話。

下一次，將分享下這種實現細節背後的一些技術。雖然實現很簡單，但是想深入分析下filter機制和web = tomcat + spring mvc 的請求處理流程，這些技術細節，是如何使一個MDC信息可以保存一個用戶依次的訪問流水記錄。

前言

如今，在 Java 開發中，日誌的打印輸出是必不可少的， Slf4j + LogBack 的組合是最通用的方式。

關於 Slf4j 的介紹，請參考本博客 http://ketao1989.github.io/posts/Java-slf4j-Introduce.html

因此，這就有了 Slf4j MDC 方法。

Slf4j MDC 介紹

logback 和 log4j 的作者為同一人，所以這裏統稱logback系列。

先來看看 MDC 對外提高的接口：

public class MDC {
  //Put a context value as identified by key
  //into the current thread's context map.
  public static void put(String key, String val);

  //Get the context identified by the key parameter.
  public static String get(String key);

  //Remove the context identified by the key parameter.
  public static void remove(String key);

  //Clear all entries in the MDC.
  public static void clear();
}

接口定義非常簡單，此外，其使用也非常簡單。

Tags: identified current thread public 通用

文章來源：

Slf4j MDC 使用和 基於 Logback 的實現分析

前言

Slf4j MDC 介紹

前置知識介紹

InheritableThreadLocal 介紹

Log MDC 實現分析

Slf4j MDC 實現分析

Logback MDC 實現分析

MDC clear 操作

Logback 日誌輸出實現

初始化

輸出日誌模板解析

日誌輸出分析

後記

前言

Slf4j MDC 介紹

相關文章

Slf4j MDC 使用和基於 Logback 的實現分析