Problem with log4j and tomcat



  • 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?



  • 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.



  • @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. 



  • 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.
     



  • @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? 

     

     


Log in to reply
 

Looks like your connection to What the Daily WTF? was lost, please wait while we try to reconnect.