Thomas Wolf created SSHD-1307:
---------------------------------
Summary: Nio2Session.shutdownOutput() should wait for writes in
progress
Key: SSHD-1307
URL: https://issues.apache.org/jira/browse/SSHD-1307
Project: MINA SSHD
Issue Type: Bug
Affects Versions: 2.9.1
Reporter: Thomas Wolf
Assignee: Thomas Wolf
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.
{code:java}
09:16:42.873 [sshd-SshClient[477424ca]-nio2-thread-8] DEBUG
org.apache.sshd.common.forward.TcpipClientChannel -
handleData(TcpipClientChannel[id=71,
recipient=2]-ClientSessionImpl[[email protected]/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[[email protected]/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[[email protected]/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[[email protected]/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[[email protected]/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[[email protected]/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[[email protected]/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[[email protected]/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[[email protected]/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[[email protected]/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[[email protected]/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[[email protected]/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[[email protected]/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[[email protected]/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[[email protected]/10.80.104.97:22])
result=TcpipClientChannel[id=71,
recipient=2]-ClientSessionImpl[[email protected]/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[[email protected]/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[[email protected]/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
{code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
