日常技巧 - 微服务中单应用全链路日志处理

背景

最近在排查问题查询日志的的时候，有个很困扰的问题就是多线程调用的情况下，没办法查询一次调用的全链路调用日志，比如在使用elk查询日志的时候，我想看某个日志的前后调用的完整的日志，如果不做处理的话是不太好查询的，所以我通过查询资料发现确实有很多方式处理这种问题，以下是我个人认为比较好的处理方式，即通过MDC处理.

MDC介绍

MDC（Mapped Diagnostic Context，映射调试上下文）是 log4j 、logback及log4j2 提供的一种方便在多线程条件下记录日志的功能。MDC 可以看成是一个与当前线程绑定的哈希表，可以往其中添加键值对。MDC 中包含的内容可以被同一线程中执行的代码所访问。当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时，只需要从 MDC 中获取所需的信息即可。MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说，通常是在请求被处理的最开始保存这些数据

API说明：

• clear() => 移除所有MDC
• get (String key) => 获取当前线程MDC中指定key的值
• getContext() => 获取当前线程MDC的MDC
• put(String key, Object o) => 往当前线程的MDC中存入指定的键值对
• remove(String key) => 删除当前线程MDC中指定的键值对

实现（基于spring boot）

一，创建EnvironmentPostProcessor实现类，配置日志格式化全局环境配置，如："%1p [%X{X-B3-TraceId:-}]"

public class TraceEnvironmentPostProcessor implements EnvironmentPostProcessor {

    private static final String PROPERTY_SOURCE_NAME = "defaultProperties";

    private static final String LEVEL_STR_PARENT = "%1p [%X{X-B3-TraceId:-}]";

    private static final String LOG_PATTERN_LEVEL = "logging.pattern.level";

    @Override
    public void postProcessEnvironment(ConfigurableEnvironment environment, SpringApplication application) {

        Map<String, Object> map = new HashMap<>(1);
        map.put(LOG_PATTERN_LEVEL, LEVEL_STR_PARENT);

        MutablePropertySources propertySources = environment.getPropertySources();

        MapPropertySource target = null;
        if (propertySources.contains(PROPERTY_SOURCE_NAME)) {
            PropertySource<?> source = propertySources.get(PROPERTY_SOURCE_NAME);
            if (source instanceof MapPropertySource) {
                target = (MapPropertySource) source;
                for (String key : map.keySet()) {
                    if (!target.containsProperty(key)) {
                        target.getSource().put(key, map.get(key));
                    }
                }
            }
        }
        if (target == null) {
            target = new MapPropertySource(PROPERTY_SOURCE_NAME, map);
        }
        if (!propertySources.contains(PROPERTY_SOURCE_NAME)) {
            propertySources.addLast(target);
        }
    }
}

二，使用filter拦截每次请求，通过MDC为当前线程添加唯一traceId

@Component
public class TraceFilter implements Filter {

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain chain) throws IOException, ServletException {
        //String LEGACY_TRACE_ID_NAME = "X-B3-TraceId";
        HttpServletRequest request = ((HttpServletRequest) servletRequest);
        String traceId = request.getParameter(LogConstant.LEGACY_TRACE_ID_NAME);

        // 如果为空，则表示第一次访问，即上游服务端的请求
        if (StringUtils.isEmpty(traceId)) {
            //使用工具类生成uuid
            MDC.put(LogConstant.LEGACY_TRACE_ID_NAME, TraceIdUtil.traceId());
        } else {
            MDC.put(LogConstant.LEGACY_TRACE_ID_NAME, traceId);
        }
        chain.doFilter(servletRequest, servletResponse);
        MDC.clear();
    }
}

三，在META-INF目录下添加spring.factories文件，添加我们创建的processor类，在项目启动的时候通过spring boot自动扫描，通过spring调用postProcessEnvironment发放初始化配置

# Environment Post Processor
org.springframework.boot.env.EnvironmentPostProcessor=\
com.example.log.trace.processor.TraceEnvironmentPostProcessor

四，使用简单的controller测试日志

@Slf4j
@RestController
public class TraceLogController {

    @GetMapping(value = "/trace")
    public Object trace() {
        log.info("---------trace log 1--------");
        log.info("---------trace log 2--------");
        log.info("---------trace log 3--------");
        log.info("---------trace log 4--------");
        return Boolean.TRUE;
    }
}

发现打印的日志已经有我们添加的唯一的 traceId,并且多次打印的都是同一个traceId，这样我们在elk中想要查询一次调用的全链路调用日志就很方便了，只要通过traceId查询就很容易查询全链路的日志

2020-08-29 16:48:37.412 INFO [36d47a716d6d4891a264f050ff710d38] 20856 --- [nio-8080-exec-3] c.e.l.t.controller.TraceLogController    : ---------trace log 1--------
2020-08-29 16:52:11.284 INFO [36d47a716d6d4891a264f050ff710d38] 20856 --- [nio-8080-exec-3] c.e.l.t.controller.TraceLogController    : ---------trace log 2--------
2020-08-29 16:53:38.189 INFO [36d47a716d6d4891a264f050ff710d38] 20856 --- [nio-8080-exec-3] c.e.l.t.controller.TraceLogController    : ---------trace log 3--------
2020-08-29 17:23:37.527 INFO [36d47a716d6d4891a264f050ff710d38] 20856 --- [nio-8080-exec-3] c.e.l.t.controller.TraceLogController    : ---------trace log 4--------

原理分析

猜想

实现原理肯定是log-back(spring boot默认日志框架)通过拼接的方式打印日志，我们在全局添加了对应的key-value的匹配原则，在通过log打印日志的时候使用mdc通过key替换我们在添加的uuid,因此很简单的实现了全链路日志

源码分析

通过debug跟踪log链路，其调用链路还是很长的（如下图），我们只需要关心关键的逻辑就可以了，
其中打印日志拼接是通过ch.qos.logback.core.pattern.PatternLayoutBase#writeLoopOnConverters 进行处理的。

writeLoopOnConverters通过遍历调用converter的write方法拼接所需要打印的日志，如下流程：

DateConverter       -----时间---- 2020-08-29 17:45:22.318
LiteralConverter    -----空格---- 2020-08-29 17:45:22.318 有空格
CompositeConverter ----自定义---- 2020-08-29 17:45:22.318 INFO [1a3801d149bb4b5e99698ab53481e263]
......剩下的还有线程号,执行类等我们只关心自定义的规则处理.....

再看看CompositeConverter具体处理逻辑，发现其中还存在一层遍历处理如下图，
拼接了我们自定义的[traceId]的日志，其中核心的处理类就是MDCConverter的处理，替换我们定义的key

MDCConverter核心处理方法如下，通过key：X-B3-TraceId从 mdcPropertyMap中获取traceId，自此证实了我们的猜想，通过key拿到value进行日志拼接，全链路日志原理简单分析到此为止！

@Override
public String convert(ILoggingEvent event) {
    //X-B3-TraceId -> 1a3801d149bb4b5e99698ab53481e263
    Map<String, String> mdcPropertyMap = event.getMDCPropertyMap();

    if (mdcPropertyMap == null) {
        return defaultValue;
    }

    if (key == null) {
        return outputMDCForAllKeys(mdcPropertyMap);
    } else {
        //X-B3-TraceId
        String value = mdcPropertyMap.get(key);
        if (value != null) {
            return value;
        } else {
            return defaultValue;
        }
    }
}