[
https://issues.apache.org/jira/browse/SSHD-1307?focusedWorklogId=819382&page=com.atlassian.jira.plugin.system.issuetabpanels:worklog-tabpanel#worklog-819382
]
ASF GitHub Bot logged work on SSHD-1307:
----------------------------------------
Author: ASF GitHub Bot
Created on: 22/Oct/22 21:41
Start Date: 22/Oct/22 21:41
Worklog Time Spent: 10m
Work Description: tomaswolf opened a new pull request, #257:
URL: https://github.com/apache/mina-sshd/pull/257
Nio2Session.shutdownOutputStream() can be invoked while there are still
writes in progress. The output is shut down in TCP/IP port forwarding to
propagate an SSH_MSG_CHANNEL_EOF from the channel to whatever is on the other
side of the forwarded port; see SSHD-1055. However, writing through the socket
is asynchronous, so a channel may get the following sequence of events:
1. receive last SSH_MSG_CHANNEL_DATA
2. Nio2Session.writeBuffer() enqueues the write request
3. SSH_MSG_CHANNEL_DATA handling completes
4. receive SSH_MSG_CHANNEL_EOF
5. call Nio2Session.shutdownOutputStream()
If (5) shuts down the output immediately but the write request from (2) has
not been written yet, that write attempt will fail with a
ClosedChannelException.
The output stream on the socket should not be shut down immediately but only
once already pending writes have been done. This is already the case with the
MINA and Netty transport back-ends, which only schedule a shutdown request on
their write queue.
Implement the same for the NIO2 transport. A write future with a null buffer
signifies a shutdown request; true write requests always have a non-null
buffer. Make shutdownOutputStream() only enqueue such a shutdown request on the
session's write queue; the output will be shut down once startWriting() pops
this shutdown request from the write queue.
Issue Time Tracking
-------------------
Worklog Id: (was: 819382)
Remaining Estimate: 0h
Time Spent: 10m
> 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
> Priority: Major
> Time Spent: 10m
> Remaining Estimate: 0h
>
> Split out from
> [SSHD-1055|https://issues.apache.org/jira/browse/SSHD-1055?focusedCommentId=17621354&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-17621354]:
> 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[r...@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[r...@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[r...@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[r...@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[r...@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[r...@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[r...@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[r...@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[r...@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[r...@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[r...@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[r...@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[r...@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[r...@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[r...@elib17.us.oracle.com/10.80.104.97:22])
> result=TcpipClientChannel[id=71,
> recipient=2]-ClientSessionImpl[r...@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[r...@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[r...@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
> {code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@mina.apache.org
For additional commands, e-mail: dev-h...@mina.apache.org
