cats-effect
cats-effect copied to clipboard
using timeout prints stack trace to console if effect throws exception
IO.delay(throw new Exception("moi 1")).timeout(10 minutes).unsafeRunSync()
does seem to work as expected, but does print exception to console
java.lang.Exception: moi 1
| => rat test.TimeoutSpec.$anonfun$new$4(TimeoutSpec.scala:20)
at delay @ test.TimeoutSpec.$anonfun$new$3(TimeoutSpec.scala:20)
Affected cats-effect version are 3.3.8+
example project for bug https://github.com/margussipria/cats-effect-timout-bug
This is reproducible with the following unit test:
"not report errors in timeouts" in ticked { implicit ticker =>
case object TestException extends RuntimeException
val action = IO.executionContext flatMap { ec =>
IO defer {
var ts: List[Throwable] = Nil
val ec2 = new ExecutionContext {
def reportFailure(t: Throwable) = ts ::= t
def execute(r: Runnable) = ec.execute(r)
}
for {
_ <- (IO.sleep(10.millis) *> IO.raiseError(TestException)).timeout(100.millis).evalOn(ec2).attempt
back <- IO(ts)
} yield back
}
}
action must completeAs(Nil)
}
See #2963, which fixes this specific case. However, it is still possible to do a start/join and observe a similar reporting of an error.
Leaving this open for the moment to track the start
/join
investigation and brainstorm. Honestly this might just be a race condition, but I can't remember exactly how that call chain comes together.
I think it's just a race between the started fiber and join
. If we do this:
for {
fiber <- something.start
oc <- fiber.join
} yield ...
There is a race between something
and the .join
. If something
is quick enough, it may finish before .join
is invoked. In that case IOFiber#done
finds no callbacks, and reports the exception. Later .join
is executed, but by then it's already too late. (RacePair
avoids this problem by using an internal API to create fibers which already have the callbacks added when they're scheduled.)
Can https://github.com/valskalla/odin/issues/364 be related to this issue?
@iRevive it looks like that issue pre-dates CE 3.3.8? This behavior is due to changes in https://github.com/typelevel/cats-effect/pull/2868.
This bug collapsed our logging system with million of errors in the stderr. 🙈
With cats-effect 3.3.11:
@ IO.delay(throw new Exception("message")).timeout(1.minute).attempt.unsafeRunSync()
java.lang.Exception: message
at ammonite.$sess.cmd16$$anonfun$1.apply(cmd16.sc:1)
at ammonite.$sess.cmd16$$anonfun$1.apply(cmd16.sc:1)
at delay @ ammonite.$sess.cmd16$.<clinit>(cmd16.sc:1)
res16: Either[Throwable, Nothing] = Left(java.lang.Exception: message)
@ IO.delay(throw new Exception("message")).attempt.unsafeRunSync()
res17: Either[Throwable, Nothing] = Left(java.lang.Exception: message)
With cats-effect 3.3.7:
@ IO.delay(throw new Exception("message")).timeout(1.minute).attempt.unsafeRunSync()
res5: Either[Throwable, Nothing] = Left(java.lang.Exception: message)
@ IO.delay(throw new Exception("message")).attempt.unsafeRunSync()
res6: Either[Throwable, Nothing] = Left(java.lang.Exception: message)
We have reverted to cats-effect 3.3.7 until there is a new release that solves the problem.
dependencyOverrides ++= Seq(
"org.typelevel" %% "cats-effect" % "3.3.7",
"org.typelevel" %% "cats-effect-kernel" % "3.3.7",
"org.typelevel" %% "cats-effect-std" % "3.3.7"
)
Thanks for the report.
Sorry for your problems and thanks for the report. At this point there's been multiple complaints about this, I've opened https://github.com/typelevel/cats-effect/pull/2978 to revert it 😕 @djspiewak wdyt?
Oh, I missed the fact that https://github.com/typelevel/cats-effect/pull/2963 has not been released yet. As mentioned, that fixes a special case, but this problem could still arise in general. Still, maybe it doesn't deserve a complete revert ...
I think this is now resolved? Feel free to bump if it's not the case and I'll reopen.