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

時間 2019-11-13

標籤 slf4j slf mdc 使用基於 logback 實現分析欄目 Log4j 简体版

原文原文鏈接

前言

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

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

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

所以，這就有了 Slf4j MDC 方法。 github

Slf4j MDC 介紹

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

logback 和 log4j 的做者爲同一人，因此這裏統稱logback系列。 spring

先來看看 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(); }

接口定義很是簡單，此外，其使用也很是簡單。 tomcat

如上代碼所示，通常，咱們在代碼中，只須要將指定的值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="${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 == null) { return null; } else { return new HashMap<String, String>(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 defaultValue = ""; @Override public void start() { String[] keyInfo = extractDefaultReplacement(getFirstOption()); key = keyInfo[0]; if (keyInfo[1] != null) { defaultValue = keyInfo[1]; } super.start(); } @Override public void stop() { key = null; super.stop(); } @Override public String convert(ILoggingEvent event) { Map<String, String> 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信息能夠保存一個用戶依次的訪問流水記錄。