0

I wanted to create a context-based logger in a reactive Spring environment using Kotlin coroutines.

Using configuration: https://github.com/archie-swif/webflux-mdc/tree/master/src/main/java/com/example/webfluxmdc

I have created a GitHub "playground-code": https://github.com/Numichi/reactive-kotlin-coroutines-mdc README.md is contain responses of controller.

Run timeline /work/X and /notwork/X:

/(not)work/20 [--------------------]
/(not)work/10 [ ----------         ]
/(not)work/1  [  -                 ]

We can see there is a moment when all requests runs same time.

So, for "work", everything works fine, but I don't understand why I didn't get like the result for "work". The data slips. I'm sure the delay is the cause, but I don’t see the reasons and why. Can you help explain why? And how can this be fixed?

Expected operation: Should get back same data in { data: X, ... } where ?data=X

@Component
class Filter : WebFilter {
    override fun filter(exchange: ServerWebExchange, chain: WebFilterChain): Mono<Void> {
        return chain.filter(exchange)
            .contextWrite {
                it.putNonNull("data", exchange.request.queryParams["data"]?.get(0))
            }
    }
}

@RestController
class MdcController {

    @GetMapping("work/{delay}")
    suspend fun work(@PathVariable delay: Int): Map<String, String> {
        MDC.put("threadName", Thread.currentThread().name)

        return withContext(MDCContext()) {
            delay((delay * 1000).toLong()) // <-- IN the withContext

            MDC.put("threadName-in-context", Thread.currentThread().name)
            MDC.getCopyOfContextMap()
        }
    }

    @GetMapping("notwork/{delay}")
    suspend fun notwork(@PathVariable delay: Int): Map<String, String> {
        MDC.put("threadName", Thread.currentThread().name)

        delay((delay * 1000).toLong())  // <-- OUT the withContext

        return withContext(MDCContext()) {
            MDC.put("threadName-in-context", Thread.currentThread().name)
            MDC.getCopyOfContextMap()
        }
    }
}
Numichi
  • 926
  • 6
  • 14
  • 1
    You described everything expect what actually is wrong. What is your expected result and how does it differ from the real result? – broot Jan 15 '22 at 10:22
  • So, I still have limited understanding of the whole problem (limited experience with webflux), but I assume your case is like this: 1. Spring automatically adds query params to MDC (because I don't see you set it anywhere in the code). 2. In `work` you see query params in MDC, but you don't see them in `notwork`. If this is correct then it actually makes sense. `withContext(MDCContext())` handles moving MDC data while switching threads. In `notwork` we switch the thread before we get to `withContext()`, so we lose the data before it gets protected. – broot Jan 15 '22 at 11:06
  • Inserted into contextus by contextWrite, but there is a separate lifter configuration that transfers it to MDC. You can find it under the configuration folder. It is important (as lifter) because reactive can use more request in same thread. So MDC does not work with normal implementation with ThreadLocal (log4j2). – Numichi Jan 15 '22 at 11:15
  • 1
    So, what is the part that is not clear to you? The request switches between threads and then MDC data becomes messed up. `withContext(MDCContext())` protects you by moving MDC between threads when switching, but by putting `delay()` outside of `withContext()` you switches the thread before MDC is protected. As a result you get MDC data of another request. – broot Jan 15 '22 at 11:27
  • I understand withContext() is protect MDC, just I don't understand the reason why delay() intervenes so that the last request /1?data=1 (which ends soonest) won't return data key-value pair. It's like adding MDC to a previous request. And that’s why it slips into the other MDC environment. I'm in a kind of "where and why is the wormhole" search to find the cause so the solution is as well. Or just understand why. – Numichi Jan 15 '22 at 11:37
  • Do you even need to use MDC in this case? `Context` is a key/value store. You can directly access the `Context` and transform it into a `Map`. I think MDC may be redundant for this requirement. – Michael McFadyen Jan 16 '22 at 21:22

0 Answers0