文章

log4j 同一线程隔离classloader下MDC信息不同问题解决 ThreadLocal问题分析

最近遇到日志文件记录错误的问题。一个任务的日志信息会被莫名的拆分到两个不同目录中。且有一个目录还是曾经执行过的任务的目录。经过分析,首先怀疑的是MDC没有清理的问题,这也是最直观的问题。因为任务是在线程池(fixedThreadPool)中运行的。由于线程会被重用,而MDC是绑定在Threadlocal上的,所以如果没有清理,是会造成上述问题。但是在代码检查中发现在线程的开始,是重新设置过MDC信息的。所以,怀疑的对象转移到了多classloader上。由于不能肯定,所以进行测试如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
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的实现机制有关了。

1
2
3
4
5
6
7
8
9
10
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中的值还是可以互通的。

本文由作者按照 CC BY 4.0 进行授权