Open geirolz opened 2 years ago
This is very interesting! Can definitely confirm this is a bug.
Okay, I figured this out. It has to do with the way that we're keying traces. full
tracing mode should have avoided the issue, but that appears to have some other issues that need ironing out.
The problem is that the first one wins on determining the call site for the flatMap
inside of timeout
. Anything starting with the cats.
package is filtered out, which is why the trace lists your source code as being the caller. When you only have the one timeout
call, the call site is correct (relative to expectations), and so you see the right thing in the trace (albeit with some repeated frames due to the aforementioned filtering). With multiple timeout
s, you'll end up getting the very first as the trace value for the flatMap
inside of timeout
(since obviously that flatMap
is fully shared), meaning that all timeout
s will be traced back to that very first evaluation call site, which is precisely why the stack trace is so weird.
This is a bit annoying. Under normal circumstances, we wouldn't be trying to trace timeout
at all, it's just the fact that it happens to be derived from flatMap
and race
which makes it in any way traceable, but of course it's the same flatMap
every time, resulting in the unintuitive attribution you reproduced. Going to give some thought to this.
Sorry for the late reply @djspiewak, thank you for your detailed explanation. The real problem is that when you have several timeouts with the same duration could be difficult to understand which one is expired(this is the problem we had in prod and the reason behind this ticket)
I expected as much, but one thing kind of puzzles me: even if the last trace frame is deceptive, wouldn't the previous trace frames be a little more illustrative? That doesn't hold true in the OP example, but a production codebase is unlikely to just consist of a whole bunch of timeout
calls.
In our case we have an engine that executes some steps ( like saga orchestrator pattern ), each step has a max timeout in the engine while each step action is defined as IO
so, in some case, we have timeout inside the step action.
That step action sometimes is a composition of multiple IO
that could have an inner timeout.
So, in case of timeout exception, we have a stack trace that brings us in the first timeout that isn't the one that threw the exception
So as a quick note, one workaround (not ideal, but functional) for this problem would be to replace .timeout(5.seconds)
with .timeoutTo(5.seconds, IO.defer(IO.raiseError(new TimeoutException)))
. (credit to @armanbilge for realizing this would solve it)
Thanks, @djspiewak!
not ideal
just because it is a bit verbose?
Just because it's a bit verbose :-) It's annoying because it's forcing you to effectively inline a combinator in order to manipulate the stack trace. This type of thing is somewhat to be expected, but that doesn't make it ideal.
Tested this again with v3.5.0-RC5. Setting cats.effect.tracing.mode=full
seems to give accurate stack traces, so if there was a bug there it was since quashed.
For cached
tracing it is technically working as it should AFAICT ... and in a production codebase, it seems like there should typically be other context in the trace anyway ... right? 😀
Btw, here's a slightly minimized minimizer.
The only way I can think to fix this for cached
tracing is maybe if we collected some other trace event at the timeout
call site and inserted it into the stack. E.g. if it was => Duration
. But that's a rather bespoke change that would have to happen in the typeclasses.
So I propose we either:
timeout
Btw, another related idea I had: we currently have IO.trace: IO[Trace]
which returns the current trace. But I wonder if we could have something like:
object IO {
def traced[A](=> ioa: IO[A]): IO[A] = ???
}
It would basically be like defer
but collect and insert(/replace?) a tracing event via the lambda, as an easier workaround for these kinds of issues. Actually, I don't yet fully understand why this doesn't work with defer
already.
Given the following code, I get a
TimeoutException
for 15000 millis that is right BUT the stack trace take me to the line oft2
instead oft3
I was expecting that the stack trace takes me to the timeout exceededWhile if I add a timeout at
t1
i get the same exception but the stack trace bring me tot1
If there aren't nested timeout i get the right stack trace
The issue persists with all
cats.effect.tracing.mode
mode