Unable to close client properly #1412
Description
Calling close on a client instance with default config does not wait for all resources to be closed. Wait means that ChannelManager.close() starts an async process (eventLoopGroup.shutdownGracefully...) but does not wait for the future to be completed.
Because it does not wait, the close call completes before the async task is completed and my application continues to shutdown while the async task is still running. This results in an IllegalStateException and lots of NoClassDefFoundErrors in my application. The IllegalStateException is caused because the web application which integrates the ahc is already terminated. The NoClassDefFoundErrors are caused because the netty threads are still running but the classloader is not able to load the classes anymore. Because there are lots of threads, there are also lots of this NoClassDefFoundErrors.
I miss either a wait till all futures are completed or a close method which provides a future as return value so I can wait for the close.
Current workaround is to call Thread.sleep after calling close but this is not a deterministic solution.
09-May-2017 11:23:39.493 INFO [globalEventExecutor-1-2] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [io.netty.channel.group.ChannelMatchers]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [io.netty.channel.group.ChannelMatchers]. 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:1305)
at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1293)
at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1158)
at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1119)
at io.netty.channel.group.DefaultChannelGroup.close(DefaultChannelGroup.java:208)
at org.asynchttpclient.netty.channel.ChannelManager.doClose(ChannelManager.java:357)
at org.asynchttpclient.netty.channel.ChannelManager.lambda$close$1(ChannelManager.java:364)
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:507)
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:481)
at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:420)
at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:95)
at io.netty.util.concurrent.MultithreadEventExecutorGroup$1.operationComplete(MultithreadEventExecutorGroup.java:94)
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:507)
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:481)
at io.netty.util.concurrent.DefaultPromise.access$000(DefaultPromise.java:34)
at io.netty.util.concurrent.DefaultPromise$1.run(DefaultPromise.java:431)
at io.netty.util.concurrent.GlobalEventExecutor$TaskRunner.run(GlobalEventExecutor.java:237)
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
at java.lang.Thread.run(Thread.java:745)
09-May-2017 11:23:39.493 INFO [globalEventExecutor-1-2] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [ch.qos.logback.classic.spi.ThrowableProxy]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [ch.qos.logback.classic.spi.ThrowableProxy]. 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:1305)
at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1293)
at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1158)
at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1119)
at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:119)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:419)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.warn(Logger.java:692)
at io.netty.util.internal.logging.Slf4JLogger.warn(Slf4JLogger.java:151)
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:509)
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:481)
at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:420)
at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:95)
at io.netty.util.concurrent.MultithreadEventExecutorGroup$1.operationComplete(MultithreadEventExecutorGroup.java:94)
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:507)
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:481)
at io.netty.util.concurrent.DefaultPromise.access$000(DefaultPromise.java:34)
at io.netty.util.concurrent.DefaultPromise$1.run(DefaultPromise.java:431)
at io.netty.util.concurrent.GlobalEventExecutor$TaskRunner.run(GlobalEventExecutor.java:237)
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
at java.lang.Thread.run(Thread.java:745)
Exception in thread "globalEventExecutor-1-2" java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy
at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:119)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:419)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.warn(Logger.java:692)
at io.netty.util.internal.logging.Slf4JLogger.warn(Slf4JLogger.java:151)
at io.netty.util.concurrent.GlobalEventExecutor$TaskRunner.run(GlobalEventExecutor.java:239)
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
at java.lang.Thread.run(Thread.java:745)
Also the implementation of isClosed is not implemented properly because it returns whether the close has been triggered but not if close has been finished. This should also be improved. A method like isClosing may return the AtomicBoolean close value.