Coroutines, exception handling and withTimeout. Can't wrap my head around this combination

[psteiger]

import kotlinx.coroutines.*
import kotlinx.coroutines.flow.*
import kotlin.system.measureTimeMillis

fun time() = System.currentTimeMillis()

fun main(args: Array<String>) {
    runBlocking {
        repeat(5) {
            try {
                println("${time()} withTimeout before")
                withTimeout(1L) {
                    try {
                        delay(200L)
                    } catch (e: Exception) {
                        println("${time()} withTimeout exception " + e.localizedMessage)
                    }
                }
                println("${time()} withTimeout done")
            } catch (e: Exception) {
                println("${time()} exception " + e.localizedMessage)
            }
            println("${time()} -----")
        }
    }
}

This gives me the output:

1586923684774 withTimeout before
1586923684788 withTimeout exception Timed out waiting for 1 ms
1586923684789 withTimeout done
1586923684789 -----
1586923684789 withTimeout before
1586923684790 withTimeout exception Timed out waiting for 1 ms
1586923684791 exception Timed out waiting for 1 ms
1586923684791 -----
1586923684791 withTimeout before
1586923684792 withTimeout exception Timed out waiting for 1 ms
1586923684792 exception Timed out waiting for 1 ms
1586923684792 -----
1586923684792 withTimeout before
1586923684794 withTimeout exception Timed out waiting for 1 ms
1586923684794 exception Timed out waiting for 1 ms
1586923684794 -----
1586923684794 withTimeout before
1586923684795 withTimeout exception Timed out waiting for 1 ms
1586923684795 exception Timed out waiting for 1 ms
1586923684795 -----

On the first loop, withTimeout done gets printed.

Question 1: Why only on the first iteration?

Question 2: If I change the wait time in withTimeout from 1L to 10L, it does not get printed. Instead, the exception is propagated to the outer try/catch, like on the next iterations (See below). Why?

1586923727317 withTimeout before
1586923727333 withTimeout exception Timed out waiting for 10 ms
1586923727334 exception Timed out waiting for 10 ms
1586923727334 -----
1586923727334 withTimeout before
1586923727347 withTimeout exception Timed out waiting for 10 ms
1586923727347 exception Timed out waiting for 10 ms
1586923727347 -----
1586923727347 withTimeout before
1586923727360 withTimeout exception Timed out waiting for 10 ms
1586923727360 exception Timed out waiting for 10 ms
1586923727360 -----
1586923727360 withTimeout before
1586923727370 withTimeout exception Timed out waiting for 10 ms
1586923727371 exception Timed out waiting for 10 ms
1586923727371 -----
1586923727371 withTimeout before
1586923727382 withTimeout exception Timed out waiting for 10 ms
1586923727382 exception Timed out waiting for 10 ms
1586923727382 -----

Question 3: Why, even though the exception is being caught inside a try/catch block in withTimeout(), it is being propagated to the outer try/catch block?

I appreciate and thank you in advance for your help.

[psteiger]

A user in StackOverflow reports:

This is looking like a bug to me. Sometimes withTimeout rethrows the exception even if it's caught internally, and sometimes it doesn't. The second behavior seems to be triggered even by allowing a withTimeout to time out in a completely separate coroutine first: pl.kotl.in/ze45lyz2o It also does it if you specify a dispatcher: pl.kotl.in/c7hlNdlTM

[elizarov]

Thanks. Something strange is going on when timeout exception is caught inside the withTimeout block. I'll take a look.

[psteiger]

Hi @elizarov , thanks for your response. Could you please clarify what would be the expected behavior here for the exceptions? If they are caught inside the withTimeout block, I believe they should not be propagated upwards. Am I correct in this assumption?

[jxdabc]

Hi, @elizarov

I did some tracking. It seems to be much a design problem (maybe not a problem at all) than a bug as I could see.

Actually, withTimeout has a property which is not clearly documented (but commented elsewhere at ScopeCoroutine<T>.undispatchedResult):

If timeout is exceeded, but withTimeout() block was not suspended, we would like to return block value, not a timeout exception.

If we modify the code above as below, everything becomes obvious:

runBlocking {
    repeat(5) {
        try {
            println("${time()} withTimeout before")
            withTimeout(1L) {
                Thread.sleep(1000)
            }
            println("${time()} withTimeout done")
        } catch (e: Exception) {
            println("${time()} exception " + e.localizedMessage)
        }
        println("${time()} -----")
    }
}

Since Thread.sleep(1000) won't suspend, it will always print withTimeout done

The detail why the origin code

withTimeout(1L) {
    try {
        delay(200L)
    } catch (e: Exception) {
        println("${time()} withTimeout exception " + e.localizedMessage)
    }
}

won't (always) suspend is:

1. The above withTimeout counts down and cancels the coroutine in another thread rather than the runBlocking thread.
2. The coroutine is canceled before delay(200L).
3. Inside suspendCancellableCoroutine of delay(200L), getResult() of CancellableContinuation ends immediately with canceled state without suspending.

It seems we could fix the documentation or adjust the design (maybe this is not necessary or proper as I could see).

[qwwdfsad]

The reasoning is indeed perfectly right, so I'm closing this as "works as intended".
Yet this is a contract that wasn't updated along with atomic cancellation and is worth reconsidering in #1374

[qwwdfsad]

For the future self: the difference in code paths becomes quite clear after the following modification:

    try {
        println("${time()} withTimeout before")
        withTimeout(1L) {
            println(coroutineContext.job.isCancelled) // <- this one
                        ...