Spring @PreDestroy: No logging because Logback stops too soon

Question

In my project, I am using Logback as logging facility. I have the following class

@Component
class Test {
    @PreDestroy
    public void destroy() {
        try {
            ...
        } catch (Exception e) {
            LoggerFactory.getLogger(getClass()).error(e.getLocalizedMessage(), e);
        }
    }
}

Now, I undeploy the servlet. When an exception occurs, Logback is not printing the message and stack trace. This is because Logback is cleaning up before the destroy() is called by Spring. When undeploying the servlet, this is the first (and last) log line:

15:46:19,084 |-INFO in ch.qos.logback.classic.servlet.LogbackServletContextListener@7957fe56 - About to stop ch.qos.logback.classic.LoggerContext [default]

I verified that Logback stops first by adding a System.out.println("..."); in the destroy().

Is there any way to fix this?

My dependencies:

<dependencyManagement>
    <dependencies>
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-framework-bom</artifactId>
            <version>5.0.1.RELEASE</version>
            <type>pom</type>
            <scope>import</scope>
        </dependency>
        <dependency>
            <groupId>commons-logging</groupId>
            <artifactId>commons-logging</artifactId>
            <version>99-empty</version>
        </dependency>
    </dependencies>
</dependencyManagement>

<dependencies>
    <dependency>
        <groupId>commons-logging</groupId>
        <artifactId>commons-logging</artifactId>
    </dependency>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>1.7.25</version>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-core</artifactId>
        <version>1.2.3</version>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>
        <version>1.2.3</version>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-access</artifactId>
        <version>1.2.3</version>
    </dependency>
    <dependency>
        <groupId>org.springframework</groupId>
        <artifactId>spring-core</artifactId>
    </dependency>
    <dependency>
        <groupId>org.springframework</groupId>
        <artifactId>spring-jcl</artifactId>
    </dependency>
</dependencies>

Please note that spring-jcl is used to route commons-logging to slf4j (which will route to logback). I am not using jcl-over-slf4j.

Possible duplicate of [Spring's @PreDestroy results in logging randomly not logging](https://stackoverflow.com/questions/30426533/springs-predestroy-results-in-logging-randomly-not-logging) — niekname, Nov 08 '17 at 17:21
I think it's indeed the same issue. Any idea how to disable the automatic shutdown from Logback (the `LogbackServletContextListener`) and manually shutdown Logback as late as possible? I am in a Tomcat/Spring environment. — Franz They, Nov 08 '17 at 19:25
Also duplicate of: https://stackoverflow.com/questions/17400136/how-to-log-within-shutdown-hooks-with-log4j2 Make sure you read the answer of user 'DjDCH' — niekname, Nov 08 '17 at 20:23
How about not registering LogbackServletContextListener in the web.xml, or WebAppInitializer, then it won't shutdown the logging. — David Roussel, Nov 08 '17 at 21:35
It's registered automatically. All I am doing is adding Logback and slf4j to my dependencies and having a logback.xml in the classpath. I am not doing anything in the code. — Franz They, Nov 08 '17 at 21:42

score 8 · Accepted Answer · answered Nov 09 '17 at 01:26

There is a documented way to disable to disable the registering of the LogbackServletContextListener:

You may disable the automatic the installation of LogbackServletContextListener by setting a named logbackDisableServletContainerInitializer in your web-application's web.xml file. Here is the relevant snippet.
<web-app>
    <context-param>
        <param-name>logbackDisableServletContainerInitializer</param-name>
        <param-value>true</param-value>
    </context-param>
    .... 
</web-app>
Note that logbackDisableServletContainerInitializer variable can also be set as a Java system property an OS environment variable. The most local setting has priority, i.e. web-app first, system property second and OS environment last.

I would imagine you'll probably want to write your own shutdown hook if this is the case and stop the LoggerContext

score 2 · Answer 2 · answered Jan 29 '18 at 18:44

To pick up Dovmo's answer. It's all about ordering. I have the same issue on Tomcat 8.5.x. Bacially, the initializer does an addListener, you don't have any control over the listener. At shutdown, Tomcat reverse-iterates that list, picking the Logback listener first: Spring won't log anything.

A custom listener won't help because you cannot prepend it. What works for me on Tomcat is:

<listener>
    <listener-class>ch.qos.logback.classic.servlet.LogbackServletContextListener</listener-class>
</listener>
<listener>
    <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
</listener>

<context-param>
    <param-name>logbackDisableServletContainerInitializer</param-name>
    <param-value>true</param-value>
</context-param>

Spring @PreDestroy: No logging because Logback stops too soon

2 Answers2

Linked