Kotlin coroutines stack trace issue
Tags: kotlin, android
Published: 2022-01-18 17:26:41

Kotlin coroutines is a great feature that allows you to write asynchronous code in synchronous style.

It's absolutely perfect until you need to investigate problems in your code.

One of the coroutines common problems is the shortened stack trace in exceptions thrown in coroutines. For example, this code prints out the stack trace below:

```kotlin
import kotlinx.coroutines.delay
import kotlinx.coroutines.runBlocking

suspend fun fun1() {
    delay(10)
    throw Exception("exception at ${System.currentTimeMillis()}")
}

suspend fun fun2() {
    fun1()
    delay(10)
}

suspend fun fun3() {
    fun2()
    delay(10)
}

fun main() {
    try {
        runBlocking {
            fun3()
        }
    } catch (e: Exception) {
        e.printStackTrace()
    }
}
```

```
java.lang.Exception: exception at 1641842199891
  at MainKt.fun1(main.kt:6)
  at MainKt$fun1$1.invokeSuspend(main.kt)
  at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
  at kotlinx.coroutines.DispatchedTaskKt.resume(DispatchedTask.kt:234)
  at kotlinx.coroutines.DispatchedTaskKt.dispatch(DispatchedTask.kt:166)
  at kotlinx.coroutines.CancellableContinuationImpl.dispatchResume(CancellableContinuationImpl.kt:397)
  at kotlinx.coroutines.CancellableContinuationImpl.resumeImpl(CancellableContinuationImpl.kt:431)
  at kotlinx.coroutines.CancellableContinuationImpl.resumeImpl$default(CancellableContinuationImpl.kt:420)
  at kotlinx.coroutines.CancellableContinuationImpl.resumeUndispatched(CancellableContinuationImpl.kt:518)
  at kotlinx.coroutines.EventLoopImplBase$DelayedResumeTask.run(EventLoop.common.kt:494)
  at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:279)
  at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
  at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
  at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source)
  at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
  at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source)
  at MainKt.main(main.kt:21)
  at MainKt.main(main.kt)
```
The stack trace doesn't represent the true coroutine call stack: calls of functions `fun3` and `fun2` are absent.

In complex systems, even more calls may be missing. This can make debugging much more difficult.

Where did the missing calls go? The answer lies in the [implementation](https://github.com/JetBrains/kotlin/blob/92d200e093c693b3c06e53a39e0b0973b84c7ec5/libraries/stdlib/jvm/src/kotlin/coroutines/jvm/internal/ContinuationImpl.kt#L21) of coroutines: when "waking up" (calling the `resumeWith` method), the coroutine does not restore its entire call stack, but only calls one function, which is at the top of the call stack. After the completion of this function, the next one in order is called, and so on. Accordingly, if an exception is thrown in the coroutine, only the function at the top of the call stack gets into its stack trace.

The Kotlin team are known about the problem and has created a [debug-mode](https://github.com/Kotlin/kotlinx.coroutines/blob/master/docs/topics/debugging.md#debugging-coroutines) for coroutines. Runs our example in this debug mode (to do this, for example, just add the -ea switch in the JVM launch line) and see... that nothing has changed.

What is the reason? After a long reading into the Kotlin stdlib code, I understand that the stack trace recovery mechanics only work for the case when the coroutine is "awakened" with an exception (by calling `resumeWith` with an exception). Exceptions created in the code of the coroutine itself (as in our case) do not change in any way.

Therefore, after studying the implementation of coroutines, I wrote my own solution based on bytecode generation and MethodHandle API. I called it [Stacktrace-decoroutinator](https://github.com/Anamorphosee/stacktrace-decoroutinator). My tool replaces the coroutine awakening implementation. It generates classes at runtime with names that match the entire coroutine call stack. These classes don't do anything except call each other in the coroutine call stack order. Thus, if the coroutine throws an exception, they mimic the real call stack of the coroutine during the creation of the exception stack trace.

Let's modify our example, add the dependency `dev.reformator.stacktracedecoroutinator:stacktrace-decoroutinator-jvm:2.1.0` and initialization in the `main` function:
```kotlin
import dev.reformator.stacktracedecoroutinator.runtime.DecoroutinatorRuntime
import kotlinx.coroutines.delay
import kotlinx.coroutines.runBlocking

suspend fun fun1() {
    delay(10)
    throw Exception("exception at ${System.currentTimeMillis()}")
}

suspend fun fun2() {
    fun1()
    delay(10)
}

suspend fun fun3() {
    fun2()
    delay(10)
}

fun main() {
    DecoroutinatorRuntime.load()
    try {
        runBlocking {
            fun3()
        }
    } catch (e: Exception) {
        e.printStackTrace()
    }
}
```
Launch and see the stack trace:
```
java.lang.Exception: exception at 1642524227957
	at GarbKt.fun1(garb.kt:7)
	at GarbKt$fun1$1.invokeSuspend(garb.kt)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.decoroutinatorResumeWith$lambda-1(continuation-stdlib.kt:47)
	at GarbKt.fun2(garb.kt:11)
	at GarbKt.fun3(garb.kt:16)
	at GarbKt$main$1.invokeSuspend(garb.kt:24)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.decoroutinatorResumeWith(continuation-stdlib.kt:177)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(continuation-stdlib.kt:21)
	at kotlinx.coroutines.DispatchedTaskKt.resume(DispatchedTask.kt:234)
	at kotlinx.coroutines.DispatchedTaskKt.dispatch(DispatchedTask.kt:166)
	at kotlinx.coroutines.CancellableContinuationImpl.dispatchResume(CancellableContinuationImpl.kt:397)
	at kotlinx.coroutines.CancellableContinuationImpl.resumeImpl(CancellableContinuationImpl.kt:431)
	at kotlinx.coroutines.CancellableContinuationImpl.resumeImpl$default(CancellableContinuationImpl.kt:420)
	at kotlinx.coroutines.CancellableContinuationImpl.resumeUndispatched(CancellableContinuationImpl.kt:518)
	at kotlinx.coroutines.EventLoopImplBase$DelayedResumeTask.run(EventLoop.common.kt:494)
	at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:279)
	at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
	at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
	at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source)
	at GarbKt.main(garb.kt:23)
	at GarbKt.main(garb.kt)
```
which contains calls of functions `fun2` and `fun3`.

The tool supports JVM 1.8 or higher and Android API 26 (Android 8) or higher.

Lately I've been using Stacktrace-decoroutinator in my production environment and will be glad if you join me.