[jira] [Commented] (LOG4J2-1606) log4j-web deinitalizes the Logger too early if listeners defined in web.xml use it

["David Johle (Jira)" <ji...@apache.org>]

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

David Johle commented on LOG4J2-1606:
-------------------------------------

So it's been a few years since this all started, and I can confirm it's still a thing in at least version 2.13.1 that I recently upgraded to.  Much like [~rturner@e-djuster.com], "I've been fighting with this issue all night, reading Tomcat code, reading log4j code, etc." as well.   Finally understood this well enough, and was going to log the bug here, but now knowing the actual problem & magic terms to search for I found this issue.

I was having two main symptoms:
 # The logging from MyContextListener.contextDestroyed was going nowhere.
 # Tomcat was complaining about threads my application started, but didn't stop, and thus creating leaks.

So I was focusing on #2 at the time, and tracking down how/when these threads were created.  It was clear they were Log4j2, so I put in some conditional breakpoints and let it rip.  It was then that I found out they were being created during MyContextListener.contextDestroyed being called at undeploy time.  One was named Log4j2-TF-8-Schedule-3 and the other AsyncAppender-apendername.

So after much playing with things, I realized that the "TF" one was actually a different name than the "TF" thread name I would see while the application was running.  Digging deeper, it turns out the other one was named the same, but not actually the same thread.  So these were not even from the same logging context that the rest of my webapp used, the plot thickened!

I was also paying attention to the order of operations here, and noticed that, as mentioned in other comments, the logging context was being destroyed prior to my own listener's destroy.  So I played around with web.xml, and even made my own JAR with its own web-fragment.xml, but nothing would affect the order of Log4j2 init nor destroy with respect to my listener.

So, in case it helps explain what's going on, I'll offer up what I've learned in the past several hours:

*Order of startup operations...*

1. Log4jServletContainerInitializer.onStartup is called
 * Since we are servlet 3.0+, this actually initializes the logging context
This agrees with the documentation in "[The Short Story|https://logging.apache.org/log4j/2.x/manual/webapp.html#Servlet-3.0]"
 * Log4jWebInitializerImpl.start is what actually does this
 * It also creates & registers the new Log4jServletContextListener that will be used during shutdown

2. MyContextListener.contextInitialized is called
 * This performs some logging, which works properly since the logging context was initialized before

3. Log4jServletContextListener.contextInitialized is called
 * This calls Log4jWebInitializerImpl.start, but because it's already initialized, it does nothing.

 

*Order of shutdown operations...*

1. Log4jServletContextListener.contextDestroyed is called
 * This gets rid of the logging context for the web app

2. MyContextListener.contextDestroyed is called
 * This attempts to do some logging, but since the logging context is gone, a new one is auto-created!

3. The webapp is finished shutting down, and at this point Tomcat freaks out because of the dangling threads from the extra logging context, which are leaked

 

*Conclusion...*

Even when my listener is a web-fragment, and defined as <after> the log4j fragment, it still comes _first_ because the Log4jServletContextListener is added programmatically, and thus simply appended to the end of the list instead of considered in the specified ordering!  However, this _completely defeats the purpose_ of "configured to order before any other web fragments" mentioned in "[The Long Story|https://logging.apache.org/log4j/2.x/manual/webapp.html#Servlet-3.0]" section.

So to answer the the question from [~rgoers] above, "Log4j's listener is supposed to be first. Doesn't the documentation say that?"

Yes, the documentation says that, and yes it is _supposed_ to be first, however the _code_ dictates otherwise and that's what matters most ;)

 

*Solution...?*

It is not clear to me why the listener isn't declared in the web-fragment.xml, allowing the logging context to be created in the right sequence.  I guess perhaps it's because of some of the other things performed in Log4jServletContainerInitializer.onStartup?  I'm not sure if those things need/have to be in there vs the listener, if not I propose the init & dynamic listener registration be removed and the listener be defined in the web-fragment.

If there is an actual need/benefit to using the ContainerInitializer instead of the ContextListener, then perhaps there could be an init parameter added to skip the logging context init & dynamic listener registration in ContainerInitializer, so that the init does end up happening in from the listener call (which would also need to be defined in the web-fragment).

 

> log4j-web deinitalizes the Logger too early if listeners defined in web.xml use it 
> -----------------------------------------------------------------------------------
>
>                 Key: LOG4J2-1606
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-1606
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Web/Servlet
>    Affects Versions: 2.6.2
>         Environment: Java8, Linux/Mac, Tomcat
>            Reporter: Lukas Vogel
>            Priority: Major
>
> We use log4j in a Apache Tomcat environment.
> In the web.xml file we define a custom ServerStartup listener that initializes the DB etc and logs both in contextInitialized and contextDestroyed.
> If we use the log4j-web package the class Log4jServletContainerInitializer initializes the logger and adds a Log4jServletContextListener to the ServletContext. Since this listener is added after our listener the method Log4jServletContextListener#contextDestroyed is called before our listener's contextDestroyed method. Thus the Logger is de-initialized too early.
> We could disable auto initialization and initialize the logger ourselves but then doing it in the listener is too late since the WebService-framework (Metro glassfish) initializes the webservice endpoints before the listener. Since we use static logger variables in those webservice classes this would trigger the message "StatusLogger no log4j configuration found..."  because the logger was not yet initialized.
> One possible patch we see is that we make an option to manually add the Log4jServletContextListener:
> In Log4jServletContainerInitializer we would put an "if (! Manually added)" around the  call "servletContext.addListener(new Log4jServletContextListener());" and then we could manually add it to the listeners in web.xml
> If you have any other suggestions I would be glad to hear them.



--
This message was sent by Atlassian Jira
(v8.3.4#803005)