[ https://issues.apache.org/jira/browse/SSHD-1334?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ryan Livingston updated SSHD-1334: ---------------------------------- Description: When attempting to upload/scp a byte stream using the below method, the main thread will always block until the exit status timeout is reached. {code:java} DefaultScpClient::upload(InputStream local, String remote, long size,Collection<PosixFilePermission> perms, ScpTimestampCommandDetails time){code} It appears this is the case because the _handleCommandExitStatus(cmd, channel)_ is called before the In/Out channels are auto-closed by the try-with-resources block, and thus the EOF is not sent to the remote prior to handling the exit status. The current implementation always times out first and then sends an EOF while closing the channels. Using the API to send based on file paths will invoke _DefaultScpClient::runUpload()_ which first closes the channel resources and then waits for the exit status. This API works well without the exit status blocking the thread. I have overridden the default client to ignore the status exit, and there is a dedicated property to adjust this timeout. Though, this is not really a solution to this issue. I attempted to override and close the channels first prior to handling the exit status like `runUpload()`, but this introduced some async issues when processing some remaining inbound messages from the remote after the pipe is closed. This issue is persistent on remote SSH servers running with CentOS and MacOS. This example is being run on MacOS 13.3.1 with a remote SSH server that has no explicit SSH configuration. Path based logging: {code:java} 2023-08-02 14:17:50 DEBUG ScpHelper:597 - sendStream(ScpHelper[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[/Users/ryanlivingston/tmp/testfile.txt] command='C0644 9 testfile.txt' ACK=0 2023-08-02 14:17:50 DEBUG ChannelExec:940 - sendEof(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_EOF (state=Opened) 2023-08-02 14:17:50 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #11 sending command=96[SSH_MSG_CHANNEL_EOF] len=5 2023-08-02 14:17:50 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:54429, remote=localhost/127.0.0.1:22]) writing 36 bytes 2023-08-02 14:17:50 DEBUG DefaultScpClient:155 - runUpload(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) /Users/ryanlivingston/tmp/testfile2.txt => [/Users/ryanlivingston/tmp/testfile.txt] - failed (UnsupportedOperationException) to close file system=sun.nio.fs.MacOSXFileSystem@9ebe38b: null 2023-08-02 14:17:50 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #16 SSH_MSG_CHANNEL_EOF 2023-08-02 14:17:50 DEBUG ChannelExec:873 - handleEof(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_EOF 2023-08-02 14:17:50 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #17 SSH_MSG_CHANNEL_REQUEST 2023-08-02 14:17:50 DEBUG ChannelExec:271 - handleChannelRequest(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_REQUEST exit-status wantReply=false 2023-08-02 14:17:50 DEBUG ExitStatusChannelRequestHandler:50 - processRequestValue(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) status=0 2023-08-02 14:17:50 DEBUG ExitStatusChannelRequestHandler:59 - process(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[exit-status] wantReply=false: 0 2023-08-02 14:17:50 DEBUG ChannelExec:114 - notifyEvent(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]): exit-status 2023-08-02 14:17:50 DEBUG ExitStatusChannelRequestHandler:101 - notifyStateChanged(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[exit-status] event=exit-status 2023-08-02 14:17:50 DEBUG ChannelExec:345 - sendResponse(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) request=exit-status result=ReplySuccess, want-reply=false 2023-08-02 14:17:50 DEBUG ChannelExec:247 - waitFor(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) mask=[CLOSED, EXIT_STATUS] - exit status=0 2023-08-02 14:17:50 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #18 SSH_MSG_CHANNEL_CLOSE 2023-08-02 14:17:50 DEBUG DefaultScpClient:176 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -t -- /Users/ryanlivingston/tmp/testfile2.txt', waited=636667 nanos, events=[EOF, EXIT_STATUS, OPENED] 2023-08-02 14:17:50 DEBUG DefaultScpClient:206 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -t -- /Users/ryanlivingston/tmp/testfile2.txt', exit-status=OK {code} Stream based logging: {code:java} 2023-08-02 14:32:57 DEBUG ScpHelper:597 - sendStream(ScpHelper[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt] command='C0666 9 testfile.txt' ACK=0 2023-08-02 14:32:57 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #15 SSH_MSG_CHANNEL_DATA 2023-08-02 14:32:57 DEBUG LocalWindow:87 - Consume LocalWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) by 1 down to 2097148 2023-08-02 14:32:57 DEBUG ChannelExec:788 - handleData(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_DATA len=1 2023-08-02 14:33:02 DEBUG DefaultScpClient:176 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt', waited=5007089542 nanos, events=[TIMEOUT, OPENED] 2023-08-02 14:33:02 DEBUG DefaultScpClient:206 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt', exit-status=null 2023-08-02 14:33:02 DEBUG ChannelExec:940 - sendEof(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_EOF (state=Opened) 2023-08-02 14:33:02 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #12 sending command=96[SSH_MSG_CHANNEL_EOF] len=5 2023-08-02 14:33:02 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:54518, remote=localhost/127.0.0.1:22]) writing 36 bytes 2023-08-02 14:33:02 DEBUG ChannelExec:107 - close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Closing gracefully {code} was: When attempting to upload/scp a byte stream using the below method, the main thread will always block until the exit status timeout is reached. {code:java} DefaultScpClient::upload(InputStream local, String remote, long size,Collection<PosixFilePermission> perms, ScpTimestampCommandDetails time){code} It appears this is the case because the _handleCommandExitStatus(cmd, channel)_ is called before the In/Out channels are auto-closed by the try-with-resources block, and thus the EOF is not sent to the remote prior to handling the exit status. The current implementation always times out first and then sends an EOF while closing the channels. Using the API to send based on file paths will invoke _DefaultScpClient::runUpload()_ which first closes the channel resources and then waits for the exit status. This API works well without the exit status blocking the thread. I have overridden the default client to ignore the status exit, and there is a dedicated property to adjust this timeout. Though, this is not really a solution to this issue. I attempted to override and close the channels first prior to handling the exit status like `runUpload()`, but this introduced some async issues when processing some remaining inbound messages from the remote after the pipe is closed. This issue is persistent on remote SSH servers running with CentOS and MacOS. This example is being run on MacOS 13.3.1 with a remote SSH server that has no explicit SSH configuration. Path based logging: {code:java} 2023-08-02 14:17:50 DEBUG ScpHelper:597 - sendStream(ScpHelper[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[/Users/ryanlivingston/tmp/testfile.txt] command='C0644 9 testfile.txt' ACK=0 2023-08-02 14:17:50 DEBUG ChannelExec:940 - sendEof(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_EOF (state=Opened) 2023-08-02 14:17:50 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #11 sending command=96[SSH_MSG_CHANNEL_EOF] len=5 2023-08-02 14:17:50 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:54429, remote=localhost/127.0.0.1:22]) writing 36 bytes 2023-08-02 14:17:50 DEBUG DefaultScpClient:155 - runUpload(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) /Users/ryanlivingston/tmp/testfile2.txt => [/Users/ryanlivingston/tmp/testfile.txt] - failed (UnsupportedOperationException) to close file system=sun.nio.fs.MacOSXFileSystem@9ebe38b: null 2023-08-02 14:17:50 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #16 SSH_MSG_CHANNEL_EOF 2023-08-02 14:17:50 DEBUG ChannelExec:873 - handleEof(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_EOF 2023-08-02 14:17:50 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #17 SSH_MSG_CHANNEL_REQUEST 2023-08-02 14:17:50 DEBUG ChannelExec:271 - handleChannelRequest(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_REQUEST exit-status wantReply=false 2023-08-02 14:17:50 DEBUG ExitStatusChannelRequestHandler:50 - processRequestValue(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) status=0 2023-08-02 14:17:50 DEBUG ExitStatusChannelRequestHandler:59 - process(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[exit-status] wantReply=false: 0 2023-08-02 14:17:50 DEBUG ChannelExec:114 - notifyEvent(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]): exit-status 2023-08-02 14:17:50 DEBUG ExitStatusChannelRequestHandler:101 - notifyStateChanged(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[exit-status] event=exit-status 2023-08-02 14:17:50 DEBUG ChannelExec:345 - sendResponse(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) request=exit-status result=ReplySuccess, want-reply=false 2023-08-02 14:17:50 DEBUG ChannelExec:247 - waitFor(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) mask=[CLOSED, EXIT_STATUS] - exit status=0 2023-08-02 14:17:50 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #18 SSH_MSG_CHANNEL_CLOSE 2023-08-02 14:17:50 DEBUG DefaultScpClient:176 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -t -- /Users/ryanlivingston/tmp/testfile2.txt', waited=636667 nanos, events=[EOF, EXIT_STATUS, OPENED] 2023-08-02 14:17:50 DEBUG DefaultScpClient:206 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -t -- /Users/ryanlivingston/tmp/testfile2.txt', exit-status=OK {code} Stream based logging: {code:java} // code placeholder {code} > DefaultScpClient::upload(InputStream, ...) will always hit the exit status > timeout > ---------------------------------------------------------------------------------- > > Key: SSHD-1334 > URL: https://issues.apache.org/jira/browse/SSHD-1334 > Project: MINA SSHD > Issue Type: Bug > Affects Versions: 2.10.0 > Reporter: Ryan Livingston > Priority: Major > Attachments: file-based.txt, stream-based.txt > > > When attempting to upload/scp a byte stream using the below method, the main > thread will always block until the exit status timeout is reached. > {code:java} > DefaultScpClient::upload(InputStream local, String remote, long > size,Collection<PosixFilePermission> perms, ScpTimestampCommandDetails > time){code} > It appears this is the case because the _handleCommandExitStatus(cmd, > channel)_ is called before the In/Out channels are auto-closed by the > try-with-resources block, and thus the EOF is not sent to the remote prior to > handling the exit status. The current implementation always times out first > and then sends an EOF while closing the channels. > Using the API to send based on file paths will invoke > _DefaultScpClient::runUpload()_ which first closes the channel resources and > then waits for the exit status. This API works well without the exit status > blocking the thread. > I have overridden the default client to ignore the status exit, and there is > a dedicated property to adjust this timeout. Though, this is not really a > solution to this issue. > I attempted to override and close the channels first prior to handling the > exit status like `runUpload()`, but this introduced some async issues when > processing some remaining inbound messages from the remote after the pipe is > closed. > This issue is persistent on remote SSH servers running with CentOS and MacOS. > This example is being run on MacOS 13.3.1 with a remote SSH server that has > no explicit SSH configuration. > Path based logging: > {code:java} > 2023-08-02 14:17:50 DEBUG ScpHelper:597 - > sendStream(ScpHelper[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[/Users/ryanlivingston/tmp/testfile.txt] > command='C0644 9 testfile.txt' ACK=0 > 2023-08-02 14:17:50 DEBUG ChannelExec:940 - sendEof(ChannelExec[id=0, > recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > SSH_MSG_CHANNEL_EOF (state=Opened) > 2023-08-02 14:17:50 DEBUG ClientSessionImpl:1402 - > encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #11 > sending command=96[SSH_MSG_CHANNEL_EOF] len=5 > 2023-08-02 14:17:50 DEBUG Nio2Session:179 - > writeBuffer(Nio2Session[local=/127.0.0.1:54429, > remote=localhost/127.0.0.1:22]) writing 36 bytes > 2023-08-02 14:17:50 DEBUG DefaultScpClient:155 - > runUpload(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > /Users/ryanlivingston/tmp/testfile2.txt => > [/Users/ryanlivingston/tmp/testfile.txt] - failed > (UnsupportedOperationException) to close file > system=sun.nio.fs.MacOSXFileSystem@9ebe38b: null > 2023-08-02 14:17:50 DEBUG ClientSessionImpl:544 - > doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > process #16 SSH_MSG_CHANNEL_EOF > 2023-08-02 14:17:50 DEBUG ChannelExec:873 - handleEof(ChannelExec[id=0, > recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > SSH_MSG_CHANNEL_EOF > 2023-08-02 14:17:50 DEBUG ClientSessionImpl:544 - > doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > process #17 SSH_MSG_CHANNEL_REQUEST > 2023-08-02 14:17:50 DEBUG ChannelExec:271 - > handleChannelRequest(ChannelExec[id=0, > recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > SSH_MSG_CHANNEL_REQUEST exit-status wantReply=false > 2023-08-02 14:17:50 DEBUG ExitStatusChannelRequestHandler:50 - > processRequestValue(ChannelExec[id=0, > recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > status=0 > 2023-08-02 14:17:50 DEBUG ExitStatusChannelRequestHandler:59 - > process(ChannelExec[id=0, > recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[exit-status] > wantReply=false: 0 > 2023-08-02 14:17:50 DEBUG ChannelExec:114 - notifyEvent(ChannelExec[id=0, > recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]): > exit-status > 2023-08-02 14:17:50 DEBUG ExitStatusChannelRequestHandler:101 - > notifyStateChanged(ChannelExec[id=0, > recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[exit-status] > event=exit-status > 2023-08-02 14:17:50 DEBUG ChannelExec:345 - sendResponse(ChannelExec[id=0, > recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > request=exit-status result=ReplySuccess, want-reply=false > 2023-08-02 14:17:50 DEBUG ChannelExec:247 - waitFor(ChannelExec[id=0, > recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > mask=[CLOSED, EXIT_STATUS] - exit status=0 > 2023-08-02 14:17:50 DEBUG ClientSessionImpl:544 - > doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > process #18 SSH_MSG_CHANNEL_CLOSE > 2023-08-02 14:17:50 DEBUG DefaultScpClient:176 - > handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > cmd='scp -t -- /Users/ryanlivingston/tmp/testfile2.txt', waited=636667 > nanos, events=[EOF, EXIT_STATUS, OPENED] > 2023-08-02 14:17:50 DEBUG DefaultScpClient:206 - > handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > cmd='scp -t -- /Users/ryanlivingston/tmp/testfile2.txt', exit-status=OK > {code} > Stream based logging: > {code:java} > 2023-08-02 14:32:57 DEBUG ScpHelper:597 - > sendStream(ScpHelper[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[scp > -p -t -- /Users/ryanlivingston/tmp/testfile.txt] command='C0666 9 > testfile.txt' ACK=0 2023-08-02 14:32:57 DEBUG ClientSessionImpl:544 - > doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > process #15 SSH_MSG_CHANNEL_DATA 2023-08-02 14:32:57 DEBUG LocalWindow:87 - > Consume LocalWindow[client](ChannelExec[id=0, > recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) by 1 > down to 2097148 2023-08-02 14:32:57 DEBUG ChannelExec:788 - > handleData(ChannelExec[id=0, > recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > SSH_MSG_CHANNEL_DATA len=1 2023-08-02 14:33:02 DEBUG DefaultScpClient:176 - > handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > cmd='scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt', waited=5007089542 > nanos, events=[TIMEOUT, OPENED] 2023-08-02 14:33:02 DEBUG > DefaultScpClient:206 - > handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > cmd='scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt', exit-status=null > 2023-08-02 14:33:02 DEBUG ChannelExec:940 - sendEof(ChannelExec[id=0, > recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > SSH_MSG_CHANNEL_EOF (state=Opened) 2023-08-02 14:33:02 DEBUG > ClientSessionImpl:1402 - > encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #12 > sending command=96[SSH_MSG_CHANNEL_EOF] len=5 2023-08-02 14:33:02 DEBUG > Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:54518, > remote=localhost/127.0.0.1:22]) writing 36 bytes 2023-08-02 14:33:02 DEBUG > ChannelExec:107 - close(ChannelExec[id=0, > recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) > Closing gracefully {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