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

Deprecates ExceptionLoggingFilter and disables it by default #1633

Merged
merged 4 commits into from May 15, 2020

Conversation

codefromthecrypt
Copy link
Contributor

@codefromthecrypt codefromthecrypt commented May 15, 2020

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 remove this, ending 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.

`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.
@codefromthecrypt
Copy link
Contributor Author

It may be curious what's the alternative? for those impeded by Spring Boot's recommendation about error handling here.. https://docs.spring.io/spring-boot/docs/current-SNAPSHOT/reference/htmlsingle/#boot-features-error-handling

they can do exactly what this does, which is add a servlet filter which logs uncaught exceptions.

	@Bean
	@ConditionalOnProperty("spring.sleuth.web.exception-logging-filter-enabled")
	public FilterRegistrationBean exceptionThrowingFilter(
			SleuthWebProperties webProperties) {
		FilterRegistrationBean filterRegistrationBean = new FilterRegistrationBean(
				new ExceptionLoggingFilter());
		filterRegistrationBean.setDispatcherTypes(DispatcherType.ASYNC,
				DispatcherType.ERROR, DispatcherType.FORWARD, DispatcherType.INCLUDE,
				DispatcherType.REQUEST);
		filterRegistrationBean.setOrder(webProperties.getFilterOrder());
		return filterRegistrationBean;
	}

Those that don't wish to do that can know that the span will include an error regardless, and unlike the filter here, it will also be there in async cases. A future different solution could be considered, but I think we've proven over the last few years without reasonable doubt.. the current strategy of having sleuth log synchronous errors is not the right answer to the problem of uncaught exception management

@codecov
Copy link

codecov bot commented May 15, 2020

Codecov Report

Merging #1633 into 2.2.x will decrease coverage by 0.26%.
The diff coverage is 71.42%.

Impacted file tree graph

@@             Coverage Diff              @@
##              2.2.x    #1633      +/-   ##
============================================
- Coverage     59.26%   59.00%   -0.27%     
+ Complexity      853      848       -5     
============================================
  Files           161      161              
  Lines          4662     4664       +2     
  Branches        533      535       +2     
============================================
- Hits           2763     2752      -11     
- Misses         1643     1655      +12     
- Partials        256      257       +1     
Impacted Files Coverage Δ Complexity Δ
.../sleuth/instrument/web/ExceptionLoggingFilter.java 0.00% <ø> (-63.64%) 0.00 <0.00> (-5.00)
...strument/web/TraceWebServletAutoConfiguration.java 83.33% <ø> (-16.67%) 4.00 <0.00> (-1.00)
...loud/sleuth/autoconfig/TraceAutoConfiguration.java 81.31% <66.66%> (-1.83%) 27.00 <4.00> (+1.00) ⬇️
...k/cloud/sleuth/log/SleuthLogAutoConfiguration.java 100.00% <100.00%> (ø) 1.00 <0.00> (ø)

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 75756fd...81ca576. Read the comment docs.

@codefromthecrypt
Copy link
Contributor Author

PS I added a commit showing that you can log the exception from any framework using a FinishedSpanHandler (soon to be SpanHandler in Brave 5.12 which is next release here)

This works even with buggy stuff like webflux that frequently loses context, provided the exception hook was eventually called cc @olssonoskar

@codefromthecrypt codefromthecrypt merged commit f982149 into 2.2.x May 15, 2020
@codefromthecrypt codefromthecrypt deleted the deprecate-ExceptionLoggingFilter branch May 15, 2020 12:27
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants