Problem with log4j and tomcat

Nether

I'm having some trouble setting up log4j with the webapp I'm working on. I have tomcat running an application consisting of hundreds of jsps and dozens of .java files, and the goal is to allow easy, unified access to all the normal log4j appenders from both the .jsp files and the .java files. I am not using servlets. What I want to do right now is keep the logging for tomcat's internal stuff and the application completely seperate, because logging what tomcat is doing is not a priority at all. The application's logging should go straight to System.out.

The problem is that, when accessing a jsp, tomcat's default JSP servlet container spams the DEBUG log level in the application with everything that happens during the processing of the JSP file. Here's the setup:

tomcat/common/lib/log4j-1.2.15.jar
WEB-INF/lib/log4j-1.2.15.jar

tomcat/common/common/classes/log4j.properties:

log4j.rootLogger=INFO, R
log4j.appender.R=org.apache.log4j.RollingFileAppender
log4j.appender.R.File=${catalina.home}/logs/Tomcat_DBG.log
log4j.appender.R.MaxFileSize=20MB
log4j.appender.R.MaxBackupIndex=100
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%d [%t] %-5p %c - %m%n

WEB-INF/classes/log4j.properties:

log4j.rootLogger=debug, stdout
### direct log messages to stdout ###
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

log.jsp:

<%@ page
    import = "org.apache.log4j.Logger"
%>

<%
    org.apache.log4j.Logger log = Logger.getRootLogger();
            //log.trace("Trace");
            log.debug("Debug");
            log.info("Info");
            log.warn("Warn");
            log.error("Error");
            log.fatal("Fatal");
%>

Console Output from accessing log.jsp:

11:39:39,843 DEBUG JspServlet:247 - JspEngine --> /log.jsp
11:39:39,846 DEBUG JspServlet:248 -          ServletPath: /log.jsp
11:39:39,846 DEBUG JspServlet:249 -             PathInfo: null
11:39:39,847 DEBUG JspServlet:250 -             RealPath: /usr/local/cats/adTaker/log.jsp
11:39:39,847 DEBUG JspServlet:251 -           RequestURI: /****/log.jsp
11:39:39,847 DEBUG JspServlet:252 -          QueryString: null
11:39:39,847 DEBUG JspServlet:253 -       Request Params:
11:39:39,848 DEBUG root:48 - Debug
11:39:39,848 INFO root:49 - Info
11:39:39,849 WARN root:50 - Warn
11:39:39,849 ERROR root:51 - Error
11:39:39,849 FATAL root:52 - Fatal

For a non-trivial jsp, the DEBUG output reaches many thousands of lines of unwanted text. I've read the apache-commands log4j manual and I can't figure out why this would happen. Tomcat should not be able to access or know about the application's logger. I don't want to make another explicit loglevel and use that in the app for debugging to get around this. Any ideas?

PhillS

One easy solution would be to use a prefix in your JSP:

Logger.getLogger("com.company.jsp.prefix")

And then set up a separate logger for that in your log4j.properties file.

The fact that you are doing all this from a JSP does worry me slightly, though - have you inherited an old application?

Ideally the logging would be from a controller class, JSPs would just be used for presentation. Not always possible though depending on circumstances.

Nether

@PhillS said:

One easy solution would be to use a prefix in your JSP:
Logger.getLogger("com.company.jsp.prefix")
And then set up a separate logger for that in your log4j.properties file.

Ok well that's getting me somewhere. The problem now is my logging calls are printing to the console twice. The loglevel options really irritate me. I can't omit the rootLogger declaration, and I can't turn it off ( I tried "no", "none", etc.), nor can I omit the appenders from it, even though I don't want to use it for anything. Here's what I have:

WEB-INF/classes/log4j.properties:

log4j.rootLogger=FATAL, stdout

### direct log messages to stdout ###
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

log4j.logger.com.somecompany.app=debug, R

log4j.appender.R=org.apache.log4j.ConsoleAppender
log4j.appender.R.Target=System.out
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

log.jsp:

<%@ page
    import = "org.apache.log4j.Logger"
%>

<%
    org.apache.log4j.Logger log = Logger.getLogger("com.somecompany.app");

    //log.trace("Trace");
    log.debug("Debug");
    log.info("Info");
    log.warn("Warn");
    log.error("Error");
    log.fatal("Fatal");
%>

Output:

12:31:57,947 DEBUG app:49 - Debug
12:31:57,947 DEBUG app:49 - Debug
12:31:57,951 INFO app:50 - Info
12:31:57,951 INFO app:50 - Info
12:31:57,951 WARN app:51 - Warn
12:31:57,951 WARN app:51 - Warn
12:31:57,954 ERROR app:52 - Error
12:31:57,954 ERROR app:52 - Error
12:31:57,955 FATAL app:53 - Fatal
12:31:57,955 FATAL app:53 - Fatal

The fact that you are doing all this from a JSP does worry me slightly, though - have you inherited an old application?
Ideally the logging would be from a controller class, JSPs would just be used for presentation. Not always possible though depending on circumstances.

It's an application that was not designed with discrete MVC in mind at all. It's getting better, and a lot of the jsps that used to be both V and C are now just V or C, but the line is still pretty blurry, and fixing it isn't an immediate goal.

I still want to figure out why Tomcat is printing to a logger that is declared and instantiated only from with the application. Everything in the appropriate levels declared in tomcat's log4j.properties is going to its own log file, but everything at a log level that should be ignored by the tomcat logger is instead getting printed to the app's logger. I hate things I can't figure out.

PhillS

I think your problem is here:

log4j.logger.com.somecompany.app=debug, R

You're setting the logger for this particular package to use logger 'R', and it will also log out of the root logger. If you remove ', R' from that line it should work. Look at the docs for log4j for more info on that, but I had exactly the same problem before.

I still want to figure out why Tomcat is printing to a logger that is declared and instantiated only from with the application

At a guess, that's because log4j has static configuration (i.e., global per-vm) and I have a feeling Tomcat uses one VM for applications. Could be wrong on that one though.

no_name

@PhillS said:

At a guess, that's because log4j has static configuration (i.e., global per-vm) and I have a feeling Tomcat uses one VM for applications. Could be wrong on that one though.

Nope, it's per class loader. Each war should have it's own class loader, but due to class loader chaining they can still share classes depending on which class loader loads them.

The last time I used Tomcat (4.something) it used the commons logging API, which would take advantage of log4j if it finds it, but otherwise use it's own logging API. We had multiple instances of our application running in separate wars, and they all had their own log4j configuration (although that took some doing since they all wanted to load the same properties file by default).

Where is the log4j jar being loaded from?