Hi. there is something that I’d like to understand...

# coroutines

[Jakub Gwóźdź]

Hi. there is something that I’d like to understand:
Suppose we have this minimal piece of code:

suspend fun main() = withContext(MDCContext(mapOf("host" to "local"))) {
    val ktorClient = HttpClient(OkHttp)
    log("entering context")

    (1..10).forEach { i ->
        val newContextMap = MDC.getCopyOfContextMap()
        newContextMap["i"] = i.toString()
        withContext(MDCContext(newContextMap)) {
            log("before calling ktor client $i")
            ktorClient.get { url("<https://example.com/$i>") }.bodyAsText()
            log("after calling ktor client $i")
        }
    }

    log("exiting context")
    ktorClient.close()
}

when run, the MDC is shuffled totally indeterministic:

10:21:45.238 [main] - entering context {host=local}
10:21:45.240 [main] - before calling ktor client 1 {host=local, i=1}
10:21:45.824 [DefaultDispatcher-worker-1] - after calling ktor client 1 {}
10:21:45.824 [DefaultDispatcher-worker-1] - before calling ktor client 2 {host=local, i=2}
10:21:45.998 [DefaultDispatcher-worker-1] - after calling ktor client 2 {}
10:21:45.998 [DefaultDispatcher-worker-1] - before calling ktor client 3 {host=local, i=3}
10:21:46.102 [DefaultDispatcher-worker-1] - after calling ktor client 3 {host=local}
10:21:46.103 [DefaultDispatcher-worker-1] - before calling ktor client 4 {host=local, i=4}
10:21:46.208 [DefaultDispatcher-worker-3] - after calling ktor client 4 {}
...

But as soon as I change first line to

suspend fun main() = withContext(Dispatchers.Default + MDCContext(mapOf("host" to "local"))) {

it magically starts working as intended. (same on any other dispatcher, IO or Unconfined)

Why is it so? Is it a problem with suspend fun main , ktor-client, or - most probably - me messing up something here?

[Robert Williams]

Almost certainly an issue with suspend fun main, just search this chat and you'll find plenty of unexpected behaviour related to its Dispatcher implementation

[Jakub Gwóźdź]

thing is, if I replace ktorClient.get {} with

launch(<http://Dispatchers.IO|Dispatchers.IO>) { Thread.sleep(200) }

I still get the suspension, still get the thread switching, but MDC stays correct.

Basically, I cannot reproduce the behaviour without ktor, even if I strongly elieve the problem is within suspend fun main 🙂

[Joffrey]

I still get the suspension, still get the thread switching, but MDC stays correct

<http://Dispatchers.IO|Dispatchers.IO> shares threads with Dispatchers.Default so you might not effectively be switching threads here. You might reproduce with a custom dispatcher.

[Jakub Gwóźdź]

according to logs, the entries are on different threads

[Joffrey]

By the way, no need for (1..10).forEach { i ->, you can use repeat(10) { i -> which is easier to read IMO (however indexing will be 0-based)

[Joffrey]

according to logs, the entries are on different threads

Ok, it might be because you use more threads than what is available in DIsptachers.Default so eventually it does create other threads

[Jakub Gwóźdź]

I know, I prefer counting from 1 here and it’s not the point anyway

[Joffrey]

it’s not the point anyway

It was just a side remark indeed

[Jakub Gwóźdź]

when using launch(<http://Dispatchers.IO|Dispatchers.IO>) { Thread.sleep(200) } instead of ktor client: (notice MDC is correct here while threads switch)

11:24:30.535 [main] - entering context {host=local}
11:24:30.537 [main] - before calling ktor client 1 {host=local, i=1}
11:24:30.537 [main] - after calling ktor client 1 {host=local, i=1}
11:24:30.744 [DefaultDispatcher-worker-1] - before calling ktor client 2 {host=local, i=2}
11:24:30.745 [DefaultDispatcher-worker-1] - after calling ktor client 2 {host=local, i=2}
11:24:30.951 [DefaultDispatcher-worker-3] - before calling ktor client 3 {host=local, i=3}
11:24:30.952 [DefaultDispatcher-worker-3] - after calling ktor client 3 {host=local, i=3}

[Joffrey]

But in any case, as @Robert Williams said, there is a bunch of weird stuff that may happen with suspend fun main. Recently I discovered that it didn't have a Job (which makes sense, because Job is from kotlinx-coroutines) but that means coroutineContext.isActive returns false, unintuitively. There definitely may be other weird things with `suspend fun main`'s coroutine context.

[Joffrey]

Oh you mean just changing the Ktor call while keeping suspend fun main() = withContext() without dispatcher there works?

[Jakub Gwóźdź]

yes

[Joffrey]

Then I'm out of ideas 🤔

[Jakub Gwóźdź]

It’s possible that ktor uses some more coroutines magic that I’m simulating

[Joffrey]

But then it would mean that Ktor breaks some coroutine invariants. Or maybe it uses MDC itself in a way that overrides yours? 🤷

[Robert Williams]

The problem with the main dispatcher isn't that it never works, it just works differently and doesn't provide as strong guarantees on ordering if multiple coroutines are scheduled (similar to a lot of problems that occur with UnconfinedTestDispatcher)

[Robert Williams]

It's entirely possible that delays are simple enough that it always works "as expected"

[Robert Williams]

wheras ktor may be doing multiple thread/ context switches or enqueing multiple coroutines at once (don't really know what ktor does internally but the point is it could do any of that and more)

[Jakub Gwóźdź]

so I understand that it is better to stay away from suspend fun main? 🙂

[Robert Williams]

Pretty much, it's not actually part of kotlinx.coroutines and just bolted on for language consistency

[Robert Williams]

If you want to use it the standard advice is to immediately start a new coroutineScope inside (which also gives you the Job and cancellation behaviour as @Joffrey mentioned)