New SPAN created for handling on /error when request does not have span header
#859
Comments
|
It's a known issue that I haven't filed. Thanks for doing that for me ;) |
|
Well... according to me, everything is fine in |
|
Seriously? Interesting, I'll double check that then. Thanks for the sample! |
|
I suspect a new span is actually created for |
|
I think that the problem might be present in both cases but Brave & Zipkin combination is handled in a more intelligent way. |
|
To give you some background: we have a custom handler behind |
|
I wonder if the difference in behaviour comes from the following changes in
What's the purpose of instrumenting the HandlerExceptionResolver by the way - besides maybe capturing details about the exception... ? |
|
In The problem wasn't with the aspect, it was in |
|
Nice - I'm gonna test latest SNAPSHOT asap. I'll keep you informed. Your comment let me think the TraceFilter expects Tomcat to forward the request to |
Correct
I haven't tested that at all so we can actually give it a go and check it out. |
`ExceptionLoggingFilter` logs "Uncaught exception thrown" to error level when there is a synchronous exception not otherwise swallowed. This is a cure worse than the disease. This issue disables by default and the 3.x should end the years of problems it caused. Fixes #1347 This was done IIUC to help @jfuerth who had log messages with trace IDs, except the uncaught one, in #714 (Sept 2017). They were formerly told to use `ExceptionHandler` and noted that didn't work in practice as it subverted their status code logic. Concretely, 4203566 "solved" the issue by having sleuth log all uncaught exceptions with the message "Uncaught exception thrown". This code was initially embedded in sleuth's and later pulled out to `ExceptionLoggingFilter` in 2.0. A few months later @brenuart noticed this "solution" had problems. For example, it caused the same exception to be logged twice. Bertrand also mentioned some faults in the implementation including edge cases like `ClientAbortException` not addressed by this. (In fact, there are even more problems: the implementation assumes async isn't in use!) Bertands concerns about this having surprising logging effects were dismissed as a non-issue. Bertrand raised #859 about glitches this caused, the status_code related ones being if statemented around, and it went quiet a while. A month later @oburgosm opened #902 (currently 5 thumbs up) asking to remove the "Uncaught exception thrown" or at least set it to debug. The response was if they don't like it, control their own tracing filter and the issue was closed. A month later, @nickcodefresh opened #966 confused about "Uncaught exception thrown" messages raised by sleuth, incidentally the `ClientAbortException` mentioned by @brenuart before. Because the logging came from Sleuth, it appeared they were zipkin errors, and was explained they weren't. A year later, @T3rm1 opened #1347 to remove the filter, or at least disable it by default. The response was first to set the Logger to OFF. A few days later the issue was closed as the submitter was told they were the first person to complain about this. 5 months later, another user rallied for support. In April 2020, #902 was re-touched by @kosciej who asked to please reconsider, mentioning it was not typical even in Spring to do this, for example 'org.springframework.web.filter' package. The impact of needing to specifically change apps to OFF the sleuth logger seemed harsh. The suggestion was instead of setting log config, to set a property instead `spring.sleuth.web.exception-logging-filter-enabled`, to `false` as that could also accomplish the goal of stopping "Uncaught exception thrown". A month later (yesterday) @MrHurniak commented again on #1347 with the usual complaint that it is redundant and confusing.
Uncaught exceptions are catched by Tomcat and forwarded to
/errorfor handling by Spring's defaultBasicErrorController.It appears the span logged from within the
BasicErrorHandler(and anywhere in the handling chain after the TraceFilter) may not refer to the same span as from within the handler that threw the uncaught exception. It actually depends on whether the original request had span headers on it or not:/error/error.This behaviour is observed with SpringCloud
Edgware.SR2.Things are different however with
Finchley.M6: the same span is reported in both cases.I have attached two sample applications to illustrate the case. They are built from Spring Initializr with Web and Sleuth features only. Both are the same except one is built on
Edgware.SR2and the other onFinchley.SR6.The application contains a simple RestController that logs a small message and throws a RuntimeException whenever it receives a request (mapped on
/**).The context also contains a custom DefaultErrorAttributes with the same behaviour as the original except it logs a message when the
errorAttributes()method is invoked. This method is invoked after Tomcat has forwarded the request to the ErrorDispatcher after reception of an uncaught exception.The application starts on port 8080 by default.
Scenario 1
Invoke the service - an uncaught RuntimeException is thrown
Application logs:
The first two lines are caused by the request hitting the RestController handler. They both refer to the same Span (
e7f50e4c43a76f7c).The third line is logged by Tomcat because of the uncaught exception - it does not contain any Span (as expected, see #714).
The last line is caused by the handling on
/error.--> Logs generated by
/errorrefer to a DIFFERENT span than when the request originally hit the rest controller.Scenario 2
Invoke the service with Span headers:
Application logs:
Note: exception logged by Tomcat is omitted for brevity.
--> All logs now refer to the SAME span, including those generated by
/error.The text was updated successfully, but these errors were encountered: