写了一个追踪业务异常的工具，欢迎体验！

发表于 分类于 阅读次数： 本文字数： 2.8k 阅读时长 ≈ 10 分钟

工具名称：LogTrace

建议使用gradle作为项目管理工具，下面是一些建议的版本号：jdk8～11 gradle7+ LogTrace v0.0.1-SNAPSHOT

Part1: 解决的问题

本产品尝试解决以下场景的问题：假设现在有一块依赖了很多上下游服务的代码，且上下游的返回决定了它的逻辑走向，其中弯弯绕绕的if-else一大堆，除了没写注释外，还没有打印任何日志，举个例子：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
public Student complexScene(String... args) {
    if(args == null || args.length == 0) {
        return null;
    }

    int aResult = aService.getA(args[0]); //假设getA底层是通过数据库拿到的结果
    if(aResult > 5){
        return null;
    }

    List<String> bResults = bService.getBs(args[0]); //假设getBs是通过一个rpc服务拿到的结果
    if(bResults != null && bResults.size() > 0){
        Student student = new Student();
        student.setAge(aResult);
        student.setName(bResults.get(0));
        return student;
    }
    return null;
}

这段代码中有3种逻辑走向会返回null，假如现在这块逻辑在生产环境突然返回了不符合预期的结果（比如应该返回student，却返回了null），需要排查问题，你会怎么做?

你可能会想到利用可观测系统（即监控+日志+链路追踪）进行一系列分析，最终得出结论，但这只适用于上下游服务异常的情况(IO错误)，像上面这种情况各方调用都是正常的，仅仅是返回了不符合预期的结果而已，在这种场景下可观测系统就显得力不从心了。

排查这类问题，最简单的方式就是给每个影响逻辑走向的地方打上追踪日志：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
public Student complexScene(String... args) {
    if(args == null || args.length == 0) {
        log.debug("args == null or length == 0 is true! args={}", args); //逻辑追踪日志
        return null;
    }

    int aResult = aService.getA(args[0]);
    if(aResult > 5){
        log.debug("aResult > 5 is true! aResult={}", aResult); //逻辑追踪日志
        return null;
    }

    List<String> bResults = bService.getBs(args[0]);
    log.debug("bResults={}", bResults); //逻辑追踪日志
    if(bResults != null && bResults.size() > 0){
        Student student = new Student();
        student.setAge(aResult);
        student.setName(bResults.get(0));
        return student;
    }
    return null;
}

这样就可以通过日志系统分析出逻辑走向。

这只是个简单的例子，在实际开发中往往有巨复杂的逻辑，最典型的就是网关接口，内部可能聚合了高达十几个rpc服务的返回值，中间产生的条件判断逻辑更是数不胜数， 像这种场景一旦返回了不符合预期的结果，如果没有追踪日志排查起来将会极其痛苦。

虽然通过追踪日志很容易排查出问题所在，但打印这些日志是麻烦的，你要考虑在哪里打，输出哪些数据，格式应该怎样，如何避免打印无意义的日志。
LogTrace就是用来解决这些问题的，它会自动解析语法树，在影响逻辑走向的地方植入风格统一的业务追踪日志，下面来看看它具体的用法。

Part2: 导包

将下面的jar包导入到你的项目中

⚠️ 注意:
Slf4j和logback是必须的，如果你项目中已经引入了，就不用再引了
除了logback，引入其他Slf4j标准实现也可以，如log4j

gradle：

1
2
3
4
5
implementation 'org.slf4j:slf4j-api:1.7.7'
implementation 'ch.qos.logback:logback-classic:1.2.9'

compileOnly 'io.github.exceting:log-trace:0.0.1-SNAPSHOT'
annotationProcessor 'io.github.exceting:log-trace:0.0.1-SNAPSHOT'

maven：

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
<dependencies>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>1.7.7</version>
    </dependency>
    <dependency>
    <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>
        <version>1.2.9</version>
    </dependency>
    <dependency>
        <groupId>io.github.exceting</groupId>
        <artifactId>log-trace</artifactId>
        <version>0.0.1-SNAPSHOT</version>
    </dependency>
</dependencies>

<build>
    <plugins>
        <plugin>
            <groupId>org.apache.maven.plugins</groupId>
            <artifactId>maven-compiler-plugin</artifactId>
            <configuration>
                <source>1.8</source>
                <target>1.8</target>
                <annotationProcessors>
                    <annotationProcessor>io.github.exceting.cicada.tools.logtrace.LogTraceProcessor</annotationProcessor>
                </annotationProcessors>
            </configuration>
        </plugin>
    </plugins>
</build>

现在的包是snapshot版本（正式版需要进行更多的测试case后才能发布），所以要把sonatype的snapshot仓库依赖加进来：
gradle：

1
2
//将snapshot仓库加到repositories里
maven { url "https://s01.oss.sonatype.org/content/repositories/snapshots/" }

maven：

1
2
3
4
5
6
<!-- 将snapshot仓库加到<repositories>里-->
<repository>
    <id>snapshots</id>
    <name>sonatype snapshot</name>
    <url>https://s01.oss.sonatype.org/content/repositories/snapshots/</url>
</repository>

Part3: 快速开始

确定jar包和仓库已经配好后开始快速使用，首先在测试类上加@Slf4jCheck注解

@Slf4j注解

然后在需要被追踪的方法上加@MethodLog注解，运行效果如图:

@MethodLog注解

Part4: 格式&基本原理

通过LogTrace植入的追踪日志统一格式如下：

日志格式LogTrace的工作原理与lombok一致，都是在编译期解析语法树，通过对应的注解增强原有代码，即在编译期修改源代码的方式实现， 参考这里 ，它是对java源代码的增强，除此之外还有增强字节码的技术，如asm和javassist。

Part5: 注解&用法

@Slf4jCheck

每个需要打追踪日志的类上都应该加上这个注解，加上此注解后，类内会自动创建一个Slf4j的Logger对象，作用等同于lombok的@Slf4j且兼容lombok。
它有一个属性：

  • isOpen：用来控制是否输出追踪日志，默认为空（输出），支持定制AtomicBoolean开关，灵活控制是否输出日志，对全局方法生效，开关这块内容会放到自定义开关小节详细介绍，这里不再赘述。

@MethodLog

除了要在类上加@Slf4jCheck，还要在每个需要植入追踪日志的方法上加上@MethodLog注解，程序运行起来后，只会给加了此注解的方法植入追踪日志。
它有6个属性：

  • isOpen：默认为空，作用跟@Slf4jCheck里的isOpen一样，但优先级更高，仅对当前方法生效。

  • traceLevel：默认为Level.DEBUG，可通过此项定制追踪日志的级别。

  • exceptionLog：是否打印方法异常信息，为true时开启，默认false，它的增强效果如下：

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    // 原始代码
    @MethodLog(exceptionLog = true)
    void methodTest() {
        // 方法体省略...
    }
        
    // ⬇⬇ 被LogTrace增强后的代码
        
    void methodTest() {
        try {
            // 方法体省略...
        } catch(Exception e) { // try-catch
            log.error("LOG_TRACE >>>>>> OUTPUT: [METHOD: methodTest][TRY][LINE: 5] Error! Data: ", e); // 输出错误日志（注：异常日志的级别强制为error）
            throw e;
        }
    }

  • noThrow：需要和exceptionLog搭配使用，当它的值为true时，则只catch异常，不抛出异常，默认false，它的增强效果如下：

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    // 原始代码
    @MethodLog(exceptionLog = true, noThrow = true)
    void methodTest() {
        // 方法体省略...
    }
        
    // ⬇⬇ 被LogTrace增强后的代码
        
    void methodTest() {
      try {
        // 方法体省略...
      } catch(Exception e) { //仅输出日志，不再throw异常
        log.error("LOG_TRACE >>>>>> OUTPUT: [METHOD: methodTest][TRY][LINE: 5] Error! Data: ", e);
      }
    }

  • dur：是否打印方法耗时？为true时开启，默认false，开启后的增强逻辑如下：

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    // 原始代码
    @MethodLog(dur = true)
    void methodTest() {
      // 方法体省略...
    }
        
    // ⬇⬇ 被LogTrace增强后的代码
        
    void methodTest() {
      // 植入的计数变量会加个UUID后缀，防止局部变量冲突
      long start_${UUID} = System.nanoTime();
      try{
        // 方法体省略...
      } finally { //打印出本方法执行耗时
        log.debug("LOG_TRACE >>>>>> OUTPUT: [METHOD: methodTest][TRY][LINE: 5] Finished! Data: duration = {}", (System.nanoTime()-start_${UUID})/1000000L);
      }
    }

  • onlyVar：是否只打印变量追踪日志？默认false，为false时，那些加了@MethodLog的方法，会在所有影响逻辑走势的地方都加上追踪日志(即方法内任意地方的任意if、if-else，switch-case语句)，增强效果如下：

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    // 原始代码
    @MethodLog
    void methodTest() {
      int a = 2;
      if(a == 2) {
        // 条件1命中
      } else {
        // 条件2命中
    }
        
    // ⬇⬇ 被LogTrace增强后的代码
        
    void methodTest() {
        int a = 2;
        if(a == 2) { // 这里会植入各条件命中时的追踪日志
            log.debug("LOG_TRACE >>>>>> OUTPUT: [METHOD: methodTest][IF][LINE: 29] The condition: (a == 2) is true!");
            // 条件1命中
        } else {
            log.debug("LOG_TRACE >>>>>> OUTPUT: [METHOD: methodTest][IF][LINE: 31] The condition: else is true!");
            // 条件2命中
        }
    }

    如果onlyVar为true，这些日志将不再打印，这时就只会打印方法体中被@VarLog标注的局部变量日志(@VarLog后面会介绍)。
    如果你认为不需要那么详细的追踪日志，可以利用此项放弃这些日志。

@VarLog

对于方法体中局部变量的追踪，如果你要对方法体中某个局部变量感兴趣，可以在其声明的位置打上这个注解，之后这个变量的值会被追踪，增强过程如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
// 原始代码
@MethodLog
void methodTest() {
    @VarLog //利用@VarLog追踪局部变量a
    int a = getA(); //假设getA是调用另一个RPC服务来拿a的值
    a=5;
}

// ⬇⬇ 被LogTrace增强后的代码

void methodTest() {
    int a = getA(); //⬇追踪后会打印a的值
    log.debug("LOG_TRACE >>>>>> OUTPUT: [METHOD: methodTest][VARIABLE][LINE: 28]  Data: a = {}", new Object[]{Integer.valueOf(a)});
    a = 5; //⬇之后局部变量在程序中的任意位置被重新赋值，都会将其新值打印出来
    log.debug("LOG_TRACE >>>>>> OUTPUT: [METHOD: methodTest][VARIABLE][LINE: 31]  Data: a = {}", new Object[]{Integer.valueOf(a)});
}

除此之外，这个注解还包含一个dur属性，默认值为false，当设置为true时，会打印获取这个变量所消耗的时间。
对于复杂场景，你可以利用这个注解灵活的追踪任意变量，记录变量被赋予的所有值。

@Ban

所有追踪日志在打印时，会无脑打印方法的入参，如果你不需要某个参数被打印，就给它加上这个注解：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
// 原始代码
@MethodLog
void methodTest(int a, @Ban int b, int c) { //禁止打印参数b
    if(a == 1){
        //业务代码省略...
    }
}

// ⬇⬇ 被LogTrace增强后的代码

void methodTest(int a, int b, int c) {
    Object final_c = c;
    Object final_a = a;
    if (a == 1) { //⬇在植入的追踪日志中，打印入参时，只打印a和c，被@Ban修饰的b则不打印
        log.debug("LOG_TRACE >>>>>> OUTPUT: [METHOD: methodTest][IF][LINE: 30] The condition: (a == 1) is true! Data: a = {}, c = {}", new Object[]{final_a, final_c});
    }
}

Part6: 自定义日志开关

LogTrace提供非常灵活的开关定制方式，在@Slf4jCheck和@MethodLog里面通过isOpen属性控制日志是否输出，默认输出，@MethodLog优先级更高。

定制开关: 在任意类里定义一个开关，这个开关必须是static、final的AtomicBoolean对象：

1
public static final AtomicBoolean isOpen = new AtomicBoolean(true)

利用全限定名#开关名的格式给isOpen属性赋值：

1
2
@Slf4jCheck(isOpen = "io.cicada.mock.tools.config.Test#isOpen")
@MethodLog(isOpen = "io.cicada.mock.tools.config.Test#isOpen")

剩下的事情就很简单了，你可以写个定时任务定时从配置系统中获取具体的开关值，来刷新这个对象的值(注意刷新的时候只刷值，不要改开关的引用指针!)，从而利用配置系统灵活控制日志的输出：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
@Component
public class OffOnTest {
    
    // 开关
    public static final AtomicBoolean isOpen = new AtomicBoolean(false);
    
    ScheduledExecutorService refreshTask = ThreadPools.newScheduledThreadPool("RefreshSwitch", 1);
    @PostConstruct
    private void init() {
        refreshTask.scheduleWithFixedDelay(() -> {
            // 定时刷新开关值，具体从哪里获取开关状态，取决于你自己的需求，最典型的就是拉取远程配置系统里的值，这样你只需要更新配置系统里的配置，就能控制追踪日志是否打印
            isOpen.set(当前开关值);
        }, 5000, 5000, TimeUnit.MILLISECONDS);
    }
}

一些C端服务流量较高，如果担心日志的上报对性能有影响，可以通过开关来控制是否输出追踪日志。

Part7: lombok可以让它更好的工作

利用lombok生成对象的toString方法，将对象整个打印出来:

日志格式

Part8: 常见问题

使用maven运行时可能出现类型转换错误异常：

1
java: java.lang.ClassCastException: class com.sun.proxy.$Proxy15 cannot be cast to class com.sun.tools.javac.processing.JavacProcessingEnvironment (com.sun.proxy.$Proxy15 is in unnamed module of loader java.net.URLClassLoader @59690aa4; com.sun.tools.javac.processing.JavacProcessingEnvironment is in module jdk.compiler of loader 'app')

解决：点开IDEA的settings选项，在弹出窗口找到如下位置

日志格式

将-Djps.track.ap.dependencies填入上图指定位置即可解决。