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.

Sign up for GitHub

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

Jump to bottom

SFTP fails and returns BufferException during file upload #275

Closed
GabriRuflex opened this issue Nov 23, 2022 · 14 comments · Fixed by #276
Closed

SFTP fails and returns BufferException during file upload #275

GabriRuflex opened this issue Nov 23, 2022 · 14 comments · Fixed by #276
Assignees
@tomaswolf
Labels
bug An issue describing a bug in the code
Milestone
2.10

Comments

@GabriRuflex
Copy link

Version

2.9.2

Bug description

On specific devices I got BufferException exception when I open new SFTP session in order to upload a local file to the remote device.

This is the code I use:

...
byte[] localfileBytes = new FileInputStream(localfilepath).readAllBytes();
try (SftpClient sftp = DefaultSftpClientFactory.INSTANCE.createSftpClient(session)) {
    try (SftpClient.CloseableHandle handle = sftp.open(remotefilepath,
                           EnumSet.of(SftpClient.OpenMode.Write, SftpClient.OpenMode.Create))) {
        sftp.write(handle, 0, localfileBytes, 0, localfileBytes.length);
    } catch (IOException e) {}
} catch (IOException e) {}
...

Actual behavior

The file is not uploaded to the remote device. I tried with both relative and absolute paths.

Expected behavior

The file must be uploaded to the remote device.

Relevant log output

org.apache.sshd.common.util.buffer.BufferException: Underflow: requested=4, available=0
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.ensureAvailable(Buffer.java:635)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getUInt(Buffer.java:281)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getInt(Buffer.java:277)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.ByteArrayBuffer.getString(ByteArrayBuffer.java:240)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getString(Buffer.java:309)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.checkHandleResponse(AbstractSftpClient.java:248)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.checkHandle(AbstractSftpClient.java:232)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.open(AbstractSftpClient.java:573)
        at deployment.test.ear//com.test.UploadFile.upload(UploadFile.java:106)

Other information

The local device run OpenSSH 8.0p1.
@tomaswolf
Copy link
Member

tomaswolf commented Nov 23, 2022 •
edited
Loading

What does the remote device run?

Three points:

  1. The exception occurs after having received an error reply from the server in response to the sftp.open() call. So even if this particular exception is fixed, your problem will not be solved.
  2. The BufferException: Underflow: requested=4, available=0 at that point indicates that the server sent no error message or language tag in the error status reply. I can't find any information that would say these were optional... but Apache MINA sshd could perhaps be lenient and consider them so.
  3. The failing code has been touched last 8 years ago, so the problem is certainly not new in 2.9.2. I wonder why this problem never was reported before? Probably the remote device runs a very old version of SFTP. Prior to SFTP version 3, the SSH_FXP_STATUS reply indeed didn't have the error message and language tag fields.

@GabriRuflex
Copy link
Author

Hi Tomas and thanks for your support!

What does the remote device run?

SSH 2.0, unfortunately no more details :(

Three points:

1. The exception occurs after having received an error reply from the server in response to the `sftp.open()` call. So even if this particular exception is fixed, your problem will not be solved.

I tried also to mount the remote filesystem but it's still not working (only in that specific device)

...
SftpFileSystemProvider provider = new SftpFileSystemProvider(client);
try (FileSystem fs = provider.newFileSystem(session)) {
    Path remotePath = fs.getPath(remotefilepath);
    try {
        Files.copy(localfileStream, remotePath, StandardCopyOption.REPLACE_EXISTING);
    } catch (IOException e) {}
}
...

org.apache.sshd.common.util.buffer.BufferException: Underflow: requested=4, available=0
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.ensureAvailable(Buffer.java:635)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getUInt(Buffer.java:281)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getInt(Buffer.java:277)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.ByteArrayBuffer.getString(ByteArrayBuffer.java:240)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getString(Buffer.java:309)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.checkAttributesResponse(AbstractSftpClient.java:298)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.checkAttributes(AbstractSftpClient.java:283)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.stat(AbstractSftpClient.java:997)
        at deployment.test.ear//org.apache.sshd.sftp.client.fs.SftpFileSystem$Wrapper.stat(SftpFileSystem.java:412)
        at deployment.test.ear//org.apache.sshd.sftp.client.fs.SftpFileSystemProvider.resolveRemoteFileAttributes(SftpFileSystemProvider.java:981)
        at deployment.test.ear//org.apache.sshd.sftp.client.fs.SftpFileSystemProvider.lambda$readRemoteAttributes$0(SftpFileSystemProvider.java:969)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.SftpPathImpl.withAttributeCache(SftpPathImpl.java:120)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.SftpPathImpl.withAttributeCache(SftpPathImpl.java:140)
        at deployment.test.ear//org.apache.sshd.sftp.client.fs.SftpFileSystemProvider.readRemoteAttributes(SftpFileSystemProvider.java:969)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpFileAttributeView.readRemoteAttributes(AbstractSftpFileAttributeView.java:71)
        at deployment.test.ear//org.apache.sshd.sftp.client.fs.SftpPosixFileAttributeView.readAttributes(SftpPosixFileAttributeView.java:52)
        at deployment.test.ear//org.apache.sshd.sftp.client.fs.SftpPosixFileAttributeView.readAttributes(SftpPosixFileAttributeView.java:40)
        at deployment.test.ear//org.apache.sshd.sftp.client.fs.SftpFileSystemProvider.checkAccess(SftpFileSystemProvider.java:826)
        at deployment.test.ear//org.apache.sshd.sftp.client.fs.SftpFileSystemProvider.delete(SftpFileSystemProvider.java:581)
        at java.base/java.nio.file.spi.FileSystemProvider.deleteIfExists(FileSystemProvider.java:787)
        at java.base/java.nio.file.Files.deleteIfExists(Files.java:1181)
        at java.base/java.nio.file.Files.copy(Files.java:3055)
        at deployment.test.ear//com.test.UploadFile.upload(UploadFile.java:109)

2. The `BufferException: Underflow: requested=4, available=0` [at that point](https://github.com/apache/mina-sshd/blob/45fd3a4a84c453a5e053cce624f63465844deb07/sshd-sftp/src/main/java/org/apache/sshd/sftp/client/impl/AbstractSftpClient.java#L248) indicates that the server sent no error message or language tag in the error status reply. I can't find any information that would say these were optional... but Apache MINA sshd could perhaps be lenient and consider them so.

I can login to that device via CLI using ssh or sftp tools. Also other java libraries can do that.

3. The failing code has been touched last 8 years ago, so the problem is certainly not new in 2.9.2. I wonder why this problem never was reported before? Probably the remote device runs a very old version of SFTP. [Prior to SFTP version 3](https://datatracker.ietf.org/doc/html/draft-ietf-secsh-filexfer-09#section-12.4), the SSH_FXP_STATUS reply indeed didn't have the error message and language tag fields.

I'm trying to migrate from another java library (which is working properly) to Apache MINA sshd so I don't know if this issue is new or it a regression related to the latest version

On the old library I just added a try catch to ignore the SSH_FXP_STATUS error and go ahead with the execution.

The current SFTP version is 3

sftp> version
SFTP protocol version 3

@tomaswolf
Copy link
Member

Could you please run your client code with debug logging on and post or attach the log here?

@GabriRuflex
Copy link
Author

GabriRuflex commented Nov 24, 2022 •
edited
Loading

Could you please run your client code with debug logging on and post or attach the log here?

Put file:

sftp> put test.dat 
debug3: Looking up test.dat
Uploading test.dat to /test.dat
debug3: Sent message SSH2_FXP_OPEN I:2 P:/test.dat
test.dat                                                                                                                                                                    100%    0     0.0KB/s   00:00    
debug3: Sent message SSH2_FXP_CLOSE I:3
debug3: SSH2_FXP_STATUS 0
sftp>

LS and remove file:

sftp> rm tesdebug3: Sending SSH2_FXP_READDIR I:26
debug3: Received reply T:104 I:26
debug3: Received 23 SSH2_FXP_NAME responses
debug3: Sending SSH2_FXP_READDIR I:27
debug3: Received reply T:101 I:27
debug3: Received SSH2_FXP_STATUS 1
debug3: Sent message SSH2_FXP_CLOSE I:28
debug3: SSH2_FXP_STATUS 0
debug3: Sent message fd 3 T:7 I:29
debug3: Received stat reply T:105 I:29
sftp> rm test.dat 
debug3: Sent message fd 3 T:7 I:30
debug3: Received stat reply T:105 I:30
Removing /test.dat
debug2: Sending SSH2_FXP_REMOVE "/test.dat"
debug3: Sent message fd 3 T:13 I:31
debug3: SSH2_FXP_STATUS 0
sftp>

If I try to remove the file using MINA sshd library, the file is removed but a BufferException is returned:

org.apache.sshd.common.util.buffer.BufferException: Underflow: requested=4, available=0
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.ensureAvailable(Buffer.java:635)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getUInt(Buffer.java:281)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getInt(Buffer.java:277)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.ByteArrayBuffer.getString(ByteArrayBuffer.java:240)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getString(Buffer.java:309)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.checkResponseStatus(AbstractSftpClient.java:184)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.checkCommandStatus(AbstractSftpClient.java:164)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.remove(AbstractSftpClient.java:608)
        at deployment.test.ear//org.apache.sshd.sftp.client.fs.SftpFileSystem$Wrapper.remove(SftpFileSystem.java:330)
        at deployment.test.ear//org.apache.sshd.sftp.client.fs.SftpFileSystemProvider.delete(SftpFileSystemProvider.java:593)
        at java.base/java.nio.file.spi.FileSystemProvider.deleteIfExists(FileSystemProvider.java:787)
        at java.base/java.nio.file.Files.deleteIfExists(Files.java:1181)

@tomaswolf
Copy link
Member

Sorry for not having been clear enough: I'm interested in the debug log of your Java client that is using Apache MINA SSHD and that is getting the exception. And please show the full log from the initial connection to the exception.

@GabriRuflex
Copy link
Author

GabriRuflex commented Nov 24, 2022 •
edited
Loading

Sorry for not having been clear enough: I'm interested in the debug log of your Java client that is using Apache MINA SSHD and that is getting the exception. And please show the full log from the initial connection to the exception.

This is the code:

    public static void upload() {
        ...
        byte[] localfileBytes;
        try {
            localfileBytes = new FileInputStream(localfilepath).readAllBytes();
        } catch (FileNotFoundException ignored) { }
        try (SshClient client = SshClient.setUpDefaultClient()) {
            client.setSessionHeartbeat(SessionHeartbeatController.HeartbeatType.IGNORE, HEARTBEAT);
            client.start();
            try (ClientSession session = client.connect(username, remotehost, remoteport).verify(WAIT).getSession()) {
                session.addPasswordIdentity(password);
                try {
                    session.auth().verify(WAIT);
                } catch (IOException ignored) { }
                try (SftpClient sftp = DefaultSftpClientFactory.INSTANCE.createSftpClient(session)) {
                    try (SftpClient.CloseableHandle handle = sftp.open(remotefilepath, EnumSet.of(SftpClient.OpenMode.Write, SftpClient.OpenMode.Create))) {
                        sftp.write(handle, 0, localfileBytes, 0, localfileBytes.length);
                    } catch (IOException ignored) { }
                } catch (IOException ignored) { }
            } catch (IOException ignored) { }
        } catch (IOException ignored) { }
    }

Log:

org.apache.sshd.common.util.buffer.BufferException: Underflow: requested=4, available=0
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.ensureAvailable(Buffer.java:635)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getUInt(Buffer.java:281)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getInt(Buffer.java:277)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.ByteArrayBuffer.getString(ByteArrayBuffer.java:240)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getString(Buffer.java:309)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.checkHandleResponse(AbstractSftpClient.java:248)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.checkHandle(AbstractSftpClient.java:232)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.open(AbstractSftpClient.java:573)
        at deployment.test.ear//com.test.UploadFile.upload(UploadFile.java:106)

@tomaswolf
Copy link
Member

Yes, that is the code. But what about the debug log when you run that code? (You should include a logging back-end in your test application, for instance slf4j-simple, and then configure it to produce logging output at the debug level.)

@GabriRuflex
Copy link
Author 

[org.apache.sshd.common.util.security.SecurityUtils] register(BC) not registered - enabled=true, supported=false
[org.apache.sshd.common.util.security.eddsa.EdDSASecurityProviderRegistrar] getOrCreateProvider(EdDSA) created instance of net.i2p.crypto.eddsa.EdDSASecurityProvider
[org.apache.sshd.common.io.DefaultIoServiceFactoryFactory] No detected/configured IoServiceFactoryFactory; using Nio2ServiceFactoryFactory
[org.apache.sshd.client.config.hosts.DefaultConfigFileHostEntryResolver] resolveEffectiveHost(admin@10.0.0.1:22/null) => null
[org.apache.sshd.client.SshClient] connect(admin@10.0.0.1:22) no overrides
[org.apache.sshd.common.io.nio2.Nio2Connector] Connecting to /10.0.0.1:22
[org.apache.sshd.common.io.nio2.Nio2Connector] setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
[org.apache.sshd.common.io.nio2.Nio2Session] (sshd-SshClient[cee5a9]-nio2-thread-1) Creating IoSession on /127.0.0.1:33146 from /10.0.0.1:22 via null
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-1) Client session created: Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]
[org.apache.sshd.client.session.ClientUserAuthService] (sshd-SshClient[cee5a9]-nio2-thread-1) ClientUserAuthService(ClientSessionImpl[null@/10.0.0.1:22]) client methods: [publickey, keyboard-interactive, password]
[org.apache.sshd.common.session.helpers.SessionTimeoutListener] (sshd-SshClient[cee5a9]-nio2-thread-1) sessionCreated(ClientSessionImpl[null@/10.0.0.1:22]) tracking
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-1) initializeProxyConnector(ClientSessionImpl[null@/10.0.0.1:22]) no proxy to initialize
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-1) sendIdentification(ClientSessionImpl[null@/10.0.0.1:22]): SSH-2.0-APACHE-SSHD-2.9.2
[org.apache.sshd.common.io.nio2.Nio2Session] (sshd-SshClient[cee5a9]-nio2-thread-1) writeBuffer(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) writing 27 bytes
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-1) sendKexInit(ClientSessionImpl[null@/10.0.0.1:22]) Send SSH_MSG_KEXINIT
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-1) encode(ClientSessionImpl[null@/10.0.0.1:22]) packet #0 sending command=20[SSH_MSG_KEXINIT] len=1306
[org.apache.sshd.common.io.nio2.Nio2Session] (sshd-SshClient[cee5a9]-nio2-thread-1) writeBuffer(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) writing 1320 bytes
[org.apache.sshd.client.SshClient] (sshd-SshClient[cee5a9]-nio2-thread-1) setupDefaultSessionIdentities(ClientSessionImpl[admin@/10.0.0.1:22]) key identity provider override in session listener
[org.apache.sshd.client.future.DefaultConnectFuture] Connected to /10.0.0.1:22 after 72839697 nanos
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-1) doReadIdentification(ClientSessionImpl[admin@/10.0.0.1:22]) line='SSH-2.0-HUAWEI-1.5'
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-1) readIdentification(ClientSessionImpl[admin@/10.0.0.1:22]) Server version string: SSH-2.0-HUAWEI-1.5
[org.apache.sshd.client.session.ClientSessionImpl] addPasswordIdentity(ClientSessionImpl[admin@/10.0.0.1:22]) SHA256:[REMOVED]
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-2) doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #0 SSH_MSG_KEXINIT
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-2) handleKexInit(ClientSessionImpl[admin@/10.0.0.1:22]) SSH_MSG_KEXINIT
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-2) setNegotiationResult(ClientSessionImpl[admin@/10.0.0.1:22]) Kex: kex algorithms = diffie-hellman-group15-sha512
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-2) setNegotiationResult(ClientSessionImpl[admin@/10.0.0.1:22]) Kex: server host key algorithms = ecdsa-sha2-nistp256
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-2) setNegotiationResult(ClientSessionImpl[admin@/10.0.0.1:22]) Kex: encryption algorithms (client to server) = aes128-ctr
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-2) setNegotiationResult(ClientSessionImpl[admin@/10.0.0.1:22]) Kex: encryption algorithms (server to client) = aes128-ctr
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-2) setNegotiationResult(ClientSessionImpl[admin@/10.0.0.1:22]) Kex: mac algorithms (client to server) = hmac-sha2-256
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-2) setNegotiationResult(ClientSessionImpl[admin@/10.0.0.1:22]) Kex: mac algorithms (server to client) = hmac-sha2-256
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-2) setNegotiationResult(ClientSessionImpl[admin@/10.0.0.1:22]) Kex: compression algorithms (client to server) = none
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-2) setNegotiationResult(ClientSessionImpl[admin@/10.0.0.1:22]) Kex: compression algorithms (server to client) = none
[org.apache.sshd.client.kex.DHGClient] (sshd-SshClient[cee5a9]-nio2-thread-2) init(DHGClient[diffie-hellman-group15-sha512])[ClientSessionImpl[admin@/10.0.0.1:22]] Send SSH_MSG_KEXDH_INIT
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-2) encode(ClientSessionImpl[admin@/10.0.0.1:22]) packet #1 sending command=30[30] len=389
[org.apache.sshd.common.io.nio2.Nio2Session] (sshd-SshClient[cee5a9]-nio2-thread-2) writeBuffer(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) writing 408 bytes
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #1 31
[org.apache.sshd.client.kex.DHGClient] (sshd-SshClient[cee5a9]-nio2-thread-3) next(DHGClient[diffie-hellman-group15-sha512])[ClientSessionImpl[admin@/10.0.0.1:22]] process command=SSH_MSG_KEXDH_REPLY
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) setServerKey(ClientSessionImpl[admin@/10.0.0.1:22]) keyType=ecdsa-sha2-nistp256, digest=SHA256:[REMOVED]
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) handleKexMessage(ClientSessionImpl[admin@/10.0.0.1:22])[diffie-hellman-group15-sha512] KEX processing complete after cmd=31
[org.apache.sshd.client.keyverifier.AcceptAllServerKeyVerifier] (sshd-SshClient[cee5a9]-nio2-thread-3) Server at /10.0.0.1:22 presented unverified EC key: SHA256:[REMOVED]
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) checkKeys(ClientSessionImpl[admin@/10.0.0.1:22]) key=ecdsa-sha2-nistp256-SHA256:[REMOVED], verified=true
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) sendNewKeys(ClientSessionImpl[admin@/10.0.0.1:22]) Send SSH_MSG_NEWKEYS
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) prepareNewKeys(ClientSessionImpl[admin@/10.0.0.1:22]) session ID=[REMOVED]
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) encode(ClientSessionImpl[admin@/10.0.0.1:22]) packet #2 sending command=21[SSH_MSG_NEWKEYS] len=1
[org.apache.sshd.common.io.nio2.Nio2Session] (sshd-SshClient[cee5a9]-nio2-thread-3) writeBuffer(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) writing 16 bytes
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) setOutputEncoding(ClientSessionImpl[admin@/10.0.0.1:22]): cipher BaseCipher[AES, ivSize=16, kdfSize=16,AES/CTR/NoPadding, blkSize=16]; mac BaseMac[HmacSHA256] -  block=32/32 bytes, encrypt-then-mac=false; compression none[Deflater/-1]; blocks limit 134217728
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) handleNewKeys(ClientSessionImpl[admin@/10.0.0.1:22]) No pending packets to flush at end of KEX
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #2 SSH_MSG_NEWKEYS
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) handleNewKeys(ClientSessionImpl[admin@/10.0.0.1:22]) SSH_MSG_NEWKEYS command=SSH_MSG_NEWKEYS
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) setInputEncoding(ClientSessionImpl[admin@/10.0.0.1:22]): cipher BaseCipher[AES, ivSize=16, kdfSize=16,AES/CTR/NoPadding, blkSize=16]; mac BaseMac[HmacSHA256] -  block=32/32 bytes, encrypt-then-mac=false; compression none[Inflater/-1]; blocks limit 4294967296
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) sendInitialServiceRequest(ClientSessionImpl[admin@/10.0.0.1:22]) Send SSH_MSG_SERVICE_REQUEST for ssh-userauth
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) encode(ClientSessionImpl[admin@/10.0.0.1:22]) packet #3 sending command=5[SSH_MSG_SERVICE_REQUEST] len=17
[org.apache.sshd.common.io.nio2.Nio2Session] (sshd-SshClient[cee5a9]-nio2-thread-3) writeBuffer(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) writing 80 bytes
[org.apache.sshd.client.session.ClientUserAuthService] (sshd-SshClient[cee5a9]-nio2-thread-3) auth(ClientSessionImpl[admin@/10.0.0.1:22])[ssh-connection] send SSH_MSG_USERAUTH_REQUEST for 'none'
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-3) encode(ClientSessionImpl[admin@/10.0.0.1:22]) packet #4 sending command=50[SSH_MSG_USERAUTH_REQUEST] len=36
[org.apache.sshd.common.io.nio2.Nio2Session] (sshd-SshClient[cee5a9]-nio2-thread-3) writeBuffer(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) writing 96 bytes
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-4) doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #3 SSH_MSG_SERVICE_ACCEPT
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-4) handleServiceAccept(ClientSessionImpl[admin@/10.0.0.1:22]) SSH_MSG_SERVICE_ACCEPT service=ssh-userauth
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-4) doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #4 SSH_MSG_USERAUTH_FAILURE
[org.apache.sshd.client.session.ClientUserAuthService] (sshd-SshClient[cee5a9]-nio2-thread-4) processUserAuth(ClientSessionImpl[admin@/10.0.0.1:22]) Received SSH_MSG_USERAUTH_FAILURE - partial=true, methods=password
[org.apache.sshd.client.session.ClientUserAuthService] (sshd-SshClient[cee5a9]-nio2-thread-4) tryNext(ClientSessionImpl[admin@/10.0.0.1:22]) starting authentication mechanisms: client=[publickey, keyboard-interactive, password], server=[password]
[org.apache.sshd.client.session.ClientUserAuthService] (sshd-SshClient[cee5a9]-nio2-thread-4) tryNext(ClientSessionImpl[admin@/10.0.0.1:22]) attempting method=password
[org.apache.sshd.client.auth.password.UserAuthPassword] (sshd-SshClient[cee5a9]-nio2-thread-4) sendPassword(ClientSessionImpl[admin@/10.0.0.1:22])[ssh-connection] send SSH_MSG_USERAUTH_REQUEST for password - modified=false
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-4) encode(ClientSessionImpl[admin@/10.0.0.1:22]) packet #5 sending command=50[SSH_MSG_USERAUTH_REQUEST] len=53
[org.apache.sshd.common.io.nio2.Nio2Session] (sshd-SshClient[cee5a9]-nio2-thread-4) writeBuffer(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) writing 112 bytes
[org.apache.sshd.client.session.ClientUserAuthService] (sshd-SshClient[cee5a9]-nio2-thread-4) tryNext(ClientSessionImpl[admin@/10.0.0.1:22]) successfully processed initial buffer by method=password
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-5) doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #5 SSH_MSG_USERAUTH_SUCCESS
[org.apache.sshd.client.session.ClientUserAuthService] (sshd-SshClient[cee5a9]-nio2-thread-5) processUserAuth(ClientSessionImpl[admin@/10.0.0.1:22]) SSH_MSG_USERAUTH_SUCCESS Succeeded with password
[org.apache.sshd.client.auth.password.UserAuthPassword] (sshd-SshClient[cee5a9]-nio2-thread-5) destroy(ClientSessionImpl[admin@/10.0.0.1:22])[ssh-connection]
[org.apache.sshd.client.session.ClientConnectionService] (sshd-SshClient[cee5a9]-nio2-thread-5) stopHeartBeat(ClientSessionImpl[admin@/10.0.0.1:22]) no heartbeat to stop
[org.apache.sshd.client.session.ClientConnectionService] (sshd-SshClient[cee5a9]-nio2-thread-5) startHeartbeat(ClientSessionImpl[admin@/10.0.0.1:22]) heartbeat type=IGNORE, interval=PT1M32S
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] init() service=ClientConnectionService[ClientSessionImpl[admin@/10.0.0.1:22]] session=ClientSessionImpl[admin@/10.0.0.1:22] id=0
[org.apache.sshd.common.channel.LocalWindow] init(LocalWindow[client](SftpChannelSubsystem[id=0, recipient=-1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp])) size=2097152, max=2097152, packet=32768
[org.apache.sshd.client.session.ClientConnectionService] registerChannel(ClientConnectionService[ClientSessionImpl[admin@/10.0.0.1:22]])[id=0, registered=true] SftpChannelSubsystem[id=0, recipient=-1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] open(SftpChannelSubsystem[id=0, recipient=-1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) Send SSH_MSG_CHANNEL_OPEN - type=session
[org.apache.sshd.client.session.ClientSessionImpl] encode(ClientSessionImpl[admin@/10.0.0.1:22]) packet #6 sending command=90[SSH_MSG_CHANNEL_OPEN] len=24
[org.apache.sshd.common.io.nio2.Nio2Session] writeBuffer(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) writing 80 bytes
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-7) doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #6 SSH_MSG_CHANNEL_OPEN_CONFIRMATION
[org.apache.sshd.client.session.ClientConnectionService] (sshd-SshClient[cee5a9]-nio2-thread-7) channelOpenConfirmation(SftpChannelSubsystem[id=0, recipient=-1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) SSH_MSG_CHANNEL_OPEN_CONFIRMATION sender=1, window-size=131072, packet-size=32768
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] (sshd-SshClient[cee5a9]-nio2-thread-7) setRecipient(SftpChannelSubsystem[id=0, recipient=-1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) recipient=1
[org.apache.sshd.common.channel.RemoteWindow] (sshd-SshClient[cee5a9]-nio2-thread-7) init(RemoteWindow[client](SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp])) size=131072, max=131072, packet=32768
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] (sshd-SshClient[cee5a9]-nio2-thread-7) addPendingRequest(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) request=subsystem, pending=Thu Nov 24 10:42:48 CET 2022
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-7) encode(ClientSessionImpl[admin@/10.0.0.1:22]) packet #7 sending command=98[SSH_MSG_CHANNEL_REQUEST] len=27
[org.apache.sshd.common.io.nio2.Nio2Session] (sshd-SshClient[cee5a9]-nio2-thread-7) writeBuffer(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) writing 80 bytes
[org.apache.sshd.common.channel.RemoteWindow] Consume RemoteWindow[client](SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) by 9 down to 131063
[org.apache.sshd.client.session.ClientSessionImpl] encode(ClientSessionImpl[admin@/10.0.0.1:22]) packet #8 sending command=94[SSH_MSG_CHANNEL_DATA] len=18
[org.apache.sshd.common.io.nio2.Nio2Session] writeBuffer(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) writing 80 bytes
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-9) doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #7 SSH_MSG_CHANNEL_SUCCESS
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] (sshd-SshClient[cee5a9]-nio2-thread-9) removePendingRequest(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) request=subsystem, pending=Thu Nov 24 10:42:48 CET 2022
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] (sshd-SshClient[cee5a9]-nio2-thread-9) handleSuccess(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) subsystem=sftp, pending since=Thu Nov 24 10:42:48 CET 2022
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-10) doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #8 SSH_MSG_CHANNEL_DATA
[org.apache.sshd.common.channel.LocalWindow] (sshd-SshClient[cee5a9]-nio2-thread-10) Consume LocalWindow[client](SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) by 9 down to 2097143
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] (sshd-SshClient[cee5a9]-nio2-thread-10) handleData(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) SSH_MSG_CHANNEL_DATA len=9
[org.apache.sshd.sftp.client.impl.DefaultSftpClient] negotiateVersion(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) current=3 [3] -> 3
[org.apache.sshd.common.channel.RemoteWindow] Consume RemoteWindow[client](SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) by 37 down to 131026
[org.apache.sshd.client.session.ClientSessionImpl] encode(ClientSessionImpl[admin@/10.0.0.1:22]) packet #9 sending command=94[SSH_MSG_CHANNEL_DATA] len=46
[org.apache.sshd.common.io.nio2.Nio2Session] writeBuffer(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) writing 112 bytes
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-12) doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #9 SSH_MSG_CHANNEL_DATA
[org.apache.sshd.common.channel.LocalWindow] (sshd-SshClient[cee5a9]-nio2-thread-12) Consume LocalWindow[client](SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) by 13 down to 2097130
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] (sshd-SshClient[cee5a9]-nio2-thread-12) handleData(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) SSH_MSG_CHANNEL_DATA len=13
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] close(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) Closing gracefully
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] close(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) no EOF sent
[org.apache.sshd.common.channel.LocalWindow] Closing LocalWindow[client](SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp])
[org.apache.sshd.common.channel.RemoteWindow] Closing RemoteWindow[client](SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp])
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem$1] close([SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]] cmd=SSH_MSG_CHANNEL_DATA) Closing gracefully
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] sendEof(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) SSH_MSG_CHANNEL_EOF (state=Graceful)
[org.apache.sshd.client.session.ClientSessionImpl] encode(ClientSessionImpl[admin@/10.0.0.1:22]) packet #10 sending command=96[SSH_MSG_CHANNEL_EOF] len=5
[org.apache.sshd.common.io.nio2.Nio2Session] writeBuffer(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) writing 64 bytes
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem$1] close([SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]] cmd=SSH_MSG_CHANNEL_DATA][Graceful] - operationComplete() closed
[org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable] close(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp])[immediately=false] processing
[org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable] close(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp])[immediately=false] send SSH_MSG_CHANNEL_CLOSE
[org.apache.sshd.client.session.ClientSessionImpl] encode(ClientSessionImpl[admin@/10.0.0.1:22]) packet #11 sending command=97[SSH_MSG_CHANNEL_CLOSE] len=5
[org.apache.sshd.common.io.nio2.Nio2Session] writeBuffer(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) writing 64 bytes
[org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable] handleClosePacketWritten(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp])[immediately=false] SSH_MSG_CHANNEL_CLOSE written on channel
[org.apache.sshd.client.session.ClientSessionImpl] close(ClientSessionImpl[admin@/10.0.0.1:22]) Closing immediately
[org.apache.sshd.client.session.ClientSessionImpl] signalAuthFailure(ClientSessionImpl[admin@/10.0.0.1:22]) type=SshException, signalled=false, first=false: Session is being closed
[org.apache.sshd.common.session.helpers.SessionTimeoutListener] sessionClosed(ClientSessionImpl[admin@/10.0.0.1:22]) un-tracked
[org.apache.sshd.client.session.ClientConnectionService] close(ClientConnectionService[ClientSessionImpl[admin@/10.0.0.1:22]]) Closing immediately
[org.apache.sshd.client.session.ClientConnectionService] stopHeartBeat(ClientSessionImpl[admin@/10.0.0.1:22]) stopping
[org.apache.sshd.client.session.ClientConnectionService] stopHeartBeat(ClientSessionImpl[admin@/10.0.0.1:22]) stopped
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] close(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) Closing immediately
[org.apache.sshd.client.session.ClientSessionImpl] (sshd-SshClient[cee5a9]-nio2-thread-15) doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #10 SSH_MSG_CHANNEL_CLOSE
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem$1] close([SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]] cmd=SSH_MSG_CHANNEL_DATA)[Immediately] state already Closed
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] (sshd-SshClient[cee5a9]-nio2-thread-15) handleClose(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) SSH_MSG_CHANNEL_CLOSE
[org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable] close(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp])[immediately=true] processing
[org.apache.sshd.client.session.ClientConnectionService] unregisterChannel(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) result=SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]
[org.apache.sshd.client.session.ClientConnectionService] (sshd-SshClient[cee5a9]-nio2-thread-15) unregisterChannel(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) result=null
[org.apache.sshd.common.util.closeable.SequentialCloseable] doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@2736db5b) signal close complete immediately=true
[org.apache.sshd.common.util.closeable.SequentialCloseable] (sshd-SshClient[cee5a9]-nio2-thread-15) doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@39cc2d93) signal close complete immediately=false
[org.apache.sshd.common.util.closeable.SequentialCloseable] doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@55cb0a61) signal close complete immediately=true
[org.apache.sshd.common.util.closeable.SequentialCloseable] doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@467f91c7) signal close complete immediately=true
[org.apache.sshd.common.util.closeable.SequentialCloseable] (sshd-SshClient[cee5a9]-nio2-thread-15) doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@370bd4da) signal close complete immediately=false
[org.apache.sshd.common.util.closeable.SequentialCloseable] (sshd-SshClient[cee5a9]-nio2-thread-15) doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@333446e3) signal close complete immediately=false
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] close(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp])[Immediately] closed
[org.apache.sshd.client.session.ClientConnectionService] close(ClientConnectionService[ClientSessionImpl[admin@/10.0.0.1:22]])[Immediately] closed
[org.apache.sshd.common.io.nio2.Nio2Session] close(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) Closing immediately
[org.apache.sshd.common.io.nio2.Nio2Session] doCloseImmediately(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) closing socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/127.0.0.1:33146 remote=/10.0.0.1:22]
[org.apache.sshd.common.io.nio2.Nio2Session] doCloseImmediately(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[closed] closed
[org.apache.sshd.common.io.nio2.Nio2Connector] unmapSession(id=101): Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]
[org.apache.sshd.client.session.ClientSessionImpl] close(ClientSessionImpl[admin@/10.0.0.1:22])[Immediately] state already Immediate
[org.apache.sshd.common.io.nio2.Nio2Session] close(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22])[Immediately] closed
[org.apache.sshd.common.util.closeable.SequentialCloseable] doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@15ce01ef) signal close complete immediately=true
[org.apache.sshd.client.session.ClientSessionImpl] close(ClientSessionImpl[admin@/10.0.0.1:22])[Immediately] closed
[org.apache.sshd.common.io.nio2.Nio2Session] (sshd-SshClient[cee5a9]-nio2-thread-16) handleReadCycleFailure(Nio2Session[local=/127.0.0.1:33146, remote=/10.0.0.1:22]) AsynchronousCloseException after 1445950 nanos at read cycle=12: null
[org.apache.sshd.client.SshClient] close(SshClient[cee5a9]) Closing immediately
[org.apache.sshd.common.io.nio2.Nio2Connector] close(org.apache.sshd.common.io.nio2.Nio2Connector@6ee75013) Closing immediately
[org.apache.sshd.common.io.nio2.Nio2Connector] close(org.apache.sshd.common.io.nio2.Nio2Connector@6ee75013)[Immediately] closed
[org.apache.sshd.common.io.nio2.Nio2ServiceFactory] close(org.apache.sshd.common.io.nio2.Nio2ServiceFactory@b43f559) Closing immediately
[org.apache.sshd.common.io.nio2.Nio2ServiceFactory] Shutdown group
[org.apache.sshd.common.io.nio2.Nio2ServiceFactory] Group successfully shut down
[org.apache.sshd.common.io.nio2.Nio2ServiceFactory] Shutdown executor
[org.apache.sshd.common.io.nio2.Nio2ServiceFactory] Shutdown complete
[org.apache.sshd.common.io.nio2.Nio2ServiceFactory] close(org.apache.sshd.common.io.nio2.Nio2ServiceFactory@b43f559)[Immediately] closed
[org.apache.sshd.common.util.closeable.SequentialCloseable] doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@1d3cee0f) signal close complete immediately=true
[org.apache.sshd.client.SshClient] close(SshClient[cee5a9])[Immediately] closed
[com.test.log.ExceptionLogger] org.apache.sshd.common.util.buffer.BufferException: Underflow: requested=4, available=0
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.ensureAvailable(Buffer.java:635)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getUInt(Buffer.java:281)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getInt(Buffer.java:277)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.ByteArrayBuffer.getString(ByteArrayBuffer.java:240)
        at deployment.test.ear//org.apache.sshd.common.util.buffer.Buffer.getString(Buffer.java:309)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.checkHandleResponse(AbstractSftpClient.java:248)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.checkHandle(AbstractSftpClient.java:232)
        at deployment.test.ear//org.apache.sshd.sftp.client.impl.AbstractSftpClient.open(AbstractSftpClient.java:573)

@tomaswolf
Copy link
Member

Thanks. So this is some device using Huawei VRP. (The server identifies as SSH-2.0-HUAWEI-1.5.) Indeed the negotiated SFTP version is SFTP v3.

I'll fix this BufferException: Underflow and improve SFTP logging, but as I wrote above, I don't think this will resolve the problem with this device. But maybe with better logging we can then see better what might be going on.

tomaswolf added a commit to tomaswolf/mina-sshd that referenced this issue Nov 25, 2022
@tomaswolf
apacheGH-275: Improve SFTP status message parsing
95526ce 
Introduce a message record for SSH_FXP_STATUS to centralize parsing it
from a buffer. Treat the error message and the language tag as optional
because these fields exist only since SFTP v3, and apparently there are
SFTP v3 servers that don't send it.

Bug: apache#275
tomaswolf added a commit to tomaswolf/mina-sshd that referenced this issue Nov 25, 2022
@tomaswolf
apacheGH-275: More logging for SFTP clients
e19e1e2 
Log all SFTP requests and replies at debug level, and include the
command name in the log message. A simple grep for SSH_FXP or SSH_FX
should then find all lines relating to SFTP commands.
@tomaswolf
Copy link
Member

tomaswolf commented Nov 25, 2022 •
edited
Loading

Probably the remote device runs a very old version of SFTP. Prior to SFTP version 3, the SSH_FXP_STATUS reply indeed didn't have the error message and language tag fields.

Actually, it's a bit worse: the very first of the SFTP v3 drafts also did not have these two fields yet. They appeared only in the second SFTPv3 draft.

Therefore there may indeed be old servers that implement only that very early specification, and rightfully claim to implement SFTPv3 but not send these fields. In order to support such old SFTPv3 servers, an SFTP client must treat the error message and language tag fields in SSH_FXP_STATUS as optional.

Note: this also means that if the SSH implementation used by this device is OpenSSH, it must be a truly ancient version <OpenSSH 2.5.2p2, which was released 2001-03-22!

@tomaswolf tomaswolf added this to the 2.9.3 milestone Nov 25, 2022
@tomaswolf tomaswolf added the bug An issue describing a bug in the code label Nov 25, 2022
@tomaswolf tomaswolf self-assigned this Nov 25, 2022
tomaswolf added a commit to tomaswolf/mina-sshd that referenced this issue Nov 25, 2022
@tomaswolf
apacheGH-275: Improve SFTP status message parsing
9630cf9 
Introduce a message record for SSH_FXP_STATUS to centralize parsing
it from a buffer. Treat the error message and the language tag as
optional.

These fields did not exist in the first draft of SFTP v3.[1] They
only exist since the second draft[2]. There are still old SFTP server
implementations that implement SFTP v3 but don't send these two
fields.

[1] https://datatracker.ietf.org/doc/html/draft-ietf-secsh-filexfer-00#section-7
[2] https://datatracker.ietf.org/doc/html/draft-ietf-secsh-filexfer-01#section-6

Bug: apache#275
tomaswolf added a commit to tomaswolf/mina-sshd that referenced this issue Nov 25, 2022
@tomaswolf
apacheGH-275: More logging for SFTP clients
d04aadc 
Log all SFTP requests and replies at debug level, and include the
command name in the log message. A simple grep for SSH_FXP or SSH_FX
should then find all lines relating to SFTP commands.
@tomaswolf tomaswolf mentioned this issue Nov 25, 2022
Merged
@tomaswolf
Copy link
Member

@GabriRuflex : a fix for this problem has been merged. If there is still a problem with SFTP uploads to that device using the current master branch of Apache MINA SSHD, feel free to open a new bug report. (I suspect there might be, since the server should respond to an open() call with an SSH_FXP_STATUS reply only if it encountered an error. If the open() succeeds, it should send back an SSH_FXP_HANDLE response.)

@GabriRuflex
Copy link
Author

@GabriRuflex : a fix for this problem has been merged. If there is still a problem with SFTP uploads to that device using the current master branch of Apache MINA SSHD, feel free to open a new bug report. (I suspect there might be, since the server should respond to an open() call with an SSH_FXP_STATUS reply only if it encountered an error. If the open() succeeds, it should send back an SSH_FXP_HANDLE response.)

Thanks Tomas.

I'll test it on monday and I'll inform you about the results 😄

@GabriRuflex
Copy link
Author

GabriRuflex commented Nov 29, 2022 •
edited
Loading

@tomaswolf

If I use the SftpFileSystemProvider there are no issue anymore and the file upload works properly, thanks!

SftpFileSystemProvider provider = new SftpFileSystemProvider(client);
try (FileSystem fs = provider.newFileSystem(session)) {
    Path remotePath = fs.getPath(remotefilepath);
    try {
        Files.copy(localfileStream, remotePath, StandardCopyOption.REPLACE_EXISTING);
    } catch (IOException e) {}
}

Log:

[org.apache.sshd.client.session.ClientSessionImpl] doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #10 SSH_MSG_CHANNEL_DATA
[org.apache.sshd.common.channel.LocalWindow] Consume LocalWindow[client](SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) by 13 down to 2097103
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] handleData(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) SSH_MSG_CHANNEL_DATA len=13
[org.apache.sshd.sftp.client.impl.DefaultSftpClient] validateIncomingResponse(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]): received SSH_FXP_STATUS(SSH_FX_NO_SUCH_FILE) for command SSH_FXP_STAT (id=102)
[org.apache.sshd.sftp.client.impl.DefaultSftpClient] throwStatusException(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp])[id=102] cmd=SSH_FXP_STAT status=SSH_FXP_STATUS[SSH_FX_NO_SUCH_FILE ,language=null ,message=null]
[org.apache.sshd.sftp.client.impl.DefaultSftpClient] open(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]): send SSH_FXP_OPEN /test.dat
[org.apache.sshd.common.channel.RemoteWindow] Consume RemoteWindow[client](SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) by 63 down to 130931
[org.apache.sshd.client.session.ClientSessionImpl] encode(ClientSessionImpl[admin@/10.0.0.1:22]) packet #11 sending command=94[SSH_MSG_CHANNEL_DATA] len=72
[org.apache.sshd.common.io.nio2.Nio2Session] writeBuffer(Nio2Session[local=/127.0.0.1:44642, remote=/10.0.0.1:22]) writing 128 bytes
[org.apache.sshd.client.session.ClientSessionImpl] doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #11 SSH_MSG_CHANNEL_DATA
[org.apache.sshd.common.channel.LocalWindow] Consume LocalWindow[client](SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) by 17 down to 2097086
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] handleData(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) SSH_MSG_CHANNEL_DATA len=17
[org.apache.sshd.sftp.client.impl.DefaultSftpClient] validateIncomingResponse(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]): received SSH_FXP_HANDLE for command SSH_FXP_OPEN (id=103)

If I use a simple SftpClient with open function I still have issue and I can't upload the file:

                try (SftpClient sftp = DefaultSftpClientFactory.INSTANCE.createSftpClient(session)) {
                    try (SftpClient.CloseableHandle handle = sftp.open(remotefilepath, EnumSet.of(SftpClient.OpenMode.Write, SftpClient.OpenMode.Create))) {
                        sftp.write(handle, 0, localfileBytes, 0, localfileBytes.length);
                    } catch (IOException ignored) { }
                } catch (IOException ignored) { }
            } catch (IOException ignored) { }
        } catch (IOException ignored) { }
    }

Log:

[org.apache.sshd.client.session.ClientSessionImpl] doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #8 SSH_MSG_CHANNEL_DATA
[org.apache.sshd.common.channel.LocalWindow] Consume LocalWindow[client](SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) by 9 down to 2097143
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] handleData(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) SSH_MSG_CHANNEL_DATA len=9
[org.apache.sshd.sftp.client.impl.DefaultSftpClient] negotiateVersion(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) current=3 [3] -> 3
[org.apache.sshd.sftp.client.impl.DefaultSftpClient] open(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]): send SSH_FXP_OPEN /test.dat
[org.apache.sshd.common.channel.RemoteWindow] Consume RemoteWindow[client](SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) by 37 down to 131026
[org.apache.sshd.client.session.ClientSessionImpl] encode(ClientSessionImpl[admin@/10.0.0.1:22]) packet #9 sending command=94[SSH_MSG_CHANNEL_DATA] len=46
[org.apache.sshd.common.io.nio2.Nio2Session] writeBuffer(Nio2Session[local=/127.0.0.1:60194, remote=/10.0.0.1:22]) writing 112 bytes
[org.apache.sshd.client.session.ClientSessionImpl] doHandleMessage(ClientSessionImpl[admin@/10.0.0.1:22]) process #9 SSH_MSG_CHANNEL_DATA
[org.apache.sshd.common.channel.LocalWindow] Consume LocalWindow[client](SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) by 13 down to 2097130
[org.apache.sshd.sftp.client.impl.DefaultSftpClient$SftpChannelSubsystem] handleData(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]) SSH_MSG_CHANNEL_DATA len=13
[org.apache.sshd.sftp.client.impl.DefaultSftpClient] validateIncomingResponse(SftpChannelSubsystem[id=0, recipient=1]-ClientSessionImpl[admin@/10.0.0.1:22][sftp]): received SSH_FXP_STATUS(SSH_FX_FAILURE) for command SSH_FXP_OPEN (id=101)

@tomaswolf
Copy link
Member

Looks like we should also write the file open modes to the log.

Using the file system

  • the file will be deleted first if it existed (it didn't, as the stat response shows), and
  • the open() call will include the Exclusive flag.

I don't know why the server seems to have a problem with the direct open() call. I don't really see how I could help here further. AFAIK, the actual open() call is in both cases the very same piece of code in Apache MINA sshd. So any difference in server behavior must be caused by different request parameters (different flags), or a different device state (such as the file already existing).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@tomaswolf tomaswolf

Labels
bug An issue describing a bug in the code
Projects
None yet
Milestone
2.10
Development

Successfully merging a pull request may close this issue.

SFTP: parsing of SSH_FXP_STATUS tomaswolf/mina-sshd
2 participants
@GabriRuflex @tomaswolf