Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

DefaultScpClient.upload(InputStream, ...) will always hit the exit status timeout #427

Closed
TerraNibble opened this issue Oct 31, 2023 · 4 comments · Fixed by #464
Closed
Milestone

Comments

@TerraNibble
Copy link
Contributor

TerraNibble commented Oct 31, 2023

Version

2.11.0

Bug 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.
DefaultScpClient::upload(InputStream local, String remote, long size,Collection<PosixFilePermission> perms, ScpTimestampCommandDetails time)

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 exit status result, and there is a dedicated property to adjust this timeout. Though, this is not really a solution to this issue.

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. Testing on sshd-scp 2.10.0 and 2.11.0.

Overriding the client to do the following seems to resolve the issue:

@Override
    public void upload(
            InputStream local, String remote, long size, Collection<PosixFilePermission> perms, ScpTimestampCommandDetails time)
            throws IOException {
        int namePos = ValidateUtils.checkNotNullAndNotEmpty(remote, "No remote location specified").lastIndexOf('/');
        String name = (namePos < 0)
                ? remote
                : ValidateUtils.checkNotNullAndNotEmpty(remote.substring(namePos + 1), "No name value in remote=%s", remote);
        Collection<Option> options = (time != null) ? EnumSet.of(Option.PreserveAttributes) : Collections.emptySet();
        String cmd = ScpClient.createSendCommand(remote, options);
        ClientSession session = getClientSession();
        ChannelExec channel = openCommandChannel(session, cmd);
        try {
            try (InputStream invOut = channel.getInvertedOut();
                 OutputStream invIn = channel.getInvertedIn()) {
                // NOTE: we use a mock file system since we expect no invocations for it
                ScpHelper helper = new ScpHelper(session, invOut, invIn, new MockFileSystem(remote), opener, listener);
                Path mockPath = new MockPath(remote);
                helper.sendStream(new DefaultScpStreamResolver(name, mockPath, perms, time, size, local, cmd),
                        options.contains(Option.PreserveAttributes), ScpHelper.DEFAULT_SEND_BUFFER_SIZE);
            }
            handleCommandExitStatus(cmd, channel);
        }finally {
            channel.close(false);
        }
    }

Actual behavior

The upload method blocked the main thread after byte transfer for 5 seconds.

Expected behavior

The upload SCP routine should receive an exit status immediately after byte array upload.

Relevant log output

2023-10-31 14:44:24 INFO  BouncyCastleSecurityProviderRegistrar:112 - getOrCreateProvider(BC) created instance of org.bouncycastle.jce.provider.BouncyCastleProvider
2023-10-31 14:44:24 DEBUG SecurityUtils:450 - register(EdDSA) not registered - enabled=true, supported=false
2023-10-31 14:44:25 INFO  DefaultIoServiceFactoryFactory:68 - No detected/configured IoServiceFactoryFactory; using Nio2ServiceFactoryFactory
2023-10-31 14:44:25 INFO  DefaultConfigFileHostEntryResolver:89 - resolveEffectiveResolver(ryanlivingston@localhost:22/null) no configuration file at /Users/ryanlivingston/.ssh/config
2023-10-31 14:44:25 DEBUG DefaultConfigFileHostEntryResolver:62 - resolveEffectiveHost(ryanlivingston@localhost:22/null) => null
2023-10-31 14:44:25 DEBUG SshClient:700 - connect(ryanlivingston@localhost:22) no overrides
2023-10-31 14:44:25 DEBUG Nio2Connector:62 - Connecting to localhost/127.0.0.1:22
2023-10-31 14:44:25 DEBUG Nio2Connector:201 - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2023-10-31 14:44:25 DEBUG Nio2Connector:101 - connect(localhost/127.0.0.1:22): waiting for connection (timeout=60000ms)
2023-10-31 14:44:25 DEBUG Nio2Session:93 - Creating IoSession on /127.0.0.1:60645 from localhost/127.0.0.1:22 via null
2023-10-31 14:44:25 DEBUG ClientSessionImpl:78 - Client session created: Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]
2023-10-31 14:44:25 DEBUG ClientUserAuthService:107 - ClientUserAuthService(ClientSessionImpl[null@localhost/127.0.0.1:22]) client methods: [publickey, keyboard-interactive, password]
2023-10-31 14:44:25 DEBUG SessionTimeoutListener:50 - sessionCreated(ClientSessionImpl[null@localhost/127.0.0.1:22]) tracking
2023-10-31 14:44:25 DEBUG ClientSessionImpl:332 - initializeProxyConnector(ClientSessionImpl[null@localhost/127.0.0.1:22]) no proxy to initialize
2023-10-31 14:44:25 DEBUG ClientSessionImpl:850 - sendIdentification(ClientSessionImpl[null@localhost/127.0.0.1:22]): SSH-2.0-APACHE-SSHD-2.11.0
2023-10-31 14:44:25 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 28 bytes
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1703 - sendKexInit(ClientSessionImpl[null@localhost/127.0.0.1:22]) Send SSH_MSG_KEXINIT
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[null@localhost/127.0.0.1:22]) packet #0 sending command=20[SSH_MSG_KEXINIT] len=1234
2023-10-31 14:44:25 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 1248 bytes
2023-10-31 14:44:25 DEBUG SshClient:849 - setupDefaultSessionIdentities(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) key identity provider override in session listener
2023-10-31 14:44:25 DEBUG DefaultConnectFuture:59 - Connected to localhost/127.0.0.1:22 after 20944625 nanos
2023-10-31 14:44:25 DEBUG ClientSessionImpl:922 - doReadIdentification(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) line='SSH-2.0-OpenSSH_9.0'
2023-10-31 14:44:25 DEBUG ClientSessionImpl:533 - readIdentification(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Server version string: SSH-2.0-OpenSSH_9.0
2023-10-31 14:44:25 DEBUG OpenSSHKeyPairResourceParser:127 - extractKeyPairs(/Users/ryanlivingston/.ssh/id_rsa) decode 1 keys using context=OpenSSHParserContext[cipher=none, kdfOptions=none: options=]
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #0 SSH_MSG_KEXINIT
2023-10-31 14:44:25 DEBUG ClientSessionImpl:825 - handleKexInit(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_KEXINIT
2023-10-31 14:44:25 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: kex algorithms = curve25519-sha256
2023-10-31 14:44:25 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: server host key algorithms = ecdsa-sha2-nistp256
2023-10-31 14:44:25 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: encryption algorithms (client to server) = chacha20-poly1305@openssh.com
2023-10-31 14:44:25 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: encryption algorithms (server to client) = chacha20-poly1305@openssh.com
2023-10-31 14:44:25 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: mac algorithms (client to server) = hmac-sha2-256-etm@openssh.com
2023-10-31 14:44:25 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: mac algorithms (server to client) = hmac-sha2-256-etm@openssh.com
2023-10-31 14:44:25 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: compression algorithms (client to server) = none
2023-10-31 14:44:25 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: compression algorithms (server to client) = none
2023-10-31 14:44:25 DEBUG DHGClient:102 - init(DHGClient[curve25519-sha256])[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]] Send SSH_MSG_KEXDH_INIT
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #1 sending command=30[30] len=37
2023-10-31 14:44:25 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 56 bytes
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #1 31
2023-10-31 14:44:25 DEBUG DHGClient:119 - next(DHGClient[curve25519-sha256])[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]] process command=SSH_MSG_KEXDH_REPLY
2023-10-31 14:44:25 DEBUG ClientSessionImpl:145 - setServerKey(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) keyType=ecdsa-sha2-nistp256, digest=SHA256:RByIUcL/TqyhhieJda6AIKHXaEiav7ylwTRHbp2olt0
2023-10-31 14:44:25 DEBUG ClientSessionImpl:724 - handleKexMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[curve25519-sha256] KEX processing complete after cmd=31
2023-10-31 14:44:25 WARN  AcceptAllServerKeyVerifier:59 - Server at localhost/127.0.0.1:22 presented unverified EC key: SHA256:RByIUcL/TqyhhieJda6AIKHXaEiav7ylwTRHbp2olt0
2023-10-31 14:44:25 DEBUG ClientSessionImpl:639 - checkKeys(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) key=ecdsa-sha2-nistp256-SHA256:RByIUcL/TqyhhieJda6AIKHXaEiav7ylwTRHbp2olt0, verified=true
2023-10-31 14:44:25 DEBUG ClientSessionImpl:666 - sendNewKeys(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Send SSH_MSG_NEWKEYS
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1832 - prepareNewKeys(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) session ID=ff:2c:23:bf:7b:d2:78:4b:4d:40:3c:99:d7:ba:20:00:34:ff:ea:89:85:1e:ab:d9:cc:d8:b1:6e:ab:d0:9c:c6
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #2 sending command=21[SSH_MSG_NEWKEYS] len=1
2023-10-31 14:44:25 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 16 bytes
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1953 - setOutputEncoding(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]): cipher org.apache.sshd.common.cipher.ChaCha20Cipher@60ae53d0; mac null; compression none[Deflater/-1]; blocks limit 134217728
2023-10-31 14:44:25 DEBUG ClientSessionImpl:705 - handleNewKeys(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) No pending packets to flush at end of KEX
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #2 SSH_MSG_NEWKEYS
2023-10-31 14:44:25 DEBUG ClientSessionImpl:900 - handleNewKeys(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_NEWKEYS command=SSH_MSG_NEWKEYS
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1985 - setInputEncoding(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]): cipher org.apache.sshd.common.cipher.ChaCha20Cipher@622abc83; mac null; compression none[Inflater/-1]; blocks limit 134217728
2023-10-31 14:44:25 DEBUG ClientSessionImpl:231 - sendInitialServiceRequest(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Send SSH_MSG_SERVICE_REQUEST for ssh-userauth
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #3 sending command=5[SSH_MSG_SERVICE_REQUEST] len=17
2023-10-31 14:44:25 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 52 bytes
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #3 7
2023-10-31 14:44:25 DEBUG DefaultClientKexExtensionHandler:104 - handleServerSignatureAlgorithms(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]): [ssh-ed25519, ssh-rsa, rsa-sha2-256, rsa-sha2-512, ssh-dss, ecdsa-sha2-nistp256, ecdsa-sha2-nistp384, ecdsa-sha2-nistp521]
2023-10-31 14:44:25 DEBUG DefaultClientKexExtensionHandler:112 - handleServerSignatureAlgorithms(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]): PubkeyAcceptedAlgorithms before: [ecdsa-sha2-nistp256-cert-v01@openssh.com, ecdsa-sha2-nistp384-cert-v01@openssh.com, ecdsa-sha2-nistp521-cert-v01@openssh.com, rsa-sha2-512-cert-v01@openssh.com, rsa-sha2-256-cert-v01@openssh.com, ecdsa-sha2-nistp256, ecdsa-sha2-nistp384, ecdsa-sha2-nistp521, sk-ecdsa-sha2-nistp256@openssh.com, rsa-sha2-512, rsa-sha2-256, ssh-rsa]
2023-10-31 14:44:25 DEBUG DefaultClientKexExtensionHandler:129 - handleServerSignatureAlgorithms(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]): PubkeyAcceptedAlgorithms after: [ecdsa-sha2-nistp256, ecdsa-sha2-nistp384, ecdsa-sha2-nistp521, rsa-sha2-512, rsa-sha2-256, ssh-rsa, ecdsa-sha2-nistp256-cert-v01@openssh.com, ecdsa-sha2-nistp384-cert-v01@openssh.com, ecdsa-sha2-nistp521-cert-v01@openssh.com, rsa-sha2-512-cert-v01@openssh.com, rsa-sha2-256-cert-v01@openssh.com, sk-ecdsa-sha2-nistp256@openssh.com]
2023-10-31 14:44:25 INFO  HostBoundPubkeyAuthentication:58 - Server announced support for publickey-hostbound@openssh.com version 0
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #4 SSH_MSG_SERVICE_ACCEPT
2023-10-31 14:44:25 DEBUG ClientSessionImpl:813 - handleServiceAccept(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_SERVICE_ACCEPT service=ssh-userauth
2023-10-31 14:44:25 DEBUG FileKeyPairProvider:157 - doLoadKeys(/Users/ryanlivingston/.ssh/id_rsa) loaded
2023-10-31 14:44:25 DEBUG ClientSessionImpl:296 - addPublicKeyIdentity(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) ssh-rsa-SHA256:TPc6+7awmzPVoiyDGeBpM2YBTTc9KL1OjThm9a/6emw
2023-10-31 14:44:25 DEBUG ClientUserAuthService:213 - auth(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[ssh-connection] send SSH_MSG_USERAUTH_REQUEST for 'none'
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #4 sending command=50[SSH_MSG_USERAUTH_REQUEST] len=45
2023-10-31 14:44:25 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 76 bytes
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #5 SSH_MSG_USERAUTH_FAILURE
2023-10-31 14:44:25 DEBUG ClientUserAuthService:315 - processUserAuth(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Received SSH_MSG_USERAUTH_FAILURE - partial=false, methods=publickey,password,keyboard-interactive
2023-10-31 14:44:25 DEBUG ClientUserAuthService:358 - tryNext(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) starting authentication mechanisms: client=[publickey, keyboard-interactive, password], server=[publickey, password, keyboard-interactive]
2023-10-31 14:44:25 DEBUG ClientUserAuthService:407 - tryNext(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) attempting method=publickey
2023-10-31 14:44:25 DEBUG UserAuthPublicKey:237 - sendAuthDataRequest(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[ssh-connection] send SSH_MSG_USERAUTH_REQUEST request publickey-hostbound-v00@openssh.com type=rsa-sha2-512 - fingerprint=SHA256:TPc6+7awmzPVoiyDGeBpM2YBTTc9KL1OjThm9a/6emw
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #5 sending command=50[SSH_MSG_USERAUTH_REQUEST] len=612
2023-10-31 14:44:25 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 644 bytes
2023-10-31 14:44:25 DEBUG ClientUserAuthService:369 - tryNext(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) successfully processed initial buffer by method=publickey
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #6 60
2023-10-31 14:44:25 DEBUG ClientUserAuthService:340 - processUserAuth(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) delegate processing of 60 to publickey
2023-10-31 14:44:25 DEBUG UserAuthPublicKey:379 - processAuthDataRequest(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[ssh-connection][publickey-hostbound-v00@openssh.com] SSH_MSG_USERAUTH_PK_OK type=rsa-sha2-512, fingerprint=SHA256:TPc6+7awmzPVoiyDGeBpM2YBTTc9KL1OjThm9a/6emw
2023-10-31 14:44:25 DEBUG UserAuthPublicKey:410 - processAuthDataRequest(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[ssh-connection][publickey-hostbound-v00@openssh.com]: signing with algorithm rsa-sha2-512
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #6 sending command=50[SSH_MSG_USERAUTH_REQUEST] len=1020
2023-10-31 14:44:25 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 1052 bytes
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #7 SSH_MSG_USERAUTH_SUCCESS
2023-10-31 14:44:25 DEBUG ClientUserAuthService:286 - processUserAuth(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_USERAUTH_SUCCESS Succeeded with publickey
2023-10-31 14:44:25 DEBUG UserAuthPublicKey:99 - destroy(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[ssh-connection]
2023-10-31 14:44:25 DEBUG ClientConnectionService:279 - stopHeartBeat(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) no heartbeat to stop
2023-10-31 14:44:25 DEBUG ClientConnectionService:192 - startHeartbeat(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) heartbeat type=NONE, interval=PT0S
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #8 SSH_MSG_GLOBAL_REQUEST
2023-10-31 14:44:25 DEBUG ClientConnectionService:857 - globalRequest(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]]) received SSH_MSG_GLOBAL_REQUEST hostkeys-00@openssh.com want-reply=false
2023-10-31 14:44:25 DEBUG ChannelExec:389 - init() service=ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]] session=ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22] id=0
2023-10-31 14:44:25 DEBUG LocalWindow:110 - init(LocalWindow[client](ChannelExec[id=0, recipient=-1]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])) size=2097152, max=2097152, packet=32768
2023-10-31 14:44:25 DEBUG ClientConnectionService:420 - registerChannel(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[id=0, registered=true] ChannelExec[id=0, recipient=-1]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]
2023-10-31 14:44:25 DEBUG ClientSessionImpl:392 - createExecChannel(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt] created id=0 - PTY=null
2023-10-31 14:44:25 DEBUG ChannelExec:351 - open(ChannelExec[id=0, recipient=-1]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Send SSH_MSG_CHANNEL_OPEN - type=session
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #7 sending command=90[SSH_MSG_CHANNEL_OPEN] len=24
2023-10-31 14:44:25 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 60 bytes
2023-10-31 14:44:25 DEBUG OpenSshHostKeysHandler:75 - process(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[hostkeys-00@openssh.com] key type=ssh-rsa, fingerprint=SHA256:MvFu/b1/RZ5YFloo+tMPHB0NNDSake2BuDCoI/NGwqk
2023-10-31 14:44:25 DEBUG OpenSshHostKeysHandler:75 - process(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[hostkeys-00@openssh.com] key type=ecdsa-sha2-nistp256, fingerprint=SHA256:RByIUcL/TqyhhieJda6AIKHXaEiav7ylwTRHbp2olt0
2023-10-31 14:44:25 DEBUG ClientConnectionService:899 - sendGlobalResponse(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[hostkeys-00@openssh.com] result=ReplyFailure, want-reply=false
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #9 SSH_MSG_DEBUG
2023-10-31 14:44:25 DEBUG ReservedSessionMessagesHandlerAdapter:87 - handleDebugMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_DEBUG (display=false) [lang=] '/Users/ryanlivingston/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding'
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #10 SSH_MSG_DEBUG
2023-10-31 14:44:25 DEBUG ReservedSessionMessagesHandlerAdapter:87 - handleDebugMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_DEBUG (display=false) [lang=] '/Users/ryanlivingston/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding'
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #11 SSH_MSG_CHANNEL_OPEN_CONFIRMATION
2023-10-31 14:44:25 DEBUG ClientConnectionService:534 - channelOpenConfirmation(ChannelExec[id=0, recipient=-1]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_OPEN_CONFIRMATION sender=0, window-size=0, packet-size=32768
2023-10-31 14:44:25 DEBUG ChannelExec:197 - setRecipient(ChannelExec[id=0, recipient=-1]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) recipient=0
2023-10-31 14:44:25 DEBUG RemoteWindow:110 - init(RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])) size=0, max=0, packet=32768
2023-10-31 14:44:25 DEBUG ChannelExec:69 - doOpen(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) send SSH_MSG_CHANNEL_REQUEST exec command=scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #8 sending command=98[SSH_MSG_CHANNEL_REQUEST] len=69
2023-10-31 14:44:25 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 100 bytes
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #12 SSH_MSG_CHANNEL_WINDOW_ADJUST
2023-10-31 14:44:25 DEBUG ChannelExec:949 - handleWindowAdjust(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_WINDOW_ADJUST window=2097152
2023-10-31 14:44:25 DEBUG RemoteWindow:108 - expand(RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])) increase window from 0 by 2097152 up to 2097152
2023-10-31 14:44:25 DEBUG RemoteWindow:192 - waitForSpace(RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])) available: 2097152
2023-10-31 14:44:25 DEBUG RemoteWindow:151 - waitAndConsume(RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])) - requested=27, available=2097152
2023-10-31 14:44:25 DEBUG RemoteWindow:82 - Consume RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) by 27 down to 2097125
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #9 sending command=94[SSH_MSG_CHANNEL_DATA] len=36
2023-10-31 14:44:25 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 68 bytes
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #13 SSH_MSG_CHANNEL_DATA
2023-10-31 14:44:25 DEBUG LocalWindow:85 - Consume LocalWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) by 2 down to 2097150
2023-10-31 14:44:25 DEBUG ChannelExec:829 - handleData(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_DATA len=2
2023-10-31 14:44:25 DEBUG ScpHelper:556 - sendStream(ScpHelper[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt] command='T1698777865 0 1698777865 0' ACK=0
2023-10-31 14:44:25 DEBUG ScpHelper:569 - sendStream(ScpHelper[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt] send 'C' command: C0666 9 testfile.txt
2023-10-31 14:44:25 DEBUG RemoteWindow:192 - waitForSpace(RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])) available: 2097125
2023-10-31 14:44:25 DEBUG RemoteWindow:151 - waitAndConsume(RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])) - requested=21, available=2097125
2023-10-31 14:44:25 DEBUG RemoteWindow:82 - Consume RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) by 21 down to 2097104
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #10 sending command=94[SSH_MSG_CHANNEL_DATA] len=30
2023-10-31 14:44:25 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 60 bytes
2023-10-31 14:44:25 DEBUG ScpHelper:574 - sendStream(ScpHelper[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt] command='C0666 9 testfile.tx' ACK=0
2023-10-31 14:44:25 DEBUG RemoteWindow:192 - waitForSpace(RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])) available: 2097104
2023-10-31 14:44:25 DEBUG RemoteWindow:151 - waitAndConsume(RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])) - requested=10, available=2097104
2023-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #14 SSH_MSG_CHANNEL_DATA
2023-10-31 14:44:25 DEBUG RemoteWindow:82 - Consume RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) by 10 down to 2097094
2023-10-31 14:44:25 DEBUG LocalWindow:85 - Consume LocalWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) by 1 down to 2097149
2023-10-31 14:44:25 DEBUG ChannelExec:829 - handleData(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_DATA len=1
2023-10-31 14:44:25 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #11 sending command=94[SSH_MSG_CHANNEL_DATA] len=19
2023-10-31 14:44:25 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 52 bytes
2023-10-31 14:44:25 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-10-31 14:44:25 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #15 SSH_MSG_CHANNEL_DATA
2023-10-31 14:44:25 DEBUG LocalWindow:85 - Consume LocalWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) by 1 down to 2097148
2023-10-31 14:44:25 DEBUG ChannelExec:829 - handleData(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_DATA len=1
2023-10-31 14:44:30 DEBUG DefaultScpClient:177 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt', waited=5005150209 nanos, events=[TIMEOUT, OPENED]
2023-10-31 14:44:30 DEBUG DefaultScpClient:207 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt', exit-status=null
2023-10-31 14:44:30 DEBUG ChannelExec:1004 - sendEof(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_EOF (state=Opened)
2023-10-31 14:44:30 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #12 sending command=96[SSH_MSG_CHANNEL_EOF] len=5
2023-10-31 14:44:30 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 36 bytes
2023-10-31 14:44:30 DEBUG ChannelExec:107 - close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Closing gracefully
2023-10-31 14:44:30 DEBUG LocalWindow:136 - Closing LocalWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])
2023-10-31 14:44:30 DEBUG RemoteWindow:136 - Closing RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])
2023-10-31 14:44:30 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #16 SSH_MSG_CHANNEL_EOF
2023-10-31 14:44:30 DEBUG ChannelExec:934 - handleEof(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_EOF
2023-10-31 14:44:30 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #17 SSH_MSG_CHANNEL_REQUEST
2023-10-31 14:44:30 DEBUG ChannelExec:296 - handleChannelRequest(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_REQUEST exit-status wantReply=false
2023-10-31 14:44:30 DEBUG ExitStatusChannelRequestHandler:50 - processRequestValue(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) status=0
2023-10-31 14:44:30 DEBUG ExitStatusChannelRequestHandler:59 - process(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[exit-status] wantReply=false: 0
2023-10-31 14:44:30 DEBUG ChannelExec:114 - notifyEvent(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]): exit-status
2023-10-31 14:44:30 DEBUG ExitStatusChannelRequestHandler:101 - notifyStateChanged(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[exit-status] event=exit-status
2023-10-31 14:44:30 DEBUG ChannelExec:370 - sendResponse(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) request=exit-status result=ReplySuccess, want-reply=false
2023-10-31 14:44:30 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #18 SSH_MSG_CHANNEL_CLOSE
2023-10-31 14:44:30 DEBUG ChannelExec:565 - handleClose(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_CLOSE
2023-10-31 14:44:30 DEBUG ChannelExec:130 - close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[Graceful] state already Graceful
2023-10-31 14:44:30 DEBUG AbstractChannel$GracefulChannelCloseable:649 - close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[immediately=false] processing
2023-10-31 14:44:30 DEBUG AbstractChannel$GracefulChannelCloseable:660 - close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[immediately=false] send SSH_MSG_CHANNEL_CLOSE
2023-10-31 14:44:30 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #13 sending command=97[SSH_MSG_CHANNEL_CLOSE] len=5
2023-10-31 14:44:30 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) writing 36 bytes
2023-10-31 14:44:30 DEBUG AbstractChannel$GracefulChannelCloseable:697 - handleClosePacketWritten(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[immediately=false] SSH_MSG_CHANNEL_CLOSE written on channel
2023-10-31 14:44:30 DEBUG ClientConnectionService:441 - unregisterChannel(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) result=ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]
2023-10-31 14:44:30 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@2c07545f) signal close complete immediately=false
2023-10-31 14:44:30 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@e57b96d) signal close complete immediately=false
2023-10-31 14:44:30 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@32c726ee) signal close complete immediately=false
2023-10-31 14:44:30 DEBUG AbstractChannel$GracefulChannelCloseable:649 - close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[immediately=true] processing
2023-10-31 14:44:30 DEBUG ClientConnectionService:441 - unregisterChannel(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) result=null
2023-10-31 14:44:30 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@34c01041) signal close complete immediately=true
2023-10-31 14:44:30 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@76f4b65) signal close complete immediately=true
2023-10-31 14:44:30 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@c94fd30) signal close complete immediately=true
2023-10-31 14:44:30 DEBUG ChannelExec:116 - close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]][Graceful] - operationComplete() closed
2023-10-31 14:44:30 DEBUG ClientSessionImpl:92 - close(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Closing immediately
2023-10-31 14:44:30 DEBUG ClientSessionImpl:200 - signalAuthFailure(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) type=SshException, signalled=false, first=false: Session is being closed
2023-10-31 14:44:30 DEBUG SessionTimeoutListener:71 - sessionClosed(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) un-tracked
2023-10-31 14:44:30 DEBUG ClientConnectionService:92 - close(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]]) Closing immediately
2023-10-31 14:44:30 DEBUG ClientConnectionService:279 - stopHeartBeat(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) no heartbeat to stop
2023-10-31 14:44:30 DEBUG ClientConnectionService:97 - close(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[Immediately] closed
2023-10-31 14:44:30 DEBUG Nio2Session:92 - close(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) Closing immediately
2023-10-31 14:44:30 DEBUG Nio2Session:268 - doCloseImmediately(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) closing socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/127.0.0.1:60645 remote=localhost/127.0.0.1:22]
2023-10-31 14:44:30 DEBUG Nio2Session:274 - doCloseImmediately(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[closed] closed
2023-10-31 14:44:30 DEBUG Nio2Connector:147 - unmapSession(id=101): Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]
2023-10-31 14:44:30 DEBUG ClientSessionImpl:101 - close(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[Immediately] state already Immediate
2023-10-31 14:44:30 DEBUG Nio2Session:97 - close(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22])[Immediately] closed
2023-10-31 14:44:30 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@41e68d87) signal close complete immediately=true
2023-10-31 14:44:30 DEBUG Nio2Session:568 - handleReadCycleFailure(Nio2Session[local=/127.0.0.1:60645, remote=localhost/127.0.0.1:22]) AsynchronousCloseException after 5787750 nanos at read cycle=15: null
2023-10-31 14:44:30 DEBUG ClientSessionImpl:97 - close(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[Immediately] closed

Other information

No response

@TerraNibble
Copy link
Contributor Author

I should update that this is observed against an OpenSSH server with a default client side SSH configuration.

From the large logging you can observe the exit timeout delay here:

2023-10-31 14:44:25 DEBUG LocalWindow:85 - Consume LocalWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) by 1 down to 2097148
2023-10-31 14:44:25 DEBUG ChannelExec:829 - handleData(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_DATA len=1
2023-10-31 14:44:30 DEBUG DefaultScpClient:177 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt', waited=5005150209 nanos, events=[TIMEOUT, OPENED]
2023-10-31 14:44:30 DEBUG DefaultScpClient:207 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -p -t -- /Users/ryanlivingston/tmp/testfile.txt', exit-status=null
2023-10-31 14:44:30 DEBUG ChannelExec:1004 - sendEof(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_EOF (state=Opened)
2023-10-31 14:44:30 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #12 sending command=96[SSH_MSG_CHANNEL_EOF] len=5

@TerraNibble
Copy link
Contributor Author

TerraNibble commented Feb 8, 2024

This is also easily reproducible using the including unit test ScpTest.testStreamsUploadAndDownload. Running it you can observe the 5 second exit timeout being hit.

Moving the handleCommandExitStatus to after the I/O stream try-with-resources resolves the timeout but introduces a new race-condition with the channels not shutting down gracefully.

I am still not sure why only upload is susceptible to this and not runUpload based on their slightly different use of the ScpHelper.

You can simulate the issue by introducing a 200ms delay between the IO streams and the channel closing. Hopefully this information is helpful.

ClientSession session = getClientSession();
        ChannelExec channel = openCommandChannel(session, cmd);
        // Wrapped with an additional try/finally.
        try {      
            try (InputStream invOut = channel.getInvertedOut();
                 OutputStream invIn = channel.getInvertedIn()) {
                // NOTE: we use a mock file system since we expect no invocations for it
                ScpHelper helper = new ScpHelper(session, invOut, invIn, new MockFileSystem(remote), opener, listener);
                Path mockPath = new MockPath(remote);
                helper.sendStream(new DefaultScpStreamResolver(name, mockPath, perms, time, size, local, cmd),
                        options.contains(Option.PreserveAttributes), ScpHelper.DEFAULT_SEND_BUFFER_SIZE);
//            handleCommandExitStatus(cmd, channel);
            }
            Thread.sleep(200);
//            handleCommandExitStatus(cmd, channel);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        } finally {
            channel.close(false);
        }
16:45:28.569 | DEBUG | main             | o.a.s.s.c.ScpHelper              | org.apache.sshd.scp.common.ScpHelper                              603 | sendStream(ScpHelper[ClientSessionImpl[proxy@localhost/127.0.0.1:2222]])[scp -t -- upload.txt] command='C0644 63 upload.txt' ACK=0
16:45:28.569 | DEBUG | main             | o.a.s.c.c.ChannelExec            | org.apache.sshd.common.channel.AbstractChannel                   1005 | sendEof(ChannelExec[id=0, recipient=0]-ClientSessionImpl[proxy@localhost/127.0.0.1:2222]) SSH_MSG_CHANNEL_EOF (state=Opened)
16:45:28.569 | DEBUG | main             | o.a.s.c.s.ClientSessionImpl      | org.apache.sshd.common.session.helpers.AbstractSession           1441 | encode(ClientSessionImpl[proxy@localhost/127.0.0.1:2222]) packet #8 sending command=96[SSH_MSG_CHANNEL_EOF] len=5
16:45:28.570 | DEBUG | main             | o.a.s.c.i.n.Nio2Session          | org.apache.sshd.common.io.nio2.Nio2Session                        179 | writeBuffer(Nio2Session[local=/127.0.0.1:51986, remote=localhost/127.0.0.1:2222]) writing 36 bytes
16:45:28.570 | DEBUG | b]-nio2-thread-6 | o.a.s.c.s.ClientSessionImpl      | org.apache.sshd.common.session.helpers.AbstractSession            566 | doHandleMessage(ClientSessionImpl[proxy@localhost/127.0.0.1:2222]) process #10 SSH_MSG_CHANNEL_DATA
16:45:28.570 | DEBUG | b]-nio2-thread-6 | o.a.s.c.c.LocalWindow            | org.apache.sshd.common.channel.LocalWindow                         85 | Consume LocalWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[proxy@localhost/127.0.0.1:2222]) by 1 down to 2097149
16:45:28.570 | DEBUG | b]-nio2-thread-6 | o.a.s.c.c.ChannelExec            | org.apache.sshd.common.channel.AbstractChannel                    829 | handleData(ChannelExec[id=0, recipient=0]-ClientSessionImpl[proxy@localhost/127.0.0.1:2222]) SSH_MSG_CHANNEL_DATA len=1
16:45:28.570 | DEBUG | b]-nio2-thread-6 | o.a.s.c.i.n.Nio2Session          | org.apache.sshd.common.util.logging.LoggingUtils                  568 | handleReadCycleFailure(Nio2Session[local=/127.0.0.1:51986, remote=localhost/127.0.0.1:2222]) IOException after 1161791 nanos at read cycle=13: Pipe closed
16:45:28.570 | DEBUG | b]-nio2-thread-6 | o.a.s.c.i.n.Nio2Session          | org.apache.sshd.common.io.nio2.Nio2Session                        205 | exceptionCaught(Nio2Session[local=/127.0.0.1:51986, remote=localhost/127.0.0.1:2222]) caught IOException[Pipe closed] - calling handler
16:45:28.570 | DEBUG | b]-nio2-thread-6 | o.a.s.c.s.ClientSessionImpl      | org.apache.sshd.client.session.ClientSessionImpl                  200 | signalAuthFailure(ClientSessionImpl[proxy@localhost/127.0.0.1:2222]) type=IOException, signalled=false, first=false: Pipe closed
16:45:28.572 | WARN  | b]-nio2-thread-6 | o.a.s.c.s.ClientSessionImpl      | org.apache.sshd.common.util.logging.LoggingUtils                  616 | exceptionCaught(ClientSessionImpl[proxy@localhost/127.0.0.1:2222])[state=Opened] IOException: Pipe closed
java.io.IOException: Pipe closed
	at org.apache.sshd.common.channel.ChannelPipedInputStream.receive(ChannelPipedInputStream.java:196)
	at org.apache.sshd.common.channel.ChannelPipedOutputStream.write(ChannelPipedOutputStream.java:53)
	at org.apache.sshd.client.channel.AbstractClientChannel.doWriteData(AbstractClientChannel.java:442)
	at org.apache.sshd.common.channel.AbstractChannel.handleData(AbstractChannel.java:839)

@TerraNibble
Copy link
Contributor Author

TerraNibble commented Feb 9, 2024

With some further testing this appears to happen if we trigger the sending of an EOF too quickly after sending a stream. Placing a 100ms delay between these actions alleviates the issue and further demonstrates the race condition.

        try {
            try (InputStream invOut = channel.getInvertedOut();
                 OutputStream invIn = channel.getInvertedIn()) {
                // NOTE: we use a mock file system since we expect no invocations for it
                ScpHelper helper = new ScpHelper(session, invOut, invIn, new MockFileSystem(remote), opener, listener);
                Path mockPath = new MockPath(remote);
                helper.sendStream(new DefaultScpStreamResolver(name, mockPath, perms, time, size, local, cmd),
                        options.contains(Option.PreserveAttributes), ScpHelper.DEFAULT_SEND_BUFFER_SIZE);
                Thread.sleep(100);
            }
            handleCommandExitStatus(cmd, channel);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        } finally {
            channel.close(false);
        }

It appears that the server is responding with an unexpected additional ACK after sending the payload stream and this message is racing with the channel closure.

09:42:37.896 | DEBUG | b]-nio2-thread-4 | o.a.s.c.c.LocalWindow            | org.apache.sshd.common.channel.LocalWindow                         85 | Consume LocalWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[proxy@localhost/127.0.0.1:2222]) by 1 down to 2097150
09:42:37.896 | DEBUG | b]-nio2-thread-4 | o.a.s.c.c.ChannelExec            | org.apache.sshd.common.channel.AbstractChannel                    829 | handleData(ChannelExec[id=0, recipient=0]-ClientSessionImpl[proxy@localhost/127.0.0.1:2222]) SSH_MSG_CHANNEL_DATA len=1
09:42:37.896 | DEBUG | main             | o.a.s.s.c.ScpHelper              | org.apache.sshd.scp.common.ScpHelper                              603 | sendStream(ScpHelper[ClientSessionImpl[proxy@localhost/127.0.0.1:2222]])[scp -t -- upload.txt] command='C0644 63 upload.txt' ACK=0
09:42:37.896 | DEBUG | b]-nio2-thread-5 | o.a.s.c.s.ClientSessionImpl      | org.apache.sshd.common.session.helpers.AbstractSession            566 | doHandleMessage(ClientSessionImpl[proxy@localhost/127.0.0.1:2222]) process #10 SSH_MSG_CHANNEL_DATA
09:42:37.896 | DEBUG | b]-nio2-thread-5 | o.a.s.c.c.LocalWindow            | org.apache.sshd.common.channel.LocalWindow                         85 | Consume LocalWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[proxy@localhost/127.0.0.1:2222]) by 1 down to 2097149
09:42:37.896 | DEBUG | b]-nio2-thread-5 | o.a.s.c.c.ChannelExec            | org.apache.sshd.common.channel.AbstractChannel                    829 | handleData(ChannelExec[id=0, recipient=0]-ClientSessionImpl[proxy@localhost/127.0.0.1:2222]) SSH_MSG_CHANNEL_DATA len=1
09:42:37.896 | DEBUG | main             | o.a.s.c.c.ChannelExec            | org.apache.sshd.common.channel.AbstractChannel                   1005 | sendEof(ChannelExec[id=0, recipient=0]-ClientSessionImpl[proxy@localhost/127.0.0.1:2222]) SSH_MSG_CHANNEL_EOF (state=Opened)

@TerraNibble
Copy link
Contributor Author

TerraNibble commented Feb 9, 2024

It appears that this is caused by an initial ACK not being processed when the channel is opened, then the following sequence of ACKs are not processed in the correct order, which leaves a trailing ACK at the end to race with channel closure.

runUpload is different here because it passes ScpHelper.send as an executor method which reads this first initial ACK immediately at line ScpHelper:414 before calling ScpHelper.sendStream.

I will submit a PR, though I am not sure of the protocol here so please ensure this fix would not be server dependent.

TerraNibble added a commit to TerraNibble/mina-sshd that referenced this issue Feb 9, 2024
TerraNibble added a commit to TerraNibble/mina-sshd that referenced this issue Feb 9, 2024
tomaswolf added a commit that referenced this issue Apr 27, 2024
GH-427: Read initial ACK on channel open prior to direct stream upload & close streams prior to exit code handling
@tomaswolf tomaswolf added this to the 2.13.0 milestone May 11, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
2 participants