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

ScpClient download fails silently when the remote files does not exist #428

Closed
TerraNibble opened this issue Oct 31, 2023 · 11 comments
Closed
Labels
bug An issue describing a bug in the code
Milestone

Comments

@TerraNibble
Copy link
Contributor

TerraNibble commented Oct 31, 2023

Version

2.11.0

Bug description

When calling ScpClient.download(String, String), the method does not throw any exception or indicate to the caller that the SCP failed when the remote file is not available. Is this the expected behavior?

From the logging, we can see a WARNING exit status is received but it is only logged.

Is the expectation here to override the client and handle this warning as the client? Or is it expected that I check the filesystem to determine a status?

Actual behavior

To the client, the API ScpClient.download(String, String) behaves no differently if the remote file exists or does not exist.

Expected behavior

Some API level indication that the download has failed.

Relevant log output

2023-10-31 14:48:10 INFO  BouncyCastleSecurityProviderRegistrar:112 - getOrCreateProvider(BC) created instance of org.bouncycastle.jce.provider.BouncyCastleProvider
2023-10-31 14:48:10 DEBUG SecurityUtils:450 - register(EdDSA) not registered - enabled=true, supported=false
2023-10-31 14:48:10 INFO  DefaultIoServiceFactoryFactory:68 - No detected/configured IoServiceFactoryFactory; using Nio2ServiceFactoryFactory
2023-10-31 14:48:10 INFO  DefaultConfigFileHostEntryResolver:89 - resolveEffectiveResolver(ryanlivingston@localhost:22/null) no configuration file at /Users/ryanlivingston/.ssh/config
2023-10-31 14:48:10 DEBUG DefaultConfigFileHostEntryResolver:62 - resolveEffectiveHost(ryanlivingston@localhost:22/null) => null
2023-10-31 14:48:10 DEBUG SshClient:700 - connect(ryanlivingston@localhost:22) no overrides
2023-10-31 14:48:10 DEBUG Nio2Connector:62 - Connecting to localhost/127.0.0.1:22
2023-10-31 14:48:10 DEBUG Nio2Connector:201 - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2023-10-31 14:48:10 DEBUG Nio2Connector:101 - connect(localhost/127.0.0.1:22): waiting for connection (timeout=60000ms)
2023-10-31 14:48:10 DEBUG Nio2Session:93 - Creating IoSession on /127.0.0.1:60689 from localhost/127.0.0.1:22 via null
2023-10-31 14:48:10 DEBUG ClientSessionImpl:78 - Client session created: Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]
2023-10-31 14:48:10 DEBUG ClientUserAuthService:107 - ClientUserAuthService(ClientSessionImpl[null@localhost/127.0.0.1:22]) client methods: [publickey, keyboard-interactive, password]
2023-10-31 14:48:10 DEBUG SessionTimeoutListener:50 - sessionCreated(ClientSessionImpl[null@localhost/127.0.0.1:22]) tracking
2023-10-31 14:48:10 DEBUG ClientSessionImpl:332 - initializeProxyConnector(ClientSessionImpl[null@localhost/127.0.0.1:22]) no proxy to initialize
2023-10-31 14:48:10 DEBUG ClientSessionImpl:850 - sendIdentification(ClientSessionImpl[null@localhost/127.0.0.1:22]): SSH-2.0-APACHE-SSHD-2.11.0
2023-10-31 14:48:10 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) writing 28 bytes
2023-10-31 14:48:10 DEBUG ClientSessionImpl:1703 - sendKexInit(ClientSessionImpl[null@localhost/127.0.0.1:22]) Send SSH_MSG_KEXINIT
2023-10-31 14:48:10 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:48:10 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) writing 1248 bytes
2023-10-31 14:48:10 DEBUG SshClient:849 - setupDefaultSessionIdentities(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) key identity provider override in session listener
2023-10-31 14:48:10 DEBUG DefaultConnectFuture:59 - Connected to localhost/127.0.0.1:22 after 20384625 nanos
2023-10-31 14:48:10 DEBUG OpenSSHKeyPairResourceParser:127 - extractKeyPairs(/Users/ryanlivingston/.ssh/id_rsa) decode 1 keys using context=OpenSSHParserContext[cipher=none, kdfOptions=none: options=]
2023-10-31 14:48:10 DEBUG ClientSessionImpl:922 - doReadIdentification(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) line='SSH-2.0-OpenSSH_9.0'
2023-10-31 14:48:10 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:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #0 SSH_MSG_KEXINIT
2023-10-31 14:48:10 DEBUG ClientSessionImpl:825 - handleKexInit(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_KEXINIT
2023-10-31 14:48:10 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: kex algorithms = curve25519-sha256
2023-10-31 14:48:10 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: server host key algorithms = ecdsa-sha2-nistp256
2023-10-31 14:48:10 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: encryption algorithms (client to server) = [email protected]
2023-10-31 14:48:10 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: encryption algorithms (server to client) = [email protected]
2023-10-31 14:48:10 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: mac algorithms (client to server) = [email protected]
2023-10-31 14:48:10 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: mac algorithms (server to client) = [email protected]
2023-10-31 14:48:10 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: compression algorithms (client to server) = none
2023-10-31 14:48:10 DEBUG ClientSessionImpl:2172 - setNegotiationResult(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Kex: compression algorithms (server to client) = none
2023-10-31 14:48:10 DEBUG DHGClient:102 - init(DHGClient[curve25519-sha256])[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]] Send SSH_MSG_KEXDH_INIT
2023-10-31 14:48:10 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #1 sending command=30[30] len=37
2023-10-31 14:48:10 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) writing 56 bytes
2023-10-31 14:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #1 31
2023-10-31 14:48:10 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:48:10 DEBUG FileKeyPairProvider:157 - doLoadKeys(/Users/ryanlivingston/.ssh/id_rsa) loaded
2023-10-31 14:48:10 DEBUG ClientSessionImpl:296 - addPublicKeyIdentity(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) ssh-rsa-SHA256:TPc6+7awmzPVoiyDGeBpM2YBTTc9KL1OjThm9a/6emw
2023-10-31 14:48:10 DEBUG ClientSessionImpl:145 - setServerKey(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) keyType=ecdsa-sha2-nistp256, digest=SHA256:RByIUcL/TqyhhieJda6AIKHXaEiav7ylwTRHbp2olt0
2023-10-31 14:48:10 DEBUG ClientSessionImpl:724 - handleKexMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[curve25519-sha256] KEX processing complete after cmd=31
2023-10-31 14:48:10 WARN  AcceptAllServerKeyVerifier:59 - Server at localhost/127.0.0.1:22 presented unverified EC key: SHA256:RByIUcL/TqyhhieJda6AIKHXaEiav7ylwTRHbp2olt0
2023-10-31 14:48:10 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:48:10 DEBUG ClientSessionImpl:666 - sendNewKeys(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Send SSH_MSG_NEWKEYS
2023-10-31 14:48:10 DEBUG ClientSessionImpl:1832 - prepareNewKeys(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) session ID=02:ed:25:aa:68:a9:e3:33:c3:91:81:1f:02:c5:37:b3:dc:0c:36:4e:48:c4:b8:4d:26:15:f3:ce:b8:2e:bf:e7
2023-10-31 14:48:10 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:48:10 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) writing 16 bytes
2023-10-31 14:48:10 DEBUG ClientSessionImpl:1953 - setOutputEncoding(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]): cipher org.apache.sshd.common.cipher.ChaCha20Cipher@65aed70c; mac null; compression none[Deflater/-1]; blocks limit 134217728
2023-10-31 14:48:10 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:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #2 SSH_MSG_NEWKEYS
2023-10-31 14:48:10 DEBUG ClientSessionImpl:900 - handleNewKeys(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_NEWKEYS command=SSH_MSG_NEWKEYS
2023-10-31 14:48:10 DEBUG ClientSessionImpl:1985 - setInputEncoding(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]): cipher org.apache.sshd.common.cipher.ChaCha20Cipher@7adbc39e; mac null; compression none[Inflater/-1]; blocks limit 134217728
2023-10-31 14:48:10 DEBUG ClientSessionImpl:231 - sendInitialServiceRequest(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Send SSH_MSG_SERVICE_REQUEST for ssh-userauth
2023-10-31 14:48:10 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:48:10 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) writing 52 bytes
2023-10-31 14:48:10 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:48:10 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:48:10 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) writing 76 bytes
2023-10-31 14:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #3 7
2023-10-31 14:48:10 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:48:10 DEBUG DefaultClientKexExtensionHandler:112 - handleServerSignatureAlgorithms(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]): PubkeyAcceptedAlgorithms before: [[email protected], [email protected], [email protected], [email protected], [email protected], ecdsa-sha2-nistp256, ecdsa-sha2-nistp384, ecdsa-sha2-nistp521, [email protected], rsa-sha2-512, rsa-sha2-256, ssh-rsa]
2023-10-31 14:48:10 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, [email protected], [email protected], [email protected], [email protected], [email protected], [email protected]]
2023-10-31 14:48:10 INFO  HostBoundPubkeyAuthentication:58 - Server announced support for [email protected] version 0
2023-10-31 14:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #4 SSH_MSG_SERVICE_ACCEPT
2023-10-31 14:48:10 DEBUG ClientSessionImpl:813 - handleServiceAccept(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_SERVICE_ACCEPT service=ssh-userauth
2023-10-31 14:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #5 SSH_MSG_USERAUTH_FAILURE
2023-10-31 14:48:10 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:48:10 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:48:10 DEBUG ClientUserAuthService:407 - tryNext(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) attempting method=publickey
2023-10-31 14:48:10 DEBUG UserAuthPublicKey:237 - sendAuthDataRequest(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[ssh-connection] send SSH_MSG_USERAUTH_REQUEST request [email protected] type=rsa-sha2-512 - fingerprint=SHA256:TPc6+7awmzPVoiyDGeBpM2YBTTc9KL1OjThm9a/6emw
2023-10-31 14:48:10 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:48:10 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) writing 644 bytes
2023-10-31 14:48:10 DEBUG ClientUserAuthService:369 - tryNext(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) successfully processed initial buffer by method=publickey
2023-10-31 14:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #6 60
2023-10-31 14:48:10 DEBUG ClientUserAuthService:340 - processUserAuth(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) delegate processing of 60 to publickey
2023-10-31 14:48:10 DEBUG UserAuthPublicKey:379 - processAuthDataRequest(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[ssh-connection][[email protected]] SSH_MSG_USERAUTH_PK_OK type=rsa-sha2-512, fingerprint=SHA256:TPc6+7awmzPVoiyDGeBpM2YBTTc9KL1OjThm9a/6emw
2023-10-31 14:48:10 DEBUG UserAuthPublicKey:410 - processAuthDataRequest(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[ssh-connection][[email protected]]: signing with algorithm rsa-sha2-512
2023-10-31 14:48:10 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:48:10 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) writing 1052 bytes
2023-10-31 14:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #7 SSH_MSG_USERAUTH_SUCCESS
2023-10-31 14:48:10 DEBUG ClientUserAuthService:286 - processUserAuth(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_USERAUTH_SUCCESS Succeeded with publickey
2023-10-31 14:48:10 DEBUG UserAuthPublicKey:99 - destroy(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[ssh-connection]
2023-10-31 14:48:10 DEBUG ClientConnectionService:279 - stopHeartBeat(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) no heartbeat to stop
2023-10-31 14:48:10 DEBUG ClientConnectionService:192 - startHeartbeat(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) heartbeat type=NONE, interval=PT0S
2023-10-31 14:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #8 SSH_MSG_GLOBAL_REQUEST
2023-10-31 14:48:10 DEBUG ClientConnectionService:857 - globalRequest(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]]) received SSH_MSG_GLOBAL_REQUEST [email protected] want-reply=false
2023-10-31 14:48:10 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:48:10 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:48:10 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:48:10 DEBUG ClientSessionImpl:392 - createExecChannel(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[scp -f -- /Users/ryanlivingston/tmp/null.txt] created id=0 - PTY=null
2023-10-31 14:48:10 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:48:10 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:48:10 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) writing 60 bytes
2023-10-31 14:48:10 DEBUG OpenSshHostKeysHandler:75 - process(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[[email protected]] key type=ssh-rsa, fingerprint=SHA256:MvFu/b1/RZ5YFloo+tMPHB0NNDSake2BuDCoI/NGwqk
2023-10-31 14:48:10 DEBUG OpenSshHostKeysHandler:75 - process(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[[email protected]] key type=ecdsa-sha2-nistp256, fingerprint=SHA256:RByIUcL/TqyhhieJda6AIKHXaEiav7ylwTRHbp2olt0
2023-10-31 14:48:10 WARN  ClientConnectionService:624 - globalRequest(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[[email protected], want-reply=false] failed (SshException) to process: EdDSA provider not supported
org.apache.sshd.common.SshException: EdDSA provider not supported
	at org.apache.sshd.common.util.buffer.Buffer.getRawPublicKey(Buffer.java:567)
	at org.apache.sshd.common.util.buffer.Buffer.getPublicKey(Buffer.java:542)
	at org.apache.sshd.common.global.AbstractOpenSshHostKeysHandler.process(AbstractOpenSshHostKeysHandler.java:73)
	at org.apache.sshd.common.global.AbstractOpenSshHostKeysHandler.process(AbstractOpenSshHostKeysHandler.java:38)
	at org.apache.sshd.common.session.helpers.AbstractConnectionService.globalRequest(AbstractConnectionService.java:868)
	at org.apache.sshd.common.session.helpers.AbstractConnectionService.process(AbstractConnectionService.java:486)
	at org.apache.sshd.common.session.helpers.CurrentService.process(CurrentService.java:109)
	at org.apache.sshd.common.session.helpers.AbstractSession.doHandleMessage(AbstractSession.java:592)
	at org.apache.sshd.common.session.helpers.AbstractSession.lambda$handleMessage$0(AbstractSession.java:523)
	at org.apache.sshd.common.util.threads.ThreadUtils.runAsInternal(ThreadUtils.java:68)
	at org.apache.sshd.common.session.helpers.AbstractSession.handleMessage(AbstractSession.java:522)
	at org.apache.sshd.common.session.helpers.AbstractSession.decode(AbstractSession.java:1649)
	at org.apache.sshd.common.session.helpers.AbstractSession.messageReceived(AbstractSession.java:483)
	at org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.messageReceived(AbstractSessionIoHandler.java:64)
	at org.apache.sshd.common.io.nio2.Nio2Session.handleReadCycleCompletion(Nio2Session.java:409)
	at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:382)
	at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:377)
	at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$completed$0(Nio2CompletionHandler.java:38)
	at java.base/java.security.AccessController.doPrivileged(AccessController.java:318)
	at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37)
	at java.base/sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:129)
	at java.base/sun.nio.ch.Invoker$2.run(Invoker.java:221)
	at java.base/sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:113)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.security.NoSuchAlgorithmException: EdDSA provider not supported
	at org.apache.sshd.common.util.security.SecurityUtils.generateEDDSAPublicKey(SecurityUtils.java:633)
	at org.apache.sshd.common.util.buffer.keys.ED25519BufferPublicKeyParser.getRawPublicKey(ED25519BufferPublicKeyParser.java:46)
	at org.apache.sshd.common.util.buffer.keys.BufferPublicKeyParser$2.getRawPublicKey(BufferPublicKeyParser.java:102)
	at org.apache.sshd.common.util.buffer.Buffer.getRawPublicKey(Buffer.java:565)
	... 25 more
2023-10-31 14:48:10 DEBUG ClientConnectionService:899 - sendGlobalResponse(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[[email protected]] result=ReplyFailure, want-reply=false
2023-10-31 14:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #9 SSH_MSG_DEBUG
2023-10-31 14:48:10 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:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #10 SSH_MSG_DEBUG
2023-10-31 14:48:10 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:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #11 SSH_MSG_CHANNEL_OPEN_CONFIRMATION
2023-10-31 14:48:10 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:48:10 DEBUG ChannelExec:197 - setRecipient(ChannelExec[id=0, recipient=-1]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) recipient=0
2023-10-31 14:48:10 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:48:10 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 -f -- /Users/ryanlivingston/tmp/null.txt
2023-10-31 14:48:10 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #8 sending command=98[SSH_MSG_CHANNEL_REQUEST] len=62
2023-10-31 14:48:10 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) writing 92 bytes
2023-10-31 14:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #12 SSH_MSG_CHANNEL_WINDOW_ADJUST
2023-10-31 14:48:10 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:48:10 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:48:10 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:48:10 DEBUG RemoteWindow:151 - waitAndConsume(RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])) - requested=1, available=2097152
2023-10-31 14:48:10 DEBUG RemoteWindow:82 - Consume RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) by 1 down to 2097151
2023-10-31 14:48:10 DEBUG ClientSessionImpl:1402 - encode(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) packet #9 sending command=94[SSH_MSG_CHANNEL_DATA] len=10
2023-10-31 14:48:10 DEBUG Nio2Session:179 - writeBuffer(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) writing 44 bytes
2023-10-31 14:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #13 SSH_MSG_CHANNEL_DATA
2023-10-31 14:48:10 DEBUG LocalWindow:85 - Consume LocalWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) by 68 down to 2097084
2023-10-31 14:48:10 DEBUG ChannelExec:829 - handleData(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) SSH_MSG_CHANNEL_DATA len=68
2023-10-31 14:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #14 SSH_MSG_CHANNEL_EOF
2023-10-31 14:48:10 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:48:10 DEBUG ScpHelper:257 - receiveNextCmd - ACK=1: scp: /Users/ryanlivingston/tmp/null.txt: No such file or directory
2023-10-31 14:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #15 SSH_MSG_CHANNEL_REQUEST
2023-10-31 14:48:10 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:48:10 DEBUG ExitStatusChannelRequestHandler:50 - processRequestValue(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) status=1
2023-10-31 14:48:10 DEBUG ExitStatusChannelRequestHandler:59 - process(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[exit-status] wantReply=false: 1
2023-10-31 14:48:10 DEBUG ChannelExec:114 - notifyEvent(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]): exit-status
2023-10-31 14:48:10 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:48:10 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:48:10 DEBUG ClientSessionImpl:544 - doHandleMessage(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) process #16 SSH_MSG_CHANNEL_CLOSE
2023-10-31 14:48:10 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:48:10 DEBUG ChannelExec:572 - handleClose(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) prevent sending EOF
2023-10-31 14:48:10 DEBUG ChannelExec:107 - close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Closing gracefully
2023-10-31 14:48:10 DEBUG LocalWindow:136 - Closing LocalWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])
2023-10-31 14:48:10 DEBUG RemoteWindow:136 - Closing RemoteWindow[client](ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])
2023-10-31 14:48:10 DEBUG ChannelExec:997 - sendEof(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) already sent (state=Graceful)
2023-10-31 14:48:10 DEBUG ChannelExec:247 - waitFor(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) mask=[CLOSED, EXIT_STATUS] - exit status=1
2023-10-31 14:48:10 DEBUG DefaultScpClient:177 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -f -- /Users/ryanlivingston/tmp/null.txt', waited=193125 nanos, events=[CLOSED, EOF, EXIT_STATUS, OPENED]
2023-10-31 14:48:10 DEBUG DefaultScpClient:207 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -f -- /Users/ryanlivingston/tmp/null.txt', exit-status=WARNING
2023-10-31 14:48:10 WARN  DefaultScpClient:221 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -f -- /Users/ryanlivingston/tmp/null.txt' may have terminated with some problems
2023-10-31 14:48:10 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:48:10 DEBUG DefaultScpClient:130 - download(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) /Users/ryanlivingston/tmp/null.txt => /Users/ryanlivingston/tmp/null.download.txt - failed (UnsupportedOperationException) to close file system=sun.nio.fs.MacOSXFileSystem@13ad5cd3: null
2023-10-31 14:48:10 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:48:10 DEBUG ClientSessionImpl:92 - close(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Closing immediately
2023-10-31 14:48:10 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:48:10 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:48:10 DEBUG AbstractChannel$GracefulChannelCloseable:560 - close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[immediately=false] SshException while writing SSH_MSG_CHANNEL_CLOSE packet on channel: Write attempt on closing session: SSH_MSG_CHANNEL_CLOSE
2023-10-31 14:48:10 DEBUG ChannelExec:92 - close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) Closing immediately
2023-10-31 14:48:10 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:48:10 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:48:10 DEBUG SessionTimeoutListener:71 - sessionClosed(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) un-tracked
2023-10-31 14:48:10 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@649972ce) signal close complete immediately=true
2023-10-31 14:48:10 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@43bf5a8a) signal close complete immediately=true
2023-10-31 14:48:10 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@39e36304) signal close complete immediately=true
2023-10-31 14:48:10 DEBUG ClientConnectionService:92 - close(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]]) Closing immediately
2023-10-31 14:48:10 DEBUG ClientConnectionService:279 - stopHeartBeat(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) no heartbeat to stop
2023-10-31 14:48:10 DEBUG ChannelExec:97 - close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[Immediately] closed
2023-10-31 14:48:10 DEBUG ClientConnectionService:97 - close(ClientConnectionService[ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]])[Immediately] closed
2023-10-31 14:48:10 DEBUG ClientConnectionService:441 - unregisterChannel(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) result=null
2023-10-31 14:48:10 DEBUG Nio2Session:92 - close(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) Closing immediately
2023-10-31 14:48:10 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@27377880) signal close complete immediately=false
2023-10-31 14:48:10 DEBUG Nio2Session:268 - doCloseImmediately(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) closing socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/127.0.0.1:60689 remote=localhost/127.0.0.1:22]
2023-10-31 14:48:10 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@1ee50de6) signal close complete immediately=false
2023-10-31 14:48:10 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@3c3cb67d) signal close complete immediately=false
2023-10-31 14:48:10 DEBUG Nio2Session:568 - handleReadCycleFailure(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) ClosedChannelException after 117375 nanos at read cycle=13: null
2023-10-31 14:48:10 DEBUG Nio2Session:101 - close(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22])[Immediately] state already Immediate
2023-10-31 14:48:10 DEBUG Nio2Session:274 - doCloseImmediately(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]) socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[closed] closed
2023-10-31 14:48:10 DEBUG Nio2Connector:147 - unmapSession(id=101): Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22]
2023-10-31 14:48:10 DEBUG ClientSessionImpl:101 - close(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[Immediately] state already Immediate
2023-10-31 14:48:10 DEBUG Nio2Session:97 - close(Nio2Session[local=/127.0.0.1:60689, remote=localhost/127.0.0.1:22])[Immediately] closed
2023-10-31 14:48:10 DEBUG SequentialCloseable:63 - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@673be18f) signal close complete immediately=true
2023-10-31 14:48:10 DEBUG ClientSessionImpl:97 - close(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[Immediately] closed

Other information

No response

@lgoldstein
Copy link
Contributor

The log is very long and convoluted - can you show what you mean by

From the logging, we can see a WARNING exit status is received but it is only logged.

@TerraNibble
Copy link
Contributor Author

TerraNibble commented Nov 3, 2023

The log is very long and convoluted - can you show what you mean by

From the logging, we can see a WARNING exit status is received but it is only logged.

Apologies for including the entire log. After calling download(String, String) with a non-existent remote file path the log prints a warning related to the SCP exit status being "warning". Though there is no indication to the caller at runtime that something went wrong (no RTE is thrown) and the file was not able to be downloaded.

2023-10-31 14:48:10 DEBUG DefaultScpClient:177 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -f -- /Users/ryanlivingston/tmp/null.txt', waited=193125 nanos, events=[CLOSED, EOF, EXIT_STATUS, OPENED]
2023-10-31 14:48:10 DEBUG DefaultScpClient:207 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -f -- /Users/ryanlivingston/tmp/null.txt', exit-status=WARNING
2023-10-31 14:48:10 WARN  DefaultScpClient:221 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -f -- /Users/ryanlivingston/tmp/null.txt' may have terminated with some problems
2023-10-31 14:48:10 DEBUG ChannelExec:130 - close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22])[Graceful] state already Graceful

@lgoldstein
Copy link
Contributor

Thank you for the clarification - this sounds very strange - will need to look into it, though there is one more question - what server are you using ? Is it OpenSSH, MINA SSHD itself or something else ?. FYI, in SCP, the server decides on the severity of an error. Our code simply reflects this severity by logging WARNING(s) and throwing exceptions only if server signalled one. Perhaps this is some non-standard implementation of the SCP protocol, or perhaps some non-standard configuration.

@lgoldstein
Copy link
Contributor

Another question - I see that the command being executed is

scp -f -- /Users/ryanlivingston/tmp/null.txt

What does the "--" stand for ? I am not familiar with this option - usually we copy /some/file1 to /some/file/2

@TerraNibble
Copy link
Contributor Author

TerraNibble commented Nov 3, 2023

Thanks for the response!

This testing is being done on macOS (JDK 18) with what I believe is an OpenSSH server. The testing user has no explicit ~/.ssh/ssh_config defined and I am connecting locally (I am seeing this issue on other Linux systems with a true remote host).

The test I am running is:

        SshClient sshClient = SshClient.setUpDefaultClient();
        sshClient.start();
        try (ClientSession session = sshClient.connect("ryanlivingston", "localhost", 22).verify().getClientSession())
        {
            Path keyPath = Path.of("/Users/ryanlivingston/.ssh/id_rsa");
            FileKeyPairProvider keyProvider = new FileKeyPairProvider(keyPath);
            Iterable<KeyPair> keyPairs = keyProvider.loadKeys(session);
            session.addPublicKeyIdentity(keyPairs.iterator().next());
            session.auth().verify();
            ScpClient scpClient = DefaultScpClientCreator.INSTANCE.createScpClient(session);
            scpClient.download("/Users/ryanlivingston/tmp/null.txt", "/Users/ryanlivingston/tmp/null.download.txt");
        } catch (IOException e) {
            throw new RuntimeException(e);
        }

@TerraNibble
Copy link
Contributor Author

Another question - I see that the command being executed is

scp -f -- /Users/ryanlivingston/tmp/null.txt

What does the "--" stand for ? I am not familiar with this option - usually we copy /some/file1 to /some/file/2

I am not sure how that option was generated in the command string. I do not believe I explicelty set that.

@lgoldstein
Copy link
Contributor

Thanks for the information - I will try and take a look at it when I have some free time (not sure when it will be...)

@brigadoon0
Copy link

ScpClient upload also fails silently for permission denied. Is issue 428 here the same issue as #392?

@lgoldstein
Copy link
Contributor

Seems likely...

lgoldstein pushed a commit to lgoldstein/mina-sshd that referenced this issue Nov 10, 2023
…led due to missing file or lacking permissions
lgoldstein pushed a commit to lgoldstein/mina-sshd that referenced this issue Nov 10, 2023
…led due to missing file or lacking permissions
lgoldstein pushed a commit to lgoldstein/mina-sshd that referenced this issue Nov 10, 2023
…led due to missing file or lacking permissions
@lgoldstein
Copy link
Contributor

lgoldstein commented Nov 10, 2023

Here is the problem: the OpenSSH server defines the missing file a WARNING (status=1) rather than an ERROR (status=2):

receive(ScpHelper[ClientSessionImpl[lgoldstein@localhost/127.0.0.1:5252]]) ack=1: scp: 1234.txt: No such file or directory

This also reflected by the log you attached

2023-10-31 14:48:10 DEBUG DefaultScpClient:207 - handleCommandExitStatus(ClientSessionImpl[ryanlivingston@localhost/127.0.0.1:22]) cmd='scp -f -- /Users/ryanlivingston/tmp/null.txt', exit-status=WARNING

Therefore the code is correct in not treating this as an error. In order to allow user code to handle this otherwise, we will add a new method to the listener to enable users to reach their own decision. Caveat emptor: due to the way the code is written we can only provide the raw command that caused the error/warning and let the user decide whether to throw an exception or not.

Furthermore, I would recommend opening an issue with OpenSSH as to this behavior - perhaps also for PR#392 regarding similar behavior when lacking appropriate permissions to access the file

lgoldstein pushed a commit to lgoldstein/mina-sshd that referenced this issue Nov 10, 2023
…led due to missing file or lacking permissions
lgoldstein pushed a commit to lgoldstein/mina-sshd that referenced this issue Nov 10, 2023
…led due to missing file or lacking permissions
lgoldstein pushed a commit to lgoldstein/mina-sshd that referenced this issue Nov 10, 2023
…led due to missing file or lacking permissions
asfgit pushed a commit that referenced this issue Nov 23, 2023
@tomaswolf tomaswolf added this to the 2.12.0 milestone Jan 4, 2024
@tomaswolf tomaswolf added the bug An issue describing a bug in the code label Jan 4, 2024
@tomaswolf
Copy link
Member

Should have been fixed by commit f908189.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug An issue describing a bug in the code
Projects
None yet
Development

No branches or pull requests

4 participants