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

Inappropriate warn logging in AbstractHandlerExceptionResolver (e.g. for 404 status) [SPR-13596] #18174

Closed
spring-issuemaster opened this Issue Oct 22, 2015 · 6 comments

Comments

Projects
None yet
2 participants
@spring-issuemaster
Copy link
Collaborator

spring-issuemaster commented Oct 22, 2015

Jakob Kylberg opened SPR-13596 and commented

In the AbstractHandlerExceptionResolver the log level for all responses handled by the resolveException method is set to WARN, in bold below. The problem is that not all responses handled by the method are responses that should be treated at the WARN log level, as normal responses to the end user can be handled by this method.

The log level should be reduced to DEBUG.

	@Override
	public ModelAndView resolveException(HttpServletRequest request, HttpServletResponse response,
			Object handler, Exception ex) {

		if (shouldApplyTo(request, handler)) {
			// Log exception at debug log level
			if (this.logger.isDebugEnabled()) {
				this.logger.debug("Resolving exception from handler [" + handler + "]: " + ex);
			}
			prepareResponse(ex, response);
			ModelAndView mav = doResolveException(request, response, handler, ex);
			if (mav != null) {
				// Log exception message at warn log level
				logException(ex, request);
			}
			return mav;
		}
		else {
			return null;
		}
	}

Affects: 4.2.1, 4.2.2

Issue Links:

  • #17691 Spring does not log deserialization / marshalling errors to the console
  • #18189 Consistent warn logging without stacktrace in Portlet HandlerExceptionResolver

Referenced from: commits 76d7f45

0 votes, 5 watchers

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

spring-issuemaster commented Oct 26, 2015

Juergen Hoeller commented

We're only really logging resolved error views at warn level... which doesn't really qualify as a normal user response. REST-like translations to a certain response status etc will never return a ModelAndView there to begin with.

If you're unhappy with the warn-level logging for error views, consider setting your HandlerExceptionResolver's warnLogCategory property to null or overriding the logException method in a custom subclass.

Assigning this to Rossen Stoyanchev for further review. We may of course fine-tune this in 4.3 if there turns out to be some common scenario where warn-level logging is irritating.

Juergen

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

spring-issuemaster commented Oct 26, 2015

Rossen Stoyanchev commented

Indeed the logging occurs when the resolver returns a ModelAndView which indicates the exception was resolved by the handler and an (error) view is about to be displayed. Can you clarify what you mean by "normal responses" in this context? And why switch to DEBUG altogether. Shouldn't that be for "normal" only which leads back to the question about how you would identify a normal response within an exception resolver.

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

spring-issuemaster commented Oct 26, 2015

Jakob Kylberg commented

What I meant with a normal response is e.g. if an exception is thrown by a component in an application and that exception signals that some data hasn't been found and that a 404 should be returned to the client of the application. That exception will be caught by an exception handler and mapped to a 404 response. This flow will pass through the AbstractHandlerExceptionResolver and lead to a WARN log message that in this case IMO is not appropriate as even though it's not a 200 OK flow, it's not something that warrants a WARN log message.

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

spring-issuemaster commented Oct 26, 2015

Juergen Hoeller commented

It turns out that this default warn logging is rather recent: introduced through #17691 for 4.2. We should fine-tune this to only apply to certain kinds of responses then, not firing in case of a plain 404 or the like.

Juergen

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

spring-issuemaster commented Nov 2, 2015

Sébastien Deleuze commented

I resolved this issue by reverting most #17691 changes since #17858 (logging conversion exceptions at DefaultHandlerExceptionResolver level) was a better fix.

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

spring-issuemaster commented Nov 29, 2018

danielrohe commented

We tested the warn logging with an OutputCapture and a validation error and still see that validation errors are logged using the warnLogger for 400. For me it looks like initializing the warn logger in the constructor causes the problem as now it is always set and will always log something (https://github.com/spring-projects/spring-framework/blob/v4.3.21.RELEASE/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/support/DefaultHandlerExceptionResolver.java#L100). .)

In a normal production environment I would run with Info level (which includes warn level) for most of the categories. If in the DefaultHandlerExceptionResolver the warnLogger is set on line 100 and all methods return an empty ModelAndView object the method logException(Exception ex, HttpServletRequest request) in AbstractHandlerExceptionResolver will always be called and logs out the exception because both conditions (warnLogger different than null and warnLevel is enabled) are met.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment