Log exception from @ExceptionHandler at higher level than debug [SPR-14861]

[spring-projects-issues]

Ibrahim Ghazal opened SPR-14861 and commented

If an @ExceptionHandler annotated method throws an exception, the exception is only logged at the Debug level (see:

spring-framework/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/ExceptionHandlerExceptionResolver.java

Line 385 in 9ccffb6

if (logger.isDebugEnabled()) {

). This means that by default, no log is produced. I think this should instead be logged at Error level.

Note that spring-web-reactive already logs it at the Error level (see:

spring-framework/spring-web-reactive/src/main/java/org/springframework/web/reactive/result/method/annotation/RequestMappingHandlerAdapter.java

Line 241 in 9ccffb6

if (logger.isErrorEnabled()) {

)

---

Affects: 4.3.3

Issue Links:

• ExceptionHandlerExceptionResolver should not log propagated exceptions at warn level [SPR-14907] #19473 ExceptionHandlerExceptionResolver should not log propagated exceptions at warn level
• Exclude an exception from @ExceptionHandler [SPR-13932] #18504 Exclude an exception from @ExceptionHandler

Referenced from: commits 7627c38, 7e80d2d

[spring-projects-issues]

Ibrahim Ghazal commented

To reproduce:

@RestController
public class DemoController {

	@RequestMapping("/")
	public String root() throws Exception {
		throw new Exception("Exception thrown from root()");
	}

	@ExceptionHandler
	public String exceptionHandler(Exception ex) {
		System.err.println("Handling exception");
		throw new RuntimeException("Unexpected RuntimeException!");
	}

}

Only the first exception is logged. "Unexpected RuntimeException!" does not get logged:

Handling exception
�[2m2016-10-30 09:29:54.976�[0;39m �[31mERROR�[0;39m �[35m13772�[0;39m �[2m---�[0;39m �[2m[nio-8080-exec-1]�[0;39m �[36mo.a.c.c.C.[.[.[/].[dispatcherServlet]   �[0;39m �[2m:�[0;39m Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.Exception: Exception thrown from root()] with root cause

java.lang.Exception: Exception thrown from root()
	at org.example.demo.DemoController.root(DemoController.java:12) ~[classes/:na]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_112]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_112]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_112]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_112]
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:136) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:114) ~[spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) ~[spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) ~[spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) ~[spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963) ~[spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897) ~[spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) ~[spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861) ~[spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:622) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) ~[spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:729) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:230) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) ~[tomcat-embed-websocket-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:89) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:108) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:349) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:784) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:802) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1410) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_112]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_112]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at java.lang.Thread.run(Thread.java:745) [na:1.8.0_112]

[spring-projects-issues]

Juergen Hoeller commented

Indeed, debug level does not seem appropriate there since exception handler methods are not meant to throw exceptions of their own in the first place, so it is likely a mistake that needs to be noticed.

I tend to use warn level for such scenarios (since it only affects per-request state, not application-wide state), so I'm considering that level for both the Servlet MVC and the Web Reactive case.

[spring-projects-issues]

Eric Deandrea commented

Yes but they should be able to throw exceptions that are annotated with @ResponseStatus. In that case these aren't necessarily error conditions.

[spring-projects-issues]

Phil Krasko commented

Juergen - I just recently updated to Spring 4.3.4 and started seeing this specific warning spew out in the logs.
I'm also using Spring Security and the AuthenticationException and AccessDeniedExceptions are being handled in the Spring Security filter chain via the ExceptionTranslationFilter.

In my use case I have a generic exception handler which acts as a catch-all across my APIs. I was forced to create another @ExceptionHandler to "re-throw" Spring Security's AccessDeniedException to insure that the generic catch-all handler doesn't handle this exception by mistake (i want it to bubble up and be handled by Spring Security's ExceptionTranslationFilter).

In the particular scenario the warning message is bogus and very misleading. "Failed to invoke @ExceptionHandler method:...". It actually succeeded in calling the handler method and did exactly what I wanted it to do.

Do you have any recommendations on how to handle this? FWIW i understand why the level was changed to WARNING. It seems like this might be a fairly common case for those using both spring web and spring security. Perhaps the alternative/enhancement would be to update the @ExceptionHandler annotation to accept a list of exceptions to ignore in the scenario where a "catch-all" is being used, or create an entirely new annotation to act as a catchall. Usually the list of exceptions to ignore is much smaller than the list of exceptions to include. This would be more maintainable for consumers integrating with the framework, and would avoid the necessity of having to re-throw exceptions from @ExceptionHandlers.

Idea...

@DefaultExceptionHandler(ignores = { AccessDeniedException.class })
@ResponseStatus(HttpStatus.INTERNAL_SERVER_ERROR)
public void handleGenericException(final Throwable ex) {
   // everything falls in here except for ignored items
}

@ExceptionHandler(FooException.class)
public void handleFooException(final FooException ex) {
    return;
}

Spring framework would resolve exceptions as it does today. If the exception isn't handled it would check for the presence of a @DefaultExceptionHandler where the inbound exception is not included in the "ignores" list.

[spring-projects-issues]

Juergen Hoeller commented

Phil Krasko, have you seen #19473 (linked as related above)? We allow an incoming exception to get silently re-thrown now and just log a warning for any other exception coming out of an exception handler method. This is currently just in recent 5.0 snapshots but will be backported to 4.3.5.BUILD-SNAPSHOT soon.

[spring-projects-issues]

Phil Krasko commented

No, I didn't see that but it sums up exactly what I'm after.
Thanks!