Shutdown of Log4j2 initialized via Log4jServletContainerInitializer happens first not last

[cseewald]

Description

Shutdown of Log4j2 system initialized via org.apache.logging.log4j.web.Log4jServletContainerInitializer happens first before all ServletContextListener contextDestroyed methods are called in a servlet container (tomcat).

I would expect Log4j2 to shutdown itself at the very end, so other context listeners have the change to log something during their shutdown procedure.

If I intialize/shutdown log4j2 via org.apache.logging.log4j.web.Log4jServletContextListener and put the context listener at the very top in web.xml then log4j2 properly shuts down after every other listener.

If I debug

        if (!"true".equalsIgnoreCase(servletContext.getInitParameter(
                Log4jWebSupport.IS_LOG4J_AUTO_SHUTDOWN_DISABLED))) {
            servletContext.addListener(new Log4jServletContextListener());
        }

in Log4jServletContainerInitializer, all other listener already exists in the servletContext and the Log4jServletContextListener is added to the very end, thus shutdown happens as the very first.

Configuration

Version: log4j2-web 2.20.0

Operating system: MacOS

JDK: JDK 11 Temurin

Servlet Container:: Tomcat 9.0.73

Logs

N/A

[ppkarwasz]

@cseewald,

Thank you for noticing this issue. Unfortunately the Servlet API treats listeners as second-class citizens compared to servlets and filters: there is no way to give them a name, overwrite their definition or even check if such a listener is defined. Section 8.2.3 gives some rules on how listeners are ordered and gives a warning:

If the order in which the listeners, servlets, filters are invoked is important to an application then a deployment descriptor must be used.

Unless I am mistaken the order of the listeners is:

1. those explicitly defined in web.xml,
2. those annotated with @WebListener (in a random order) unless metadata-complete is set,
3. those explicitly defined in web-fragment.xml unless metadata-complete is set,
4. those added by a ServletContainerInitializer.

so there is no way for Log4j to put their listener first. The best we can do is:

• document this problem and ask the user to explicitly add org.apache.logging.log4j.web.Log4jServletContextListener at the top of their web.xml file,
• count the number of Log4jServletContextListener instances (there will be more than one, since they don't have a name), in a servlet container, so that only the last call to contextDestroyed shuts down the logger context.

[cseewald]

That is definitely unfortunate. I think changing the documentation of the org.apache.logging.log4j.web.Log4jServletContextListener would definitely help and also not make it look like a 2nd class citizen in the docs which should not be used anymore nowadays. I think counting the the number of listeners does not help as the contextDestroyed method added by Log4jServletContainerInitializer (via adding Log4jServletContextListener) will always be called first.

[ppkarwasz]

@cseewald,

I merged my PR. Log4jServletContextListener is now increasing the reference counter at each contextInitialized call and decreasing it when contextDestroyed is called. The logger context is actually destroyed only when the count goes to zero.

Can you check the latest 2.21.0-SNAPSHOT to see if this works for you?

[cseewald]

@ppkarwasz

I tested the 2.21.0-SNAPSHOT in my setting. In my initial issue description I was bothered that log4j is being shutdown before all other context listeners are being shutdown. Thus everything they log during shutdown is simply gone. This only happens if log4j is being initialized with Log4jServletContainerInitializer

This did not change with the changes you made. (by setting status="trace" in the log4j configuration, I can see that the log4j shutdown happens before all the other context listeners are destroyed).

Also initialization still happens twice (minor thing I assume). Once from Log4jServletContainerInitializer and a second time from Log4jServletContextListener.

[ppkarwasz]

@cseewald,

Did you test with a Log4jServletContextListener explicitly defined in your web.xml?

[cseewald]

@cseewald,

Did you test with a Log4jServletContextListener explicitly defined in your web.xml?

No, just using the Log4jServletContainerInitializer. In my "fixed/workaround" configuration, I simply disable Log4jServletContainerInitializer via isLog4jAutoInitializationDisabled and simply declare a Log4jServletContextListener as the first listener in web.xml and then the shutdown of log4j happens last.

As you already established given the constraints of the Servlet API it is impossible to do this with Log4jServletContainerInitializer.

So I am not entirely sure what your changes are actually trying to fix since when Log4jServletContainerInitializer is enabled only a single Log4jServletContextListener is added to the servlet container.

[ppkarwasz]

So I am not entirely sure what your changes are actually trying to fix since when Log4jServletContainerInitializer is enabled only a single Log4jServletContextListener is added to the servlet container.

After the change you should be able to drop the isLog4jAutoInitializationDisabled property. The two listeners (the one automatically added by the initializer and the one explicitly added by you) should work together and only the listener in web.xml should stop the logger context.

[cseewald]

Yes now I got it. With the current Snapshot version it also works in my setting without isLog4jAutoInitializationDisabled just the context listener.

👏