在Log4j2中实现只有在traceId有值时才输出

记录如何在Log4j2中使用traceId实现链路追踪时只有在请求header中有trace-id时才显示前端发送过来的trace-id值。

前置工作

假设使用的程序框架为Spring Boot并通过Maven管理依赖，需要预先添加如下代码配置：

pom.xml中排除Spring Boot自带的日志框架并添加log4j2依赖

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter</artifactId>
    <version>${spring.boot.version}</version>
    <exclusions>
        <exclusion>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-logging</artifactId>
        </exclusion>
    </exclusions>
</dependency>
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
    <version>${spring.boot.version}</version>
    <exclusions>
        <exclusion>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-logging</artifactId>
        </exclusion>
    </exclusions>
</dependency>
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-log4j2</artifactId>
    <version>${spring.boot.version}</version>
</dependency>

添加Filter用于从请求header中获取前端传递的trace-id并传入MDC中

@Order(0)
@Component
@WebFilter(filterName = "traceIdFilter", urlPatterns = "/*")
public class TraceIdFilter implements Filter {

    public static final String TRACE_ID = "TRACE_ID";
    public static final String TRACE_ID_HEADER = "trace-id";

    @Override
    public void init(FilterConfig filterConfig) throws ServletException {
    }

    @Override
    public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain) throws ServletException, IOException {
        HttpServletRequest request = (HttpServletRequest) req;
        String traceId = request.getHeader(TRACE_ID_HEADER);
        MDC.put(TRACE_ID, traceId);
        chain.doFilter(req, res);
    }

    @Override
    public void destroy() {
        MDC.clear();
    }

}

在主启动类中添加如下配置用于在线程间传递MDC值

@SpringBootApplication
public class TestApplication {

    // 用于在线程间传递mdc值
    static {
        System.setProperty("log4j2.isThreadContextMapInheritable", "true");
    }

    public static void main(String[] args) {
        SpringApplication.run(TestApplication.class, args);
    }
}

log4j2.xml配置如下

<Configuration status="warn">
    <Appenders>
        <!-- Console appender configuration -->
        <Console name="console" target="SYSTEM_OUT">
            <PatternLayout pattern="%yellow{[%d{yyyy-MM-dd HH:mm:ss.SSS}]} %clr{[%-5level]} %green{[TraceId-%X{TRACE_ID}]} %cyan{[%c]}- %msg%n" />
        </Console>
    </Appenders>
    <Loggers>
        <!-- Root logger referring to console appender -->
        <Root level="info" additivity="false">
            <AppenderRef ref="console" />
        </Root>
    </Loggers>
</Configuration>

其中的%green{[TraceId-%X{TRACE_ID}]}就是将获取到的trace-id在控制台中按照TraceId-xxx的格式以绿色打印出来，该段配置是我们进行链路最终的核心。

其中%X专门用于获取MDC中的值，在log4j2官网对应的说明如下

log4j2关于%X的用法说明

测试&问题

测试代码如下

@Slf4j
@RestController
@RequestMapping("user")
public class UserController {

    @Resource
    private UserService userService;

    @RequestMapping("queryAll")
    public List<UserModel> all() {
        List<UserModel> userList = userService.queryAllUsers();
        log.info("==========all user size: {}", userList.size());
        return userList;
    }

}

在Postman中发送类似如下请求，在header中将trace-id的值设置为123456

通过postman发送带header的请求

在控制台可发现类似如下输出，可发现前面几条系统启动时输出的日志也会按照trace-id格式进行输出，由于此时还没接收到前端发送的请求，故其值为空导致只显示一个TraceId-前缀，看起来不美观且影响使用。

traceId没有值时也会输出

解决方案

终极目标是实现在有trace-id时按照格式输出，没有时则正常输出，很明显要达成此效果需要判断trace-id是否为空。

最开始Google和Stackoverflow搜索的结果建议使用ScriptPatternSelector，在官网给出的使用示例如下，看起来有一丢丢复杂，在有多个Appenders时不适合扩展。

<PatternLayout>
  <ScriptPatternSelector defaultPattern="[%-5level] %c{1.} %C{1.}.%M.%L %msg%n">
    <Script name="BeanShellSelector" language="bsh"><![CDATA[
      if (logEvent.getLoggerName().equals("NoLocation")) {
        return "NoLocation";
      } else if (logEvent.getMarker() != null && logEvent.getMarker().isInstanceOf("FLOW")) {
        return "Flow";
      } else {
        return null;
      }]]>
    </Script>
    <PatternMatch key="NoLocation" pattern="[%-5level] %c{1.} %msg%n"/>
    <PatternMatch key="Flow" pattern="[%-5level] %c{1.} ====== %C{1.}.%M:%L %msg ======%n"/>
  </ScriptPatternSelector>
</PatternLayout>

上述方式需要设置两个Pattern且在不同的Appender中都需要动态配置，使用起来不是特别灵活。

有木有可能通过一个Pattern同时兼容这两种情况呢？

经过网络搜索和查看log4j2中关于Pattern Layout的说明之后，最终找到了解决方案，那就是%notEmpty!

官方文档中关于%notEmpty的说明如下

log4j2关于%notEmpty的用法说明

基于上述说明可尝试将%green{%notEmpty{[TraceId-%X{TRACE_ID}]}}修改为%green{%notEmpty{[TraceId-%X{TRACE_ID}]}}，最终完整的PatternLayout如下

<PatternLayout pattern="%yellow{[%d{yyyy-MM-dd HH:mm:ss.SSS}]} %clr{[%-5level]} %green{%notEmpty{[TraceId-%X{TRACE_ID}]}} %cyan{[%c]}- %msg%n" />

重新调用Postman的输出结果如下，完美实现功能！

traceId只有在有值时才输出

服务间调用

在微服务中通常会有多个模块协同工作，各个模块之间也可能会互相调用，在此种情况下也需要将trace-id准确的传递与获取，确保单次请求调用链路中的trace-id都一样才能体现链路追踪的意义。

Feign调用

当使用Feign作为远程调用实现时，需在被调用方中添加如下配置代码才能确保trace-id被正常传递与获取。

import com.hirain.orienlink.mfs.filter.TraceIdFilter;
import feign.RequestInterceptor;
import feign.RequestTemplate;
import org.slf4j.MDC;
import org.springframework.context.annotation.Configuration;

@Configuration
public class FeignConfig implements RequestInterceptor {

    @Override
    public void apply(RequestTemplate requestTemplate) {
        String traceId = String.valueOf(MDC.get(TraceIdFilter.TRACE_ID));
        requestTemplate.header(TraceIdFilter.TRACE_ID_HEADER, traceId);
    }
}

文章目录

前置工作

测试&问题

解决方案

服务间调用

Feign调用