kotest: Strange timeout error even though tests aren't timing out
Kotest 5.0.1 The tests followed a simple structure:
class Test: FunSpec() {
init {
test("(test1)") { ... }
test("(test2)") { ... }
test("(test3)") { ... }
}
}
We ended up getting a TestTimeoutException even though each test was under a minute and Test as a whole was definitely less than 10 minutes.
io.kotest.engine.test.interceptors.TestTimeoutException: Test '(test)' did not complete within 10m
at io.kotest.engine.test.interceptors.InvocationTimeoutInterceptor.intercept(InvocationTimeoutInterceptor.kt:45)
at io.kotest.engine.test.interceptors.InvocationTimeoutInterceptor$intercept$1.invokeSuspend(InvocationTimeoutInterceptor.kt)
at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
at kotlinx.coroutines.internal.ScopeCoroutine.afterResume(Scopes.kt:33)
at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:102)
at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
at kotlinx.coroutines.DispatchedTaskrun(DispatchedTask.kt:104)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:834)
2021-12-06 15:39:32.130 [pool-2-thread-1 @coroutine#7421] INFO i.k.p.ProjectConfig$TimerListener - Starting test (test1)
2021-12-06 15:39:51.694 [pool-2-thread-1 @coroutine#7421] INFO i.k.p.ProjectConfig$TimerListener - Duration of (test1) = 19564
2021-12-06 15:39:51.697 [pool-2-thread-1 @coroutine#7854] INFO i.k.p.ProjectConfig$TimerListener - Starting test (test2)
2021-12-06 15:40:21.468 [pool-2-thread-1 @coroutine#7854] INFO i.k.p.ProjectConfig$TimerListener - Duration of (test2) = 29771
2021-12-06 15:40:21.471 [pool-2-thread-1 @coroutine#8286] INFO i.k.p.ProjectConfig$TimerListener - Starting test (test3)
2021-12-06 15:40:23.296 [pool-2-thread-1 @coroutine#8286] INFO i.k.p.ProjectConfig$TimerListener - Duration of (test3) = 1825
Previously only projectTimeout was overriden to 15 since our test suite took longer than 10 minutes.
object ProjectConfig : AbstractProjectConfig() {
...
override val projectTimeout: Duration = 15.minutes
}
I solved the issue by setting them all to 15
override val projectTimeout: Duration = 15.minutes
override val timeout = 15.minutes
override val invocationTimeout = 15.minutes.inWholeMilliseconds
But I’m not sure why that fixed the problem. Each test individually did not take anywhere near 10 minutes, and neither did all of the tests in Test combined.
The test suite as a whole did surpass 10 minutes, but that’s what projectTimeout is for right?
The timer listener producing these logs is:
object TimerListener : TestListener {
private var started = 0L
override suspend fun beforeTest(testCase: TestCase) {
started = System.currentTimeMillis()
log.info("Starting test ${testCase.name.testName}")
}
override suspend fun afterTest(testCase: TestCase, result: TestResult) {
log.info("Duration of ${testCase.name.testName} = " + (System.currentTimeMillis() - started))
}
}
About this issue
- Original URL
- State: closed
- Created 3 years ago
- Comments: 20 (12 by maintainers)
Commits related to this issue
- Fixed erroneous timeout reporting in tests #2714 — committed to kotest/kotest by sksamuel 3 years ago
- Fixed erroneous timeout reporting in tests #2714 (#2726) * Fixed erroneous timeout reporting in tests #2714 * more — committed to kotest/kotest by sksamuel 3 years ago
Yep that’s it, thanks for finding this.
The
TimeoutCancellationExceptionthat is thrown from your own withTimeout is then caught by Kotest’s InvocationTimeoutInterceptor, and then the timeout used by Kotest is reported, even tho that’s not the timeout that was triggered.Yes I think you’re right. Turns out 600 x 1000 is not 60 minutes but 10 minutes. Who knew 😂