Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Provide meaningful stacktrace on cancellation #1625

Closed
vlsi opened this issue Oct 22, 2019 · 2 comments
Closed

Provide meaningful stacktrace on cancellation #1625

vlsi opened this issue Oct 22, 2019 · 2 comments
Assignees

Comments

@vlsi
Copy link

vlsi commented Oct 22, 2019

Sample: https://stackoverflow.com/questions/58482407/is-there-a-way-to-understand-what-the-coroutine-was-doing-when-it-was-cancelled

import kotlinx.coroutines.*

suspend fun test() {
    println("test.begin")
    delay(5000)
    println("test.end")
}

suspend fun proxy() {
    test()
}

fun main() {
    runBlocking {
        withTimeout(100) {
            proxy()
        }
    }
}

Output:

Exception in thread "main" kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 100 ms
 at kotlinx.coroutines.TimeoutKt.TimeoutCancellationException (Timeout.kt:126) 
 at kotlinx.coroutines.TimeoutCoroutine.run (Timeout.kt:92) 
 at kotlinx.coroutines.EventLoopImplBase$DelayedRunnableTask.run (EventLoop.common.kt:491) 
 at kotlinx.coroutines.EventLoopImplBase.processNextEvent (EventLoop.common.kt:270) 
 at kotlinx.coroutines.DefaultExecutor.run (DefaultExecutor.kt:68) 
 at java.lang.Thread.run (Thread.java:745) 

Note: neither test nor proxy nor main are mentioned in the stack trace.

Expected: "at least test" should be mentioned (because the coroutine resumes from that function). Ideally, proxy and withTimeout should be present as well.

As far as I see, Kotlin-JVM generates state machine like

var6_4 = IntrinsicsKt.getCOROUTINE_SUSPENDED();
switch ($continuation.label) {
    case 0: {
        ResultKt.throwOnFailure((Object)$result);
        var2_5 = "test.begin";

What if it added and extra string parameter to throwOnFailure method like
ResultKt.throwOnFailure((Object)$result, "com.acme.Example.test(Example.kt:15)"); ?

Then failure cases could contain proper stacktraces for cancelation / exceptional outcomes.

@fvasco
Copy link
Contributor

fvasco commented Oct 22, 2019

That string should be removed by shrinkers/obfuscators.

@qwwdfsad
Copy link
Collaborator

qwwdfsad commented Oct 22, 2019

Unfortunately, we cannot provide generic mechanism that will always properly recover a stacktrace.
For example, your proposal

ResultKt.throwOnFailure((Object)$result, "com.acme.Example.test(Example.kt:15)");

is quite hard to implement, because $result already has an instance of the exception (potentially shared!)

Expected: "at least test" should be mentioned (because the coroutine resumes from that function).

True, but the exception is created in a different place, not in a resumption point

To improve the debugging experience, we have a debug mode that copies an exception and enhance the copy with coroutine-related frames (using mechanism quite similar to what you proposed :) ).
Debug mode can be enabled by -ea VM option or corresponding system property.

Unfortunately, TimeoutException cannot be recovered yet (I will fix it in the next release), but debug mode can be demonstrated with CE anyway, e.g. the following code

suspend fun test() {
    println("test.begin")
    suspendCancellableCoroutine<Unit> {
        thread {
            Thread.sleep(100)
            it.cancel()
        }
    }
    println("test.end")
}

suspend fun proxy() {
    test()
    println("Proxy.end") // Prevent tail-call optimization by kotlinc
}

fun main() {
    runBlocking {
        proxy()
    }
}

will produce

java.util.concurrent.CancellationException: Continuation CancellableContinuation(DispatchedContinuation[BlockingEventLoop@124ca831, Continuation at kotlinx.coroutines.AsyncJvmTest.test(AsyncJvmTest.kt:38)@e0cfd13]){Active}@7053d0dc was cancelled normally
	(Coroutine boundary)
	at kotlinx.coroutines.AsyncJvmTest.test(AsyncJvmTest.kt:38)
	at kotlinx.coroutines.AsyncJvmTest.proxy(AsyncJvmTest.kt:25)
	at kotlinx.coroutines.AsyncJvmTest$main$1.invokeSuspend(AsyncJvmTest.kt:33)
Caused by: java.util.concurrent.CancellationException: Continuation CancellableContinuation(DispatchedContinuation[BlockingEventLoop@124ca831, Continuation at kotlinx.coroutines.AsyncJvmTest.test(AsyncJvmTest.kt:38)@e0cfd13]){Active}@7053d0dc was cancelled normally
	at kotlinx.coroutines.CancelledContinuation.<init>(CompletedExceptionally.kt:51)
	at kotlinx.coroutines.CancellableContinuationImpl.cancel(CancellableContinuationImpl.kt:168)
	at kotlinx.coroutines.CancellableContinuation$DefaultImpls.cancel$default(CancellableContinuation.kt:118)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants