cats-effect icon indicating copy to clipboard operation
cats-effect copied to clipboard

using timeout prints stack trace to console if effect throws exception

Open margussipria opened this issue 2 years ago • 9 comments

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

margussipria avatar Apr 14 '22 20:04 margussipria

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)
      }

djspiewak avatar Apr 14 '22 22:04 djspiewak

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.

durban avatar Apr 15 '22 16:04 durban

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.

djspiewak avatar Apr 16 '22 20:04 djspiewak

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.)

durban avatar Apr 22 '22 11:04 durban

Can https://github.com/valskalla/odin/issues/364 be related to this issue?

iRevive avatar Apr 25 '22 06:04 iRevive

@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.

armanbilge avatar Apr 25 '22 13:04 armanbilge

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.

fernandomora avatar May 05 '22 15:05 fernandomora

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?

armanbilge avatar May 05 '22 15:05 armanbilge

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 ...

armanbilge avatar May 05 '22 15:05 armanbilge

I think this is now resolved? Feel free to bump if it's not the case and I'll reopen.

djspiewak avatar Feb 27 '23 17:02 djspiewak