view/ JSP compilation exceptions, not logged from JstlView or DispatcherServlet. [SPR-10340]

[spring-projects-issues]

Thomas Whitmore opened SPR-10340 and commented

View Rendering/ JSP/ JSP compilation errors are not logged at WARN level by standard Spring MVC framework. (DispatcherServlet, JstlView, AbstractView, etc).

This is particularly an issue when building AJAX pages -- by comparison, when building main HTML pages, a default Tomcat exception-trace can be seen in the browser.

View compilation/ rendering exceptions should really be logged at WARN level -- these are pretty major.

---

Affects: 3.1.2

[spring-projects-issues]

Rossen Stoyanchev commented

I'd expect those exceptions bubble all the way up to the container in which case they should be "visible". Or are they getting caught somewhere? What's the outcome that you see?

[spring-projects-issues]

Thomas Whitmore commented

Hi Rossen, thanks for your quick response.

Errors in AJAX pages are not visible. No exception is logged to my application (Log4J) logs or the Tomcat console.

Tomcat, no error-handling configured in web.xml -- pretty bog standard. There's one AnnotationMethodHandlerExceptionResolver in my XML, which wouldn't appear to apply at the view-rendering phase of handling.

Tomcat's producing a default error-page, which (since not a success) doesn't show anything in most AJAX handlers. Nothing shows on the Tomcat console, or in my application logs, whatsoever.

The only place I can find any error-reporting is when I go digging in Tomcat/logs/localhost -- I can find a whole load of exceptions, completely without context (no application logging around or leading up to them).

Tomcat 6.0.35, Spring 3.1.2.

I've looked thru the DispatcherServlet, JstlView and View ancestor classes. There's 'DEBUG' logging of dispatching & view rendering, etc, but no 'WARN' logging of failures. It would appear to me that DispatcherServlet.render() would be an ideal place to catch, log, & re-throw such exceptions.

Controller errors, earlier in the request-processing cycle, appear to typically be logged via HandlerExceptionResolver -- which works fine. However, HandlerExceptionResolvers are not applicable during View rendering. So this phase of processing, needs more robust error-reporting.

Thanks again for your interest, Rossen.

[spring-projects-issues]

Rossen Stoyanchev commented

So I still don't quite understand what happens with the exceptions? You wrote those are errors in Ajax pages that are not visible and you also implied the exceptions occur during view rendering. However, view rendering happens on the server side while Ajax requests are performed from the client side. So I'm not sure what is different or special about the Ajax pages.

JSP rendering is done by forwarding through the Servlet container. I presume at some point during JSP rendering, an exception occurs. What happens then? Since forwarding is a synchronous call (i.e. happens on the same thread), I would expect that the call stack to unwind and the exception will bubble up through Spring MVC and into the Servlet container, which by default should send an error page to the client. It doesn't sounds like this is the case. What happens with the exception instead?

It might help to use a debugger. IDEs allow creating breakpoints for when specific exception types are raised.

[spring-projects-issues]

Thomas Whitmore commented

Spring doesn't log the error to my loggers, Tomcat doesn't log the error to my loggers or the console. It doesn't get logged anywhere I would see it.

Tomcat renders it as an 'error page'. That assumes, that I'm viewing it as a main HTML page in the browser. However since it is an AJAX response & AJAX handlers typically only show on "200 success" responses, and then with various ways in which they treat the result. Therefore in AJAX scenarios, error details are likely never surfaced.

Frankly we need view-rendering errors to go to the application logs & the Tomcat console, not just be allowed to disappear. (I think Tomcat has also got it pretty wrong here, as well, in rendering it to a response-page without printing it on the console.)

But we definitely need it logged at application level, so it shows up.

[spring-projects-issues]

Rossen Stoyanchev commented

That assumes, that I'm viewing it as a main HTML page in the browser.

I'm not make any assumptions. I'm simply trying to understand what happens to the exception. I wrote a summary of what could be taking place and posed some questions (that remain not answered):

JSP rendering is done by forwarding through the Servlet container. I presume at some point during JSP rendering, an exception occurs. What happens then? Since forwarding is a synchronous call (i.e. happens on the same thread), I would expect that the call stack to unwind and the exception will bubble up through Spring MVC and into the Servlet container, which by default should send an error page to the client. It doesn't sounds like this is the case. What happenswith the exception instead?

Without a clear understanding of what's going on, I can't offer a fix. A fix could come in many forms, including no fix at all if it is possible for an application to handle (and log) the exception. If it isn't possible for the application to handle the exception, then that is an issue as well. So we can't just add logging without understanding better what actually happens with the exception.

If it is possible to create a small sample at our issue repro repository that would be really ideal.

[spring-projects-issues]

Thomas Whitmore commented

Hi Rossen, I've tried to explain this absolutely clearly, twice.

The point here is that exceptions in View-rendering pass out of Spring without being logged by Spring or application logs, and that the Tomcat error-page is not visible in the browser since it goes only to an AJAX handler and is not an "200 success".

Exceptions thrown during Controller handling, are dealt with by HandlerExceptionResolver -- which have a property "warnLogCategory" to enable exceptions to be logged, inside application logs.

Exceptions thrown during View rendering, are not dealt with by a HandlerExceptionResolver -- and, as explained, there is not an opportunity to log these into application logs. We also have the situation where Tomcat's default behaviour prevents the trace being seen at all, for AJAX views.

Does this not absolutely clearly explain the issue here?

[spring-projects-issues]

Thomas Whitmore commented

I've already traced where the exception went, what the potential for logging/ reporting it is, how it compares with exception handling/reporting during the Controller handling phase.

I did all these analyses before I posted the issue! And summarized them in the issue & in my first comment. I'm really not sure what was unclear about it.

DispatcherServlet is processing thru doDispatch(), calls to render(), exceptions are thrown somewhere in there, and neither JstlView/ DispatcherServlet ever offer a "warnLogCategory" or means to properly log the exceptions.

I've got line-numbers in the 3.1.2 Spring source, do you want those?

[spring-projects-issues]

Rossen Stoyanchev commented

Thomas, there is no need for that. Please, understand sometimes things do get lost in translation. If I'm asking follow-up questions, it's because something is not clear to me. What threw me off is the initial explanation that made it sound like there was something special about Ajax requests. There isn't and I get it now. I suppose I was thinking more about the exception handling side of things rather than simply logging. I still find it slightly odd that the question is about logging and not about handling such exceptions in which case logging can be done in addition to handling.

At any rate, have you considered a HandlerInterceptor mapped to all incoming requests (via the MVC Namespace or Java config or by declaring a MappedInterceptor with no patterns) that does logging from afterCompletion if the exception argument is not null?

There is also an ApplicationContext that gets published as a second alternative.

I'm open to the option of adding a dedicated logger like the pageNotFoundLogger. I just wanted to check first if you've considered those options.

[spring-projects-issues]

Thomas Whitmore commented

Thanks Rossen, sorry if I was unclear.

As I said, Tomcat doesn't log the exception -- it renders it as an HTML error-page, which for AJAX requests never gets seen.

Spring's handling/logging of exceptions differs between Controller and View Rendering phases -- exceptions in Controller execution are logged perfectly nicely, exceptions in View Rendering are just assumed to be someone else's problem.

Even if Tomcat was showing them somewhere, it would be nice to at least have them in my application's Log4J logfiles -- which suggests logging them in the webapp, before they are thrown out to the container.

Rather than duplicating Controller exception logging with a HandlerInterceptor, I took the route of subclassing JstlView and overriding render() to put a try-catch..

The other alternative, to me, would seem to be logging it in DispatcherServlet.render() -- but it seemed quicker for me to subclass JstlView to JstlView_Diagnosed, than to patch DispatcherServlet (perhaps I could have subclassed it, but...)

What do you think?

[spring-projects-issues]

Rossen Stoyanchev commented

As I said, Tomcat doesn't log the exception – it renders it as an HTML error-page, which for AJAX requests never gets seen.

They do see a 500 status code, don't they, so the exception should not go unnoticed.

What do you think?

My main concern is adding log statements (even at warn level) that put stack traces in the log for exceptions that we don't handle. Existing applications are likely dealing with, potentially logging or even handling such exceptions higher up so adding logging would certainly be problematic to someone. There are a number of options -- a HandlerInterceptor via afterCompletion, consuming an ApplicationContext event (raised by the FrameworkServlet), or through a web.xml mapping of the status code (or exception), possibly customizing the default container error page. Even though logging can be suppressed, it would be frustrating to suddenly have the additional logging the next time you upgrade.

Rather than duplicating Controller exception logging with a HandlerInterceptor, I took the route of subclassing JstlView and overriding render() to put a try-catch..

If I understand correctly you simply want the exception logged, not handled so there shouldn't be duplication.

[spring-projects-issues]

Thomas Whitmore commented

Hi Rossen, thanks for your response. We're both on the same page & understanding the same issue now!

They do see a 500 status code, don't they, so the exception should not go unnoticed.

Working with JQuery pages & the simplest AJAX handlers, the main effect is that nothing happens -- the 'success' callback is never triggered, by default there is no 'failure' callback, and nothing appears on the Tomcat console either.

My concern was how, in these -- fairly common -- AJAX circumstances, there's effectively no engineering feedback or diagnostic being shown to the developer.

My main concern is adding log statements (even at warn level) that put stack traces in the log for exceptions that we don't handle. Existing applications are likely dealing with, potentially logging or even handling such exceptions higher up so adding logging would certainly be problematic to someone.

You're correct that the container is "handling" it, in this case -- somewhat badly. However there is already a property in the DispatcherServlet, IIRC, to log Controller expections additionally to other handling.. we could definitely consider taking such an approach. (Or even rolling it into this.)

However I don't believe logging View rendering exceptions, would likely interfere with almost any real applications -- a failed View is unlikely to be considering "correct functionality" in almost any conceivable circumstance.

(Failed View rendering would leave partly-buffered output, and refer flow control to the container -- a place where exception-recovery logic & subsequent diversion onto "correct functionality", would seem to be exceedingly implausible or unlikely. Controller failures OTOH could be considered to be plausibly recoverable.)

If I understand correctly you simply want the exception logged, not handled so there shouldn't be duplication.

Yes, there's nothing I want to do to recover from it.. I just want to see it visible on the Tomcat console & in the application logs, so myself & other developers aren't scratching their head wondering why nothing happened.

This is quite frequent, any minor JSP syntax error can cause it. So when you're working with AJAX, potentially a lot of JSP slipups can just 'disappear' like this.

As an engineer, I believe in reporting & visibility of faults. And I think there's scope for Spring to help report these, in a configurable way, without trampling on valid handling arrangements.

Thanks Rossen!

[spring-projects-issues]

Rossen Stoyanchev commented

However I don't believe logging View rendering exceptions, would likely interfere with almost any real applications – a failed View is unlikely to be considering "correct functionality" in almost any conceivable circumstance.

Sorry for taking as long to respond but I am not arguing that a failed View would be considered correct by any application. Rather I am saying there are a variety of ways applications could already be processing such exceptions (via web.xml exception mappings, through a HandlerInterceptor in Spring MVC) and they likely are. Hence adding this logging at any level is most certainly going to cause issues for someone. At best this could be done through a flag that would be disabled by default, i.e. making it a very explicit choice.

[spring-projects-issues]

Thomas Whitmore commented

Thanks Rossen, I understand the desire to avoid screwing up anyone's existing clean & controlled logging output.

I do note that DispatcherServlet logs quite a bit by default:

1. "Handler execution resulted in exception - forwarding to resolved error view:"
2. "Rendering view [" + view + "] in DispatcherServlet with name ..."
3. "No mapping found for HTTP request with URI"

As regards upsetting existing logging, seeing the same error twice is but a very minor problem -- compared with never seeing the error. And Tomcat is the most popular Java webserver, so the latter significant problem is probably quite common in the wild.

Obviously it's quite easy to put in a property, either in DispatcherServlet or JstlView or similar -- this could default to DEBUG level, but at least people would see something on their console.

Thanks again! Regards, Tom

[spring-projects-issues]

Rossen Stoyanchev commented

A flag in JstlView sounds like a good option. If you have time to put together a pull request that would be much appreciated.

[spring-projects-issues]

Thomas Whitmore commented

Hi Rossen,

Thanks, I had a look at this. I examined the possibility of placing a flag in AbstractView, and configuring that from UrlBasedResourceViewResolver.

1. I could not see a way to make configuration not require both a flag in the View and additionally code in the UrlBasedResourceViewResolver to set it, with the potential for other View types or other View resolvers to not have/ or configure this flag.

2. There was the possibility for the developer to define a bean-factory BeanPostProcessor, but this seems unlikely to be in effect by default & difficult for developers to find, if they did wish to enable such logging.

3. My suggestion would therefore be to augment the existing 'DEBUG' logging in DispatcherServlet to include reporting View rendering exceptions, similar to how many other conditions (Controller exceptions & forwarding to error views, HandlerInterceptor exceptions, multipart requests) are already logged.

(Feature complexity 1, code-path coverage 100%)

As a result of this consideration I have submitted a pull request for my #14974 proposed fix, using 3) a catch & augmented logging in DispatcherServlet.

This looks to me reasonable & even conservative, definitely will within accordance with the existing level of logging in DispatcherServlet. So perhaps we can consider this as a possible solution.

If we can't accept an extra 'catch' in DispatcherServlet, then 4) I am happy to go & do a different patch with 'logExceptions' property on AbstractView & configure that from UrlBasedResourceViewResolver via another 'logExceptions' property.

(Feature complexity 3, code-path coverage 60%)

My design preference would be to the first solution, for lower number of features in code & greater coverage of error-paths (eg other View types, other ViewResolver types).

Thanks again Rossen!

I look forward to your response.