Log4j 2
  1. Log4j 2
  2. LOG4J2-161

Using Log4J2 in Tomcat and WebApp results in all messages being sent to Tomcat's logger

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta4
    • Fix Version/s: 2.0-beta5
    • Component/s: Core
    • Labels:
      None
    • Environment:

      Ubuntu 12.04 64bit: Java 1.6.0_38
      Solaris 10 u9 x64: Java 1.6.0_33

      Tomcat 6.0.29 and Tomcat 6.0.36

      Description

      We are experiencing difficulty getting web applications deployed under Tomcat 6.0.x to honor per-app Log4J2 configuration, when Tomcat itself has been modified to also use Log4J2.

      I will attach a modified Tomcat archive with the following steps applied:
      1. Download and decompress Tomcat 6.0.36
      2. Follow steps #3 and #4 at https://tomcat.apache.org/tomcat-6.0-doc/logging.html#Using_Log4j , but instead of using Log4J 1.x, use Log4J 2.0-beta4 core, api, and log4j-1.2 jars.
      3. Deploy a web application to Tomcat which includes Log4J 2.0-beta4 .jar files, and includes the following in web.xml:
      <context-param>
      <param-name>log4jConfiguration</param-name>
      <param-value>$

      {log4j.app.configurationFile}

      </param-value>
      </context-param>

      <listener>
      <listener-class>org.apache.logging.log4j.core.web.Log4jContextListener</listener-class>
      </listener>
      4. Create two Log4J2 configuration files, one for Tomcat and one for the web app. They should use different PatternLayouts so output can be distinguished from each other.
      5. Launch Tomcat, passing the following environment variable:
      CATALINA_OPTS="-Dlog4j.app.configurationFile=/path/to/log4j2-webapp.xml -Dlog4j.configurationFile=/path/to/log4j2-tomcat.xml"
      6. Force the web app to generate a log message.
      7. View Tomcat's catalina.out file, and observe messages from the web app are output with Tomcat's configured PatternLayout.

      With the attached Tomcat archive, it's simplified to :
      1. Unzip tomcat-6.0.36-log4j2.tar.gz
      2. Set the CATALINA_OPTS environment variable to:
      CATALINA_OPTS="-Dlog4j.app.configurationFile=/path/to/tomcat-6.0.36/webapps/log4j2-tomcat/WEB-INF/log4j2.xml -Dlog4j.configurationFile=/path/to/tomcat-6.0.36/conf/log4j2.xml"
      3. Run the platform-appropriate startup.[sh|bat] file
      4. Access http://localhost:8080/log4j2-tomcat/ in a web browser.

      /path/to/tomcat-6.0.36/logs/catalina.out will contain something like:
      TOMCAT: 16:53:09.065 INFO org.apache.coyote.http11.Http11Protocol - Starting Coyote HTTP/1.1 on http-8080
      TOMCAT: 16:53:09.096 INFO org.apache.jk.common.ChannelSocket - JK: ajp13 listening on /0.0.0.0:8009
      TOMCAT: 16:53:09.099 INFO org.apache.jk.server.JkMain - Jk running ID=0 time=0/10 config=null
      TOMCAT: 16:53:09.100 INFO org.apache.catalina.startup.Catalina - Server startup in 324 ms
      TOMCAT: 16:53:23.617 WARN JSP - App message 1

      The final message is from the web app, and should be prefixed with "APP" instead of "TOMCAT".

      We've run this process in a debugger, and can observe Log4J2 being initialized both by Tomcat and the web app, with no errors. Still, for some reason the web application is using Tomcat's configuration instead of the supplied app-specific config file.

      A mailing list suggestion was to only include Log4J2 core .jar in Tomcat (not in the web app). However, at startup, we get the "SimpleLogger" error message from the web app, as the Tomcat's version of the Log4J2 core .jar is hidden from the web app's classloader.

      We're at a loss. Due to Tomcat's architecture, we seemingly must include Log4J2 core in both Tomcat and the web app. In a debugger, we can see both configuration files being loaded. However, when the application sends log messages, they end up using Tomcat's configuration.

      1. tomcat-6.0.36-log4j2.tar.gz
        6.44 MB
        Scott Severtson
      2. LOG4J2-161.patch
        20 kB
        Ralph Goers

        Activity

        Scott Severtson created issue -
        Hide
        Scott Severtson added a comment -

        Tomcat pre-configured with Log4J2 and sample web application to demonstrate the problem.

        Show
        Scott Severtson added a comment - Tomcat pre-configured with Log4J2 and sample web application to demonstrate the problem.
        Scott Severtson made changes -
        Field Original Value New Value
        Attachment tomcat-6.0.36-log4j2.tar.gz [ 12568098 ]
        Hide
        Scott Severtson added a comment -

        FYI, there's no complied classes in the web app included in the Tomcat demo. Just a web.xml file, an index.jsp file to invoke logging, and Log4J2 .jar files in WEB-INF/lib. We have also confirmed that the problem exists in compiled class files, but went for the simplest demonstration possible.

        Show
        Scott Severtson added a comment - FYI, there's no complied classes in the web app included in the Tomcat demo. Just a web.xml file, an index.jsp file to invoke logging, and Log4J2 .jar files in WEB-INF/lib. We have also confirmed that the problem exists in compiled class files, but went for the simplest demonstration possible.
        Hide
        Ralph Goers added a comment -

        Here is what I see when I debug it:
        1. You are configured to use the ClassLoaderContextSelector, which is the default.
        2. The class that shows up when the JSP calls getLogger is org.apache.jsp.index_jsp.
        3. This class has a class loader of org.apache.jasper.servlet.JasperLoader.
        4. It has no LoggerContext associated with it and there is no configuration being passed to create the LoggerContext.
        5. It has a parent ClassLoader of the WebAppClassLoader which does have a LoggerContext and a configuration.

        Due to this a new LoggerContext is created and it is reconfigured with the configuration from the log4j.configurationFile property.
        You can actually see all of this if you enable status="debug" in the tomcat log4j2.xml.

        Oh - and the ThreadContext ClassLoader is also the WebAppClassLoader.

        I'm going to have to test with JBoss but my suspicion is that it doesn't make sense to choose the current class loader if it has no configuration and it has a parent that does have a configuration, especially if that ClassLoader is the ThreadContext ClassLoader.

        Show
        Ralph Goers added a comment - Here is what I see when I debug it: 1. You are configured to use the ClassLoaderContextSelector, which is the default. 2. The class that shows up when the JSP calls getLogger is org.apache.jsp.index_jsp. 3. This class has a class loader of org.apache.jasper.servlet.JasperLoader. 4. It has no LoggerContext associated with it and there is no configuration being passed to create the LoggerContext. 5. It has a parent ClassLoader of the WebAppClassLoader which does have a LoggerContext and a configuration. Due to this a new LoggerContext is created and it is reconfigured with the configuration from the log4j.configurationFile property. You can actually see all of this if you enable status="debug" in the tomcat log4j2.xml. Oh - and the ThreadContext ClassLoader is also the WebAppClassLoader. I'm going to have to test with JBoss but my suspicion is that it doesn't make sense to choose the current class loader if it has no configuration and it has a parent that does have a configuration, especially if that ClassLoader is the ThreadContext ClassLoader.
        Hide
        Ralph Goers added a comment -

        The attached patch fixes the problem under Tomcat. I still need to test it with JBoss and a couple of other environmens.

        Show
        Ralph Goers added a comment - The attached patch fixes the problem under Tomcat. I still need to test it with JBoss and a couple of other environmens.
        Ralph Goers made changes -
        Attachment LOG4J2-161.patch [ 12570733 ]
        Hide
        Ralph Goers added a comment -

        Fixed in revision 1452133. Please verify and close.

        Show
        Ralph Goers added a comment - Fixed in revision 1452133. Please verify and close.
        Ralph Goers made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Assignee Ralph Goers [ ralph.goers@dslextreme.com ]
        Fix Version/s 2.0-beta5 [ 12323970 ]
        Resolution Fixed [ 1 ]
        Transition Time In Source Status Execution Times Last Executer Last Execution Date
        Open Open Resolved Resolved
        25d 23h 34m 1 Ralph Goers 03/Mar/13 21:44

          People

          • Assignee:
            Ralph Goers
            Reporter:
            Scott Severtson
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development