Spring Cloud Sleuth 集成 Log4j2 无法在日志中输出 traceId 和 spanId

最近，出于项目（基于当前最新的 Spring Cloud 2020.0.3 ）需求，我需要集成 Spring Cloud 提供的链路追踪组件 Spring Cloud Sleuth。

我在 Maven pom.xml 文件中引入了相关依赖 spring-cloud-starter-sleuth，版本是目前最新的 3.0.3 。

<dependency>
	<groupId>org.springframework.cloud</groupId>
	<artifactId>spring-cloud-starter-sleuth</artifactId>
</dependency>

在项目中，我们使用的并不是 Spring Cloud 官方默认的日志工具 Logback，而是 Log4j2，对应的 Maven依赖配置如下：

<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>
</dependency>

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

但是，在集成 Log4j2 的前提下，却发现 Spring Cloud Sleuth 根本无法在控制台日志中输出对应的 traceId 和 spanId。

我们测试得到的日志输出如下：

2021-09-21 10:55:12.229  INFO [service-order,,] 13132 --- [           main] m.c.OrderApp                             : Starting OrderApp using Java 11.0.12 on Ready-PC with PID 13132 (D:\Java\springcloud-alibaba\order\target\classes started by pc in D:\Java\springcloud-alibaba)
2021-09-21 10:55:12.236  INFO [service-order,,] 13132 --- [           main] m.c.OrderApp                             : No active profile set, falling back to default profiles: default
2021-09-21 10:55:13.055  INFO [service-order,,] 13132 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2021-09-21 10:55:13.145  INFO [service-order,,] 13132 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 80 ms. Found 1 JPA repository interfaces.
2021-09-21 10:55:13.378  INFO [service-order,,] 13132 --- [           main] o.s.c.c.s.GenericScope                   : BeanFactory id=f4e60614-a733-3f35-9757-57fc447c37c2
2021-09-21 10:55:13.681  INFO [service-order,,] 13132 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'spring.cloud.sentinel-com.alibaba.cloud.sentinel.SentinelProperties' of type [com.alibaba.cloud.sentinel.SentinelProperties] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-09-21 10:55:13.686  INFO [service-order,,] 13132 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'com.alibaba.cloud.sentinel.custom.SentinelAutoConfiguration' of type [com.alibaba.cloud.sentinel.custom.SentinelAutoConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-09-21 10:55:13.944  INFO [service-order,,] 13132 --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomcat initialized with port(s): 82 (http)
2021-09-21 10:55:13.954  INFO [service-order,,] 13132 --- [           main] o.a.c.c.StandardService                  : Starting service [Tomcat]
2021-09-21 10:55:13.955  INFO [service-order,,] 13132 --- [           main] o.a.c.c.StandardEngine                   : Starting Servlet engine: [Apache Tomcat/9.0.52]
2021-09-21 10:55:14.101  INFO [service-order,,] 13132 --- [           main] o.a.c.c.C.[.[.[/]                        : Initializing Spring embedded WebApplicationContext
2021-09-21 10:55:14.102  INFO [service-order,,] 13132 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1829 ms
2021-09-21 10:55:14.481  INFO [service-order,,] 13132 --- [           main] c.z.h.HikariDataSource                   : HikariPool-1 - Starting...
2021-09-21 10:55:14.787  INFO [service-order,,] 13132 --- [           main] c.z.h.p.HikariPool                       : HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@38ba8b45
2021-09-21 10:55:14.790  INFO [service-order,,] 13132 --- [           main] c.z.h.HikariDataSource                   : HikariPool-1 - Start completed.
2021-09-21 10:55:14.838  INFO [service-order,,] 13132 --- [           main] o.h.j.i.u.LogHelper                      : HHH000204: Processing PersistenceUnitInfo [name: default]
2021-09-21 10:55:14.892  INFO [service-order,,] 13132 --- [           main] o.h.Version                              : HHH000412: Hibernate ORM core version 5.5.7.Final
2021-09-21 10:55:15.059  INFO [service-order,,] 13132 --- [           main] o.h.a.c.Version                          : HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
2021-09-21 10:55:15.179  INFO [service-order,,] 13132 --- [           main] o.h.d.Dialect                            : HHH000400: Using dialect: org.hibernate.dialect.MySQL8Dialect
2021-09-21 10:55:15.650  INFO [service-order,,] 13132 --- [           main] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2021-09-21 10:55:15.657  INFO [service-order,,] 13132 --- [           main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2021-09-21 10:55:15.994  WARN [service-order,,] 13132 --- [           main] JpaBaseConfiguration$JpaWebConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
2021-09-21 10:55:16.091  WARN [service-order,,] 13132 --- [           main] o.s.c.o.FeignClientFactoryBean           : The provided URL is empty. Will try picking an instance via load-balancing.
2021-09-21 10:55:16.393  INFO [service-order,,] 13132 --- [           main] c.a.c.s.SentinelWebAutoConfiguration     : [Sentinel Starter] register SentinelWebInterceptor with urlPatterns: [/**].
2021-09-21 10:55:16.958  WARN [service-order,,] 13132 --- [           main] iguration$LoadBalancerCaffeineWarnLogger : Spring Cloud LoadBalancer is currently working with the default cache. You can switch to using Caffeine cache, by adding it and org.springframework.cache.caffeine.CaffeineCacheManager to the classpath.
2021-09-21 10:55:17.367  INFO [service-order,,] 13132 --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomcat started on port(s): 82 (http) with context path ''
2021-09-21 10:55:17.392  INFO [service-order,,] 13132 --- [           main] c.a.c.n.r.NacosServiceRegistry           : nacos registry, DEFAULT_GROUP service-order 192.168.2.2:82 register finished
2021-09-21 10:55:17.501  INFO [service-order,,] 13132 --- [           main] m.c.OrderApp                             : Started OrderApp in 5.905 seconds (JVM running for 7.284)
2021-09-21 10:55:49.522  INFO [service-order,,] 13132 --- [p-nio-82-exec-1] o.a.c.c.C.[.[.[/]                        : Initializing Spring DispatcherServlet 'dispatcherServlet'
2021-09-21 10:55:49.523  INFO [service-order,,] 13132 --- [p-nio-82-exec-1] o.s.w.s.DispatcherServlet                : Initializing Servlet 'dispatcherServlet'
2021-09-21 10:55:49.525  INFO [service-order,,] 13132 --- [p-nio-82-exec-1] o.s.w.s.DispatcherServlet                : Completed initialization in 2 ms
INFO: Sentinel log output type is: file
INFO: Sentinel log charset is: utf-8
INFO: Sentinel log base directory is: C:\Users\Administrator\logs\csp\
INFO: Sentinel log name use pid is: false
2021-09-21 10:55:56.842  INFO [service-order,,] 13132 --- [p-nio-82-exec-2] m.c.a.OrderAction                        : 查询订单

请注意上述日志的最后一行，这是我们在链路中埋点的日志输出。

按照官方文档的描述，这里的输出内容应该存在形如 [serviceName,traceId,spanId]的内容的，例如：INFO [service-order,0b6aaf642574edd3,0b6aaf642574edd3] 。

但是，我们得到的 traceId 和 spanId 都是空的。

我们尝试将 Log4j2 替换成默认的 Logback，发现一切就恢复正常了。

我们也在网上搜索了一下相关的情况，发现其他人也有遇到类似的问题，但是并没有发现可行的解决方案。

而且，很多人使用的是 Spring Cloud Sleuth 2.x，与我们使用的最新的 3.x 有较大差异。

请问，Spring Cloud Sleuth 和 Log4j2 应该如何进行有效集成呢？

查了一下：在 spring-cloud-sleuth-autoconfigure 的 3.0.3 版本的源代码中，有一个名叫 org.springframework.cloud.sleuth.autoconfig.TraceEnvironmentPostProcessor 的类（注意，该类并不是 public 的），其中存在如下关键代码：

@Override
public void postProcessEnvironment(ConfigurableEnvironment environment, SpringApplication application) {
	Map<String, Object> map = new HashMap<String, Object>();
	// This doesn't work with all logging systems but it's a useful default so you see
	// traces in logs without having to configure it.
	if (Boolean.parseBoolean(environment.getProperty("spring.sleuth.enabled", "true"))) {
		map.put("logging.pattern.level",
				"%5p [${spring.zipkin.service.name:" + "${spring.application.name:}},%X{traceId:-},%X{spanId:-}]");
	}
	addOrReplace(environment.getPropertySources(), map);
}

上述的作用是，当 Spring Cloud Sleuth 依赖被添加到项目后，在项目启动时，会自动向 Spring Environment 中添加如下的参数配置项：

logging.pattern.level='%5p [${spring.zipkin.service.name:${spring.application.name:}},%X{traceId:-},%X{spanId:-}]'

这个配置参数只有在集成 Logback 时才能被正确解析，因为 Log4j2 的配置语法与 Logback 有所不同，而 Sleuth 官方并没有在代码中对 Log4j2 加以区分并兼容，因此在 Sleuth 集成 Log4j2 的情况下，自然也就无法正确输出traceId和spanId等参数。

因此，在使用spring-boot-starter-log4j2默认配置的情况下，我们需要在application.properties（或 yaml ）中添加如下自定义配置，来让 Sleuth 支持 Log4j2 的配置语法：

# 这里必须显示地设为"on"，不能是"true"，否则此处的 logging.pattern.level 设置会被 Sleuth 中的上述代码覆盖掉
spring.sleuth.enabled=on
# 适用于 Log4j2 的 logging.pattern.level 设置
logging.pattern.level='%5p [${spring.zipkin.service.name:${spring.application.name:}},%X{traceId},%X{spanId}]'

1 个回答

撰写答案