太原高端网站建设,网站观赏,wordpress获取作者的角色,网站内部的信息安全建设一、引言 最近有个线上日志丢失tag的问题#xff0c;是组内封装了后置请求的拦截器把请求的响应结果存到ClickHouse里面去#xff0c;但是日志总有一些tag丢失。 作者提出父级线程的threadlocal被清空#xff0c;同事认为可能是threadlocal的弱引用在gc的时候被回收。两种想…一、引言 最近有个线上日志丢失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) {MapString, String logTags log.getCommonTags();return () - {log.setCommonTags(logTags);runnable.run();};}private static void doLog(PostResponseFilterArgs args) {// 构建业务信息MapString, 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 MapString, String getCopy() {final StringMap map localMap.get();return map null ? new HashMap() : map.toMap();}Overridepublic MapString, String getCopy() {final MapString, 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) {ListTask list new ArrayList();for (int i 0; i 10000;i) {
System.out.println(i start);MapString, String md new HashMap();md.put(orderid,i 666);// 设置MDC信息MDC.setContextMap(md);int finalI i;Runnable logTask () - {
// 构建SOA信息MapString, 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 ElementMatcherTypeDescription typeMatcher() {return named(server.OperationHandler);}private static void recordMocker(Mocker mocker) {// 业务处理MDC.clear();} 他的过程可以画成这样。 关掉ar组件之后可以看到没有再发生有问题的ck日志记录了解到ar组件的执行频率是一小时10次这也说明了为什么我们发现的监控是部份发生其实这个组件导致了必然的结果。 一切的偶然总有必然的原因 四、总结 再次抒感一切的偶然总有必然的原因这次的问题告诉了我们问题不一定出现在看得见的代码java-ageng之类看不见的代码很多时候是另外一个方向。 这里再次感谢ld和cbc的协作分析合作无间
