Open yashasvirajpant opened 1 week ago
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:
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...)
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?
Do you think it is sufficient?
Don't know. The log shows it's being used.
@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]
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.
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:
or sometime:
Here is the code implementation:
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
Other information
No response