Spring Improve the documentation and discoverability of CoWebFilter

Affects: spring-boot 3.2.0

I want to implement trace id logging for my service. But MDC context is lost in controller according to logs.

There is a filter

@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
class TraceIdFilter : WebFilter {

    companion object {
        val logger: Logger = LoggerFactory.getLogger(this::class.java)
    }

    override fun filter(exchange: ServerWebExchange, chain: WebFilterChain): Mono<Void> {
        val tid = Random.nextInt(10_000)
        logger.info("TraceIdFilter started. tid $tid generated")
        MDC.put("traceId", "tid-$tid")

        logger.info("before TraceIdFilter")
        return chain.filter(exchange)
            .doFinally {
                MDC.clear()
            }
    }
}

Logs:

INFO 28207 --- [ctor-http-nio-2] c.e.mdcpoc.TraceIdFilter$Companion       [] : TraceIdFilter started. tid 9019 generated
INFO 28207 --- [ctor-http-nio-2] c.e.mdcpoc.TraceIdFilter$Companion       [tid-9019] : before TraceIdFilter
INFO 28207 --- [         task-1] c.e.mdcpoc.TestController$Companion      [] : controller method

PoC is attached. mdc-poc issue.zip Start it and execute curl --location 'http://127.0.0.1:8080/test4'

I would expect to see traceId in TestController logs. (it works for spring-boot before 3.2.0)
I additionally noticed that MDC context isn't cleared after the first request and I can see the next log message with the previous traceId c.e.mdcpoc.TraceIdFilter$Companion [tid-9019] : TraceIdFilter started. tid 2494 generated

Comment From: IevgenBizz

Related threads https://github.com/spring-projects/spring-framework/issues/26977 https://github.com/spring-projects/spring-framework/issues/27522

Comment From: sdeleuze

@IevgenBizz Thanks for the repro, could you confirm that CoTraceIdFilter (based on CoWebFilter) works as expected?

I could totally miss something since I am not an expert of the domain, but when using kotlinx-coroutines-slf4j, since Spring Boot 3.2 now supports CoroutineContext propagation, that kind of makes sense to me to use CoWebFilter for that use case instead of a Reactive non Coroutines-aware WebFilter. Could you elaborate on why you would want to use TraceIdFilter instead of CoTraceIdFilter?

Comment From: IevgenBizz

Hi @sdeleuze

I don't have issues when using CoTraceIdFilter (based on CoWebFilter). But I think if WebFilter isn't deprecated, it's allowed to use this class. I spent much time understanding how to work with MDC in Kotlin coroutines and spring reactive env. Our Gradle libraries are outdated, but the flow is working only on the latest version (except 3.2.0 for instance. it isn't obvious) In my opinion, it should be clear from documentation that it's recommended to use CoWebFilter together with kotlinx-coroutines-slf4j (I mean this page https://kotlinlang.org/api/kotlinx.coroutines/kotlinx-coroutines-slf4j/kotlinx.coroutines.slf4j/-m-d-c-context/ ) When we migrate from 2.7.x to 3.2.0 and don't have any compilation errors, then it's easy to break mdc context logging.
I think MDC logging will work with CoWebFilter only if we have @Order(Ordered.HIGHEST_PRECEDENCE) (At least I saw this recommendation before). It would be much better if we could have multiple CoWebFilter (to set different values to MDC context) or move CoWebFilter before spring authentication (to see logs from other filters). Should it be possible so far?
CoWebFilter has the same issue with MDC context from the previous request, that I mentioned in my first message c.e.mdcpoc.TraceIdFilter$Companion [tid-9019] : TraceIdFilter started. tid 2494 generated

Comment From: sdeleuze

WebFilter is designed to be used with Reactive APIs (as documented in org.springframework.web.server package documentation). The fact it was working with kotlinx-coroutines-slf4j was not expected, hence the fact a migration path is not documented.
Based on my tests, CoWebFilter works without @Order(Ordered.HIGHEST_PRECEDENCE). What may happen with Spring Boot 3.2.0 is that coroutine context could be overriden, but as of 3.2.1 with #31792 you should be fine.
Could be caused by a missing MDC.clear() invocation at the end of CoTraceIdFilter#filter after the withContext block.

In order to help with the first documentation point, I suggest to turn this issue into a documentation one, add a mention of CoWebFilter for Coroutines use cases in WebFilter Javadoc and mention CoWebFilter in the Kotlin documentation.

Comment From: IevgenBizz

@sdeleuze I'm ok to turn this issue into a documentation one.

It doesn't work (see screenshot). It could be required to clear MDC context for multiple threads. It's possible to clear the context at the first line of CoTraceIdFilter#filter, but then we clear context trash not immediately after request handling

Comment From: sdeleuze

Ok, thanks for your feedback. Kind of related, you can also follow our progresses on https://github.com/spring-projects/spring-framework/issues/31893 and https://github.com/micrometer-metrics/tracing/issues/174 for potential non-documentation refinements at Spring or Micrometer level.

For 3. - I can't reproduce (I am using Spring Boot 3.2.1, not sure if that's related), I always see lines like [] : CoTraceIdFilter started. tid 2964 generated - You should maybe put MDC.put("traceId", "tid-$tid") before logger.info("CoTraceIdFilter started. tid $tid generated") toi avoid this kind of issue

Comment From: IevgenBizz

For 3.

The issue is reproducible on 3.2.1 version too. See my attachment. This issue will be reproduced from the second request and later. So you need to execute at least two request to the service. The first request will set MDC context that won't be cleared and you will see this trash on the next request. It's a permanent issue on my PC.

mdc-poc issue.zip

This problem is related to dirty MDC context, logging just shows the issue, so moving logging to another line won't resolve the issue

thanks for your help in this thread.