1. 程式人生 > >log4j 同一執行緒隔離classloader下MDC資訊不同問題解決 ThreadLocal問題分析

log4j 同一執行緒隔離classloader下MDC資訊不同問題解決 ThreadLocal問題分析

最近遇到日誌檔案記錄錯誤的問題。一個任務的日誌資訊會被莫名的拆分到兩個不同目錄中。且有一個目錄還是曾經執行過的任務的目錄。經過分析,首先懷疑的是MDC沒有清理的問題,這也是最直觀的問題。因為任務是線上程池(fixedThreadPool)中執行的。由於執行緒會被重用,而MDC是繫結在Threadlocal上的,所以如果沒有清理,是會造成上述問題。但是在程式碼檢查中發現線上程的開始,是重新設定過MDC資訊的。所以,懷疑的物件轉移到了多classloader上。由於不能肯定,所以進行測試如下:

package com.coderli.log4j.mdc;


import java.lang.reflect.InvocationTargetException
; import java.lang.reflect.Method; import java.net.MalformedURLException; import java.net.URL; import java.net.URLClassLoader; import org.apache.log4j.MDC; import org.slf4j.Logger; import org.slf4j.LoggerFactory; /** * 單執行緒多 classloader模式下,log4jMDC資訊傳遞測試。 * * @author OneCoder * @blog http://www.coderli.com * @date 2014年5月6日 上午10:55:34 */
public class SingleThreadMultiLoader { private static final Logger logger = LoggerFactory . getLogger(SingleThreadMultiLoader.class); private static String key = "loaderName"; static ThreadLocal<String> tl = new ThreadLocal<String>(); public static void
main(String[] args) throws MalformedURLException, ClassNotFoundException, InstantiationException, IllegalAccessException, NoSuchMethodException, SecurityException, IllegalArgumentException, InvocationTargetException { MDC. put(key, "in main loader" ); logger.info( "執行緒名: {}; 日誌MDC資訊:{}。" , Thread.currentThread().getName(), MDC. get(key)); tl.set( "huanyige"); ClassLoader cLoader = Thread.currentThread().getContextClassLoader(); URL[] urls = new URL[] { new URL("file:\\D:\\acap\\workspace\\shurnim-lab\\lib\\mdc.jar" ), new URL( "file:\\D:\\acap\\workspace\\shurnim-lab\\lib\\log4j-1.2.17.jar" ), new URL( "file:\\D:\\acap\\workspace\\shurnim-lab\\lib\\slf4j-api-1.7.5.jar" ), new URL( "file:\\D:\\acap\\workspace\\shurnim-lab\\lib\\slf4j-log4j12-1.7.5.jar" ) }; ClassLoader loader = new URLClassLoader(urls, null); Thread. currentThread().setContextClassLoader(loader); String className = SingleThreadMultiLoader.class.getName(); Class clz = loader.loadClass(className); Method main = clz.getMethod("logMethod"); main.invoke( null); logger.info( "執行緒名: {}; 日誌MDC資訊:{}。" , Thread.currentThread().getName(), MDC. get(key)); } public static void logMethod() { logger.info( "執行緒名: {}; 日誌MDC資訊:{}。" , Thread.currentThread().getName(), MDC. get(key)); MDC. put(key, "hahahahhaha" ); System. out.println( tl.get()); } }

執行結果如下:

2014-05-06 16:02:53,802 >> INFO  >> main >> com.coderli.log4j.mdc.SingleThreadMultiLoader.main(SingleThreadMultiLoader.java:32) >> 執行緒名: main; 日誌MDC資訊:in main loader。
2014-05-06 16:02:53,869 >> INFO  >> main >> com.coderli.log4j.mdc.SingleThreadMultiLoader.logMethod(SingleThreadMultiLoader.java:62) >> 執行緒名: main; 日誌MDC資訊:null。
null
2014-05-06 16:02:53,870 >> INFO  >> main >> com.coderli.log4j.mdc.SingleThreadMultiLoader.main(SingleThreadMultiLoader.java:50) >> 執行緒名: main; 日誌MDC資訊:in main loader。


可以看到,在全隔離的兩個Classloader下,MDC資訊也是隔離的,不互通的。OneCoder遇到的bug也由此而來,在沙箱內部,雖然是同一個執行緒,但是MDC內的資訊是上一個任務的,自然會出錯了。

為了更直觀的說明問題,OneCoder還驗證了ThreadLocal的情況,結果一樣也是隔離的。這就跟ThreadLocal的實現機制有關了。

public T get() {
        Thread t = Thread.currentThread();
        ThreadLocalMap map = getMap(t);
        if (map != null) {
            ThreadLocalMap.Entry e = map.getEntry(this);
            if (e != null)
                return (T)e.value;
        }
        return setInitialValue();
    }

從ThreadLocal的get()方法便可理解。在取值的時候,首先通過當前執行緒物件作為key。獲取到當前執行緒的ThreadLocalMap,再用ThreadLocal物件作為key從Map中獲取值。而在隔離的Classloader中,這個ThreadLocal物件是不同的。自然取到的值也就不同了。


當然,如果你的Classloader不是完全隔離的。在ThreadLocal層是有共同的父loader話,ThreadLocal中的值還是可以互通的。