log4j中MDC使用陷阱

作者: 全都是泡沫啦 | 来源:发表于2018-11-28 18:10 被阅读0次

log4j中MDC使用陷阱
Java日志Log4j或者Logback的NDC和MDC功能
log4j配置文档
SpringBoot+MDC实现全链路调用日志跟踪，排查问题更方
log4j
java 注解结合 spring aop 实现日志traceId
logback的MDC机制
log4j
2017-10-26 Slf4j MDC 使用和基于 Logb
logback扩展字段

1. 背景

同学求助,生产环境对于方法JSONObject.toJSONString()时不时的报以下错误,一看这个大家都会知道HashMap中modCount发生了变化,与初始化生成迭代器HashIterator的expectedModCount不同,那modCount发生变化的场景:clear(),putVal(),removeNode(),computeIfAbsent(),compute(),merge().一定是在遍历过程发生的HashMap增删变化,这个毋庸置疑。接下来我看实际场景

Exception in thread "pool-1-thread-2" java.util.ConcurrentModificationException
    at java.util.HashMap$HashIterator.nextNode(HashMap.java:1429)
    at java.util.HashMap$EntryIterator.next(HashMap.java:1463)
    at java.util.HashMap$EntryIterator.next(HashMap.java:1461)
    at com.alibaba.fastjson.serializer.MapSerializer.write(MapSerializer.java:79)
    at com.alibaba.fastjson.serializer.JSONSerializer.write(JSONSerializer.java:361)
    at com.alibaba.fastjson.JSON.toJSONString(JSON.java:594)
    at TestThread.lambda$main$1(TestThread.java:33)

对问题代码进行了抽取, 如下

<dependencies>
        <dependency>
            <groupId>log4j</groupId>
            <artifactId>log4j</artifactId>
            <version>1.2.17</version>
        </dependency>

        <dependency>
            <groupId>com.alibaba</groupId>
            <artifactId>fastjson</artifactId>
            <version>1.2.3</version>
        </dependency>
    </dependencies>

public class TestThread {
    public static JSONObject getJSONObject() {
        JSONObject json = (JSONObject) MDC.get("json");
        if (json == null) {
            json = new JSONObject();
            MDC.put("json", json);
        }
        jsonObject.clear();
        return json;
    }

    public static void main(String[] args) {
        ExecutorService executorService = Executors.newFixedThreadPool(3);
        boolean flag = true;
        if (flag) {
            final JSONObject jsonObject = getJSONObject();
            executorService.execute(() -> {
                System.out.println("父线程json与子线程json是否相等:" + (jsonObject == getJSONObject()));
            });
        }
        executorService.execute(() -> {
            while (true) {
                getJSONObject().toJSONString();
            }
        });
        executorService.execute(() -> {
            while (true) {
                JSONObject jsonObject1 = getJSONObject();
                while (true) {
                    jsonObject1.put("K_" + System.currentTimeMillis(), null);
                }
            }
        });
    }
}

运行结果

当flag=true
父线程json与子线程json是否相等:true
Exception in thread "pool-1-thread-2" java.util.ConcurrentModificationException
    at java.util.HashMap$HashIterator.nextNode(HashMap.java:1429)
    at java.util.HashMap$EntryIterator.next(HashMap.java:1463)
    at java.util.HashMap$EntryIterator.next(HashMap.java:1461)
    at com.alibaba.fastjson.serializer.MapSerializer.write(MapSerializer.java:79)
    at com.alibaba.fastjson.serializer.JSONSerializer.write(JSONSerializer.java:361)
    at com.alibaba.fastjson.JSON.toJSONString(JSON.java:594)
    at TestThread.lambda$main$1(TestThread.java:33)
    at TestThread$$Lambda$2/457233904.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

当flag=false
无报错结果

分析定位到org.apache.log4j.MDC问题:错误使用InheritableThreadLocal
InheritableThreadLocal子线程会copy父线程中的所有ThreadLocal的变量,对于引用类型JSONObject则导致发现并发操作问题
解决方法

private static final ThreadLocal<JSONObject>  JSON_OBJECT_THREAD_LOCAL= new ThreadLocal();

    public static JSONObject getJSONObject(){
        JSONObject jsonObject = JSON_OBJECT_THREAD_LOCAL.get();
        if (jsonObject == null){
            jsonObject = new JSONObject();
            JSON_OBJECT_THREAD_LOCAL.set(jsonObject);
        }
        jsonObject.clear();
        return jsonObject;
    }