Kotlinx.coroutines: If change the dispatcher of the coroutine, the stack trace will be cropped

[alexmihailov]

There is a trivial case with nested calls to suspend functions. In the last of the calls, an exception is thrown, which is caught only in the start function, which launched this entire chain of suspend function calls, and the exception is sent to the log.
It is argued that the stack trace in the log should be complete, since Stack trace recovery was released in 1.1 https://github.com/Kotlin/kotlinx.coroutines/issues/74
And it really seems to work, but only if you do not change the dispatcher in intermediate calls. But if you change it, then the stack stack turns out to be cut off.

Dispatcher change example:

val logger: Logger = LoggerFactory.getLogger("Main")
fun main() {
    runBlocking {
        try {
            callThrowableSuspendFun()
        } catch (ex: Exception) {
            logger.error("Error while execute", ex)
        }
    }
}
suspend fun changeContextAndThrow(): String {
    logger.info("Call function changeContextAndThrow")
    return withContext(Dispatchers.IO) {
        throw IllegalArgumentException("Throw from changeContextAndThrow")
    }
}
suspend fun callThrowableSuspendFun(): String {
    logger.info("Call function callThrowableSuspendFun")
    return changeContextAndThrow()
}

Log:

83 [main] INFO Main - Call function callThrowableSuspendFun
83 [main] INFO Main - Call function changeContextAndThrow
98 [main] ERROR Main - Error while execute
java.lang.IllegalArgumentException: Throw from changeContextAndThrow
    at MainKt$changeContextAndThrow$2.invokeSuspend(Main.kt:30)
    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
    at kotlinx.coroutines.DispatchedTask.run(Dispatched.kt:241)
    at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:594)
    at kotlinx.coroutines.scheduling.CoroutineScheduler.access$runSafely(CoroutineScheduler.kt:60)
    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:740)

An example without changing the dispatcher:

val logger: Logger = LoggerFactory.getLogger("Main")
fun main() {
    runBlocking {
        try {
            callThrowableSuspendFun()
        } catch (ex: Exception) {
            logger.error("Error while execute", ex)
        }
    }
}
suspend fun changeContextAndThrow(): String {
    logger.info("Call function changeContextAndThrow")
    return coroutineScope {
        throw IllegalArgumentException("Throw from changeContextAndThrow")
    }
}
suspend fun callThrowableSuspendFun(): String {
    logger.info("Call function callThrowableSuspendFun")
    return changeContextAndThrow()
}

Log:

132 [main] INFO Main - Call function callThrowableSuspendFun
132 [main] INFO Main - Call function changeContextAndThrow
156 [main] ERROR Main - Error while execute
java.lang.IllegalArgumentException: Throw from changeContextAndThrow
    at MainKt$changeContextAndThrow$2.invokeSuspend(Main.kt:30)
    at MainKt$changeContextAndThrow$2.invoke(Main.kt)
    at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturn(Undispatched.kt:91)
    at kotlinx.coroutines.CoroutineScopeKt.coroutineScope(CoroutineScope.kt:180)
    at MainKt.changeContextAndThrow(Main.kt:29)
    at MainKt.callThrowableSuspendFun(Main.kt:36)
    at MainKt$main$1.invokeSuspend(Main.kt:20)
    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
    at kotlinx.coroutines.DispatchedTask.run(Dispatched.kt:241)
    at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:270)
    at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:79)
    at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:54)
    at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source)
    at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:36)
    at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source)
    at MainKt.main(Main.kt:18)
    at MainKt.main(Main.kt)

[qwwdfsad]

Please ensure that stacktrace recovery is actually enabled.

Because I cannot reproduce your problem and observe:

java.lang.IllegalArgumentException: Throw from changeContextAndThrow
    at kotlinx.coroutines.Example$changeContextAndThrow$2.invokeSuspend(Example.kt:25)
    (Coroutine boundary)
    at kotlinx.coroutines.Example$main$1.invokeSuspend(Example.kt:16)
Caused by: java.lang.IllegalArgumentException: Throw from changeContextAndThrow
    at kotlinx.coroutines.Example$changeContextAndThrow$2.invokeSuspend(Example.kt:25)
    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:56)
    at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:594)
    at kotlinx.coroutines.scheduling.CoroutineScheduler.access$runSafely(CoroutineScheduler.kt:60)
    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:740)

[ihostage]

Hi, @qwwdfsad! 👋
On this log I don't know who call a changeContextAndThrow. We have trouble to analyze the incidents by production logs because stack trace is cropped.

[alexmihailov]

I used debug mode (-ea) and explicitly enabled stack recovery (kotlinx.coroutines.stacktrace.recovery). But there is no mention in the stack trace of the callThrowableSuspendFun function

[qwwdfsad]

Yeah, callThrowableSuspendFun is missing even in debug mode, because it's optimized away by the Kotlion compiler as tail-call function. TL;DR if a suspend function has its only suspension point in the tail position, its state machine is thrown away by the compiler, making its usages significantly faster.

As a workaround, you can add something to callThrowableSuspendFun after its tail suspension point, e.g.:

suspend fun callThrowableSuspendFun(): String {
    println("Call function callThrowableSuspendFun")
    return changeContextAndThrow().also {  } // Empty 'also' call
}

[alexmihailov]

Yes, it works, but only in debug mode. Is there any way to get the full stack trace in production?

[alexmihailov]

If there is no other way, then how bad is it to enable debug mode in production? We really need a full stack trace.

[qwwdfsad]

No, for the same reasons as it cannot be done with regular threads and context switches.

Quoting already mentioned documentation:

Overhead of this feature is negligible and it can be safely turned on by default to simplify logging and diagnostic.

[gnefedev]

I wrote a workaround like this:

suspend fun <T> withIoDispatcher(block: suspend CoroutineScope.() -> T): T =
    try {
        withContext(IO, block)
    } catch (e: Throwable) {
        e.stackTrace += RuntimeException().stackTrace
        throw e
    }