Log4j-tag丢失

一、引言

        最近有个线上日志丢失tag的问题，是组内封装了后置请求的拦截器把请求的响应结果存到ClickHouse里面去，但是日志总有一些tag丢失。

        作者提出父级线程的threadlocal被清空，同事认为可能是threadlocal的弱引用在gc的时候被回收。两种想法其实都是有可能的，那就要一个个验证。这里要感谢ld和cbc的共同排查、讨论，最后锁定原因是父级线程的MDC被ar组件清空。

二、问题

1、架构背景

        这里先讲讲问题后面架构的背景，由于需要按照特定的格式存一些日志数据到ck，组内封装的后置拦截器会使用slf4j的MDC.getCopyOfContextMap()获取请求被存储在ThreadLocal里面的map，里面放了一些订单、人员信息的key-value，拿到这些数据再和一些响应参数存入ck。

        集团的日志框架里面实现了servlet的Filter，在servlet容器初始化的时候会运行这个拦截器，把一部分埋点运行，但是会清空，保证进入业务处理的时候是干净的。真正用到的买点是在业务线程里面实现的，所以在业务处理完成到后置拦截器的过程中可能存在clear的操作。需要把框架整体结构研究下。

2、问题背景

        在落数据的监控，看到有几列偶现是空的。

        看代码确认这些空列都是从MDC取出来的。

三、分析

        快速的讨论锁定了出问题的代码。

1、代码

        这个代码是从父线程取出来日志信息，作为入参返回给子runnable，等到子runnable启动的时候，它就变成了子线程里面的threadlocal。

@Overridepublic void apply(PostResponseFilterArgs args) {try {Runnable logTask = () -> doLog(args);if (CommonLogConfig.logAsync()&& StringUtilsExt.isNotBlank(CommonLogConfig.logExecutor())) {TaskRunner.create(LogTagsWrap.wrap(logTask)).start(CommonLogConfig.logExecutor());} else {logTask.run();}} catch (Throwable e) {LOGGER.info(TITLE, e);}}
public static Runnable wrap(Runnable runnable) {Map<String, String> logTags = log.getCommonTags();return () -> {log.setCommonTags(logTags);runnable.run();};}private static void doLog(PostResponseFilterArgs args) {// 构建业务信息Map<String, String> map = LogUtil.buildService(args);// 设置MDC信息LogUtil.setMdc(map);// 记录CK日志Throwable throwable = args.executionResult().throwable();if (Objects.nonNull(throwable)) {LogUtil.error(map, throwable, CommonLogConfig.logScenario());} else {LogUtil.info(map, null, CommonLogConfig.logScenario());}}

  2、浅拷贝✖️

        作者一开始以为这里父级线程取出来的可能是浅拷贝，然后在子线程启动之前被其他请求使用了，导致并发清空。但是追溯下去，MDC使用的是深拷贝拿到日志信息。

@Overridepublic Map<String, String> getCopy() {final StringMap map = localMap.get();return map == null ? new HashMap<>() : map.toMap();}@Overridepublic Map<String, String> getCopy() {final Map<String, String> map = localMap.get();return map == null ? new HashMap<>() : new HashMap<>(map);}
public HashMap(Map<? extends K, ? extends V> m) {this.loadFactor = DEFAULT_LOAD_FACTOR;putMapEntries(m, false);}
final void putMapEntries(Map<? extends K, ? extends V> m, boolean evict) {int s = m.size();if (s > 0) {if (table == null) { // pre-sizefloat ft = ((float)s / loadFactor) + 1.0F;int t = ((ft < (float)MAXIMUM_CAPACITY) ?(int)ft : MAXIMUM_CAPACITY);if (t > threshold)threshold = tableSizeFor(t);}else if (s > threshold)resize();for (Map.Entry<? extends K, ? extends V> e : m.entrySet()) {K key = e.getKey();V value = e.getValue();putVal(hash(key), key, value, false, evict);}}}

3、子级threadlocal在gc时回收✖️  

        不过子线程里面一定是在set mdc信息的时候是空的，也就引出来开头作者和同事的两个猜想。threallocal作者感觉是不太可能的，因为线程执行完才算是强引用链结束，但是还是写个测试方法试一试。

        使用system.gc强制回收，看看会不会把threadlocal给回收，结果并没有。这里要设置启动参数，不然system.gc不一定会执行。

public static void main(String[] args) {List<Task> list = new ArrayList<>();for (int i = 0; i < 10000;i++) {
System.out.println(i + "start");Map<String, String> md = new HashMap<>();md.put("orderid",i + "666");// 设置MDC信息MDC.setContextMap(md);int finalI = i;Runnable logTask = () -> {
// 构建SOA信息Map<String, String> map = new HashMap<>();map.put("soa", finalI + "666");System.gc();// 设置MDC信息LogUtil.setMdc(map);System.out.println(map);if (map.size() == 1) {
System.out.println(finalI + "soaerror");}
};Task t = TaskRunner.create(LogTagsWrap.wrap(logTask));list.add(t);System.out.println(i + "end");}
for (Task t : list) {
t.start(CommonLogConfig.logExecutor());}
}

4、父级MDC信息清空☑️

        那么接下来就是看会不会清空父级线程的threadlocal了，作者把框架整体看了一遍。感觉出问题的地方还不少，就看这些拦截器是不是会异步走清理。

         cbc使用过arthas进行线上诊断，作者也学习了一波，使用watch对全限定名的类方法进行字节码动态生成，打印方法的出入参便于排查。

        但是作者这里的情况比较特殊，由于需要确定父级丢失还是子级的gc回收，需要在两个方法里面取出MDC的log信息，在为空的时候打印出来。作者和cbc折腾了许久，比较复杂的监控arthas还是不好用的。就在这时候ld给出了新的方向。

5、ar组件清空父级MDC信息☑️

        他发现出问题的机器ip固定在某两台机器上面，于是我们开始分析这两天机器与其他机器有什么不同。cbc之前接触过测开组做了一个ar组件，使用java-agengt方法在服务发布时注入，这是我们观察不到但是有可能进行拦截增强的代码。

        于是我们开始研究他的源码，果然这个组件使用了 SerivceInstrumentation extends TypeInstrumentation类进行字节码增强，并且是在业务处理的方法外层进行增强，比后置拦截器早。

@Overrideprotected ElementMatcher<TypeDescription> typeMatcher() {return named("server.OperationHandler");}private static void recordMocker(Mocker mocker) {// 业务处理MDC.clear();}

        他的过程可以画成这样。

        关掉ar组件之后，可以看到没有再发生有问题的ck日志记录，了解到ar组件的执行频率是一小时10次，这也说明了为什么我们发现的监控是部份发生，其实这个组件导致了必然的结果。

        一切的偶然总有必然的原因！

 四、总结

        再次抒感：一切的偶然总有必然的原因！这次的问题告诉了我们，问题不一定出现在看得见的代码，java-ageng之类看不见的代码很多时候是另外一个方向。

        这里再次感谢ld和cbc的协作分析，合作无间！