ServletException logged differently in Tomcat 5.5 and Tomcat 6.0

[Chris Cayuma]

We have a web app with a single servlet - ExceptionServlet:

public class ExceptionServlet extends HttpServlet {

	private static final long serialVersionUID = 1L;

	@Override
	protected void service(HttpServletRequest req, HttpServletResponse resp)
			throws ServletException, IOException {
		throw new ServletException("ExceptionServlet.service()");
	}
}

We have Tomcat 5.5.26 and 6.0.33 in separate directories (naturally).

We have Tomcat 5.5.26 configured to use log4j library for logging, as per the Tomcat 5.5 documentation on logging - log4j.jar and commons-logging.jar in $CATALINA_HOME/common/lib, log4j.properties in $CATALINA_HOME/common/classes.

We also have Tomcat 6.0.33 configured to use log4j library for logging, as per the Tomcat 6.0 documentation on logging - log4j.jar, tomcat-juli-adapters.jar, and log4j.properties in $CATALINA_HOME/lib, tomcat-juli.jar from extras in $CATALINA_HOME/bin.

The log4j.properties file in both Tomcat installations is the same. We only set the rootLogger to use the defined appenders, we don't have any specific logger entries to direct specific traffic to certain appenders.

The web app that includes the above servlet also uses log4j, and has its own log4j.jar and log4j.properties file (as well as commons-logging.jar). The web app's log4j.properties file specifies a different set of file appenders than the Tomcat log4j.properties files.

The behavior we're observing is that in Tomcat 5.5, when the above servlet is invoked (call the servlet's URL in a browser), the ServletException stack trace appears in the web app's log file. However, in Tomcat 6.0, when the above servlet is invoked, the ServletException stack trace appears in Tomcat's log file.

Does anyone have any insight as to what's happening? We would like the ServletException stack trace to appear in the web app's log file on Tomcat 6.0.

Thanks in advance for any help!

[Koen Aerts]

Hard to see why the logging behaves differently without seeing the actual log4j properties. Is there perhaps also a log4j.xml file somewhere with properties that is being used by either tomcat or the web app?

[Chris Cayuma]

Okay, I've stripped my web app to the bare minimum, and performed exactly the steps described in Tomcat 5.5/Tomcat 6.0 documentation regarding using log4j for logging. Here's more detail, hopefully things will be made clear.

In my web app, I have a single servlet, personal.ExceptionServlet:

package personal;

import java.io.IOException;

import javax.servlet.ServletException;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

public class ExceptionServlet extends HttpServlet {

	private static final long serialVersionUID = -8368566687864709995L;

	@Override
	protected void service(HttpServletRequest arg0, HttpServletResponse arg1)
			throws ServletException, IOException {
		throw new ServletException("HEY SERVLET EXCEPTION");
	}

}

Packaged with the servlet in the war file, I've included WEB-INF/lib/log4j-1.2.16.jar, WEB-INF/lib/commons-logging-1.1.1.jar, and WEB-INF/classes/log4j.properties file containing

log4j.rootLogger=INFO,A

log4j.appender.A=org.apache.log4j.RollingFileAppender
log4j.appender.A.file=/opt/personal/logs/ex/ex.info.log
log4j.appender.A.layout=org.apache.log4j.PatternLayout
log4j.appender.A.layout.conversionPattern=%m%n
log4j.appender.A.maxFileSize=10MB
log4j.appender.A.maxBackupIndex=10

Now, in my Tomcat 5.5.26 installation, I have as per the Tomcat 5.5 Logging documentation log4j-1.2.16.jar in $TOMCAT_HOME/common/lib, commons-logging-1.1.1.jar in $TOMCAT_HOME/common/lib, and log4j.properties in $TOMCAT_HOME/common/classes containing

log4j.rootLogger=INFO,T

log4j.appender.T=org.apache.log4j.RollingFileAppender
log4j.appender.T.file=${catalina.home}/logs/tomcat.log
log4j.appender.T.layout=org.apache.log4j.PatternLayout
log4j.appender.T.layout.conversionPattern=%m%n
log4j.appender.T.maxFileSize=10MB
log4j.appender.T.maxBackupIndex=10

Finally, in my Tomcat 6.0.33 installation, I have as per the Tomcat 6.0 Logging Documentation log4j-1.2.16.jar in $TOMCAT_HOME/lib, tomcat-juli-adapters.jar from the "extras" directory for the 6.0.33 download dir also in $TOMCAT_HOME/lib, and replaced tomcat-juli.jar in $TOMCAT_HOME/bin with the one from the "extras" directory. I also have a log4j.properties file in $TOMCAT_HOME/lib containing the same as above:

log4j.rootLogger=INFO,T

log4j.appender.T=org.apache.log4j.RollingFileAppender
log4j.appender.T.file=${catalina.home}/logs/tomcat.log
log4j.appender.T.layout=org.apache.log4j.PatternLayout
log4j.appender.T.layout.conversionPattern=%m%n
log4j.appender.T.maxFileSize=10MB
log4j.appender.T.maxBackupIndex=10

So I deploy my web application into Tomcat 5.5, start it up, and invoke the ExceptionServlet. This produces an exception message and stack dump in ex.info.log:

Servlet.service() for servlet ex threw exception
javax.servlet.ServletException: HEY SERVLET EXCEPTION
        at personal.ExceptionServlet.service(ExceptionServlet.java:17)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:874)
        at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
        at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
        at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
        at java.lang.Thread.run(Thread.java:595)

Now, I stop Tomcat 5.5, copy my web application war file into Tomcat 6.0, start up Tomcat 6.0, invoke the ExceptionServlet again, this time getting the exception message and stack trace in $TOMCAT_HOME/logs/tomcat.log

Servlet.service() for servlet ex threw exception
javax.servlet.ServletException: HEY SERVLET EXCEPTION
        at personal.ExceptionServlet.service(ExceptionServlet.java:17)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:291)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:602)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
        at java.lang.Thread.run(Thread.java:595)

Same code, different location for the exception message. So where's my mistake? Not using log4j at the moment is a non-starter, nor is upgrading to Tomcat 7. I need Tomcat 6.0 to behave the way Tomcat 5.5 behaved wrt the ServletException logging. Is there something I need to add to my Tomcat log4j.properties? Any insight is greatly appreciated!

[Tim Holloway]

Tomcat doesn't log for applications. Each application is responsible for its own logging, and every application is at liberty to choose a different logger and log locations/services. In fact, it's such a free-for-all that now there are meta-loggers that handle the problems that complex apps pose when they incorporate multiple components which have different logging packages.

As far as I can remember, Tomcat5 operated under the above rules, but it's a certainty that Tomcat6 and later versions do. In any event, Tomcat6 doesn't use Log4 ordinarily, it uses the java.utilities.logging system (JULI) that's part of the core JVM. To make it use Log4J for its own internal logging needs, you have to build a custom copy of Tomcat. However, as I mentioned, the apps are responsible for their own logging, so that wouldn't make any difference anyhow as far as what you want.

Bottom line is that ServletExceptions are supposed to be reported in the applications log (as defined in WEB-INF/classes/log4j.xml or .properties). So the closest you could get to making them appear in the Tomcat log would be to have the app intercept them and do a System.out.println on the by brute force. Which isn't really logging and won't get you the proper message formatting and routing, just raw text to catalina.out. Except for the Tomcat configurations where catalina.out doesn't apply either.

[Chris Cayuma]

Hi Tim,

Thanks for the response. I actually do want the ServletException thrown by my servlet to appear in my web app log. This is indeed the behavior I observe in Tomcat 5.5 - my servlet throws that ServletException, and the exception message and stack trace appear in the web app log defined by the web app's log4j.properties file. However, this is NOT what I observe in Tomcat 6.0 - my servlet throws that ServletException, but the exception message and stack trace appear in the Tomcat log.

[Chris Cayuma]

Okay, I've boiled my example down even further, and still am getting the same behavior.

My web app consists of that single ExceptionServlet that throws a ServletException when it services a request.

For Tomcat 5.5.26 and Tomcat 6.0.33, I just unpack the packages (in separate dirs, of course) and use them as-is, no configuration changes whatsoever.

I copy my web app into Tomcat 5.5.26 webapps dir, start up Tomcat5, invoke my servlet, and observe that the exception and stack trace are logged in the web app's log.

I stop Tomcat 5.5.26, copy my web app into Tomcat 6.0.33 webapps dir, start up Tomcat6, invoke my servlet, and observe that the exception and stack trace are logged in Tomcat's log in $TOMCAT_HOME/logs/localhost.2012-02-09.log .

I also tried this with Tomcat 6.0.35 (the latest available from tomcat.apache.org as of this writing) and get the same behavior as Tomcat 6.0.33, that my web app's exception and stack trace are logged in Tomcat's log.

Any other ideas for what may be going on? This goes against my understanding and expectation for how Tomcat should behave wrt web app logging.

[Tim Holloway]

Actually, a ServletException has nowhere to go uphill in a webapp, and therefore having it appear on the master console isn't really that unreasonable, because it indicates that the application isn't handling the problem itself.

In fact, the Javadocs say this about the ServletException constructor:

Constructs a new servlet exception with the specified message. The message can be written to the server log and/or displayed for the user.

Note that it explicitly says server log.

The server can get involved in a number of ways here. First, you should be able to define a general exception handler in web.xml to permit the app to deal with the exception, where that handler can not only log to the application log, but can determine what, if any, recovery action should be taken (something that the more generic server code cannot do). Secondly, you can define a custom error page, in which case Tomcat will catch the ServletException and dispatch that page. Note, however that the operative word is page. Like login screens, these pages are invoked directly from Tomcat, and therefore cannot be routed through servlets. In other words, use HTML or JSP, not Struts or JSF.

Bottom line, though, is that throwing ServletExceptions is a sign of bad application design. It means that someone was too lazy or too rushed to properly deal with a problem. Compared to that, the location where the error is logged is of secondary importance.

[Denys Mitin]

The answer looks to be in a class that produces this log. In Tomcat 5.5 it is org.apache.catalina.core.ContainerBase. In Tomcat6 it is org.apache.catalina.core.StandardWrapperValve.
ContainerBase looks to be loaded in application class loader, so logger of application is used. StandardWrapperValve looks to be in Tomcat own class loader. Does it makes sense?
The other question is why ContainerBase is not used in Tomcat6 despite of being present in lib/catalina.jar? Does anybody have an idea? Thanks