[LOG4J2-529] Log4j2 does not auto-initialize on webapp deploy or auto-deinitialize on undeploy

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Not A Problem
• Affects Version/s: 2.0-beta9, 2.0-rc1
• Fix Version/s: 2.0-rc1
• Component/s: Configurators, Core, JMX

Environment

Tomcat 7.0.50, Tomcat 8.0.1

• Assignee: Unassigned
• Reporter: Remko Popma
• Created: 07/Feb/14 02:53
• Updated: 07/Apr/14 23:45
• Resolved: 08/Feb/14 05:30

Description

The log4j2 manuals says that "Log4j 2 "just works" in Servlet 3.0 and newer web applications. It is capable of automatically starting when the application deploys and shutting down when the application undeploys."

When testing for LOG4J2-500, I found that this does not seem to be the case, at least on Tomcat 7.0.50 and Tomcat 8.0.1.

Steps to reproduce the issue

1. Enable JMX in Tomcat: create a file setup.bat in the bin directory with the following contents: set CATALINA_OPTS=-Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=54321 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false
2. To test, I used the Tomcat sample web app, with the following modifications:
   • add log4j-api-2.0RC1-SNAPSHOT.jar to WEB-INF/lib
   • add log4j-core-2.0RC1-SNAPSHOT.jar to WEB-INF/lib
   • put log4j2.xml in WEB-INF/classes. Any valid config with status="trace" should be sufficient.
   • copy hello.jsp to log.jsp and add these lines:

     <% org.apache.logging.log4j.Logger logger = org.apache.logging.log4j.LogManager.getLogger(); %>
     <% logger.info("Logging from JSP"); %>
     <%= new String("Hello! LOGGED FROM JSP OK.") %>
     

3. create webapp1.war from the above
4. deploy webapp1. Note that in the Tomcat console you will only see "INFO: Deploying web application archive D:\apps\apache-tomcat-7.0.50\webapps\webapp1.war", you will not see the Log4J initialization status messages (like "Generated plugins in 0.175750656 seconds", or "Registering MBean org.apache.logging.log4j2:type=...")
5. Open JConsole, and connect to "localhost:54321". In the MBeans tab, you will not see MBeans for org.apache.logging.log4j2.
6. In a browser, open URL http://localhost:8080/webapp1/log.jsp
   • In the Tomcat console you should now see "Generated plugins in 0.000016172 seconds" and "Registering MBean org.apache.logging.log4j2"
   • In JConsole you should now see MBeans for org.apache.logging.log4j2. The LoggerContext name looks something like "org.apache.jasper.servlet.JasperLoader@7da612aa".
7. Now, undeploy webapp1.
   • Bad sign #1: in the Tomcat console I only see "INFO: Undeploying context /webapp1", I don't see any status messages for Log4J unloading. For example, I don't see any "Unregistering MBean ..." messages.
   • Bad sign #2: in JConsole, the MBeans for org.apache.logging.log4j2 are still displayed. Accessing their attributes may cause errors in the Tomcat console ("INFO: Illegal access: this web application instance has been stopped already. Could not load sun.reflect.SerializationConstructorAccessorImpl. The eventual following stack trace is caused by an error thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access, and has no functional impact. java.lang.IllegalStateException...")
   • Bad sign #3: In the Tomcat manager app, pressing the "Find Leaks" button shows this message: "The following web applications were stopped (reloaded, undeployed), but their classes from previous runs are still loaded in memory, thus causing a memory leak (use a profiler to confirm): /webapp1"

So with the default setup, undeploying a webapp with log4j2 in its WEB-INF/lib folder does not automatically call LoggerContext.stop().

Things do seem to work better if I modify the web.xml file and add the listener, filter and filter-mapping recommended for Servlet 2.5 web applications.

1. create webapp2.war with the modified web.xml file
2. shutdown and startup Tomcat/7.0.50
3. deploy webapp2.war. Do not open log.jsp in a browser yet. In this case I immediately see Log4J initialization status messages like "Generated plugins in 0.000019904 seconds" and "Registering MBean org.apache.logging.log4j2..."
4. open JConsole, and connect to "localhost:54321". In the MBeans tab, I can see MBeans for org.apache.logging.log4j2.
   • Interestingly, the LoggerContext name is very different now. It looks like this: "WebappClassLoader\n context: /webapp2\n delegate: false\n repositories:\n /WEB-INF/classes/\n----------> Parent Classloader:\norg.apache.catalina.loader.StandardClassLoader@1ebd2621\n"

     WebappClassLoader
       context: /webapp2
       delegate: false
       repositories:
         /WEB-INF/classes/
     ----------> Parent Classloader:
     org.apache.catalina.loader.StandardClassLoader@1ebd2621

5. undeploy webapp2
   • In the Tomcat console, I can see Log4J status messages saying "Stopping LoggerContext WebappClassLoader...", and "Unregistering MBean org.apache.logging.log4j2..."
   • In JConsole, the MBeans for org.apache.logging.log4j2 are no longer displayed.
   • Clicking the "Find Leaks" button in the Tomcat Manager app now shows message "No web applications appear to have triggered a memory leak on stop, reload or undeploy."

So, it appears that automatic configuration does not work in Tomcat 7.0.50 and that listener, filter and filter-mapping in web.xml are necessary for correct Log4J unloading...

Issue Links

• is depended upon by: LOG4J2-500 Unloading one webapp unloads JMX MBeans for all webapps
• relates to: LOG4J2-578 JMX Memory Leak in Servlet Container