微服务治理之链路染色设计与实践

1. 背景

在微服务架构中，一个请求可能会经过若干个服务节点，其所经过的路径，我们称之为请求链路/调用链路。通常，我们会把一些服务治理相关的字段(例如traceId)，通过请求头的方式在整个链路中透传。

当我们把有特定含义的请求头透传到整个链路，然后链路中每个服务会针对这个请求头做一些特殊的处理，我们把这种行为称之为链路染色，这个带有特定含义的请求头我们称之为染色字段。

链路染色的作用域是针对单个请求的链路，不带染色字段的请求不受影响。通过链路染色的机制把服务治理的粒度细化到请求级别。

在实际应用中，我们可以在发起端给请求加上染色字段，或者在网关中根据一定的规则条件，给满足条件的请求动态加上染色字段。

目前，三维家在链路染色上的业务实践有调用链跟踪系统、标签路由(支持服务多版本、灰度发布等治理功能)、压测流量识别以及链路日志等级动态调整等场景。

下面，我们以链路日志等级动态调整的实践来介绍具体的链路染色机制。

2. 需求

日常线上问题排查中，往往需要服务输出更加详细的日志信息，这时候我们希望服务在处理特定请求的时候，把日志等级调低。尤其是在生产环境上，当我们知道了故障重现的条件的时候，我们希望只针对特定的请求输出更多的日志信息，而其它正常请求不受影响。

3. 设计思路

我们可以设置一个染色字段Log-Level，其值为想要调整的目标日志等级(例如DEBUG)，那么这个请求头将会透传至整条链路，从而整条链路的日志等级均设置为DEBUG，如下图所示。

毫无疑问，这个根据染色字段来动态调整日志等级的染色逻辑在各个服务中是通用的，需要实现在基础框架MagicCube中(我们的服务化框架MagicCube是基于SpringCloud深度定制的，后续将会有一系列介绍MagicCube的文章，敬请期待)。

目前最流行的日志框架有logback以及log4j2，两者都出自同一个大师Ceki Gülcü手笔，log4j2性能上更佳，大有取代前者的气势。

3.1 基于`logback`的日志染色方案

基于logback的日志等级调整，网上有很多方案，珠玉在前，这里就不多描述了。例如开源项目dapeng-soa(https://github.com/dapeng-soa/dapeng-soa)基于turboFilter的实现LogFilter:

//从请求头中获取目标日志等级
String logLevel = soaHeader.getCookie(SoaSystemEnvProperties.THREAD_LEVEL_KEY);

if (logLevel != null) {
    //设置目标日志等级至MDC中
    MDC.put(SoaSystemEnvProperties.THREAD_LEVEL_KEY, logLevel);
    
}

另外，还需要在日志配置文件中加上turboFilter:

<turboFilter class="ch.qos.logback.classic.turbo.MDCFilter">
   <MDCKey>thread-log-level</MDCKey>
   <Value>TRACE</Value>
   <OnMatch>ACCEPT</OnMatch>
</turboFilter>

3.2 基于`Log4j2`的日志染色方案

由于我们框架的日志组件是Log4j2，而网上找了一轮也没找到类似的方案。既然没法做伸手党，那就自己动手吧(为技术圈、社区生态添砖加瓦，这个也是本文的初衷之一)。

SpringBoot其实已经提供了针对Logger对象的等级动态调整(通过springboot actuator), 但这个等级调整是针对所有请求的，不符合我们的要求(等级调整仅针对特定请求)

我们研究下Log4j2的核心类图(更多细节，请参考Log4j2官方文档)：

从架构图可以看到，Configuration，Appender，LoggerConfig中都可以配置Filter，其中Configuration中的Filter是全局生效；Appender中的Filter一般是区分不同等级的日志写入不同的文件。

因此，如果我们能配置一个Configuration级别的过滤器，拦截所有的输入进行过滤则能方便的实现该需求。DynamicThresholdFilter正是这样一个过滤器，(官方文档上的介绍), 它允许根据特定属性按日志级别进行筛选。

例如，如果用户的loginId被捕获在ThreadContext映射中，那么可以只为该用户启用DEBUG日志记录。如果日志事件不包含指定的ThreadContext项，则将返回中性项:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn" name="MyApp" packages="">
  <DynamicThresholdFilter key="loginId" defaultThreshold="ERROR"
                          onMatch="ACCEPT" onMismatch="NEUTRAL">
    <KeyValuePair key="User1" value="DEBUG"/>
  </DynamicThresholdFilter>
  <Appenders>
    ...
  </Appenders>
  <Loggers>
    ...
  </Loggers>
</Configuration>

上面示例的含义：匹配ThreadContext(MDC)中是否含有key为loginid的值，如果有，再判断是否与User1相等，如果相等，则在判断是否能打印日志时，使用value中给定的日志等级进行判断。

关键判断逻辑源码如下:

boolean filter(final Level level, final Marker marker, final String msg) {
    final Filter filter = config.getFilter();
    //全局配置文件中存在过滤器，filter不为空，使用对应的filter进行过滤。
    //这里是DynamicThresholdFilter
    if (filter != null) {
        final Filter.Result r = filter.filter(logger, level, marker, msg);
        //如果返回NEUTRAL，则使用logger配置的等级进行判断（也就是走没有配置过滤器的逻辑）
        if (r != Filter.Result.NEUTRAL) {
            return r == Filter.Result.ACCEPT;
        }
    }
    //没有配置全局过滤器时走的逻辑。
    return level != null && intLevel >= level.intLevel();
}
 
private Result filter(final Level level, final ReadOnlyStringMap contextMap) {
    //DynamicThresholdFilter中，默认使用DefaultThreadContextMap，
    //DefaultThreadContextMap里面使用了ThreadLocal<Map<String, String>>进行存储
    final String value = contextMap.getValue(key);
    if (value != null) {
        Level ctxLevel = levelMap.get(value);
        if (ctxLevel == null) {
            ctxLevel = defaultThreshold;
        }
        //如果存在对应的key/value，则将当前事件等级(level)与
        //DynamicThresholdFilter中给出的level进行比较，
        //高则返回onMatch配置的值，低则返回onMisMatch配置的值。
        return level.isMoreSpecificThan(ctxLevel) ? onMatch : onMismatch;
    }
    return Result.NEUTRAL;
 
}

4. 实现

基于我们框架的选型，我们选择了Log4j2的方案。参考 3.2 小节的内容，其实现逻辑大概有如下3步:

4.1 配置`DynamicThresholdFilter`

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn" name="MyApp" packages="">
    <DynamicThresholdFilter key="Log-Level" defaultThreshold="ERROR"
                        onMatch="ACCEPT" onMismatch="DENY">
        <KeyValuePair key="DEBUG" value="DEBUG"/>
        <KeyValuePair key="INFO" value="INFO"/>
        <KeyValuePair key="WARN" value="WARN"/>
        <KeyValuePair key="ERROR" value="ERROR"/>
    </DynamicThresholdFilter>
  <Appenders>
    ...
  </Appenders>
  <Loggers>
    ...
  </Loggers>
</Configuration>

Log4j2会判断MDC中是否含有Log-Level的key，如果有，则将对应value与KeyValuePair中的key进行匹配，匹配上则使用value中的日志等级。

这里注意onMisMatch需要设置为DENY，含义为当前事件的日志等级与Filter中匹配上的日志等级进行匹配，判断是否需要输出。（例如当前事件的日志等级为INFO，请求头传入的Log-Level=ERROR，那么当前事件的日志不应该被输出。）

4.2 设置`MDC`值

请求进来时，MagicCube判断是否含有染色字段Log-Level的请求头，如果有，则设置至MDC中。

/**
 * Magiccube Logging 日志相关过滤器
 *
 * @author 钟俊滨
 * @since 2021-01-11 21:03
 */
public class MagiccubeLoggingFilter implements Filter {

    private final MagiccubeLoggingProperties loggingProperties;
    private final AntPathMatcher pathMatcher = new AntPathMatcher();

    public MagiccubeLoggingFilter(MagiccubeLoggingProperties loggingProperties) {
        this.loggingProperties = loggingProperties;
    }

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        if (!(request instanceof HttpServletRequest)) {
            chain.doFilter(request, response);
            return;
        }
        final HttpServletRequest req = (HttpServletRequest) request;
        try {
            // 处理链路染色请求
            String loggerLevel = req.getHeader(Constant.App.LOGGER_LEVEL);
            if (!StringUtils.isEmpty(loggerLevel)) {
                MDC.put(Constant.App.LOGGER_LEVEL, loggerLevel);
            }

            chain.doFilter(request, response);
        } finally {
            MDC.remove(Constant.App.LOGGER_LEVEL);
            ReqIpHolder.clear();
            ReqIdHolder.clear();
        }
    }
}