Spring Boot WebClient中Micrometer追踪日志缺失问题排查
问题描述
在Spring Boot 3.2.2项目中使用Micrometer Tracing实现日志追踪,大部分日志已正常携带追踪信息,但WebClient的过滤器日志丢失了traceId和spanId。
使用依赖
implementation("io.micrometer:micrometer-tracing") implementation("io.micrometer:context-propagation") implementation("io.micrometer:micrometer-tracing-bridge-brave")
application.yml配置
tracing: baggage: correlation: fields: - caller - caller_version - user_agent - resource - request_id enabled: true enabled: true sampling: probability: 1.0 propagation: type: b3_multi
相关代码
VehicleApi类
@Component class VehicleApi( webClientConfig: WebClientConfig, private val observationRegistry: ObservationRegistry ) { private val logger = KotlinLogging.logger { } private val client = webClientConfig .defaultWebclient() .baseUrl("https://vehicle.foobar.com/api/v1/") .build() suspend fun getJourneyNumber(materialPartNumber: String): Int { logger.info("start") return withContext(Dispatchers.IO + observationRegistry.asContextElement()) { logger.info("beforeClient") client .method(HttpMethod.GET) .uri("/journey/$materialPartNumber") .retrieve() .awaitBody<Int>() } } }
TracerConfig类
@Configuration class TracerConfig(private val observationRegistry: ObservationRegistry, private val tracer: Tracer) { @Bean fun coroutineWebFilter() = object : CoWebFilter() { override suspend fun filter(exchange: ServerWebExchange, chain: CoWebFilterChain) { withContext(observationRegistry.asContextElement()) { addMDCContext(tracer, exchange.request) chain.filter(exchange) } } } @PostConstruct fun postConstruct() { Hooks.enableAutomaticContextPropagation() ContextRegistry.getInstance().registerThreadLocalAccessor(ObservationAwareSpanThreadLocalAccessor(tracer)) ObservationThreadLocalAccessor.getInstance().observationRegistry = observationRegistry } }
WebClientConfig类
@Configuration class WebClientConfig( environment: Environment ) { private val applicationName = environment.getProperty("spring.application.name") fun defaultWebclient( memorySizeInBytes: DataSize = defaultMaxMemorySize, mediaType: MediaType = MediaType.APPLICATION_JSON ) = WebClient.builder() .defaultHeader(CALLER_ID_HEADER, applicationName) .withFilters() .withExchangeStrategies(memorySizeInBytes, mediaType) private fun WebClient.Builder.withFilters() = this.filter(responseTimeLogging) private fun WebClient.Builder.withExchangeStrategies( memorySizeInBytes: DataSize, mediaType: MediaType, objectMapper: ObjectMapper = WebfluxConfig.objectMapper ) = exchangeStrategies( ExchangeStrategies .builder() .codecs { clientDefaultCodecsConfigurer -> clientDefaultCodecsConfigurer.defaultCodecs().also { it.maxInMemorySize(memorySizeInBytes.toBytes().toInt()) } .jackson2JsonEncoder( Jackson2JsonEncoder( objectMapper, mediaType ) ) clientDefaultCodecsConfigurer.defaultCodecs().also { it.maxInMemorySize(memorySizeInBytes.toBytes().toInt()) } .jackson2JsonDecoder( Jackson2JsonDecoder( objectMapper, mediaType ) ) }.build() ) companion object { const val CALLER_ID_HEADER = "x-caller-id" val defaultMaxMemorySize: DataSize = DataSize.ofMegabytes(2) } }
WebClient过滤器
private val logger = KotlinLogging.logger { } val responseTimeLogging: ExchangeFilterFunction = ExchangeFilterFunction { request, next: ExchangeFunction -> val startTime = ZonedDateTime.now() next.exchange(request) .doOnNext { response -> val endTime = ZonedDateTime.now() logger.info( "webclient_duration" to "${Duration.between(startTime, endTime).toMillis()}", "webclient_resource" to "${request.method().name()} ${request.url()}", "webclient_status_code" to response.statusCode().value().toString() ) { "Finish backend request to ${request.method().name()} ${request.url()}" } } }
日志现象
Finish backend request to ${request.method().name()} ${request.url()}这条日志丢失了traceId和spanId,而start和beforeClient日志正常携带:
13:37:20.678 INFO [VehicleApi] - start traceId=65ce05801941e94ac1a24b11c48b7108, spanId=6962957b4fac2f48, caller=[not set], resource=POST http://localhost:8082/api/v1/vehicles/detect, caller_version=[not set], request_id=c86881c1-63bc-434d-9188-ca9c5f57c680, user_agent=insomnia/2023.5.8 13:37:20.679 INFO [VehicleApi] - beforeClient traceId=65ce05801941e94ac1a24b11c48b7108, spanId=6962957b4fac2f48, caller=[not set], resource=POST http://localhost:8082/api/v1/vehicles/detect, caller_version=[not set], request_id=c86881c1-63bc-434d-9188-ca9c5f57c680, user_agent=insomnia/2023.5.8 13:37:20.791 INFO [VehicleApi] - Finish backend request to GET https://vehicle.foobar.com/api/v1/journey/4012 webclient_resource=GET https://vehicle.foobar.com/api/v1/journey/4012, webclient_duration=110, webclient_status_code=404
另外发现startTime时traceId和spanId存在,doOnNext中被移除,之后又恢复。
解决方案
问题出在WebClient过滤器的doOnNext操作上:WebClient的Reactor链在执行到doOnNext时,上下文已经脱离了原来的观测(Observation)上下文,导致追踪信息没有被正确传播到这个回调中。
修复步骤:
添加
contextCapture()保留上下文
在next.exchange(request)之后添加contextCapture(),确保Reactor操作链能捕获并保留当前的观测上下文:val responseTimeLogging: ExchangeFilterFunction = ExchangeFilterFunction { request, next: ExchangeFunction -> val startTime = ZonedDateTime.now() next.exchange(request) .contextCapture() // 关键:捕获当前上下文 .doOnNext { response -> val endTime = ZonedDateTime.now() logger.info( "webclient_duration" to "${Duration.between(startTime, endTime).toMillis()}", "webclient_resource" to "${request.method().name()} ${request.url()}", "webclient_status_code" to response.statusCode().value().toString() ) { "Finish backend request to ${request.method().name()} ${request.url()}" } } }验证WebClient自动观测配置
Spring Boot 3.x中WebClient默认会通过ObservationWebClientCustomizer自动添加观测支持,若手动构建WebClient,需确认未禁用该自动配置,确保自动配置的观测过滤器被保留。确认上下文传播配置有效性
你的TracerConfig已启用自动上下文传播,可检查ObservationAwareSpanThreadLocalAccessor是否正确注册,保证协程与Reactor之间的上下文互通。
原理说明
Reactor操作符默认不会自动捕获上游上下文,contextCapture()会将当前包含Micrometer观测信息的Reactor上下文绑定到后续操作符中,让doOnNext执行时能访问到原有的traceId和spanId,从而在MDC中正确输出。
内容的提问来源于stack exchange,提问作者MrAndre

