Tomcat not able to shutdown properly

Question

Tomcat not able to shutdown properly

Opened this issue 8 years ago · 1 comments

Hi,

Since I've added the GelfAppender to my application, the tomcat won't stop properly.
Log4j2.xml:

<?xml version="1.0" encoding="UTF-8" ?>
<Configuration>
    <!-- Appenders and Loggers Declarations -->
    <Appenders>
        <RollingFile name="LOCALFILE" fileName="/path/to/log/file.log"
                     filePattern="/path/to/log/file-%d{yyy-MM-dd}.log">
            <PatternLayout>
                <Pattern>%d{yyyyMMddHHmmssSSS} [%-5t] - [%-5p] - [%-5c] - %m%n</Pattern>
            </PatternLayout>
            <TimeBasedTriggeringPolicy/>
        </RollingFile>
        <GELF name="GRAYLOG" server="127.0.0.1" port="12201" hostName="Maskime-MacBook-Pro.local">
            <PatternLayout>
                <Pattern>%d{yyyyMMddHHmmssSSS} [%-5t] - [%-5p] - [%-5c] - %m%n</Pattern>
            </PatternLayout>
            <Filters>
                <MarkerFilter marker="FLOW" onMatch="DENY" onMismatch="NEUTRAL"/>
                <MarkerFilter marker="EXCEPTION" onMatch="DENY" onMismatch="ACCEPT"/>
            </Filters>
            <KeyValuePair key="platform" value="technical-platform" />
            <KeyValuePair key="version" value="1.0.0-SNAPSHOT"/>
            <KeyValuePair key="env" value="dev"/>
        </GELF>
    </Appenders>

    <Loggers>
        <Root level="INFO">
            <AppenderRef ref="GRAYLOG"/>
            <AppenderRef ref="LOCALFILE"/>
        </Root>
        <!--Prevent the logs from being polluted-->
        <logger name="org.hibernate" level="INFO"/>
        <logger name="org.springframework" level="INFO"/>
    </Loggers>
</Configuration>

When calling shutdown on the tomcat, the catalina.out ends up with the following errors:

29-Nov-2016 15:16:52.657 INFO [main] org.apache.catalina.core.StandardServer.await A valid shutdown command was received via the shutdown port. Stopping the Server instance.
29-Nov-2016 15:16:52.658 INFO [main] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-127.0.0.1-8080"]
29-Nov-2016 15:16:52.713 INFO [main] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-8080"]
29-Nov-2016 15:16:53.769 INFO [main] org.apache.catalina.core.StandardService.stopInternal Stopping service Catalina
29-Nov-2016 15:16:53.798 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [application-name] appears to have started a thread named [gelfUdpTransport-1-1] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
 sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
 sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:103)
 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
 sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
 io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:759)
 io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:400)
 io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:873)
 io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
 java.lang.Thread.run(Thread.java:745)
29-Nov-2016 15:16:53.799 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [application-name] appears to have started a thread named [GelfSenderThread-25] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 sun.misc.Unsafe.park(Native Method)
 java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
 java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
 org.graylog2.gelfclient.transport.GelfSenderThread$1.run(GelfSenderThread.java:93)
 java.lang.Thread.run(Thread.java:745)
29-Nov-2016 15:16:53.799 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [application-name] appears to have started a thread named [threadDeathWatcher-3-1] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.lang.Thread.sleep(Native Method)
 io.netty.util.ThreadDeathWatcher$Watcher.run(ThreadDeathWatcher.java:150)
 io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
 java.lang.Thread.run(Thread.java:745)
29-Nov-2016 15:16:53.800 SEVERE [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [application-name] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@36896e49]) and a value of type [io.netty.util.internal.InternalThreadLocalMap] (value [io.netty.util.internal.InternalThreadLocalMap@7da3fd9a]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
29-Nov-2016 15:16:53.806 INFO [main] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-127.0.0.1-8080"]
29-Nov-2016 15:16:53.910 INFO [main] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-8080"]
29-Nov-2016 15:16:55.053 INFO [main] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["http-nio-127.0.0.1-8080"]
29-Nov-2016 15:16:55.054 INFO [main] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["http-nio-8080"]
29-Nov-2016 15:16:55.055 SEVERE [main] org.apache.coyote.AbstractProtocol.destroy Failed to destroy end point associated with ProtocolHandler ["http-nio-8080"]
 java.io.IOException: Unknown error: 316
	at sun.nio.ch.NativeThread.signal(Native Method)
	at sun.nio.ch.ServerSocketChannelImpl.implCloseSelectableChannel(ServerSocketChannelImpl.java:292)
	at java.nio.channels.spi.AbstractSelectableChannel.implCloseChannel(AbstractSelectableChannel.java:234)
	at java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:115)
	at sun.nio.ch.ServerSocketAdaptor.close(ServerSocketAdaptor.java:137)
	at org.apache.tomcat.util.net.NioEndpoint.unbind(NioEndpoint.java:488)
	at org.apache.tomcat.util.net.AbstractEndpoint.destroy(AbstractEndpoint.java:821)
	at org.apache.coyote.AbstractProtocol.destroy(AbstractProtocol.java:534)
	at org.apache.catalina.connector.Connector.destroyInternal(Connector.java:1023)
	at org.apache.catalina.util.LifecycleBase.destroy(LifecycleBase.java:297)
	at org.apache.catalina.core.StandardService.destroyInternal(StandardService.java:589)
	at org.apache.catalina.util.LifecycleBase.destroy(LifecycleBase.java:297)
	at org.apache.catalina.core.StandardServer.destroyInternal(StandardServer.java:877)
	at org.apache.catalina.util.LifecycleBase.destroy(LifecycleBase.java:297)
	at org.apache.catalina.startup.Catalina.stop(Catalina.java:703)
	at org.apache.catalina.startup.Catalina.start(Catalina.java:664)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:351)
	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:485)

Exception in thread "gelfUdpTransport-1-1" java.lang.NoClassDefFoundError: io/netty/buffer/PoolArena$1
	at io.netty.buffer.PoolArena.freeChunk(PoolArena.java:279)
	at io.netty.buffer.PoolThreadCache$MemoryRegionCache.freeEntry(PoolThreadCache.java:456)
	at io.netty.buffer.PoolThreadCache$MemoryRegionCache.free(PoolThreadCache.java:426)
	at io.netty.buffer.PoolThreadCache$MemoryRegionCache.free(PoolThreadCache.java:418)
	at io.netty.buffer.PoolThreadCache.free(PoolThreadCache.java:275)
	at io.netty.buffer.PoolThreadCache.free(PoolThreadCache.java:266)
	at io.netty.buffer.PoolThreadCache.free0(PoolThreadCache.java:239)
	at io.netty.buffer.PoolThreadCache.free(PoolThreadCache.java:235)
	at io.netty.buffer.PooledByteBufAllocator$PoolThreadLocalCache.onRemoval(PooledByteBufAllocator.java:359)
	at io.netty.buffer.PooledByteBufAllocator$PoolThreadLocalCache.onRemoval(PooledByteBufAllocator.java:345)
	at io.netty.util.concurrent.FastThreadLocal.remove(FastThreadLocal.java:226)
	at io.netty.util.concurrent.FastThreadLocal.removeAll(FastThreadLocal.java:67)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:146)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.ClassNotFoundException: Illegal access: this web application instance has been stopped already. Could not load [io.netty.buffer.PoolArena$1]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
	at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1342)
	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1205)
	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1166)
	... 14 more
Caused by: java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [io.netty.buffer.PoolArena$1]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
	at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading(WebappClassLoaderBase.java:1352)
	at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1340)
	... 16 more
Exception in thread "gelfUdpTransport-1-3" Exception in thread "gelfUdpTransport-1-5" Exception in thread "gelfUdpTransport-1-7" Exception in thread "gelfUdpTransport-1-10" Exception in thread "gelfUdpTransport-1-12" Exception in thread "gelfUdpTransport-1-8" Exception in thread "gelfUdpTransport-1-14" Exception in thread "gelfUdpTransport-1-11" Exception in thread "gelfUdpTransport-1-13" Exception in thread "gelfUdpTransport-1-9" Exception in thread "gelfUdpTransport-1-4" Exception in thread "gelfUdpTransport-1-16" Exception in thread "gelfUdpTransport-1-15" java.lang.NoClassDefFoundError: io/netty/util/concurrent/DefaultPromise$1
Exception in thread "gelfUdpTransport-1-2" 	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:435)
	at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:102)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:912)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
	at java.lang.Thread.run(Thread.java:745)
Exception in thread "gelfUdpTransport-1-6" java.lang.NoClassDefFoundError: io/netty/util/concurrent/DefaultPromise$1
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:435)
	at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:102)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:912)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
	at java.lang.Thread.run(Thread.java:745)
java.lang.NoClassDefFoundError: io/netty/util/concurrent/DefaultPromise$1
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:435)
	at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:102)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:912)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
	at java.lang.Thread.run(Thread.java:745)
  [This one goes on and on until I kill the tomcat with a kill -9 PID command]

I'm pretty sure this comes from the appender because if I remove it the problem is solved and the tomcat exits gracefully.
Tomcat version : Apache Tomcat Version 8.0.36
Java version :

$ java -version
java version "1.8.0_66"
Java(TM) SE Runtime Environment (build 1.8.0_66-b17)
Java HotSpot(TM) 64-Bit Server VM (build 25.66-b17, mixed mode)

GelfAppender Maven dependency:

<dependency>
    <groupId>org.graylog2.log4j2</groupId>
    <artifactId>log4j2-gelf</artifactId>
    <version>1.3.1</version>
</dependency>

I hope I provided enough information for you to look into it.
Thanks for all the help that you can provide concerning this issue

Answer 1 · 2016-12-05T14:52:39.000Z

So for the sake of the poor soul that would have come all the way here to look for a solution.
Please find the stackoverflow question that I created and its solution : http://stackoverflow.com/a/40941642/352808
TL;DR : The problem lies within tomcat and its classloader system. If you put the netty lib at the same level as the webapp, netty will be in the webapp classloader, which can be problematic when you shutdown the application. The solution is to exclude netty from the maven dependency and put them in the CATALINA_HOME/lib/ directory. This way netty is in the common classloader which can be accessed outside the webapp.

I'm no expert but I guess that there ought to be a more elegant solution.