Improve behavior on timeout in runTest (#3071)

* The error is more verbose: it lists the active children.
* If the test coroutine is already finishing with an error, that error
  is added to the timeout notification as suppressed.
* The timeout is considered more important, so now, if there were
  any uncaught exceptions, they don't take precedence over it but
  are suppressed by it.

Fixes #3066
Fixes #3069

Author: dkhalanskyjb

kotlinx-coroutines-core/common/src/internal/StackTraceRecovery.common.kt

@@ -40,6 +40,7 @@ internal expect suspend inline fun recoverAndThrow(exception: Throwable): Nothin
  * The opposite of [recoverStackTrace].
  * It is guaranteed that `unwrap(recoverStackTrace(e)) === e`
  */
+@PublishedApi // only published for the multiplatform tests in our own code
 internal expect fun <E: Throwable> unwrap(exception: E): E
 
 internal expect class StackTraceElement

kotlinx-coroutines-test/common/src/TestBuilders.kt

@@ -164,7 +164,7 @@ public fun TestScope.runTest(
 ): TestResult = asSpecificImplementation().let {
     it.enter()
     createTestResult {
-        runTestCoroutine(it, dispatchTimeoutMs, testBody) { it.leave() }
+        runTestCoroutine(it, dispatchTimeoutMs, TestScopeImpl::tryGetCompletionCause, testBody) { it.leave() }
     }
 }
 
@@ -190,18 +190,20 @@ internal const val DEFAULT_DISPATCH_TIMEOUT_MS = 60_000L
  * Run the [body][testBody] of the [test coroutine][coroutine], waiting for asynchronous completions for at most
  * [dispatchTimeoutMs] milliseconds, and performing the [cleanup] procedure at the end.
  *
+ * [tryGetCompletionCause] is the [JobSupport.completionCause], which is passed explicitly because it is protected.
+ *
  * The [cleanup] procedure may either throw [UncompletedCoroutinesError] to denote that child coroutines were leaked, or
  * return a list of uncaught exceptions that should be reported at the end of the test.
  */
 internal suspend fun <T: AbstractCoroutine<Unit>> runTestCoroutine(
     coroutine: T,
     dispatchTimeoutMs: Long,
+    tryGetCompletionCause: T.() -> Throwable?,
     testBody: suspend T.() -> Unit,
     cleanup: () -> List<Throwable>,
 ) {
     val scheduler = coroutine.coroutineContext[TestCoroutineScheduler]!!
-    /** TODO: moving this [AbstractCoroutine.start] call outside [createTestResult] fails on Native with
-     * [TestCoroutineDispatcher], because the event loop is not started. */
+    /** TODO: moving this [AbstractCoroutine.start] call outside [createTestResult] fails on JS. */
     coroutine.start(CoroutineStart.UNDISPATCHED, coroutine) {
         testBody()
     }
@@ -222,13 +224,7 @@ internal suspend fun <T: AbstractCoroutine<Unit>> runTestCoroutine(
                 // we received knowledge that `scheduler` observed a dispatch event, so we reset the timeout
             }
             onTimeout(dispatchTimeoutMs) {
-                try {
-                    cleanup()
-                } catch (e: UncompletedCoroutinesError) {
-                    // we expect these and will instead throw a more informative exception just below.
-                    emptyList()
-                }.throwAll()
-                throw UncompletedCoroutinesError("The test coroutine was not completed after waiting for $dispatchTimeoutMs ms")
+                handleTimeout(coroutine, dispatchTimeoutMs, tryGetCompletionCause, cleanup)
             }
         }
     }
@@ -244,6 +240,41 @@ internal suspend fun <T: AbstractCoroutine<Unit>> runTestCoroutine(
     cleanup().throwAll()
 }
 
+/**
+ * Invoked on timeout in [runTest]. Almost always just builds a nice [UncompletedCoroutinesError] and throws it.
+ * However, sometimes it detects that the coroutine completed, in which case it returns normally.
+ */
+private inline fun<T: AbstractCoroutine<Unit>> handleTimeout(
+    coroutine: T,
+    dispatchTimeoutMs: Long,
+    tryGetCompletionCause: T.() -> Throwable?,
+    cleanup: () -> List<Throwable>,
+) {
+    val uncaughtExceptions = try {
+        cleanup()
+    } catch (e: UncompletedCoroutinesError) {
+        // we expect these and will instead throw a more informative exception.
+        emptyList()
+    }
+    val activeChildren = coroutine.children.filter { it.isActive }.toList()
+    val completionCause = if (coroutine.isCancelled) coroutine.tryGetCompletionCause() else null
+    var message = "After waiting for $dispatchTimeoutMs ms"
+    if (completionCause == null)
+        message += ", the test coroutine is not completing"
+    if (activeChildren.isNotEmpty())
+        message += ", there were active child jobs: $activeChildren"
+    if (completionCause != null && activeChildren.isEmpty()) {
+        if (coroutine.isCompleted)
+            return
+        // TODO: can this really ever happen?
+        message += ", the test coroutine was not completed"
+    }
+    val error = UncompletedCoroutinesError(message)
+    completionCause?.let { cause -> error.addSuppressed(cause) }
+    uncaughtExceptions.forEach { error.addSuppressed(it) }
+    throw error
+}
+
 internal fun List<Throwable>.throwAll() {
     firstOrNull()?.apply {
         drop(1).forEach { addSuppressed(it) }

kotlinx-coroutines-test/common/src/TestScope.kt

@@ -216,6 +216,9 @@ internal class TestScopeImpl(context: CoroutineContext) :
         }
     }
 
+    /** Throws an exception if the coroutine is not completing. */
+    fun tryGetCompletionCause(): Throwable? = completionCause
+
     override fun toString(): String =
         "TestScope[" + (if (finished) "test ended" else if (entered) "test started" else "test not started") + "]"
 }

kotlinx-coroutines-test/common/test/RunTestTest.kt

@@ -5,6 +5,7 @@
 package kotlinx.coroutines.test
 
 import kotlinx.coroutines.*
+import kotlinx.coroutines.internal.*
 import kotlinx.coroutines.flow.*
 import kotlin.coroutines.*
 import kotlin.test.*
@@ -97,6 +98,59 @@ class RunTestTest {
         }
     }
 
+    /** Tests that, on timeout, the names of the active coroutines are listed,
+     * whereas the names of the completed ones are not. */
+    @Test
+    @NoJs
+    @NoNative
+    fun testListingActiveCoroutinesOnTimeout(): TestResult {
+        val name1 = "GoodUniqueName"
+        val name2 = "BadUniqueName"
+        return testResultMap({
+            try {
+                it()
+                fail("unreached")
+            } catch (e: UncompletedCoroutinesError) {
+                assertTrue((e.message ?: "").contains(name1))
+                assertFalse((e.message ?: "").contains(name2))
+            }
+        }) {
+            runTest(dispatchTimeoutMs = 10) {
+                launch(CoroutineName(name1)) {
+                    CompletableDeferred<Unit>().await()
+                }
+                launch(CoroutineName(name2)) {
+                }
+            }
+        }
+    }
+
+    /** Tests that the [UncompletedCoroutinesError] suppresses an exception with which the coroutine is completing. */
+    @Test
+    fun testFailureWithPendingCoroutine() = testResultMap({
+        try {
+            it()
+            fail("unreached")
+        } catch (e: UncompletedCoroutinesError) {
+            @Suppress("INVISIBLE_MEMBER")
+            val suppressed = unwrap(e).suppressedExceptions
+            assertEquals(1, suppressed.size)
+            assertIs<TestException>(suppressed[0]).also {
+                assertEquals("A", it.message)
+            }
+        }
+    }) {
+        runTest(dispatchTimeoutMs = 10) {
+            launch {
+                withContext(NonCancellable) {
+                    awaitCancellation()
+                }
+            }
+            yield()
+            throw TestException("A")
+        }
+    }
+
     /** Tests that real delays can be accounted for with a large enough dispatch timeout. */
     @Test
     fun testRunTestWithLargeTimeout() = runTest(dispatchTimeoutMs = 5000) {
@@ -105,14 +159,24 @@ class RunTestTest {
         }
     }
 
-    /** Tests uncaught exceptions taking priority over dispatch timeout in error reports. */
+    /** Tests uncaught exceptions being suppressed by the dispatch timeout error. */
     @Test
     @NoNative // TODO: timeout leads to `Cannot execute task because event loop was shut down` on Native
     fun testRunTestTimingOutAndThrowing() = testResultMap({ fn ->
-        assertFailsWith<IllegalArgumentException> { fn() }
+        try {
+            fn()
+            fail("unreached")
+        } catch (e: UncompletedCoroutinesError) {
+            @Suppress("INVISIBLE_MEMBER")
+            val suppressed = unwrap(e).suppressedExceptions
+            assertEquals(1, suppressed.size)
+            assertIs<TestException>(suppressed[0]).also {
+                assertEquals("A", it.message)
+            }
+        }
     }) {
         runTest(dispatchTimeoutMs = 1) {
-            coroutineContext[CoroutineExceptionHandler]!!.handleException(coroutineContext, IllegalArgumentException())
+            coroutineContext[CoroutineExceptionHandler]!!.handleException(coroutineContext, TestException("A"))
             withContext(Dispatchers.Default) {
                 delay(10000)
                 3

kotlinx-coroutines-test/jvm/src/migration/TestBuildersDeprecated.kt

@@ -8,7 +8,6 @@
 package kotlinx.coroutines.test
 
 import kotlinx.coroutines.*
-import kotlinx.coroutines.selects.*
 import kotlin.coroutines.*
 import kotlin.jvm.*
 
@@ -137,9 +136,9 @@ public fun runTestWithLegacyScope(
 ): TestResult {
     if (context[RunningInRunTest] != null)
         throw IllegalStateException("Calls to `runTest` can't be nested. Please read the docs on `TestResult` for details.")
-    val testScope = TestBodyCoroutine<Unit>(createTestCoroutineScope(context + RunningInRunTest))
+    val testScope = TestBodyCoroutine(createTestCoroutineScope(context + RunningInRunTest))
     return createTestResult {
-        runTestCoroutine(testScope, dispatchTimeoutMs, testBody) {
+        runTestCoroutine(testScope, dispatchTimeoutMs, TestBodyCoroutine::tryGetCompletionCause, testBody) {
             try {
                 testScope.cleanup()
                 emptyList()
@@ -169,9 +168,9 @@ public fun TestCoroutineScope.runTest(
     block: suspend TestCoroutineScope.() -> Unit
 ): TestResult = runTestWithLegacyScope(coroutineContext, dispatchTimeoutMs, block)
 
-private class TestBodyCoroutine<T>(
+private class TestBodyCoroutine(
     private val testScope: TestCoroutineScope,
-) : AbstractCoroutine<T>(testScope.coroutineContext, initParentJob = true, active = true), TestCoroutineScope {
+) : AbstractCoroutine<Unit>(testScope.coroutineContext, initParentJob = true, active = true), TestCoroutineScope {
 
     override val testScheduler get() = testScope.testScheduler
 
@@ -187,4 +186,7 @@ private class TestBodyCoroutine<T>(
         )
 
     fun cleanup() = testScope.cleanupTestCoroutines()
+
+    /** Throws an exception if the coroutine is not completing. */
+    fun tryGetCompletionCause(): Throwable? = completionCause
 }

kotlinx-coroutines-test/jvm/test/migration/RunTestLegacyScopeTest.kt

@@ -6,6 +6,7 @@ package kotlinx.coroutines.test
 
 import kotlinx.coroutines.*
 import kotlinx.coroutines.flow.*
+import kotlinx.coroutines.internal.*
 import kotlin.coroutines.*
 import kotlin.test.*
 
@@ -100,10 +101,20 @@ class RunTestLegacyScopeTest {
 
     @Test
     fun testRunTestTimingOutAndThrowing() = testResultMap({ fn ->
-        assertFailsWith<IllegalArgumentException> { fn() }
+        try {
+            fn()
+            fail("unreached")
+        } catch (e: UncompletedCoroutinesError) {
+            @Suppress("INVISIBLE_MEMBER")
+            val suppressed = unwrap(e).suppressedExceptions
+            assertEquals(1, suppressed.size)
+            assertIs<TestException>(suppressed[0]).also {
+                assertEquals("A", it.message)
+            }
+        }
     }) {
         runTestWithLegacyScope(dispatchTimeoutMs = 1) {
-            coroutineContext[CoroutineExceptionHandler]!!.handleException(coroutineContext, IllegalArgumentException())
+            coroutineContext[CoroutineExceptionHandler]!!.handleException(coroutineContext, TestException("A"))
             withContext(Dispatchers.Default) {
                 delay(10000)
                 3