withLoggingContext doesn't work well when called inside coroutines

[casret]

Spent some time tracking down this logging bug involving withLoggingContext and coroutines and wanted to make sure no one else tripped over it.

I had some code written as such:

withLoggingContext("foo" to "bar") {
            withContext(MDCContext()) { suspending_function() }
}

The problem is that you may be in a different thread when you leave suspending_function as when you entered it, so the MDC.remove call won't have an effect. The wiki example code uses launch, so doesn't have this problem.

My workaround was:

val mdc = MDC.getCopyOfContextMap()?.apply { put("foo", "bar") } ?: mapOf("foo" to "bar")
withContext<T>(MDCContext(mdc)) { suspending_function() }

But I rather have something as nice as withLoggingContext. I'd be happy to submit a patch, but I wanted some direction on the API. Do we use a different function entirely, or should withLoggingContext take a flag where that flags the block as suspending? You could argue that this belongs in the slf4j integration directly and I should ping those guys.

[oshai]

I think this is a bug of MDCContext and kotlinx-coroutines. Can you please submit it there? Or do you want me to do that? here is the repo https://github.com/Kotlin/kotlinx.coroutines/blob/master/integration/kotlinx-coroutines-slf4j

[casret]

I'm not really sure it's an upstream bug. I don't think they can do anything to influence that you are in a different thread before and after the withContext. We can either 'fix it there' by making some secondary constructors as fluent as withLoggingContext, or make withLoggingContext thread agnostic by making function local copies of the MDC (like in my example), but that approach is fundamentally incompatible with setting it on the thread level.

[oshai]

I do think it's an issue with upstream. withContext<T>(MDCContext(mdc)) means the context should be applied on all threads, in and out. At least that is how I understand it.

[casret]

Sorry if I'm being unclear, the code block inside withContext runs correctly. The problem is that the values set by withLoggingContext don't get unset correctly. E.g. Thread A calls withLoggingContext and sets the foo key to bar. Inside withContext everything is great and foo returns bar no matter what thread it's running in. When withContext completes and hands control back to withLoggingContext it happens to be on thread B. Now withLoggingContext unsets foo, but on thread B. Thread A still has the bar value for foo when withLoggingContext exits, and will continue to log the wrong value until it happens to hit the same code again.

[oshai]

I think I understand now. Probably another method is a good idea. PR is welcome.

[oshai]

Closing it for now. PR is welcome.

[ntfc]

I couldn't reproduce this based on @casret instructions, do you know if this issue is still applicable?

Here is the snippet I'm using to try and reproduce it which gives me the correct output:

@GetMapping("/{userId}")
suspend fun test(
    @PathVariable userId: String
) {
    withLoggingContext("userId" to userId) { // loggingContext must be callable before MDCContext
        withContext(MDCContext()) {
            log.info { "Start something for userId $userId" }
            delay(Random.nextLong(1_000, 5_000))
            log.info { "Finished for userId $userId" }
        }
    }

    log.info { "Which userId am I? $userId" }
}

With the following JSON formatted output:

{
  "@timestamp": "2021-05-07T16:57:33.484+02:00",
  "@version": "1",
  "message": "Start something for userId 42",
  "logger_name": "me.ntfc.TestApiResource",
  "thread_name": "http-nio-8090-exec-2",
  "level": "INFO",
  "level_value": 20000,
  "userId": "42"
}
{
  "@timestamp": "2021-05-07T16:57:38.139+02:00",
  "@version": "1",
  "message": "Finished for userId 42",
  "logger_name": "me.ntfc.TestApiResource",
  "thread_name": "kotlinx.coroutines.DefaultExecutor",
  "level": "INFO",
  "level_value": 20000,
  "userId": "42"
}
{
  "@timestamp": "2021-05-07T16:57:38.142+02:00",
  "@version": "1",
  "message": "Which userId am I? 42",
  "logger_name": "me.ntfc.TestApiResource",
  "thread_name": "kotlinx.coroutines.DefaultExecutor",
  "level": "INFO",
  "level_value": 20000
}

[maniax89]

I've reproduced this test case in #597 and am interested in contributing a new method to capture the desired behavior within suspended coroutine contexts