Gracefully stop Logback in container environment

Question

Today I get PermGen OutOfMemory error.

Analysis shown that Nearest GC Root for WebappClassLoader is Logback thread:

this     - value: org.apache.catalina.loader.WebappClassLoader #4
  <- contextClassLoader (thread object)     - class: java.lang.Thread, value: org.apache.catalina.loader.WebappClassLoader #4

which is:

java.lang.Thread#11 - logback-1

Thread dump from heap dump for this thread:

"logback-1" daemon prio=5 tid=34 WAITING
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:458)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359)
   Local Variable: java.util.concurrent.SynchronousQueue$TransferStack$SNode#1
   Local Variable: java.util.concurrent.SynchronousQueue$TransferStack#6
at java.util.concurrent.SynchronousQueue.take(SynchronousQueue.java:925)
   Local Variable: java.util.concurrent.SynchronousQueue#6
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
   Local Variable: java.util.concurrent.ThreadPoolExecutor#34
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
   Local Variable: java.util.concurrent.ThreadPoolExecutor$Worker#11
at java.lang.Thread.run(Thread.java:745)

I use Tomcat 8 with hot redeploy feature reloadable="true" and externalized CLASSPATH via PreResources:

<Context docBase="/home/user/devel/app/src/main/webapp"
         reloadable="true">
    <Resources>
        <!-- To override application.properties and logback.xml -->
        <PreResources className="org.apache.catalina.webresources.DirResourceSet"
                       base="/home/user/devel/app/.config"
                       internalPath="/"
                       webAppMount="/WEB-INF/classes" />
    </Resources>
</Context>

and logback.xml with scan="true":

<configuration debug="false" scan="true" scanPeriod="5 seconds">
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    ...

After saving modification in /home/user/devel/app/.config/logback.xml Tomcat 8 receive notification (I am not sure what API used to monitor changes on fs) and application redeploying was started. That is what happen before PermGen OutOfMemory.

How can I Gracefully stop Logback in container environment?

How to stop "logback-1" thread?

I found a few related discussion but can't understand what to do with that info:

• http://logback.10977.n7.nabble.com/How-to-stop-all-appenders-td3023.html
• Do I need to flush events when shutting down using logback?
• Correct way to stop custom logback async appender
• Stopping Logback System for Clean Shutdown

UPDATE I play with heap dump in visualvm. Under level of reference jump from bad logback-1 thread:

lvl1 = flatten(filter(referees(heap.findObject(0xf4c77610)), "!/WebappClassLoader/(classof(it).name)"))

lvl2 = flatten(map(lvl1, "referees(it)"))

lvl3 = flatten(map(lvl2, "referees(it)"))

it refer to

ch.qos.logback.core.util.ExecutorServiceUtil$1

By grepping in Logback sources for ExecutorServiceUtil I found changelog entry:

All threads opened by ch.qos.logback.core.util.ExecutorServiceUtil#THREAD_FACTORY are now daemons, which fixes an application hang on shutdown when LoggerContext#stop() is not called (LOGBACK-929). Note that daemon threads are abruptly terminated by the JVM, which may cause undesirable results, such as corrupted files written by the FileAppender. It is still highly recommended for the application to call LoggerContext#stop() (e.g., in a shutdown hook) to gracefully shutdown appenders.

Is that right that in container environment daemon threads are danger and lead to memory leaks?

Answer 1

I am not fully understand what should I do. Currently I remove jul-to-slf4j bridge from project pom.xml and this line:

<contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator"/>

from logback.xml. Even with this line application have no "logback-1" thread.

As suggest official docs I register:

public class ShutdownCleanupListener implements ServletContextListener {
    @Override
    public void contextInitialized(ServletContextEvent sce) { }

    @Override
    public void contextDestroyed(ServletContextEvent sce) {
        if (LoggerFactory.getILoggerFactory() instanceof LoggerContext) {
            ((LoggerContext) LoggerFactory.getILoggerFactory() ).stop();
        } 
    }
}

in web.xml:

<listener>
    <listener-class>com.app.servlet.ShutdownCleanupListener</listener-class>
</listener>

To remove direct dependency on:

import ch.qos.logback.classic.LoggerContext;

reflection may be used.

Not sure if I am doing right. I will see if get PermGen OutOfMemory error because of Logback.

UPDATE After I have discovered reference dependency from ExecutorServiceUtil class I checked Logback sources and found that this class create threads with names like bad above:

 thread.setName("logback-" + threadNumber.getAndIncrement());

This class only used in ch.qos.logback.core.ContextBase and thread leaned up inside:

public void stop() {
  // We don't check "started" here, because the executor service uses
  // lazy initialization, rather than being created in the start method
  stopExecutorService();
  started = false;
}

Note that LoggerContext is subclass of ContextBase so above solution really fix my problem.

Answer 2

According to the Spring Boot logback example project, you should close the context to clean up the logging system: https://github.com/spring-projects/spring-boot/commit/10402a651f1ee51704b58985c7ef33619df2c110

Example:

public static void main(String[] args) throws Exception {
        SpringApplication.run(SampleLogbackApplication.class, args).close();
    }