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

Session is being closed/Invalid packet length: 1096041266 with Apache Mina SSHD #623

Open
yashasvirajpant opened this issue Oct 11, 2024 · 6 comments
Open

Session is being closed/Invalid packet length: 1096041266 with Apache Mina SSHD #623

yashasvirajpant opened this issue Oct 11, 2024 · 6 comments

Comments

@yashasvirajpant
Copy link

yashasvirajpant commented Oct 11, 2024 •
edited
Loading

Version

sshd-core-2.10.0

Bug description

I'm facing an issue while trying to authenticate an SSH session using the Apache Mina SSHD library in Java in a spring boot microservice project. I have a working implementation using JSch that connects successfully with a private key, but the equivalent code in Apache Mina SSHD fails with the error:

org.apache.sshd.common.SshException: Session is being closed
	at org.apache.sshd.common.future.AbstractSshFuture.verifyResult(AbstractSshFuture.java:141) ~[sshd-common-2.10.0.jar:2.10.0]
	at org.apache.sshd.client.future.DefaultAuthFuture.verify(DefaultAuthFuture.java:56) ~[sshd-core-2.10.0.jar:2.10.0]
	at org.apache.sshd.client.future.DefaultAuthFuture.verify(DefaultAuthFuture.java:35) ~[sshd-core-2.10.0.jar:2.10.0]

or sometime:

org.apache.sshd.common.SshException: Invalid packet length: 1096041266
	at org.apache.sshd.common.future.AbstractSshFuture.verifyResult(AbstractSshFuture.java:141) ~[sshd-common-2.10.0.jar:2.10.0]
	at org.apache.sshd.client.future.DefaultAuthFuture.verify(DefaultAuthFuture.java:56) ~[sshd-core-2.10.0.jar:2.10.0]
	at org.apache.sshd.client.future.DefaultAuthFuture.verify(DefaultAuthFuture.java:35) ~[sshd-core-2.10.0.jar:2.10.0]

Here is the code implementation:

try (SshClient sshClient = SshClient.setUpDefaultClient()) {

      // Enable DSA signatures (which is disabled by default) (for ssh-dss key type)
      sshClient.setSignatureFactories(List.of(BuiltinSignatures.dsa));

      // Enable diffie-hellman-group1-sha1 key exchange algorithm for older devices
      sshClient.setKeyExchangeFactories(
          NamedFactory.setUpTransformedFactories(
              false, BuiltinDHFactories.VALUES, ClientBuilder.DH2KEX));

    sshClient.start();

   try (ClientSession session =
          sshClient.connect(user, host, port).verify(ftpTimeOutInSeconds * 1000L).getSession()) {

          // Parse the private key string
          StringReader stringReader = new StringReader(privateKeyInString);
          PEMParser pemParser = new PEMParser(stringReader);
          JcaPEMKeyConverter converter = new JcaPEMKeyConverter().setProvider("BC");
          KeyPair keyPair = converter.getKeyPair((PEMKeyPair) pemParser.readObject());

          // Add the private key to the session
          session.addPublicKeyIdentity(keyPair);

        session.auth().verify(ftpTimeOutInSeconds * 1000L);
        LOGGER.info("Session authenticated successfully!");
    }
 catch (IOException e) {
    LOGGER.error("I/O Exception occurred: " + e.getMessage());
} catch (Exception e) {
    LOGGER.error("General Exception occurred: " + e.getMessage());
}
}

The error occurs in the code line

session.auth().verify(ftpTimeOutInSeconds * 1000L);

What could be the reason for the authentication failure in the Apache Mina SSHD implementation, and how can I resolve this issue? Any insights or recommendations for debugging further would be greatly appreciated!

Actual behavior

Not able to connect to SSH using Apache Mina SSHD

Expected behavior

We should get SSH connection correct as it can be connected with JSch

Relevant log output

2024-10-11 13:02:42.113 DEBUG 1 --- [ol-39-thread-39] c.c.h.DefaultConfigFileHostEntryResolver : resolveEffectiveHost(user@<ip>:<port>/null) => null
2024-10-11 13:02:42.113 DEBUG 1 --- [ol-39-thread-39] org.apache.sshd.client.SshClient         : connect(user@<ip>:<port>) no overrides
2024-10-11 13:02:42.113 DEBUG 1 --- [ol-39-thread-39] o.a.sshd.common.io.nio2.Nio2Connector    : Connecting to /<ip>:<port>
2024-10-11 13:02:42.114 DEBUG 1 --- [ol-39-thread-39] o.a.sshd.common.io.nio2.Nio2Connector    : setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2024-10-11 13:02:42.114 DEBUG 1 --- [resume-thread-1] o.a.sshd.common.io.nio2.Nio2Connector    : connect(/<ip>:<port>): waiting for connection (timeout=60000ms)
2024-10-11 13:02:42.154 DEBUG 1 --- [resume-thread-1] o.a.sshd.common.io.nio2.Nio2Session      : Creating IoSession on /<internal_ip>:<internal_port> from /<ip>:<port> via null
2024-10-11 13:02:42.154 DEBUG 1 --- [resume-thread-1] o.a.s.client.session.ClientSessionImpl   : Client session created: Nio2Session[local=/<internal_ip>:44140, remote=/<ip>:<port>]
2024-10-11 13:02:42.154 DEBUG 1 --- [resume-thread-1] o.a.s.c.session.ClientUserAuthService    : ClientUserAuthService(ClientSessionImpl[null@/<ip>:<port>]) client methods: [publickey, keyboard-interactive, password]
2024-10-11 13:02:42.154 DEBUG 1 --- [resume-thread-1] o.a.s.c.s.h.SessionTimeoutListener       : sessionCreated(ClientSessionImpl[null@/<ip>:<port>]) tracking
2024-10-11 13:02:42.154 DEBUG 1 --- [resume-thread-1] o.a.s.client.session.ClientSessionImpl   : initializeProxyConnector(ClientSessionImpl[null@/<ip>:<port>]) no proxy to initialize
2024-10-11 13:02:42.155 DEBUG 1 --- [resume-thread-1] o.a.s.client.session.ClientSessionImpl   : sendIdentification(ClientSessionImpl[null@/<ip>:<port>]): SSH-2.0-APACHE-SSHD-2.10.0
2024-10-11 13:02:42.155 DEBUG 1 --- [resume-thread-1] o.a.sshd.common.io.nio2.Nio2Session      : writeBuffer(Nio2Session[local=/<internal_ip>:44140, remote=/<ip>:<port>]) writing 28 bytes
2024-10-11 13:02:42.155 DEBUG 1 --- [resume-thread-1] o.a.s.client.session.ClientSessionImpl   : sendKexInit(ClientSessionImpl[null@/<ip>:<port>]) Send SSH_MSG_KEXINIT
2024-10-11 13:02:42.159 DEBUG 1 --- [resume-thread-1] o.a.s.client.session.ClientSessionImpl   : encode(ClientSessionImpl[null@/<ip>:<port>]) packet #0 sending command=20[SSH_MSG_KEXINIT] len=1012
2024-10-11 13:02:42.160 DEBUG 1 --- [resume-thread-1] o.a.sshd.common.io.nio2.Nio2Session      : writeBuffer(Nio2Session[local=/<internal_ip>:44140, remote=/<ip>:<port>]) writing 1032 bytes
2024-10-11 13:02:42.160 DEBUG 1 --- [resume-thread-1] org.apache.sshd.client.SshClient         : setupDefaultSessionIdentities(ClientSessionImpl[user@/<ip>:<port>]) key identity provider override in session listener
2024-10-11 13:02:42.160 DEBUG 1 --- [ol-39-thread-39] o.a.s.c.future.DefaultConnectFuture      : Connected to /<ip>:<port> after 45881332 nanos
2024-10-11 13:02:42.161 DEBUG 1 --- [ol-39-thread-39] o.a.s.client.session.ClientSessionImpl   : addPublicKeyIdentity(ClientSessionImpl[user@/<ip>:<port>]) ssh-dss-SHA256:<key>
2024-10-11 13:02:42.221 DEBUG 1 --- []-nio2-thread-3] o.a.s.client.session.ClientSessionImpl   : doReadIdentification(ClientSessionImpl[user@/<ip>:<port>]) line='SSH-2.0-dropbear_2014.63'
2024-10-11 13:02:42.221 DEBUG 1 --- []-nio2-thread-3] o.a.s.client.session.ClientSessionImpl   : readIdentification(ClientSessionImpl[user@/<ip>:<port>]) Server version string: SSH-2.0-dropbear_2014.63
2024-10-11 13:02:42.221 DEBUG 1 --- []-nio2-thread-3] o.a.s.client.session.ClientSessionImpl   : doHandleMessage(ClientSessionImpl[user@/<ip>:<port>]) process #0 SSH_MSG_KEXINIT
2024-10-11 13:02:42.221 DEBUG 1 --- []-nio2-thread-3] o.a.s.client.session.ClientSessionImpl   : handleKexInit(ClientSessionImpl[user@/<ip>:<port>]) SSH_MSG_KEXINIT
2024-10-11 13:02:42.221 DEBUG 1 --- []-nio2-thread-3] o.a.s.client.session.ClientSessionImpl   : setNegotiationResult(ClientSessionImpl[user@/<ip>:<port>]) Kex: kex algorithms = diffie-hellman-group1-sha1
2024-10-11 13:02:42.221 DEBUG 1 --- []-nio2-thread-3] o.a.s.client.session.ClientSessionImpl   : setNegotiationResult(ClientSessionImpl[user@/<ip>:<port>]) Kex: server host key algorithms = ssh-dss
2024-10-11 13:02:42.221 DEBUG 1 --- []-nio2-thread-3] o.a.s.client.session.ClientSessionImpl   : setNegotiationResult(ClientSessionImpl[user@/<ip>:<port>]) Kex: encryption algorithms (client to server) = aes128-ctr
2024-10-11 13:02:42.221 DEBUG 1 --- []-nio2-thread-3] o.a.s.client.session.ClientSessionImpl   : setNegotiationResult(ClientSessionImpl[user@/<ip>:<port>]) Kex: encryption algorithms (server to client) = aes128-ctr
2024-10-11 13:02:42.221 DEBUG 1 --- []-nio2-thread-3] o.a.s.client.session.ClientSessionImpl   : setNegotiationResult(ClientSessionImpl[user@/<ip>:<port>]) Kex: mac algorithms (client to server) = hmac-sha1
2024-10-11 13:02:42.221 DEBUG 1 --- []-nio2-thread-3] o.a.s.client.session.ClientSessionImpl   : setNegotiationResult(ClientSessionImpl[user@/<ip>:<port>]) Kex: mac algorithms (server to client) = hmac-sha1
2024-10-11 13:02:42.221 DEBUG 1 --- []-nio2-thread-3] o.a.s.client.session.ClientSessionImpl   : setNegotiationResult(ClientSessionImpl[user@/<ip>:<port>]) Kex: compression algorithms (client to server) = none
2024-10-11 13:02:42.221 DEBUG 1 --- []-nio2-thread-3] o.a.s.client.session.ClientSessionImpl   : setNegotiationResult(ClientSessionImpl[user@/<ip>:<port>]) Kex: compression algorithms (server to client) = none
2024-10-11 13:02:42.224 DEBUG 1 --- []-nio2-thread-3] org.apache.sshd.client.kex.DHGClient     : init(DHGClient[diffie-hellman-group1-sha1])[ClientSessionImpl[user@/<ip>:<port>]] Send SSH_MSG_KEXDH_INIT
2024-10-11 13:02:42.224 DEBUG 1 --- []-nio2-thread-3] o.a.s.client.session.ClientSessionImpl   : encode(ClientSessionImpl[user@/<ip>:<port>]) packet #1 sending command=30[30] len=133
2024-10-11 13:02:42.224 DEBUG 1 --- []-nio2-thread-3] o.a.sshd.common.io.nio2.Nio2Session      : writeBuffer(Nio2Session[local=/<internal_ip>:44140, remote=/<ip>:<port>]) writing 152 bytes
2024-10-11 13:02:45.858 DEBUG 1 --- []-nio2-thread-4] o.a.sshd.common.io.nio2.Nio2Session      : handleReadCycleCompletion(Nio2Session[local=/<internal_ip>:44140, remote=/<ip>:<port>]) Socket has been disconnected (result=-1), closing IoSession now
2024-10-11 13:02:45.858 DEBUG 1 --- []-nio2-thread-4] o.a.sshd.common.io.nio2.Nio2Session      : close(Nio2Session[local=/<internal_ip>:44140, remote=/<ip>:<port>]) Closing immediately
2024-10-11 13:02:45.858 DEBUG 1 --- []-nio2-thread-4] o.a.sshd.common.io.nio2.Nio2Session      : doCloseImmediately(Nio2Session[local=/<internal_ip>:44140, remote=/<ip>:<port>]) closing socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/<internal_ip>:44140 remote=/<ip>:<port>]
2024-10-11 13:02:45.858 DEBUG 1 --- []-nio2-thread-4] o.a.sshd.common.io.nio2.Nio2Session      : doCloseImmediately(Nio2Session[local=/<internal_ip>:44140, remote=/<ip>:<port>]) socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[closed] closed
2024-10-11 13:02:45.858 DEBUG 1 --- []-nio2-thread-4] o.a.sshd.common.io.nio2.Nio2Connector    : unmapSession(id=107): Nio2Session[local=/<internal_ip>:44140, remote=/<ip>:<port>]
2024-10-11 13:02:45.858 DEBUG 1 --- []-nio2-thread-4] o.a.s.client.session.ClientSessionImpl   : close(ClientSessionImpl[user@/<ip>:<port>]) Closing immediately
2024-10-11 13:02:45.858 DEBUG 1 --- []-nio2-thread-4] o.a.s.client.session.ClientSessionImpl   : signalAuthFailure(ClientSessionImpl[user@/<ip>:<port>]) type=SshException, signalled=true, first=false: Session is being closed
2024-10-11 13:02:45.858 DEBUG 1 --- []-nio2-thread-4] o.a.s.c.s.h.SessionTimeoutListener       : sessionClosed(ClientSessionImpl[user@/<ip>:<port>]) un-tracked
2024-10-11 13:02:45.858 DEBUG 1 --- [ol-39-thread-39] org.apache.sshd.client.SshClient         : close(SshClient[1bacb075]) Closing immediately
2024-10-11 13:02:45.858 DEBUG 1 --- []-nio2-thread-4] o.a.s.c.session.ClientUserAuthService    : close(org.apache.sshd.client.session.ClientUserAuthService@1294c333) Closing immediately
2024-10-11 13:02:45.858 DEBUG 1 --- []-nio2-thread-4] o.a.s.c.session.ClientUserAuthService    : close(org.apache.sshd.client.session.ClientUserAuthService@1294c333)[Immediately] closed
2024-10-11 13:02:45.858 DEBUG 1 --- [ol-39-thread-39] o.a.sshd.common.io.nio2.Nio2Connector    : close(org.apache.sshd.common.io.nio2.Nio2Connector@77d9db15) Closing immediately
2024-10-11 13:02:45.858 DEBUG 1 --- [ol-39-thread-39] o.a.sshd.common.io.nio2.Nio2Connector    : close(org.apache.sshd.common.io.nio2.Nio2Connector@77d9db15)[Immediately] closed
2024-10-11 13:02:45.858 DEBUG 1 --- []-nio2-thread-4] o.a.s.c.session.ClientConnectionService  : close(ClientConnectionService[ClientSessionImpl[user@/<ip>:<port>]]) Closing immediately
2024-10-11 13:02:45.858 DEBUG 1 --- [ol-39-thread-39] o.a.s.common.io.nio2.Nio2ServiceFactory  : close(org.apache.sshd.common.io.nio2.Nio2ServiceFactory@988f283) Closing immediately
2024-10-11 13:02:45.858 DEBUG 1 --- []-nio2-thread-4] o.a.s.c.session.ClientConnectionService  : stopHeartBeat(ClientSessionImpl[user@/<ip>:<port>]) no heartbeat to stop
2024-10-11 13:02:45.858 DEBUG 1 --- [ol-39-thread-39] o.a.s.common.io.nio2.Nio2ServiceFactory  : Shutdown group
2024-10-11 13:02:45.858 DEBUG 1 --- []-nio2-thread-4] o.a.s.c.session.ClientConnectionService  : close(ClientConnectionService[ClientSessionImpl[user@/<ip>:<port>]])[Immediately] closed
2024-10-11 13:02:45.859 DEBUG 1 --- []-nio2-thread-4] o.a.sshd.common.io.nio2.Nio2Session      : close(Nio2Session[local=/<internal_ip>:44140, remote=/<ip>:<port>])[Immediately] state already Closed
2024-10-11 13:02:45.859 DEBUG 1 --- []-nio2-thread-4] o.a.s.c.u.closeable.SequentialCloseable  : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@1c532f11) signal close complete immediately=true
2024-10-11 13:02:45.859 DEBUG 1 --- []-nio2-thread-4] o.a.s.client.session.ClientSessionImpl   : close(ClientSessionImpl[user@/<ip>:<port>])[Immediately] closed
2024-10-11 13:02:45.859 DEBUG 1 --- []-nio2-thread-4] o.a.sshd.common.io.nio2.Nio2Session      : close(Nio2Session[local=/<internal_ip>:44140, remote=/<ip>:<port>])[Immediately] closed
2024-10-11 13:02:45.859 DEBUG 1 --- [ol-39-thread-39] o.a.s.common.io.nio2.Nio2ServiceFactory  : Group successfully shut down
2024-10-11 13:02:45.859 DEBUG 1 --- [ol-39-thread-39] o.a.s.common.io.nio2.Nio2ServiceFactory  : Shutdown executor
2024-10-11 13:02:45.859 DEBUG 1 --- [ol-39-thread-39] o.a.s.common.io.nio2.Nio2ServiceFactory  : Shutdown complete
2024-10-11 13:02:45.859 DEBUG 1 --- [ol-39-thread-39] o.a.s.common.io.nio2.Nio2ServiceFactory  : close(org.apache.sshd.common.io.nio2.Nio2ServiceFactory@988f283)[Immediately] closed
2024-10-11 13:02:45.859 DEBUG 1 --- [ol-39-thread-39] o.a.s.c.u.closeable.SequentialCloseable  : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@42f6f160) signal close complete immediately=true
2024-10-11 13:02:45.859 DEBUG 1 --- [ol-39-thread-39] org.apache.sshd.client.SshClient         : close(SshClient[1bacb075])[Immediately] closed

org.apache.sshd.common.SshException: Session is being closed
	at org.apache.sshd.common.future.AbstractSshFuture.verifyResult(AbstractSshFuture.java:141) ~[sshd-common-2.10.0.jar:2.10.0]
	at org.apache.sshd.client.future.DefaultAuthFuture.verify(DefaultAuthFuture.java:56) ~[sshd-core-2.10.0.jar:2.10.0]
	at org.apache.sshd.client.future.DefaultAuthFuture.verify(DefaultAuthFuture.java:35) ~[sshd-core-2.10.0.jar:2.10.0]

Other information

No response
@tomaswolf
Copy link
Member

The log shows you're using 2.10.0, not 2.14.0, and it only shows that the connection to this 10-years old dropbear is closed after the client has sent the KEX_INIT message. It gives no hint why that would have happened, so I assume the dropbear server is closing it. No idea why it would do so.

Things you can try:

@tomaswolf
Copy link
Member

As an aside: 1096041266 is 0x41544332, which would be "ATC2" in ASCII. If these characters have any possible meaning with that device, then perhaps the server is producing some text output when it should not? (Perhaps a bit far-fetched, but one never knows...)

@yashasvirajpant
Copy link
Author

yashasvirajpant commented Oct 11, 2024 •
edited
Loading

The log shows you're using 2.10.0, not 2.14.0, and it only shows that the connection to this 10-years old dropbear is closed after the client has sent the KEX_INIT message. It gives no hint why that would have happened, so I assume the dropbear server is closing it. No idea why it would do so.

Things you can try:

@tomaswolf I edited the version, my mistake. I also tried with 2.14.0 though and same issue. Also, this ssh is using diffie-hellman-group1-sha1 key exchange algorithm. So, I have added line to support this:

      sshClient.setKeyExchangeFactories(
          NamedFactory.setUpTransformedFactories(
              false, BuiltinDHFactories.VALUES, ClientBuilder.DH2KEX));

Do you think it is sufficient?

@tomaswolf
Copy link
Member

Do you think it is sufficient?

Don't know. The log shows it's being used.

@yashasvirajpant
Copy link
Author

@tomaswolf another similar but a bit different log I am getting is:

2024-10-11 13:11:03.604 DEBUG 1 --- [ool-39-thread-7] c.c.h.DefaultConfigFileHostEntryResolver : resolveEffectiveHost(user@<ip>:<port>/null) => null
2024-10-11 13:11:03.604 DEBUG 1 --- [ool-39-thread-7] org.apache.sshd.client.SshClient         : connect(user@<ip>:<port>) no overrides
2024-10-11 13:11:03.604 DEBUG 1 --- [ool-39-thread-7] o.a.sshd.common.io.nio2.Nio2Connector    : Connecting to /<ip>:<port>
2024-10-11 13:11:03.604 DEBUG 1 --- [ool-39-thread-7] o.a.sshd.common.io.nio2.Nio2Connector    : setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2024-10-11 13:11:03.605 DEBUG 1 --- [resume-thread-1] o.a.sshd.common.io.nio2.Nio2Connector    : connect(/<ip>:<port>): waiting for connection (timeout=60000ms)
2024-10-11 13:11:03.647 DEBUG 1 --- [resume-thread-1] o.a.sshd.common.io.nio2.Nio2Session      : Creating IoSession on /<local_ip>:<local_port> from /<ip>:<port> via null
2024-10-11 13:11:03.647 DEBUG 1 --- [resume-thread-1] o.a.s.client.session.ClientSessionImpl   : Client session created: Nio2Session[local=/<local_ip>:<local_port>, remote=/<ip>:<port>]
2024-10-11 13:11:03.647 DEBUG 1 --- [resume-thread-1] o.a.s.c.session.ClientUserAuthService    : ClientUserAuthService(ClientSessionImpl[null@/<ip>:<port>]) client methods: [publickey, keyboard-interactive, password]
2024-10-11 13:11:03.647 DEBUG 1 --- [resume-thread-1] o.a.s.c.s.h.SessionTimeoutListener       : sessionCreated(ClientSessionImpl[null@/<ip>:<port>]) tracking
2024-10-11 13:11:03.647 DEBUG 1 --- [resume-thread-1] o.a.s.client.session.ClientSessionImpl   : initializeProxyConnector(ClientSessionImpl[null@/<ip>:<port>]) no proxy to initialize
2024-10-11 13:11:03.647 DEBUG 1 --- [resume-thread-1] o.a.s.client.session.ClientSessionImpl   : sendIdentification(ClientSessionImpl[null@/<ip>:<port>]): SSH-2.0-APACHE-SSHD-2.10.0
2024-10-11 13:11:03.647 DEBUG 1 --- [resume-thread-1] o.a.sshd.common.io.nio2.Nio2Session      : writeBuffer(Nio2Session[local=/<local_ip>:<local_port>, remote=/<ip>:<port>]) writing 28 bytes
2024-10-11 13:11:03.648 DEBUG 1 --- [resume-thread-1] o.a.s.client.session.ClientSessionImpl   : sendKexInit(ClientSessionImpl[null@/<ip>:<port>]) Send SSH_MSG_KEXINIT
2024-10-11 13:11:03.648 DEBUG 1 --- [resume-thread-1] o.a.s.client.session.ClientSessionImpl   : encode(ClientSessionImpl[null@/<ip>:<port>]) packet #0 sending command=20[SSH_MSG_KEXINIT] len=1012
2024-10-11 13:11:03.648 DEBUG 1 --- [resume-thread-1] o.a.sshd.common.io.nio2.Nio2Session      : writeBuffer(Nio2Session[local=/<local_ip>:<local_port>, remote=/<ip>:<port>]) writing 1032 bytes
2024-10-11 13:11:03.648 DEBUG 1 --- [resume-thread-1] org.apache.sshd.client.SshClient         : setupDefaultSessionIdentities(ClientSessionImpl[user@/<ip>:<port>]) key identity provider override in session listener
2024-10-11 13:11:03.648 DEBUG 1 --- [ool-39-thread-7] o.a.s.c.future.DefaultConnectFuture      : Connected to /<ip>:<port> after 43569127 nanos
2024-10-11 13:11:03.649 DEBUG 1 --- [ool-39-thread-7] o.a.s.client.session.ClientSessionImpl   : addPublicKeyIdentity(ClientSessionImpl[user@/<ip>:<port>]) ssh-dss-SHA256:<key>
2024-10-11 13:11:03.733 DEBUG 1 --- []-nio2-thread-4] o.a.s.client.session.ClientSessionImpl   : doReadIdentification(ClientSessionImpl[user@/<ip>:<port>]) line='������������'
2024-10-11 13:11:03.733 DEBUG 1 --- []-nio2-thread-4] o.a.s.client.session.ClientSessionImpl   : doReadIdentification(ClientSessionImpl[user@/<ip>:<port>]) line='SSH-2.0-APACHE-SSHD-2.10.0'
2024-10-11 13:11:03.733 DEBUG 1 --- []-nio2-thread-4] o.a.s.client.session.ClientSessionImpl   : readIdentification(ClientSessionImpl[user@/<ip>:<port>]) Server version string: SSH-2.0-APACHE-SSHD-2.10.0
2024-10-11 13:11:03.733  WARN 1 --- []-nio2-thread-4] o.a.s.client.session.ClientSessionImpl   : decode(ClientSessionImpl[user@/<ip>:<port>]) Error decoding packet(invalid length): 1096041266
2024-10-11 13:11:03.733 DEBUG 1 --- []-nio2-thread-4] o.a.sshd.common.io.nio2.Nio2Session      : handleReadCycleFailure(Nio2Session[local=/<local_ip>:<local_port>, remote=/<ip>:<port>]) SshException after 37972991 nanos at read cycle=2: Invalid packet length: 1096041266
2024-10-11 13:11:03.733 DEBUG 1 --- []-nio2-thread-4] o.a.sshd.common.io.nio2.Nio2Session      : exceptionCaught(Nio2Session[local=/<local_ip>:<local_port>, remote=/<ip>:<port>]) caught SshException[Invalid packet length: 1096041266] - calling handler
2024-10-11 13:11:03.733 DEBUG 1 --- []-nio2-thread-4] o.a.s.client.session.ClientSessionImpl   : signalAuthFailure(ClientSessionImpl[user@/<ip>:<port>]) type=SshException, signalled=true, first=false: Invalid packet length: 1096041266
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.s.client.session.ClientSessionImpl   : close(ClientSessionImpl[user@/<ip>:<port>]) Closing immediately
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.s.client.session.ClientSessionImpl   : signalAuthFailure(ClientSessionImpl[user@/<ip>:<port>]) type=SshException, signalled=false, first=false: Session is being closed
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.s.c.s.h.SessionTimeoutListener       : sessionClosed(ClientSessionImpl[user@/<ip>:<port>]) un-tracked
2024-10-11 13:11:03.733  WARN 1 --- []-nio2-thread-4] o.a.s.client.session.ClientSessionImpl   : exceptionCaught(ClientSessionImpl[user@/<ip>:<port>])[state=Opened] SshException: Invalid packet length: 1096041266

org.apache.sshd.common.SshException: Invalid packet length: 1096041266
	at org.apache.sshd.common.session.helpers.AbstractSession.decode(AbstractSession.java:1568) ~[sshd-core-2.10.0.jar:2.10.0]
	at org.apache.sshd.common.session.helpers.AbstractSession.messageReceived(AbstractSession.java:483) ~[sshd-core-2.10.0.jar:2.10.0]
	at org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.messageReceived(AbstractSessionIoHandler.java:64) ~[sshd-core-2.10.0.jar:2.10.0]
	at org.apache.sshd.common.io.nio2.Nio2Session.handleReadCycleCompletion(Nio2Session.java:407) ~[sshd-core-2.10.0.jar:2.10.0]
	at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:380) ~[sshd-core-2.10.0.jar:2.10.0]
	at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:375) ~[sshd-core-2.10.0.jar:2.10.0]
	at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$completed$0(Nio2CompletionHandler.java:38) ~[sshd-core-2.10.0.jar:2.10.0]
	at java.base/java.security.AccessController.doPrivileged(AccessController.java:318) ~[na:na]
	at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37) ~[sshd-core-2.10.0.jar:2.10.0]
	at java.base/sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:129) ~[na:na]
	at java.base/sun.nio.ch.Invoker$2.run(Invoker.java:221) ~[na:na]
	at java.base/sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:113) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:840) ~[na:na]

2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.s.c.session.ClientUserAuthService    : close(org.apache.sshd.client.session.ClientUserAuthService@5cf67d50) Closing immediately
2024-10-11 13:11:03.733 DEBUG 1 --- []-nio2-thread-4] o.a.s.c.s.h.SessionTimeoutListener       : sessionException(ClientSessionImpl[user@/<ip>:<port>]) SshException: Invalid packet length: 1096041266
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.s.c.session.ClientUserAuthService    : close(org.apache.sshd.client.session.ClientUserAuthService@5cf67d50)[Immediately] closed
2024-10-11 13:11:03.733  INFO 1 --- []-nio2-thread-4] o.a.s.client.session.ClientSessionImpl   : Disconnecting(ClientSessionImpl[user@/<ip>:<port>]): SSH2_DISCONNECT_PROTOCOL_ERROR - Invalid packet length: 1096041266
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.s.c.session.ClientConnectionService  : close(ClientConnectionService[ClientSessionImpl[user@/<ip>:<port>]]) Closing immediately
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.s.c.session.ClientConnectionService  : stopHeartBeat(ClientSessionImpl[user@/<ip>:<port>]) no heartbeat to stop
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.s.c.session.ClientConnectionService  : close(ClientConnectionService[ClientSessionImpl[user@/<ip>:<port>]])[Immediately] closed
2024-10-11 13:11:03.733 DEBUG 1 --- []-nio2-thread-4] o.a.s.client.session.ClientSessionImpl   : encode(ClientSessionImpl[user@/<ip>:<port>]) packet #1 sending command=1[SSH_MSG_DISCONNECT] len=46
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.sshd.common.io.nio2.Nio2Session      : close(Nio2Session[local=/<local_ip>:<local_port>, remote=/<ip>:<port>]) Closing immediately
2024-10-11 13:11:03.733 DEBUG 1 --- []-nio2-thread-4] o.a.sshd.common.io.nio2.Nio2Session      : writeBuffer(Nio2Session[local=/<local_ip>:<local_port>, remote=/<ip>:<port>]) writing 64 bytes
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.sshd.common.io.nio2.Nio2Session      : doCloseImmediately(Nio2Session[local=/<local_ip>:<local_port>, remote=/<ip>:<port>]) closing socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/<local_ip>:<local_port> remote=/<ip>:<port>]
2024-10-11 13:11:03.733 DEBUG 1 --- []-nio2-thread-4] o.a.sshd.common.io.nio2.Nio2Session      : close(Nio2Session[local=/<local_ip>:<local_port>, remote=/<ip>:<port>])[Immediately] state already Immediate
2024-10-11 13:11:03.733 DEBUG 1 --- []-nio2-thread-4] o.a.s.client.session.ClientSessionImpl   : disconnect(ClientSessionImpl[user@/<ip>:<port>]) operation failed (ClosedChannelException) for reason=SSH2_DISCONNECT_PROTOCOL_ERROR [Invalid packet length: 1096041266]: null
2024-10-11 13:11:03.733 DEBUG 1 --- []-nio2-thread-4] o.a.s.client.session.ClientSessionImpl   : close(ClientSessionImpl[user@/<ip>:<port>])[Immediately] state already Immediate
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.sshd.common.io.nio2.Nio2Session      : doCloseImmediately(Nio2Session[local=/<local_ip>:<local_port>, remote=/<ip>:<port>]) socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[closed] closed
2024-10-11 13:11:03.733 DEBUG 1 --- []-nio2-thread-4] o.a.sshd.common.io.nio2.Nio2Session      : close(Nio2Session[local=/<local_ip>:<local_port>, remote=/<ip>:<port>])[Immediately] state already Immediate
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.sshd.common.io.nio2.Nio2Connector    : unmapSession(id=114): Nio2Session[local=/<local_ip>:<local_port>, remote=/<ip>:<port>]
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.s.client.session.ClientSessionImpl   : close(ClientSessionImpl[user@/<ip>:<port>])[Immediately] state already Immediate
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.sshd.common.io.nio2.Nio2Session      : close(Nio2Session[local=/<local_ip>:<local_port>, remote=/<ip>:<port>])[Immediately] closed
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.s.c.u.closeable.SequentialCloseable  : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@196a0b00) signal close complete immediately=true
2024-10-11 13:11:03.733 DEBUG 1 --- [ool-39-thread-7] o.a.s.client.session.ClientSessionImpl   : close(ClientSessionImpl[user@/<ip>:<port>])[Immediately] closed
2024-10-11 13:11:03.734 DEBUG 1 --- [ool-39-thread-7] org.apache.sshd.client.SshClient         : close(SshClient[16fa647a]) Closing immediately
2024-10-11 13:11:03.734 DEBUG 1 --- [ool-39-thread-7] o.a.sshd.common.io.nio2.Nio2Connector    : close(org.apache.sshd.common.io.nio2.Nio2Connector@3f27c75c) Closing immediately
2024-10-11 13:11:03.734 DEBUG 1 --- [ool-39-thread-7] o.a.sshd.common.io.nio2.Nio2Connector    : close(org.apache.sshd.common.io.nio2.Nio2Connector@3f27c75c)[Immediately] closed
2024-10-11 13:11:03.734 DEBUG 1 --- [ool-39-thread-7] o.a.s.common.io.nio2.Nio2ServiceFactory  : close(org.apache.sshd.common.io.nio2.Nio2ServiceFactory@5f09d9b2) Closing immediately
2024-10-11 13:11:03.734 DEBUG 1 --- [ool-39-thread-7] o.a.s.common.io.nio2.Nio2ServiceFactory  : Shutdown group
2024-10-11 13:11:03.734 DEBUG 1 --- [ool-39-thread-7] o.a.s.common.io.nio2.Nio2ServiceFactory  : Group successfully shut down
2024-10-11 13:11:03.734 DEBUG 1 --- [ool-39-thread-7] o.a.s.common.io.nio2.Nio2ServiceFactory  : Shutdown executor
2024-10-11 13:11:03.734 DEBUG 1 --- [ool-39-thread-7] o.a.s.common.io.nio2.Nio2ServiceFactory  : Shutdown complete
2024-10-11 13:11:03.734 DEBUG 1 --- [ool-39-thread-7] o.a.s.common.io.nio2.Nio2ServiceFactory  : close(org.apache.sshd.common.io.nio2.Nio2ServiceFactory@5f09d9b2)[Immediately] closed
2024-10-11 13:11:03.734 DEBUG 1 --- [ool-39-thread-7] o.a.s.c.u.closeable.SequentialCloseable  : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@307a33fe) signal close complete immediately=true
2024-10-11 13:11:03.734 DEBUG 1 --- [ool-39-thread-7] org.apache.sshd.client.SshClient         : close(SshClient[16fa647a])[Immediately] closed

org.apache.sshd.common.SshException: Invalid packet length: 1096041266
	at org.apache.sshd.common.future.AbstractSshFuture.verifyResult(AbstractSshFuture.java:141) ~[sshd-common-2.10.0.jar:2.10.0]
	at org.apache.sshd.client.future.DefaultAuthFuture.verify(DefaultAuthFuture.java:56) ~[sshd-core-2.10.0.jar:2.10.0]
	at org.apache.sshd.client.future.DefaultAuthFuture.verify(DefaultAuthFuture.java:35) ~[sshd-core-2.10.0.jar:2.10.0]

@tomaswolf
Copy link
Member

I cannot help you. This log shows

doReadIdentification(ClientSessionImpl[user@/<ip>:<port>]) line='������������'
doReadIdentification(ClientSessionImpl[user@/<ip>:<port>]) line='SSH-2.0-APACHE-SSHD-2.10.0'
readIdentification(ClientSessionImpl[user@/<ip>:<port>]) Server version string: SSH-2.0-APACHE-SSHD-2.10.0

so evidently you're not connecting to dropbear anymore, and evidently something goes wrong very early.

You will have to debug this problem on your own.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@tomaswolf @yashasvirajpant