withLoggingContext doesn't work well when called inside coroutines about kotlin-logging HOT 7 CLOSED

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

from kotlin-logging.

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.

from kotlin-logging.

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.

from kotlin-logging.

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.

from kotlin-logging.

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

from kotlin-logging.

Closing it for now. PR is welcome.

from kotlin-logging.

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
}

from kotlin-logging.