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.

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

Prevent unnecessary duplicated lines in backtraces #2780

Merged
merged 10 commits into from Oct 1, 2021

Conversation

simonbasle
Copy link
Member

@simonbasle simonbasle commented Sep 21, 2021

todo:

  • rework the reference guide accordingly

outdated description:

This commit removes the `i` counter that was effectively guaranteeing
duplicated entries in the backtrace (eg. with a checkpoint) in the case
where the triggering exception was reused. The only differentiator was
then the indentation (driven by `i`).

This is especially visible when using a `checkpoint(String)` operator
along a `retry`. Provided the same exception instance is emitted on each
retry loop, `checkpoint` will add to the backtrace on each loop.

This commit removes the `i` from the tracking of existing backtraces and
thus ensures that for the same parent subscriber, prefix and description
there will be only one entry in the backtrace.

Fixes #2774.

This commit removes the `i` counter that was effectively guaranteeing
duplicated entries in the backtrace (eg. with a checkpoint) in the case
where the triggering exception was reused. The only differentiator was
then the indentation (driven by `i`).

This is especially visible when using a `checkpoint(String)` operator
along a `retry`. Provided the same exception instance is emitted on each
retry loop, `checkpoint` will add to the backtrace on each loop.

This commit removes the `i` from the tracking of existing backtraces and
thus ensures that for the same parent subscriber, prefix and description
there will be only one entry in the backtrace.

Fixes #2774.
@simonbasle simonbasle requested a review from a team as a code owner September 21, 2021 10:45
@simonbasle simonbasle added this to the 3.3.21.RELEASE milestone Sep 21, 2021
@simonbasle simonbasle added the type/bug A general bug label Sep 21, 2021
@simonbasle simonbasle self-assigned this Sep 21, 2021
@simonbasle
Copy link
Member Author

cc @osi @smaldini

@osi
Copy link
Contributor

osi commented Sep 21, 2021

intriguing that this is related to:

in the case where the triggering exception was reused.

.. its a useful clue to look in my code to see where i may be caching something that's unexpected!

@osi
Copy link
Contributor

osi commented Sep 21, 2021

So I had a logic error in my code. I was retrying a Flux that was using cache deeper in the flow, making the retry useless.

As a pattern, this is bad, as retry won't ever succeed. The check against i is the signal that the same exception is being seen.

The current implementation failed by filling my disk with the repeated checkpoints.

What if the check for the same exception instance was kept, but instead of appending to the message it modified the message to indicate that it was repeated?

@simonbasle
Copy link
Member Author

What if the check for the same exception instance was kept, but instead of appending to the message it modified the message to indicate that it was repeated?

I've thought about that but that implies more complex logic for tracking.

What's worse is that even simpler cases quickly become tricky to represent: for example, just creating 2 chains out of the same (erroring) source:

Flux<String> source = Flux.error(new RuntimeException("shared"));
Flux<String> chain1 = source.map(s -> s.toLowerCase());
Flux<String> chain2 = source.filter(s -> s.isEmpty());

This confuses the backtrace production, which would display both map and filter as if they were chained together.

Deep down, it's a matter of trying to represent a graph as a single sequence / line... 🤯

@simonbasle simonbasle linked an issue Sep 22, 2021 that may be closed by this pull request
@simonbasle
Copy link
Member Author

simonbasle commented Sep 22, 2021

@osi @smaldini I have now something that displays a counter before the operator name. It still is not perfect from the perspective of displaying multiple paths, but at least it will prevent infinitely growing backtraces and repetitions while hinting that there are more complex codepaths in play.

@simonbasle
Copy link
Member Author

I wonder to what extent it makes sense to target 3.3.x with this one. it is a change in behavior after all.

@simonbasle
Copy link
Member Author

Note: The reactor-tools shouldn't be impacted, as it delegates to Traces and correctly detects checkpoints, and this change impacts what happens after when the backtrace message is generated.

@osi
Copy link
Contributor

osi commented Sep 22, 2021

thank you @simonbasle

but at least it will prevent infinitely growing backtraces and repetitions while hinting that there are more complex codepaths in play.

this is perfect. it removes the opportunity for accidental catastrophe while leaving hints

@simonbasle
Copy link
Member Author

I have devoted a bit more time to this, and ended up refactoring the "error has been observed" part of the traceback:

  1. when multiple path are traversed, they are more obvious
  2. turned (xN) into (observed N times)
  3. make "roots" more obvious with *__ connector

It looks like this:

Assembly trace from producer [reactor.core.publisher.MonoDefer] :
	reactor.core.publisher.Mono.defer(Mono.java:213)
	reactor.core.publisher.HooksTest.testMultiReceiver(HooksTest.java:747)
Error has been observed at the following site(s):
	*____Mono.defer ⇢ at reactor.core.publisher.HooksTest.testMultiReceiver(HooksTest.java:747)
	*_____Flux.then ⇢ at reactor.core.publisher.HooksTest.testMultiReceiver(HooksTest.java:747)
	|_    Mono.flux ⇢ at reactor.core.publisher.HooksTest.testMultiReceiver(HooksTest.java:749)
	|_ Flux.publish ⇢ at reactor.core.publisher.HooksTest.testMultiReceiver(HooksTest.java:749) (observed 2 times)
	|_     Flux.map ⇢ at reactor.core.publisher.HooksTest.testMultiReceiver(HooksTest.java:751)
	*_____Flux.then ⇢ at reactor.core.publisher.HooksTest.testMultiReceiver(HooksTest.java:747)
	|_    Mono.flux ⇢ at reactor.core.publisher.HooksTest.testMultiReceiver(HooksTest.java:749)
	|_ Flux.publish ⇢ at reactor.core.publisher.HooksTest.testMultiReceiver(HooksTest.java:749) (observed 2 times)
	|_  Flux.filter ⇢ at reactor.core.publisher.HooksTest.testMultiReceiver(HooksTest.java:761)

(in the above we see 3 "roots", and 2 different sub-chains are better identified)

@simonbasle
Copy link
Member Author

Note: fixes #2774 and #2785

Copy link
Contributor

@OlegDokuka OlegDokuka left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@simonbasle simonbasle modified the milestones: 3.3.21.RELEASE, 3.4.11 Sep 27, 2021
@simonbasle simonbasle changed the base branch from 3.3.x to main September 27, 2021 13:57
@simonbasle simonbasle merged commit df44a2d into main Oct 1, 2021
@simonbasle simonbasle deleted the 2774-backtraceExtraneousDuplication branch October 1, 2021 13:46
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type/bug A general bug
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Repeated checkpoints added when using retry
3 participants