自己写分布式链路追踪框架2-包装日志组件自动输出traceId

文章目录

1. 日志组件包装

之前的第一篇文章自己写分布式链路追踪框架1–TraceId/SpanId/ParentSpanId生成及传递中，我们完成了trace的封装及通过HTTP进行传递的操作。实现了跨服务TraceId生成及传递，在实际生产中，要实现对业务链路的监控，常常基于日志输出TraceId，将日志收集到统一日志平台，例如ELK。

这样我们就能够基于日志平台提供的搜索功能，通过唯一的TraceId将贯穿多个服务的业务链路穿起来进行分析，甚至基于调用链路的完整性进行性能相关的监控。

同时，我们还要尽量减少TraceId对业务日志的侵入性，这时就需要对日志组件进行自定义的包装改造。

那么就跟着我的脚步，开始今天的话题–包装日志组件自动输出traceId吧。

日志组件包装

包装Logger

首先我们要对日志组件进行选择，这里就选择大家最熟悉的SLF4J，实现INFO,TRACE,ERROR,DEBUG等常见方法，代码如下。

public class Logger {

    private org.slf4j.Logger logger;

    private String name;

    private Class clazz;

    public Logger(String name) {
        this.name = name;
        logger = LoggerFactory.getLogger(name);
    }

    public Logger(Class clazz) {
        this.clazz = clazz;
        logger = LoggerFactory.getLogger(clazz);
    }

    public void debug(String message) {
        StackTraceElement[] stacks = Thread.currentThread().getStackTrace();
        String className = stacks[2].getClassName();
        String methodName = stacks[2].getMethodName();
        int lineNum = stacks[2].getLineNumber();
        this.logger.debug(message + ",[traceId]=" + RequestContext.getTraceId() + ",[className]=" + className + ",[methodName]=" + methodName + ",[lineNum]=" + lineNum);
    }

    public void info(String message) {
        StackTraceElement[] stacks = Thread.currentThread().getStackTrace();
        String className = stacks[2].getClassName();
        String methodName = stacks[2].getMethodName();
        int lineNum = stacks[2].getLineNumber();
        this.logger.info(message + ",[traceId]=" + RequestContext.getTraceId() + ",[className]=" + className + ",[methodName]=" + methodName + ",[lineNum]=" + lineNum);
    }


    public boolean isTraceEnabled() {
        return this.logger.isTraceEnabled();
    }

    public boolean isDebugEnabled() {
        return this.logger.isDebugEnabled();
    }

    public boolean isInfoEnabled() {
        return this.logger.isInfoEnabled();
    }

    public boolean isWarnEnabled() {
        return this.logger.isWarnEnabled();
    }

    public boolean isErrorEnabled() {
        return this.logger.isErrorEnabled();
    }

......省略get set方法
......省略trace error实现，同debug info
}

可以看到，逻辑是很简洁的，为了保持统一，我们将类名与SLF的LOGGER保持一致，在我们自定义的Logger中保持了一个org.slf4j.Logger logger的引用，对它的具体的方法进行包装，在输出的日志体中加入了TraceId信息，这个TraceId就来源于我们上一篇文章中的RequestContext上下文中。

也就是说，只要依赖了我们的Trace组件，那么在使用我们自定义的日志组件进行日志打印的时候就会将上下文中的TraceId信息输出到日志体中。这里具体的日志打印由底层的日志实现组件来进行，比如Log4j、Logback等。

包装LoggerFactory

为了保持统一，我们对Logger进行进一步的封装，为其添加工厂，同时与SLF4J保持命名的一致，代码如下

public class LoggerFactory {

    public static Logger getLogger(Class clazz) {
        return new Logger(clazz);
    }

    public static Logger getLogger(String name) {
        return new Logger(name);
    }
}

不需要进行过多的讲解，就是简单工厂模式。

如何应用

那么如何使用呢？

由于我们组合了SLF4J的依赖，那么只要引入我们的包并声明即可使用。

如下代码为我们调用日志打印的样例代码：

private static final com.snowalker.tracer.log.logger.Logger LOGGER =
com.snowalker.tracer.log.logger.LoggerFactory.getLogger(DemoController.class);

public @ResponseBody String trace(HttpServletRequest request, HttpServletResponse response) {

    LOGGER.info("[demoA]业务执行开始");
    String result =
            restTemplateWrapper.getRestTemlate().getForObject("http://localhost:8081/trace", String.class);
    return "Send Message To B,result= " + result;
}

可以看到我们只是引入的包为自定义的日志类，而具体的日志打印并没有显示的获得TraceId并输出，业务量大的时候这可以大大减少Trace信息对业务代码的侵入性。符合设计模式的迪米特原则。

我们依旧基于上文的例子，两个服务，服务A发消息到服务B，并获取服务B的返回内容，如下为两个服务的日志打印。

日志输出

服务A（调用方）

2018-09-06 10:35:42.888 -INFO  [http-nio-8080-exec-4] com.snowalker.tracer.demoA.controller.DemoController [51] 
-[demoA]业务执行开始,[traceId]=TRACE-fd96667beccb44fb861703281aca0a0f,
[className]=com.snowalker.tracer.demoA.controller.DemoController,
[methodName]=trace,[lineNum]=33

服务B（被调用方）

2018-09-06 10:35:42.915 -INFO  [http-nio-8081-exec-2] com.snowalker.tracer.demoB.controller.DemoController [51]
 -[demoB]业务逻辑执行完成,[traceId]=TRACE-fd96667beccb44fb861703281aca0a0f,
 [className]=com.snowalker.tracer.demoB.controller.DemoController,
 [methodName]=trace,[lineNum]=26

可以看到，服务A生成的TraceId不仅在A服务打印出，而且经过链路传输到服务B，并且B在上下文获取到该Id并打印到日志中，保证了TraceId在无侵入的前提下，在多个服务的日志中体现。

而我们的实现仅仅是对日志组件做了一个wrapper类，这里有点类似代码模式中的静态代理了。

小结

本文代码量并不多，核心是基于包装模式对日志组件做了自定义的封装，当然我这里的封装只是简单的一个例子。

实际开发中，我们出于业务的需要，常常需要在日志组件中体现更多的监控参数，这个请读者自行根据业务实现。

基于SLF4J的封装，我们只要从上下文中取到TraceId设置到日志体中即可，而这一切对业务没有一丝的侵入。这里体现了面向对象中封装和编程中复用的特点。

希望本文讲到的一些技巧能够对读者有所启发。

朝·闻·道

SnoWalker's Blog