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:

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?

gavenkoa · Accepted Answer · 2015-12-28T14:11:18.503

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.

Thanks this fixed my WebappClassLoader leak as well! – whitestryder May 18 '16 at 19:06 — whitestryder, May 18 '16 at 19:06

score 2 · Answer 2 · answered Sep 06 '16 at 03:11

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();
    }

answered Sep 06 '16 at 03:11

E3G

479
5
6

As I understand your solution is applicable only for Spring Boot enabled applications... – gavenkoa Sep 06 '16 at 18:04

score 1 · Answer 3 · answered Jan 07 '16 at 08:20

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

The statement about daemon threads refer to the case of a stand alone application (as in the bug report), where the JVM is supposed to shut down when the application is finished. The non-daemon thread prevents the JVM from shutting down.

In a JavaEE context, where the JVM of the application server remains the same over potentially multiple lifecycles of multiple applications, daemon vs non-daemon does not affect the fact that live threads are GC roots.

Gracefully stop Logback in container environment

3 Answers3