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.

Sign up for GitHub

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

Jump to bottom

Strange timeout error even though tests aren't timing out #2714

Closed
natdorshimer opened this issue Dec 6, 2021 · 20 comments · Fixed by #2726
Closed

Strange timeout error even though tests aren't timing out #2714

natdorshimer opened this issue Dec 6, 2021 · 20 comments · Fixed by #2726
Labels
bug 🐛 Issues that report a problem or error in the code. framework 🏗️ Pertains to the core structure and components of the Kotest framework.
Milestone
5.0.2

Comments

@natdorshimer
Copy link

natdorshimer commented Dec 6, 2021 •
edited
Loading

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))
    }
  }
@sksamuel
Copy link
Member

sksamuel commented Dec 7, 2021

Does the timeouts start happening after you've been running the entire test suite for 10 minutes ?
Or do they happen much sooner than that ?

@natdorshimer
Copy link
Author

Does the timeouts start happening after you've been running the entire test suite for 10 minutes ? Or do they happen much sooner than that ?

I've only that timeout happen after running the whole suite as it goes past the 10 minute mark

@sksamuel
Copy link
Member

sksamuel commented Dec 7, 2021 via email

@sksamuel
Copy link
Member

sksamuel commented Dec 7, 2021 via email

@natdorshimer
Copy link
Author

Are you setting 10 minutes as a value anywhere in the codebase? The Kotest suite itself is about 30 minutes long so I don't think there's a hard coded internal timeout causing this, but perhaps the 10 minutes is being picked up and erroneously used for a project timeout.
…
On Mon, 6 Dec 2021 at 23:55, Natalie Dorshimer @.***> wrote: Does the timeouts start happening after you've been running the entire test suite for 10 minutes ? Or do they happen much sooner than that ? I've only that timeout happen after running the whole suite as it goes past the 10 minute mark — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#2714 (comment)>, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAFVSGTHU2NDGLYFDGTKQI3UPWOVZANCNFSM5JPNXF7A . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

As far as I know, no. I can't find Kotest timeout settings set anywhere except in the AbstractProjectConfig. What places could it be trying to grab the timeout from? There is no parent scope in the test that I provided

@sksamuel
Copy link
Member

sksamuel commented Dec 7, 2021 via email

@natdorshimer
Copy link
Author

Then no there aren't any other timeout settings set

@sksamuel
Copy link
Member

sksamuel commented Dec 7, 2021 via email

@sksamuel
Copy link
Member

sksamuel commented Dec 7, 2021

Either a system property or an env var ?

@natdorshimer
Copy link
Author

Nope, nothing like that set in CI or as an env var anywhere

And you mentioned they're supposed to default to 30 minutes instead of 10? Was that a recent change or has it always been like that?

@sksamuel
Copy link
Member

sksamuel commented Dec 7, 2021 via email

@natdorshimer
Copy link
Author

Is that just the project timeout? The default timeout per test appears to be 10 minutes as demo'd here: https://github.com/natdorshimer/kotest-testing

@sksamuel
Copy link
Member

sksamuel commented Dec 7, 2021 via email

@sksamuel
Copy link
Member

sksamuel commented Dec 7, 2021 via email

@sksamuel
Copy link
Member

sksamuel commented Dec 7, 2021

Yes I think you're right.
Turns out 600 x 1000 is not 60 minutes but 10 minutes.
Who knew 😂

@natdorshimer
Copy link
Author

We run our tests with the gradle plugin but either should work to show the default timeout

@natdorshimer
Copy link
Author

natdorshimer commented Dec 8, 2021 •
edited
Loading

Here's what might be happening: Coroutines that use withTimeout and fail bubble up to Kotest's handler for it.

  1. Checkout https://github.com/natdorshimer/kotest-testing
  2. Run ./gradlew test --info or run KotestTesting.kt through intellij
  3. Look at the exception generated
object CoroutineService {
  suspend fun coroutineThatTimesOut(timeout: Duration) =
    withTimeout(timeout.inWholeMilliseconds) {
      launch {
        val sleepTime = timeout.plus(10.milliseconds)
        Thread.sleep(sleepTime.inWholeMilliseconds)
      }.join()
    }
}

class KotestTesting: FunSpec() {
  init {
    test("Test with service that fails withTimeout says that it times out in 10 min instead of 15ms") {
        CoroutineService.coroutineThatTimesOut(15.milliseconds)
    }
  }
}

dev.kotest.testing.KotestTesting > Test with service that fails withTimeout says that it times out in 10 min instead of 15ms FAILED
    io.kotest.engine.test.interceptors.TestTimeoutException: Test 'Test with service that fails withTimeout says that it times out in 10 min instead of 15ms' did not complete within 10m
        at app//io.kotest.engine.test.interceptors.InvocationTimeoutInterceptor.intercept(InvocationTimeoutInterceptor.kt:45)
        at app//io.kotest.engine.test.interceptors.InvocationTimeoutInterceptor$intercept$1.invokeSuspend(InvocationTimeoutInterceptor.kt)
        at app//kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
        at app//kotlinx.coroutines.internal.ScopeCoroutine.afterResume(Scopes.kt:33)
        at app//kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:102)
        at app//kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
        at app//kotlinx.coroutines.internal.ScopeCoroutine.afterResume(Scopes.kt:33)
        at app//kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:102)
        at app//kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
        at app//kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
        at java.base@16.0.2/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
        at java.base@16.0.2/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
        at java.base@16.0.2/java.lang.Thread.run(Thread.java:831)

@sksamuel
Copy link
Member

sksamuel commented Dec 9, 2021

The applicable code here is in InvocationTimeoutInterceptor.
And that only captures a TimeoutCancellationException.

I think if we create a reproduction that has a bunch of test files, each delaying for a few minutes, the error should manifest itself.

@natdorshimer
Copy link
Author

Hmm what do you mean? The build I posted above is an accurate reproduction of the problem I encountered.

Any withTimeout usage in test code will surface as a TestTimeoutException with a duration of kotest timeout instead of the duration that actually caused the original withTimeout failure in the test code. Like if you have a request handler that uses withTimeout with some duration 1s that will print out to the user Test did not complete within 10m.

@sksamuel
Copy link
Member

Here's what might be happening: Coroutines that use withTimeout and fail bubble up to Kotest's handler for it.

Yep that's it, thanks for finding this.

The TimeoutCancellationException that 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.

sksamuel added a commit that referenced this issue Dec 10, 2021
@sksamuel
Fixed erroneous timeout reporting in tests #2714
0695e4b
@sksamuel sksamuel mentioned this issue Dec 10, 2021
Merged
@sksamuel sksamuel added this to the 5.0.2 milestone Dec 10, 2021
@sksamuel sksamuel added bug 🐛 Issues that report a problem or error in the code. framework 🏗️ Pertains to the core structure and components of the Kotest framework. labels Dec 10, 2021
sksamuel added a commit that referenced this issue Dec 10, 2021
@sksamuel
Fixed erroneous timeout reporting in tests #2714 (#2726)
3e9cb80 
* Fixed erroneous timeout reporting in tests #2714

* more
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug 🐛 Issues that report a problem or error in the code. framework 🏗️ Pertains to the core structure and components of the Kotest framework.
Projects
None yet
Milestone
5.0.2
Development

Successfully merging a pull request may close this issue.

Fixed erroneous timeout reporting in tests #2714 kotest/kotest
2 participants
@sksamuel @natdorshimer