|
1 | 1 | package io.github.oshai.kotlinlogging.coroutines |
2 | 2 |
|
3 | | -import kotlinx.coroutines.CompletableDeferred |
| 3 | +import java.util.concurrent.Executors |
4 | 4 | import kotlin.test.* |
| 5 | +import kotlinx.coroutines.CompletableDeferred |
5 | 6 | import kotlinx.coroutines.ExperimentalCoroutinesApi |
6 | 7 | import kotlinx.coroutines.asCoroutineDispatcher |
7 | 8 | import kotlinx.coroutines.launch |
8 | | -import kotlinx.coroutines.runBlocking |
9 | 9 | import kotlinx.coroutines.test.runTest |
10 | 10 | import org.apache.logging.log4j.* |
11 | 11 | import org.apache.logging.log4j.core.config.* |
12 | 12 | import org.junit.jupiter.api.BeforeEach |
13 | 13 | import org.slf4j.* |
14 | | -import java.util.concurrent.Executors |
15 | 14 |
|
16 | 15 | @ExperimentalCoroutinesApi |
17 | 16 | class KotlinLoggingAsyncMDCTest { |
@@ -168,37 +167,126 @@ class KotlinLoggingAsyncMDCTest { |
168 | 167 | fun `withLoggingContextAsync leaks context across coroutines`() = runTest { |
169 | 168 | val dispatcher = Executors.newFixedThreadPool(1).asCoroutineDispatcher() |
170 | 169 | // establish order of events with deferreds: |
171 | | - // 1. request A will start, set its context, and then wait for request B (before exiting withLoggingContextAsync) |
| 170 | + // 1. request A will start, set its context, and then wait for request B (before exiting |
| 171 | + // withLoggingContextAsync) |
172 | 172 | // 2. request B will start, set its context, and then capture the MDC |
173 | 173 | val requestAStarted = CompletableDeferred<Unit>() |
174 | 174 | val requestBDone = CompletableDeferred<Unit>() |
175 | 175 |
|
176 | 176 | val requestAAfterBlock = CompletableDeferred<Map<String, String>?>() |
177 | 177 | val requestBAfterBlock = CompletableDeferred<Map<String, String>?>() |
178 | 178 |
|
179 | | - val jobA = launch(dispatcher) { |
180 | | - withLoggingContextAsync("foo" to "original") { |
181 | | - requestAStarted.complete(Unit) |
182 | | - requestBDone.await() // Suspend while B runs |
| 179 | + val jobA = |
| 180 | + launch(dispatcher) { |
| 181 | + withLoggingContextAsync("foo" to "original") { |
| 182 | + requestAStarted.complete(Unit) |
| 183 | + requestBDone.await() // Suspend while B runs |
| 184 | + } |
| 185 | + // will be empty |
| 186 | + requestAAfterBlock.complete(MDC.getCopyOfContextMap()) |
183 | 187 | } |
184 | | - // will be empty |
185 | | - requestAAfterBlock.complete(MDC.getCopyOfContextMap()) |
186 | | - } |
187 | 188 |
|
188 | | - val jobB = launch(dispatcher) { |
189 | | - requestAStarted.await() |
190 | | - withLoggingContextAsync("foo" to "bar") { } |
191 | | - // Capture MDC state immediately after Request B's block, will NOT be empty due to the bug |
192 | | - requestBAfterBlock.complete(MDC.getCopyOfContextMap()) |
193 | | - requestBDone.complete(Unit) |
194 | | - } |
| 189 | + val jobB = |
| 190 | + launch(dispatcher) { |
| 191 | + requestAStarted.await() |
| 192 | + withLoggingContextAsync("foo" to "bar") {} |
| 193 | + // Capture MDC state immediately after Request B's block, will NOT be empty due to the bug |
| 194 | + requestBAfterBlock.complete(MDC.getCopyOfContextMap()) |
| 195 | + requestBDone.complete(Unit) |
| 196 | + } |
195 | 197 |
|
196 | 198 | jobA.join() |
197 | 199 | jobB.join() |
198 | 200 |
|
199 | 201 | assertEquals(emptyMap(), requestAAfterBlock.await()) |
200 | | - // THIS IS THE BUG: Request B sees "AAA" after its own block exits |
| 202 | + // THIS IS THE BUG: Request B sees "original" after its own block exits |
201 | 203 | // It should be null (no context) but it's leaking Request A's value |
202 | | - assertEquals(mapOf("foo" to "original"), requestBAfterBlock.await()) // This will FAIL |
| 204 | + assertEquals(mapOf("foo" to "original"), requestBAfterBlock.await()) |
| 205 | + } |
| 206 | + |
| 207 | + @Test |
| 208 | + fun `withCoroutineLoggingContext does not leak context across coroutines`() = runTest { |
| 209 | + val dispatcher = Executors.newFixedThreadPool(1).asCoroutineDispatcher() |
| 210 | + // establish order of events with deferreds: |
| 211 | + // 1. request A will start, set its context, and then wait for request B (before exiting |
| 212 | + // withLoggingContextAsync) |
| 213 | + // 2. request B will start, set its context, and then capture the MDC |
| 214 | + val requestAStarted = CompletableDeferred<Unit>() |
| 215 | + val requestBDone = CompletableDeferred<Unit>() |
| 216 | + |
| 217 | + val requestAAfterBlock = CompletableDeferred<Map<String, String>?>() |
| 218 | + val requestBAfterBlock = CompletableDeferred<Map<String, String>?>() |
| 219 | + |
| 220 | + val jobA = |
| 221 | + launch(dispatcher) { |
| 222 | + withCoroutineLoggingContext("foo" to "original") { |
| 223 | + requestAStarted.complete(Unit) |
| 224 | + requestBDone.await() // Suspend while B runs |
| 225 | + } |
| 226 | + // will be empty |
| 227 | + requestAAfterBlock.complete(MDC.getCopyOfContextMap()) |
| 228 | + } |
| 229 | + |
| 230 | + val jobB = |
| 231 | + launch(dispatcher) { |
| 232 | + requestAStarted.await() |
| 233 | + withCoroutineLoggingContext("foo" to "bar") {} |
| 234 | + // Capture MDC state immediately after Request B's block, will NOT be empty due to the bug |
| 235 | + requestBAfterBlock.complete(MDC.getCopyOfContextMap()) |
| 236 | + requestBDone.complete(Unit) |
| 237 | + } |
| 238 | + |
| 239 | + jobA.join() |
| 240 | + jobB.join() |
| 241 | + |
| 242 | + assertEquals(emptyMap(), requestAAfterBlock.await()) |
| 243 | + assertEquals(emptyMap(), requestBAfterBlock.await()) |
| 244 | + } |
| 245 | + |
| 246 | + @Test |
| 247 | + fun `map withCoroutineLoggingContext`() = runTest { |
| 248 | + assertNull(MDC.get("a")) |
| 249 | + assertNull(MDC.get("c")) |
| 250 | + assertNull(MDC.get("e")) |
| 251 | + assertNull(MDC.get("f")) |
| 252 | + assertNull(MDC.get("k")) |
| 253 | + |
| 254 | + // original MDC outside of coroutine context |
| 255 | + MDC.put("e", "g") |
| 256 | + MDC.put("k", "l") |
| 257 | + |
| 258 | + withCoroutineLoggingContext(mapOf("a" to "b", "c" to "d", "e" to null, "f" to "h")) { |
| 259 | + assertEquals("b", MDC.get("a")) |
| 260 | + assertEquals("d", MDC.get("c")) |
| 261 | + // does NOT inherit original MDC |
| 262 | + assertNull(MDC.get("e")) |
| 263 | + assertEquals("h", MDC.get("f")) |
| 264 | + // does NOT inherit original MDC |
| 265 | + assertNull(MDC.get("k")) |
| 266 | + |
| 267 | + withCoroutineLoggingContext(mapOf("a" to "b", "e" to "i", "f" to "j")) { |
| 268 | + assertEquals("b", MDC.get("a")) |
| 269 | + // DOES inherit previous coroutine context |
| 270 | + assertEquals("d", MDC.get("c")) |
| 271 | + assertEquals("i", MDC.get("e")) |
| 272 | + assertEquals("j", MDC.get("f")) |
| 273 | + assertNull(MDC.get("k")) |
| 274 | + } |
| 275 | + |
| 276 | + assertEquals("b", MDC.get("a")) |
| 277 | + assertEquals("d", MDC.get("c")) |
| 278 | + assertNull(MDC.get("e")) |
| 279 | + assertEquals("h", MDC.get("f")) |
| 280 | + assertNull(MDC.get("k")) |
| 281 | + } |
| 282 | + |
| 283 | + assertNull(MDC.get("a")) |
| 284 | + assertNull(MDC.get("c")) |
| 285 | + |
| 286 | + // original MDC is restored |
| 287 | + assertEquals("g", MDC.get("e")) |
| 288 | + assertNull(MDC.get("f")) |
| 289 | + // original MDC is restored |
| 290 | + assertEquals("l", MDC.get("k")) |
203 | 291 | } |
204 | 292 | } |
0 commit comments