NullPointer in ChannelSession.closeImmediately0() leading to regular warning log spam
- Dominant language
- Java
- Stars
- 1.1k
- Forks
- 400
- Avg merge
- 5d 1h
- Merged PRs (30d)
- 1
Description
### 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_
Contributor guide
No contributing guide indexed for this repository
Research direction
Start in sshd-core/src/main/java/org/apache/sshd/client/channel/ChannelSession.java around line 174 and trace closeImmediately0(), pumper.cancel(), and the nested close path shown in the stack trace. Confirm how pumperService becomes null during re-entrant closing; done means the close path no longer produces this NullPointerException or warning spam while still handling expected close failures appropriately.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- java
- Domain
- networking
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100