Fix coroutine logging by maniax89 · Pull Request #597 · oshai/kotlin-logging

maniax89 · 2026-03-03T06:13:00Z

fixes #75

Copilot

Pull request overview

Adds a coroutine-context-based MDC wrapper to avoid thread-local MDC leakage when using suspending code in coroutines (per kotlin-logging issue #75), along with tests and documentation describing the new behavior.

Changes:

Introduces withCoroutineLoggingContext(...) suspend wrappers that build MDC state from the parent coroutine MDCContext instead of the current thread-local MDC.
Adds coroutine tests demonstrating the leak in withLoggingContextAsync and the non-leaking behavior of withCoroutineLoggingContext.
Documents the new coroutine-safe wrapper and its non-inheritance of pre-existing thread-local MDC.

Reviewed changes

Copilot reviewed 3 out of 3 changed files in this pull request and generated 6 comments.

File	Description
`src/jvmMain/kotlin/io/github/oshai/kotlinlogging/coroutines/KotlinLoggingAsyncMDC.kt`	Adds `withCoroutineLoggingContext` overloads and implementation based on parent coroutine `MDCContext`.
`src/jvmTest/kotlin/io/github/oshai/kotlinlogging/coroutines/KotlinLoggingAsyncMDCTest.kt`	Adds tests for cross-coroutine MDC leakage and for the new coroutine-context wrapper.
`src/jvmTest/kotlin/io/github/oshai/kotlinlogging/coroutines/README.md`	Documents intended usage and behavior of the new coroutine-safe wrapper.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Copilot · 2026-03-04T13:37:21Z

+          requestADuringBlock.complete(MDC.getCopyOfContextMap())
+          requestBDone.await() // Suspend while B runs
+        }
+        // will be empty
+        requestAAfterBlock.complete(MDC.getCopyOfContextMap())
+      }
+
+    val jobB =
+      launch(dispatcher) {
+        requestAStarted.await()
+        withLoggingContextAsync("foo" to "bar") {
+          requestBDuringBlock.complete(MDC.getCopyOfContextMap())
+        }
+        // Capture MDC state immediately after Request B's block, will NOT be empty due to the bug
+        requestBAfterBlock.complete(MDC.getCopyOfContextMap())
+        requestBDone.complete(Unit)
+      }
+
+    jobA.join()
+    jobB.join()
+
+    assertEquals(mapOf("foo" to "original"), requestADuringBlock.await())
+    assertEquals(emptyMap(), requestAAfterBlock.await())
+    assertEquals(mapOf("foo" to "bar"), requestBDuringBlock.await())


MDC.getCopyOfContextMap() is nullable per the SLF4J API contract (it can return null when the MDC is empty). The test currently asserts emptyMap() in a few places, which can be brittle across MDC implementations; consider normalizing captures to MDC.getCopyOfContextMap() ?: emptyMap() and using non-null deferred types.

Copilot · 2026-03-04T13:37:21Z

+    assertEquals(mapOf("foo" to "original"), requestADuringBlock.await())
+    assertEquals(emptyMap(), requestAAfterBlock.await())
+    assertEquals(mapOf("foo" to "bar"), requestBDuringBlock.await())
+    // THIS IS THE BUG: Request B sees "original" after its own block exits
+    // It should be null (no context) but it's leaking Request A's value
+    assertEquals(mapOf("foo" to "original"), requestBAfterBlock.await())
+  }


This test asserts the leaking behavior of withLoggingContextAsync as the expected outcome. That locks the current bug in as “correct” and will fail once the underlying leak is fixed; consider either (a) asserting the correct behavior (no leak) and fixing withLoggingContextAsync, or (b) marking this test as @Disabled/documentation-only with a link to the issue so it doesn’t block future fixes.

Copilot · 2026-03-04T13:37:21Z

+  crossinline body: suspend () -> T,
+): T {
+  val parent = currentCoroutineContext()[MDCContext]?.contextMap ?: emptyMap()
+  val merged = (parent + map.filterValues { it != null }).mapValues { it.value!! }


withCoroutineLoggingContext(map, ...) currently drops null entries via filterValues { it != null }, which means callers cannot remove keys inherited from the parent coroutine MDC (e.g., passing "k" to null won’t clear an existing k). Since the API accepts String? values, it’s important to define and implement null semantics; if you want parity with withLoggingContext, apply entries so that null removes the key from the merged map rather than being ignored.

Suggested change

val merged = (parent + map.filterValues { it != null }).mapValues { it.value!! }

val merged = parent.toMutableMap().apply {

for ((key, value) in map) {

if (value == null) {

remove(key)

} else {

put(key, value)

}

}

}

Copilot · 2026-03-04T13:37:22Z

+If you prefer to leverage coroutine context instead of thread local storage, you can use the `withCoroutineLoggingContext` wrapper.
+This will NOT inherit the current MDC set prior, but will carry existing coroutine context within nested declarations, restoring previous context
+at the logical coroutine level rather than thread level.


The README says this wrapper uses coroutine context “instead of thread local storage”, but the implementation still relies on SLF4J MDC thread-locals (via kotlinx.coroutines.slf4j.MDCContext) and just propagates them safely through coroutine context. Rewording this to avoid implying MDC is no longer thread-local would make the docs technically accurate and less confusing.

Suggested change

If you prefer to leverage coroutine context instead of thread local storage, you can use the `withCoroutineLoggingContext` wrapper.

This will NOT inherit the current MDC set prior, but will carry existing coroutine context within nested declarations, restoring previous context

at the logical coroutine level rather than thread level.

If you prefer to leverage coroutine context to propagate MDC safely across suspensions, you can use the `withCoroutineLoggingContext` wrapper.

This will NOT inherit the current MDC set on the calling thread, but will carry the logging context established by outer `withCoroutineLoggingContext` calls within nested declarations,

restoring the previous MDC for the current coroutine when the block completes.

Copilot · 2026-03-04T13:37:22Z

+    val dispatcher = Executors.newFixedThreadPool(1).asCoroutineDispatcher()
+    // establish order of events with deferreds:
+    // 1. request A will start, set its context, and then wait for request B (before exiting
+    // withLoggingContextAsync)
+    // 2. request B will start, set its context, and then capture the MDC
+    val requestAStarted = CompletableDeferred<Unit>()
+    val requestBDone = CompletableDeferred<Unit>()
+
+    val requestADuringBlock = CompletableDeferred<Map<String, String>?>()
+    val requestAAfterBlock = CompletableDeferred<Map<String, String>?>()
+    val requestBDuringBlock = CompletableDeferred<Map<String, String>?>()
+    val requestBAfterBlock = CompletableDeferred<Map<String, String>?>()
+
+    val jobA =
+      launch(dispatcher) {
+        withCoroutineLoggingContext("foo" to "original") {
+          requestAStarted.complete(Unit)
+          requestADuringBlock.complete(MDC.getCopyOfContextMap())
+          requestBDone.await() // Suspend while B runs
+        }
+        // will be empty
+        requestAAfterBlock.complete(MDC.getCopyOfContextMap())
+      }
+
+    val jobB =
+      launch(dispatcher) {
+        requestAStarted.await()
+        withCoroutineLoggingContext("foo" to "bar") {
+          requestBDuringBlock.complete(MDC.getCopyOfContextMap())
+        }
+        // will also be empty
+        requestBAfterBlock.complete(MDC.getCopyOfContextMap())
+        requestBDone.complete(Unit)
+      }
+
+    jobA.join()
+    jobB.join()
+
+    assertEquals(mapOf("foo" to "original"), requestADuringBlock.await())
+    assertEquals(emptyMap(), requestAAfterBlock.await())
+    assertEquals(mapOf("foo" to "bar"), requestBDuringBlock.await())
+    assertEquals(emptyMap(), requestBAfterBlock.await())


This test also creates a fixed-thread-pool-backed dispatcher and doesn’t close it. Please close the ExecutorCoroutineDispatcher (e.g., use { ... } or finally { dispatcher.close() }) to avoid leaking threads between tests.

Suggested change

val dispatcher = Executors.newFixedThreadPool(1).asCoroutineDispatcher()

// establish order of events with deferreds:

// 1. request A will start, set its context, and then wait for request B (before exiting

// withLoggingContextAsync)

// 2. request B will start, set its context, and then capture the MDC

val requestAStarted = CompletableDeferred<Unit>()

val requestBDone = CompletableDeferred<Unit>()

val requestADuringBlock = CompletableDeferred<Map<String, String>?>()

val requestAAfterBlock = CompletableDeferred<Map<String, String>?>()

val requestBDuringBlock = CompletableDeferred<Map<String, String>?>()

val requestBAfterBlock = CompletableDeferred<Map<String, String>?>()

val jobA =

launch(dispatcher) {

withCoroutineLoggingContext("foo" to "original") {

requestAStarted.complete(Unit)

requestADuringBlock.complete(MDC.getCopyOfContextMap())

requestBDone.await() // Suspend while B runs

}

// will be empty

requestAAfterBlock.complete(MDC.getCopyOfContextMap())

}

val jobB =

launch(dispatcher) {

requestAStarted.await()

withCoroutineLoggingContext("foo" to "bar") {

requestBDuringBlock.complete(MDC.getCopyOfContextMap())

}

// will also be empty

requestBAfterBlock.complete(MDC.getCopyOfContextMap())

requestBDone.complete(Unit)

}

jobA.join()

jobB.join()

assertEquals(mapOf("foo" to "original"), requestADuringBlock.await())

assertEquals(emptyMap(), requestAAfterBlock.await())

assertEquals(mapOf("foo" to "bar"), requestBDuringBlock.await())

assertEquals(emptyMap(), requestBAfterBlock.await())

Executors.newFixedThreadPool(1).asCoroutineDispatcher().use { dispatcher ->

// establish order of events with deferreds:

// 1. request A will start, set its context, and then wait for request B (before exiting

// withLoggingContextAsync)

// 2. request B will start, set its context, and then capture the MDC

val requestAStarted = CompletableDeferred<Unit>()

val requestBDone = CompletableDeferred<Unit>()

val requestADuringBlock = CompletableDeferred<Map<String, String>?>()

val requestAAfterBlock = CompletableDeferred<Map<String, String>?>()

val requestBDuringBlock = CompletableDeferred<Map<String, String>?>()

val requestBAfterBlock = CompletableDeferred<Map<String, String>?>()

val jobA =

launch(dispatcher) {

withCoroutineLoggingContext("foo" to "original") {

requestAStarted.complete(Unit)

requestADuringBlock.complete(MDC.getCopyOfContextMap())

requestBDone.await() // Suspend while B runs

}

// will be empty

requestAAfterBlock.complete(MDC.getCopyOfContextMap())

}

val jobB =

launch(dispatcher) {

requestAStarted.await()

withCoroutineLoggingContext("foo" to "bar") {

requestBDuringBlock.complete(MDC.getCopyOfContextMap())

}

// will also be empty

requestBAfterBlock.complete(MDC.getCopyOfContextMap())

requestBDone.complete(Unit)

}

jobA.join()

jobB.join()

assertEquals(mapOf("foo" to "original"), requestADuringBlock.await())

assertEquals(emptyMap(), requestAAfterBlock.await())

assertEquals(mapOf("foo" to "bar"), requestBDuringBlock.await())

assertEquals(emptyMap(), requestBAfterBlock.await())

}

Copilot · 2026-03-04T13:37:22Z

+    // establish order of events with deferreds:
+    // 1. request A will start, set its context, and then wait for request B (before exiting
+    // withLoggingContextAsync)
+    // 2. request B will start, set its context, and then capture the MDC
+    val requestAStarted = CompletableDeferred<Unit>()
+    val requestBDone = CompletableDeferred<Unit>()
+
+    val requestADuringBlock = CompletableDeferred<Map<String, String>?>()
+    val requestAAfterBlock = CompletableDeferred<Map<String, String>?>()
+    val requestBDuringBlock = CompletableDeferred<Map<String, String>?>()
+    val requestBAfterBlock = CompletableDeferred<Map<String, String>?>()
+
+    val jobA =
+      launch(dispatcher) {
+        withLoggingContextAsync("foo" to "original") {
+          requestAStarted.complete(Unit)
+          requestADuringBlock.complete(MDC.getCopyOfContextMap())
+          requestBDone.await() // Suspend while B runs
+        }
+        // will be empty
+        requestAAfterBlock.complete(MDC.getCopyOfContextMap())
+      }
+
+    val jobB =
+      launch(dispatcher) {
+        requestAStarted.await()
+        withLoggingContextAsync("foo" to "bar") {
+          requestBDuringBlock.complete(MDC.getCopyOfContextMap())
+        }
+        // Capture MDC state immediately after Request B's block, will NOT be empty due to the bug
+        requestBAfterBlock.complete(MDC.getCopyOfContextMap())
+        requestBDone.complete(Unit)
+      }
+
+    jobA.join()
+    jobB.join()
+
+    assertEquals(mapOf("foo" to "original"), requestADuringBlock.await())
+    assertEquals(emptyMap(), requestAAfterBlock.await())
+    assertEquals(mapOf("foo" to "bar"), requestBDuringBlock.await())
+    // THIS IS THE BUG: Request B sees "original" after its own block exits
+    // It should be null (no context) but it's leaking Request A's value
+    assertEquals(mapOf("foo" to "original"), requestBAfterBlock.await())


The test creates an ExecutorCoroutineDispatcher from a new fixed thread pool but never closes it. This can leak threads across the test suite; wrap the dispatcher in use { ... } or close it in a finally block (which will also shut down the underlying executor).

Suggested change

// establish order of events with deferreds:

// 1. request A will start, set its context, and then wait for request B (before exiting

// withLoggingContextAsync)

// 2. request B will start, set its context, and then capture the MDC

val requestAStarted = CompletableDeferred<Unit>()

val requestBDone = CompletableDeferred<Unit>()

val requestADuringBlock = CompletableDeferred<Map<String, String>?>()

val requestAAfterBlock = CompletableDeferred<Map<String, String>?>()

val requestBDuringBlock = CompletableDeferred<Map<String, String>?>()

val requestBAfterBlock = CompletableDeferred<Map<String, String>?>()

val jobA =

launch(dispatcher) {

withLoggingContextAsync("foo" to "original") {

requestAStarted.complete(Unit)

requestADuringBlock.complete(MDC.getCopyOfContextMap())

requestBDone.await() // Suspend while B runs

}

// will be empty

requestAAfterBlock.complete(MDC.getCopyOfContextMap())

}

val jobB =

launch(dispatcher) {

requestAStarted.await()

withLoggingContextAsync("foo" to "bar") {

requestBDuringBlock.complete(MDC.getCopyOfContextMap())

}

// Capture MDC state immediately after Request B's block, will NOT be empty due to the bug

requestBAfterBlock.complete(MDC.getCopyOfContextMap())

requestBDone.complete(Unit)

}

jobA.join()

jobB.join()

assertEquals(mapOf("foo" to "original"), requestADuringBlock.await())

assertEquals(emptyMap(), requestAAfterBlock.await())

assertEquals(mapOf("foo" to "bar"), requestBDuringBlock.await())

// THIS IS THE BUG: Request B sees "original" after its own block exits

// It should be null (no context) but it's leaking Request A's value

assertEquals(mapOf("foo" to "original"), requestBAfterBlock.await())

dispatcher.use { dispatcher ->

// establish order of events with deferreds:

// 1. request A will start, set its context, and then wait for request B (before exiting

// withLoggingContextAsync)

// 2. request B will start, set its context, and then capture the MDC

val requestAStarted = CompletableDeferred<Unit>()

val requestBDone = CompletableDeferred<Unit>()

val requestADuringBlock = CompletableDeferred<Map<String, String>?>()

val requestAAfterBlock = CompletableDeferred<Map<String, String>?>()

val requestBDuringBlock = CompletableDeferred<Map<String, String>?>()

val requestBAfterBlock = CompletableDeferred<Map<String, String>?>()

val jobA =

launch(dispatcher) {

withLoggingContextAsync("foo" to "original") {

requestAStarted.complete(Unit)

requestADuringBlock.complete(MDC.getCopyOfContextMap())

requestBDone.await() // Suspend while B runs

}

// will be empty

requestAAfterBlock.complete(MDC.getCopyOfContextMap())

}

val jobB =

launch(dispatcher) {

requestAStarted.await()

withLoggingContextAsync("foo" to "bar") {

requestBDuringBlock.complete(MDC.getCopyOfContextMap())

}

// Capture MDC state immediately after Request B's block, will NOT be empty due to the bug

requestBAfterBlock.complete(MDC.getCopyOfContextMap())

requestBDone.complete(Unit)

}

jobA.join()

jobB.join()

assertEquals(mapOf("foo" to "original"), requestADuringBlock.await())

assertEquals(emptyMap(), requestAAfterBlock.await())

assertEquals(mapOf("foo" to "bar"), requestBDuringBlock.await())

// THIS IS THE BUG: Request B sees "original" after its own block exits

// It should be null (no context) but it's leaking Request A's value

assertEquals(mapOf("foo" to "original"), requestBAfterBlock.await())

}

maniax89 force-pushed the fix-coroutine-logging branch from a4cf22f to 8f88619 Compare March 3, 2026 06:15

test(jvm): demonstrate withLoggingContextAsync bug

239fee2

maniax89 force-pushed the fix-coroutine-logging branch 2 times, most recently from 44a3974 to 3c30abf Compare March 3, 2026 06:22

feat(jvm) add withCoroutineLoggingContext

0dbe37b

maniax89 force-pushed the fix-coroutine-logging branch from 3c30abf to 0dbe37b Compare March 3, 2026 06:24

maniax89 mentioned this pull request Mar 3, 2026

withLoggingContext doesn't work well when called inside coroutines #75

Closed

maniax89 added 2 commits March 3, 2026 01:34

test(jvm): extend clarity of withCoroutineLoggingContext test case

ceff2c1

docs(jvm): update javadoc for withCoroutineLoggingContext pair

fbc9f5f

maniax89 force-pushed the fix-coroutine-logging branch from 13706b9 to fbc9f5f Compare March 3, 2026 14:28

docs(jvm): add docs explaining withCoroutineLoggingContext

6ff2f9a

maniax89 force-pushed the fix-coroutine-logging branch from 6022762 to 6ff2f9a Compare March 3, 2026 17:40

oshai requested a review from Copilot March 4, 2026 13:33

Copilot started reviewing on behalf of oshai March 4, 2026 13:33 View session

Copilot AI reviewed Mar 4, 2026

View reviewed changes

fix(jvm): apply review feedback from copilot

4b438b8

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Fix coroutine logging - #597

Fix coroutine logging#597
maniax89 wants to merge 6 commits into
oshai:masterfrom
maniax89:fix-coroutine-logging

maniax89 commented Mar 3, 2026

Uh oh!

Copilot AI left a comment

Uh oh!

Copilot AI Mar 4, 2026

Uh oh!

Copilot AI Mar 4, 2026

Uh oh!

Copilot AI Mar 4, 2026

Uh oh!

Copilot AI Mar 4, 2026

Uh oh!

Copilot AI Mar 4, 2026

Uh oh!

Copilot AI Mar 4, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

-  val merged = (parent + map.filterValues { it != null }).mapValues { it.value!! }
+  val merged = parent.toMutableMap().apply {
+    for ((key, value) in map) {
+      if (value == null) {
+        remove(key)
+      } else {
+        put(key, value)
+      }
+    }
+  }

Uh oh!

Conversation

maniax89 commented Mar 3, 2026

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Reviewed changes

Uh oh!

Copilot AI Mar 4, 2026

Choose a reason for hiding this comment

Uh oh!

Copilot AI Mar 4, 2026

Choose a reason for hiding this comment

Uh oh!

Copilot AI Mar 4, 2026

Choose a reason for hiding this comment

Uh oh!

Copilot AI Mar 4, 2026

Choose a reason for hiding this comment

Uh oh!

Copilot AI Mar 4, 2026

Choose a reason for hiding this comment

Uh oh!

Copilot AI Mar 4, 2026

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants