spring-bootkotlinspring-micrometermicrometer-tracing

Micrometer tracing logs missing with spring boot webclient


I am trying to get the logging working with the micrometer tracing library. I get the logging now almost correct through all my project except for a filter in the spring boot webclient. I use the following dependencies with spring boot version 3.2.2:

implementation("io.micrometer:micrometer-tracing")
implementation("io.micrometer:context-propagation")
implementation("io.micrometer:micrometer-tracing-bridge-brave")

Along with this config inside my 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

And the following classes:

@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>()
        }
    }
}

@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
    }
}

@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)
    }
}

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()}" }
        }
}

My problem is that the Finish backend request to ${request.method().name()} ${request.url()} does not have the trace and spanId inside the mdcContext like you can see here:

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

But it is filled for the start and beforeClient logging. Was wondering if someone could maybe explain what I am missing or doing wrong.

Edit: Also just checked and the trace and spanId also also filled by the startTime so in the doOnNext it is being removed. Also after this doOnNext in the rest of the code the trace and spanId are present again.


Solution

  • Found out that you needed to add to:

    WebClient.builder()
                .defaultHeader(CALLER_ID_HEADER, applicationName)
                .withFilters()
                .withExchangeStrategies(memorySizeInBytes, mediaType)
    

    The .observationRegistry(observationRegistry) which solved the issue for me and gives me correctly on doOnNext the trace and spanId