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

["Nick Williams (JIRA)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/LOG4J2-529?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13894172#comment-13894172 ] 

Nick Williams commented on LOG4J2-529:
--------------------------------------

Remko, I can't reproduce it. Works fine for me in Tomcat 8.0.1. Now, I haven't tested 7.0.50 yet because I don't have it installed. But since it works for me in Tomcat 8.0.1 and not for you, I think it's safe to focus on that for right now.

In Tomcat 8.0.1, the Log4jServletContainerInitializer is called (I put a breakpoint in there to confirm), the listener and filter are registered and initialized (also confirmed with breakpoint), and the MBeans are registered (they're showing up in JConsole).

I'm not sure what to do next...

Can you show me your deployment descriptor (sans the listener and filter configurations)?

> Log4j2 does not auto-initialize on webapp deploy or auto-deinitialize on undeploy
> ---------------------------------------------------------------------------------
>
>                 Key: LOG4J2-529
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-529
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Configurators, Core, JMX
>    Affects Versions: 2.0-beta9, 2.0-rc1
>         Environment: Tomcat 7.0.50, Tomcat 8.0.1
>            Reporter: Remko Popma
>
> The log4j2 manuals [says|http://logging.apache.org/log4j/2.0/manual/webapp.html#Servlet-3.0] 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*
> # 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}}
> # To test, I used the Tomcat [sample web app|http://tomcat.apache.org/tomcat-6.0-doc/appdev/sample/], 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:
> {code}
> <% org.apache.logging.log4j.Logger logger = org.apache.logging.log4j.LogManager.getLogger(); %>
> <% logger.info("Logging from JSP"); %>
> <%= new String("Hello! LOGGED FROM JSP OK.") %>
> {code}
> # create {{webapp1.war}} from the above
> # 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=...")
> # Open JConsole, and connect to "localhost:54321". In the MBeans tab, you will *not* see MBeans for {{org.apache.logging.log4j2}}.
> # 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"}}.
> # 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|http://logging.apache.org/log4j/2.0/manual/webapp.html#Servlet-2.5].
> # create webapp2.war with the modified {{web.xml}} file
> # shutdown and startup Tomcat/7.0.50
> # 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..."
> # 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"
> {code}
> WebappClassLoader
>   context: /webapp2
>   delegate: false
>   repositories:
>     /WEB-INF/classes/
> ----------> Parent Classloader:
> org.apache.catalina.loader.StandardClassLoader@1ebd2621{code}
> # 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...



--
This message was sent by Atlassian JIRA
(v6.1.5#6160)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org