[SSHD-1307] Nio2Session.shutdownOutput() should wait for writes in progress - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: 2.9.1
Fix Version/s: 2.9.2
Labels:
None

Description

Split out from SSHD-1055:

I am currently experiencing an exception that appears to be related to the use of the serverSession.shudownOutputStream(); in the TcpIpClientChannel.handleEOF method.

My context is the following

Apache Mina sshd client version 2.9.1 on the local side.
OpenSSH 5.9 on the remote server side.
Local port forwarding port 9000 to remote localhost:8080
The error occurs on the Apache Mina sshd client side.

I intermittently take exceptions on URL connections that are completed and they have received the last of the data and is processing the SSH_MSG_CHANNEL_EOF

Any ideas or thoughts would be appreciated.

09:16:42.873 [sshd-SshClient[477424ca]-nio2-thread-8] DEBUG org.apache.sshd.common.forward.TcpipClientChannel - handleData(TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22]) SSH_MSG_CHANNEL_DATA len=999
09:16:42.873 [sshd-SshClient[477424ca]-nio2-thread-8] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - writeBuffer(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027]) writing 999 bytes
09:16:42.873 [sshd-SshClient[477424ca]-nio2-thread-8] DEBUG org.apache.sshd.common.forward.TcpipClientChannel - handleData(TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22]) SSH_MSG_CHANNEL_DATA len=2
09:16:42.873 [sshd-SshClient[477424ca]-nio2-thread-8] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - writeBuffer(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027]) writing 2 bytes
09:16:42.873 [sshd-SshClient[477424ca]-nio2-thread-8] DEBUG org.apache.sshd.common.forward.TcpipClientChannel - handleData(TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22]) SSH_MSG_CHANNEL_DATA len=115
09:16:42.873 [sshd-SshClient[477424ca]-nio2-thread-8] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - writeBuffer(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027]) writing 115 bytes
09:16:42.873 [sshd-SshClient[477424ca]-nio2-thread-8] DEBUG org.apache.sshd.common.forward.TcpipClientChannel - handleEof(TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22]) SSH_MSG_CHANNEL_EOF
09:16:42.873 [sshd-SshClient[477424ca]-nio2-thread-8] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - shudownOutputStream(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027])
09:16:42.875 [sshd-SshClient[477424ca]-nio2-thread-6] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - handleWriteCycleFailure(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027]) failed (ClosedChannelException) to write 115 bytes at write cycle=17 afer 987500 nanos: null
09:16:42.875 [sshd-SshClient[477424ca]-nio2-thread-6] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - exceptionCaught(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027]) caught ClosedChannelException[null] - calling handler
09:16:42.879 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - handleReadCycleCompletion(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027]) Socket has been disconnected (result=-1), closing IoSession now
09:16:42.879 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - close(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027]) Closing immediately
09:16:42.879 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - doCloseImmediately(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027]) closing socket=sun.nio.ch.WindowsAsynchronousSocketChannelImpl[connected oshut local=/127.0.0.1:9000 remote=/127.0.0.1:62027]
09:16:42.879 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - doCloseImmediately(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027]) socket=sun.nio.ch.WindowsAsynchronousSocketChannelImpl[closed] closed
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.io.nio2.Nio2Acceptor - unmapSession(id=168): Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027]
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.forward.DefaultForwarder - sessionClosed(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027]) closing channel=TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22] after 67 messages - cause=ClosedChannelException
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.forward.TcpipClientChannel - close(TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22]) Closing immediately
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.forward.TcpipClientChannel - close(TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22]) no EOF sent
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.channel.Window - Closing Window[client/local](TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22])
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.channel.Window - Closing Window[client/remote](TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22])
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - close(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027])[Immediately] state already Closed
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.forward.TcpipClientChannel$1 - close([TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22]] cmd=SSH_MSG_CHANNEL_DATA) Closing immediately
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.forward.TcpipClientChannel$1 - close([TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22]] cmd=SSH_MSG_CHANNEL_DATA)[Immediately] closed
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.channel.ChannelAsyncInputStream - close(ChannelAsyncInputStream[TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22]]) Closing immediately
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.channel.ChannelAsyncInputStream - close(ChannelAsyncInputStream[TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22]])[Immediately] closed
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable - close(TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22])[immediately=true] processing
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.client.session.ClientConnectionService - unregisterChannel(TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22]) result=TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22]
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.util.closeable.SequentialCloseable - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@21cadb52<org.apache.sshd.common.util.closeable.SequentialCloseable$1@21cadb52>) signal close complete immediately=true
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.util.closeable.SequentialCloseable - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@28848783<org.apache.sshd.common.util.closeable.SequentialCloseable$1@28848783>) signal close complete immediately=true
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.util.closeable.SequentialCloseable - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@73eedba7<org.apache.sshd.common.util.closeable.SequentialCloseable$1@73eedba7>) signal close complete immediately=true
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.forward.TcpipClientChannel - close(TcpipClientChannel[id=71, recipient=2]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22])[Immediately] closed
09:16:42.880 [sshd-SshClient[477424ca]-nio2-thread-4] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - close(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027])[Immediately] closed
09:16:42.883 [sshd-SshClient[477424ca]-nio2-thread-6] WARN org.apache.sshd.common.forward.DefaultForwarder - exceptionCaught(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027]) ClosedChannelException: null
java.nio.channels.ClosedChannelException: null
at sun.nio.ch.AsynchronousSocketChannelImpl.write(Unknown Source)
at sun.nio.ch.AsynchronousSocketChannelImpl.write(Unknown Source)
at org.apache.sshd.common.io.nio2.Nio2Session.doWriteCycle(Nio2Session.java:492)
at org.apache.sshd.common.io.nio2.Nio2Session.startWriting(Nio2Session.java:475)
at org.apache.sshd.common.io.nio2.Nio2Session.finishWrite(Nio2Session.java:564)
at org.apache.sshd.common.io.nio2.Nio2Session.handleCompletedWriteCycle(Nio2Session.java:534)
at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:501)
at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:498)
at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$completed$0(Nio2CompletionHandler.java:38)
at java.security.AccessController.doPrivileged(Native Method)
at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37)
at sun.nio.ch.Invoker.invokeUnchecked(Unknown Source)
at sun.nio.ch.Invoker$2.run(Unknown Source)
at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
09:16:42.883 [sshd-SshClient[477424ca]-nio2-thread-6] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - close(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027])[Immediately] state already Closed
09:16:42.883 [sshd-SshClient[477424ca]-nio2-thread-6] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - close(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:62027])[Immediately] state already Closed
09:16:58.809 [sshd-SshClient[477424ca]-nio2-thread-7] DEBUG org.apache.sshd.common.forward.TcpipClientChannel - handleData(TcpipClientChannel[id=11, recipient=1]-ClientSessionImpl[root@elib17.us.oracle.com/10.80.104.97:22]) SSH_MSG_CHANNEL_DATA len=309
09:16:58.809 [sshd-SshClient[477424ca]-nio2-thread-7] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - writeBuffer(Nio2Session[local=/127.0.0.1:9000, remote=/127.0.0.1:61820]) writing 309 bytes

Attachments

Issue Links

is caused by

SSHD-1055 Remote port forwarding mode does not handle EOF properly

Resolved

Activity

People

Assignee:: Thomas Wolf

Reporter:: Thomas Wolf

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 22/Oct/22 19:54

Updated:: 23/Nov/22 22:28

Resolved:: 24/Oct/22 19:22

Time Tracking

Estimated:

Not Specified

Remaining:

Logged: