NullPointer in ChannelSession.closeImmediately0() leading to regular warning log spam

[stephen-day]

Version

2.11.0

Bug description

This method regularly produces a NullPointer which it immediately catches and logs as a warning before ignoring it. Hence, this is just warning log spam which makes it more difficult to identify true problems.

Actual behavior

The message of the NullPointerException:

Cannot invoke "org.apache.sshd.common.util.threads.CloseableExecutorService.shutdownNow()"
because "this.pumperService" is null

Makes it clear that the error is coming from this line of code:
https://github.com/apache/mina-sshd/blob/master/sshd-core/src/main/java/org/apache/sshd/client/channel/ChannelSession.java#L174

The exception is immediately caught by the code a few lines down and logged as a warning.

         if ((pumper != null) && (pumperService != null) && (!pumperService.isShutdown())) {
            try {
                if (!pumper.isDone()) {
                    pumper.cancel(true);
                }

==>             pumperService.shutdownNow();
            } catch (Exception e) {
                // we log it as WARN since it is relatively harmless
                warn("doCloseImmediately({}) failed {} to shutdown stream pumper: {}",
                        this, e.getClass().getSimpleName(), e.getMessage(), e);
            }

Expected behavior

Avoid generating the NullPointerException (and hence avoid logging this as a warning).

• Also suggest it's not ideal to catch Exception specifically because it can hide runtime errors like this. If possible, this should only catch exceptions that are expected to be thrown by the close processing (IOException/similar).

My thoughts:

• The pumperService is becoming null between the start of this method and the "pumperServer.shutdownNow()" line of code.
• This NullPointer happens a lot and just gets logged as a warning.
• While it could be a race condition with multiple threads in this method at the same time, that seems less likely.
• Likely cause is that pumper.cancel() is itself closing the channel by indirectly calling closeImmediately0() which sets the values to null such that the pumperService is null on return to this method and the call to pumperService.shutdownNow() generates a NullPointer.

Possible solutions:

• Check for pumperService being null before calling shutdownNow() with a comment that pumper.cancel() can indirectly call closeImmediately0(). This is a quick fix, but seems a bit hacky.
• At the start of the method, move pumper/pumperService to local variables and set the class members to null. This would prevent the indirect call to closeImmediately0() from pumper.cancel() from finding non-null values. But this approach would not work if any aspect of pumper.cancel() required access to these variables.
• Safe approach if previous approach doesn't work: introduce a new class member isClosingDown/similar. Ensure this is false in the first if statement; set this to true before or at the start of the try. This will ensure that the indirect call to closeImmediately0() from pumper.cancel() does nothing (i.e. detects that we're already closing down) and returns to the original closeImmediately0() for the call to pumperService.shutdownNow().

Relevant log output

Warning message:
doCloseImmediately([id=0, recipient=0]-ClientSessionImpl[...]) failed NullPointerException to shutdown stream pumper:
Cannot invoke "org.apache.sshd.common.util.threads.CloseableExecutorService.shutdownNow()" 
because "this.pumperService" is null

Stack trace
    at org.apache.sshd.common.util.logging.AbstractLoggingBean.warn(AbstractLoggingBean.java:114)
    at org.apache.sshd.client.channel.ChannelSession.closeImmediately0(ChannelSession.java:170)
    at org.apache.sshd.common.util.closeable.Builder$1.doClose(Builder.java:47)
    at org.apache.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63)
    at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:56)
    at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45)
    at org.apache.sshd.common.future.AbstractSshFuture.lambda$notifyListener$3(AbstractSshFuture.java:178)
    at org.apache.sshd.common.util.threads.ThreadUtils.runAsInternal(ThreadUtils.java:64)
    at org.apache.sshd.common.future.AbstractSshFuture.notifyListener(AbstractSshFuture.java:177)
    at org.apache.sshd.common.future.DefaultSshFuture.addListener(DefaultSshFuture.java:214)
    at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:57)
    at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45)
    at org.apache.sshd.common.util.closeable.SequentialCloseable.doClose(SequentialCloseable.java:69)
    at org.apache.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63)
    at org.apache.sshd.common.util.closeable.AbstractInnerCloseable.doCloseGracefully(AbstractInnerCloseable.java:41)
    at org.apache.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:110)
    at org.apache.sshd.common.channel.AbstractChannel.handleClose(AbstractChannel.java:551)
    at org.apache.sshd.common.session.helpers.AbstractConnectionService.channelClose(AbstractConnectionService.java:644)
    at org.apache.sshd.common.session.helpers.AbstractConnectionService.process(AbstractConnectionService.java:483)
    at org.apache.sshd.common.session.helpers.CurrentService.process(CurrentService.java:109)
    at org.apache.sshd.common.session.helpers.AbstractSession.doHandleMessage(AbstractSession.java:592)
    at org.apache.sshd.common.session.helpers.AbstractSession.lambda$handleMessage$0(AbstractSession.java:523)
    at org.apache.sshd.common.util.threads.ThreadUtils.runAsInternal(ThreadUtils.java:68)
    at org.apache.sshd.common.session.helpers.AbstractSession.handleMessage(AbstractSession.java:522)
    at org.apache.sshd.common.session.helpers.AbstractSession.decode(AbstractSession.java:1649)
    at org.apache.sshd.common.session.helpers.AbstractSession.messageReceived(AbstractSession.java:483)
    at org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.messageReceived(AbstractSessionIoHandler.java:64)
    at org.apache.sshd.common.io.nio2.Nio2Session.handleReadCycleCompletion(Nio2Session.java:407)
    at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:380)
    at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:375)
    at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$completed$0(Nio2CompletionHandler.java:38)
    at java.security.AccessController.doPrivileged(AccessController.java:318)
    at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37)
    at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:129)
    at sun.nio.ch.Invoker$2.run(Invoker.java:221)
    at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:113)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.lang.Thread.run(Thread.java:833)

Other information

No response

[tomaswolf]

Cannot reproduce. Can you provide sample code that reproduces the behavior you describe?

[stephen-day]

Cannot reproduce. Can you provide sample code that reproduces the behavior you describe?

Unfortunately, I don't have sample code to reproduce this.

However, if you change that catch (Exception) to stop catching runtime exceptions (just catch any required/declared exceptions), do the existing unit tests catch this problem?