stephen-day opened a new issue, #465: URL: https://github.com/apache/mina-sshd/issues/465
### 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 ```Shell 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_ -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: dev-unsubscr...@mina.apache.org.apache.org For queries about this service, please contact Infrastructure at: us...@infra.apache.org --------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@mina.apache.org For additional commands, e-mail: dev-h...@mina.apache.org
