您的浏览器过于古老 & 陈旧。为了更好的访问体验, 请 升级你的浏览器
Coder 发布于2021年09月21日 11:48 最近更新于 2021年09月22日 12:20

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

447 次浏览 读完需要≈ 20 分钟 Spring BootLog4j 2

最近,出于项目(基于当前最新的 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 根本无法在控制台日志中输出对应的 traceIdspanId

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

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]

但是,我们得到的 traceIdspanId 都是空的。

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

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

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

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

1 个回答

Ready · 2个月前

查了一下:在 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 的情况下,自然也就无法正确输出traceIdspanId等参数。

因此,在使用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}]'
已采纳 ? 0 0 0 编辑

撰写答案