Kotlin coroutines stack trace issue

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:

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 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 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. 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:

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.

Blog

Kotlin coroutines stack trace issue

Anamorphosee

Join Our Newsletter. No Spam, Only the good stuff.

Related