ExceptionHandlerExceptionResolver should not log propagated exceptions at warn level [SPR-14907]

[spring-projects-issues]

Eric Deandrea opened SPR-14907 and commented

In spring-webmvc - org.springframework.web.servlet.mvc.method.annotation.ExceptionHandlerExceptionResolver line 386 was changed from a logger.debug in version 4.3.3 (line 384 in version 4.3.3) to logger.warn in version 4.3.4. This might not seem like a big deal but is causing lots of non-necessary stack traces in our applications.

We have a FaultBarrier implemented as a SpringMVC @ExceptionHandler method, implemented as below. Basically its a generic handler that catches all exceptions. If the exception itself is annotated with @ResponseStatus, we simply re-throw it & let SpringMVC handle it. Now as of version 4.3.4 this is logging warning exception stack traces to our logs which is triggering out paging system to page people (our system pages out if any stack traces appear as WARN or ERROR levels), even though most of the exception codes in the @ResponseStatus are 400 series exceptions and are not error conditions at all. Our only fix so far is to downgrade back to 4.3.3.

@ExceptionHandler(Exception.class)
public ResponseEntity<Object> defaultErrorHandler(Exception ex) throws Exception {
	ResponseStatus responseStatusAnnotation = AnnotationUtils.findAnnotation(ex.getClass(), ResponseStatus.class);

	if (responseStatusAnnotation != null) {
		// If the exception is annotated with @ResponseStatus, rethrow it and let the framework handle it
		throw ex;
	}
	else {
		// Do some other stuff here which isn't important to this issue
	}
}

Here's the stack trace it generates:

[11/14/2016 16:54:24.101 | WARN](http-nio-8080-exec-1 | org.springframework.web.servlet.mvc.method.annotation.ExceptionHandlerExceptionResolver:386): Failed to invoke @ExceptionHandler method: public org.springframework.http.ResponseEntity<java.lang.Object> my.app.common.api.FaultBarrier.defaultErrorHandler(java.lang.Exception) throws java.lang.Exception
my.app.model.NotFoundException: Policy 1000 was not found
	at my.app.api.PoliciesApi.convert(PoliciesApi.java:126)
	at my.app.api.PoliciesApi.getPolicy(PoliciesApi.java:100)
	at my.app.api.PoliciesApi$$FastClassBySpringCGLIB$$b9887c8b.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:720)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
	at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:133)
	at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:121)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655)
	at my.app.api.PoliciesApi$$EnhancerBySpringCGLIB$$2c76a269.getPolicy(<generated>)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:220)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:134)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:116)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:230)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.springframework.boot.web.filter.ApplicationContextHeaderFilter.doFilterInternal(ApplicationContextHeaderFilter.java:55)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:105)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:89)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:107)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:108)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:349)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:784)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:802)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1410)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)
Caused by: my.app.model.PolicyNotFoundException: Policy 1000 was not found

---

Affects: 4.3.4

Issue Links:

• Log exception from @ExceptionHandler at higher level than debug [SPR-14861] #19427 Log exception from @ExceptionHandler at higher level than debug
• Allow HTTP status exceptions to be easily thrown from Controllers [SPR-14895] #19461 Allow HTTP status exceptions to be easily thrown from Controllers
• ExceptionHandlerExceptionResolver started to log on WARN level [SPR-17383] #21916 ExceptionHandlerExceptionResolver started to log on WARN level
• Exclude an exception from @ExceptionHandler [SPR-13932] #18504 Exclude an exception from @ExceptionHandler

Referenced from: commits 96bfc14, f22a4a4

[spring-projects-issues]

Juergen Hoeller commented

Good point, rethrowing the original exception is indeed a valid use case. Note, however, that we're not going to process the actual rethrown exception; we just take it as an indication that default processing needs to be applied to the original exception. So if any other than the original exception comes out of such a handler method, we're going to log a warning still... but not for the original exception itself anymore.

[spring-projects-issues]

Eric Deandrea commented

That sounds ok as long as at the end of the day if my application throws some RuntimeException that is annotated with @ResponseStatus that there is no warning nor stack trace logged then that satisfies this requirement.

[spring-projects-issues]

Juergen Hoeller commented

That is certainly the case now. We only really intended to log a warning for accidental exceptions coming out of a handler method, e.g. assertion failures within the exception handler method itself. Rethrowing the original exception (no matter whether with or without @ResponseStatus) is the only valid case here, triggering the rest of the exception resolver chain, so we're explicitly letting it through without any logging now.

[spring-projects-issues]

Eric Deandrea commented

Thanks a bunch!

[spring-projects-issues]

dfreudenberger commented

It seems like we have the same issue again since spring-webmvc-5.0.9.RELEASE. The regression was introduced with this commit 04141de#diff-4386c732a724a039db2007b1bac7d3d5R141. Happy to be wrong but as of right now I don't see how I can get rid of the warning without raising the logging threshold for the package / class to error.

[spring-projects-issues]

pebo commented

I face the same issue in spring boot 2.0.6 (5.0.10.RELEASE of web mvc)

[spring-projects-issues]

Juergen Hoeller commented

pebo, this is an unfortunate regression that we're tracking in #21916. Should be fixed in the latest 5.0.11.BUILD-SNAPSHOT already.