一次java-agent中字节码增强失败问题定位

Posted on | In

1 背景

我们的项目目前使用zander(公司内部的链路追踪组件, 基于skywalking)作为日志增强组件, 在日志中打印traceId, 用于多服务请求追踪标识.
目前我们服务中遇到了traceId消失的问题, 即zander中对log4j2的字节码增强失败. 需要分析原因

2 bytebuddy实现的javaagent

zander中为了实现日志增强, 采用了javaagent的方式, 对log4j的相应方法做拦截增强, 将traceid写入到对应的log文件中.

我们的工程中使用的是log4j2, 对应的增强方法为org.apache.logging.log4j.core.config.LoggerConfig#callAppenders, 该方法位于lo4j-core-2.x.x.jar

我们知道, javaagent在执行时, 会执行Premain-Class下的premain方法, 我们找到zander的Premain-Class ZanderAgent以及对应premain方法如下(做了些删减)

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
public static void premain(String agentArgs, Instrumentation instrumentation) {
    LOGGER.info("premain begin, and load config start with agentArgs: {}", new Object[]{agentArgs});
    AgentConfigInitializer.initialize();
    // 心跳检测
    HeartBeatBootService.doHeartBeat();
    CustomMethodUtils.init();
    LogInterceptorUtils.init();

    final PluginFinder pluginFinder;
    try {
        // 载入插件. log4j2的插件也会在此处被载入
        pluginFinder = new PluginFinder(new PluginBootstrap().loadPlugins());
    } catch (Exception e) {
        return;
    }

    new AgentBuilder.Default().type(enhanceClassMatcher(pluginFinder).and(not(isInterface()))).transform((builder, typeDescription, classLoader) -> {
        // 此处会找到zander log4j2插件的Log4j2Instrumentation, Log4j2Instrumentation类中会定义所要拦截的log4j2对应的方法
        List<AbstractClassEnhancePluginDefine> pluginDefines = pluginFinder.find(typeDescription.getTypeName());

        for (AbstractClassEnhancePluginDefine pluginDefine : pluginDefines) {
            DynamicType.Builder<?> newBuilder = pluginDefine.define(typeDescription.getTypeName(), builder, classLoader);
            if (newBuilder != null) {
                return newBuilder;
            }
        }
        return builder;
    }).installOn(instrumentation);
}

我们可以看到zander在premain方法中用bytebuddy实现了一个agent, 拦截log4j2对应的类和方法, 进而做增强, 写入traceid. 截取zander定义的Log4j2Interceptor类如下

public void beforeMethod(EnhancedClassInstanceContext context, InstanceMethodInvokeContext interceptorContext, MethodInterceptResult result)
           throws Throwable {
       if (ZANDER == null || ZANDER.getRpcContext() == null) {
           return;
       }
       try {
           if (interceptorContext.allArguments().length == 1) {
               LogEvent event = (LogEvent) interceptorContext.allArguments()[0];
               Message message = event.getMessage();
               String messageContext = message.getFormattedMessage();
               String log = String.format(" [traceId=%s,rpcId=%s] %s", ZANDER.getTraceId(), ZANDER.getRpcId(), messageContext);
               setField(message, log);
               Throwable throwable = event.getThrown();
               StringWriter sw = new StringWriter();
               if (throwable != null) {
                   throwable.printStackTrace(new PrintWriter(sw));
                   messageContext += " " + throwable.getMessage();
               }
               CheckBootService.logCheck(event.getLevel().toString());
               if (Config.BusinessLog.isOn() && LogLevel.valueOf(event.getLevel().toString()).compareTo(Config.BusinessLog.getLogLevel()) >= 0) {
                   RpcContext rpcContext = ZANDER.getRpcContext();
                   XtraceBusinessLog xtraceBusinessLog = new XtraceBusinessLog();
                   ......
                   xtraceBusinessLog.setBusinessId(ZANDER.getKVLog(Constants.PLUGIN_BUSINESS_ID));
                   setBusinessLog(xtraceBusinessLog);
                   LOG_COLLECTOR.startLog(xtraceBusinessLog);
               }

           }

       } catch (Exception e) {
           LOGGER.error("log4j2Interceptor exception", e);
       }
   }

3 增强失败

zander的这一套基于bytebuddy增强逻辑看着没有问题, 但是我们的traceid却消失了. 说明bytebuddy的字节码增强没生效, 为啥?

补习了下bytebuddy字节码增强的原理, 知道增强的简要流程:

  1. 通过Instrumentation注册需要增强的目标类
  2. 当classloader载入需要增强的目标类时, 使用增强的实现类替换之
  3. 调用目标类的方法时, 会相应执行增强实现类中的增强方法

问题可能出现的地方是步骤1和步骤2, 调试代码, 步骤1正确执行. 我们主要分析下步骤2.

我们知道, 类只会被class loader加载一次, 后面就不会被加载了, 所以问题大概率出现在我们需要增强的类在bytebuddy对其增强之前, 已经被加载过了.

3.1 定位增强失败的原因

是谁导致org.apache.logging.log4j.core.config.LoggerConfig类在增强生效之前被载入? 直接在java.lang.ClassLoader#loadClass(java.lang.String)上加断点, 调试结果如下:

调试后发现, 是被zander自己加载了. 这个log路径如下.

zander为了不影响log插件, 自定义了一套log(见com.xiaomi.apm.core.log.logging.BootLogger). 但是, 在心跳检测时, 如果心跳请求失败, 就会执行com.xiaomi.apm.core.utils.MailSender#send方法发邮件. com.xiaomi.apm.core.utils.MailSender中, 使用了org.apache.commons.httpclient.HttpClient, 而HttpClient中使用了org.apache.commons.logging.Log.

我们知道, commons-logging在使用时, 如果在classpath下找不到commons-logging.properties, 就会使用Log4JLogger, 看这名字就知道, 这时候会去载入Log4j了. 我们的项目里, 使用的Log4j都是2.x版本, 也就是Log4j2. 一旦这时候载入了Log4j2, 我们的增强就不会生效了, 因为接下来再也不会载入org.apache.logging.log4j.core.config.LoggerConfig了.

3.2 如何解决增强失败

调试可知, 问题出在心跳检测时, 检测失败, 发邮件报错使用了commons-logging, 进而导致org.apache.logging.log4j.core.config.LoggerConfig在增强前被classLoader载入. 但我们现在用zander只需要用traceid, 其他不重要了. 直接删掉心跳检测的部分, 打个zander包, 调试一把

这次调起org.apache.logging.log4j.core.config.LoggerConfig加载的是我们自己程序的Main类了

相应的, zander的log4j2增强也成功了

4 结论

本质上讲, 这是zander的一个bug. 因为正常情况下心跳检测应该是成功的, 但zander服务已经下线了, 所以我们的心跳检测就一直是失败了.