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

背景

最近在排查问题查问日志的的时候，有个很困扰的问题就是多线程调用的状况下，没方法查问一次调用的全链路调用日志，比方在应用 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;}
    }
}