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

TimeOut connecting using 2.14.0 #642

Open
rgarciapariente opened this issue Dec 9, 2024 · 3 comments
Open

TimeOut connecting using 2.14.0 #642

rgarciapariente opened this issue Dec 9, 2024 · 3 comments

Comments

@rgarciapariente
Copy link

rgarciapariente commented Dec 9, 2024 •
edited
Loading

Version

2.14.0

Bug description

We upgrade from 2.13.2 to 2.14.0, after that we see timeout in the connections. If we downgrade to 2.13.2 the issue dissapear

Actual behavior

Main log

2024-12-09T10:48:31.3468798Z 09 Dec 2024 10:48:31,295 [main] DEBUG SecurityUtils [] - register(BC) not registered - enabled=true, supported=false
2024-12-09T10:48:31.4238310Z 09 Dec 2024 10:48:31,349 [main] DEBUG SecurityUtils [] - register(EdDSA) not registered - enabled=true, supported=false
2024-12-09T10:48:31.9492016Z 09 Dec 2024 10:48:31,933 [main] INFO  DefaultIoServiceFactoryFactory [] - No detected/configured IoServiceFactoryFactory; using Nio2ServiceFactoryFactory
2024-12-09T10:48:32.0350592Z 09 Dec 2024 10:48:31,992 [main] DEBUG SshServer [] - start() - resolve bind host=localhost
2024-12-09T10:48:32.0353032Z 09 Dec 2024 10:48:31,993 [main] DEBUG Nio2Acceptor [] - bind(localhost/127.0.0.1:29559) binding to address
2024-12-09T10:48:32.0358267Z 09 Dec 2024 10:48:32,001 [main] DEBUG Nio2Acceptor [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2024-12-09T10:48:32.0359796Z 09 Dec 2024 10:48:32,002 [main] DEBUG Nio2Acceptor [] - bind(localhost/127.0.0.1:29559) bound to /127.0.0.1:29559
2024-12-09T10:48:32.0361626Z 09 Dec 2024 10:48:32,007 [main] DEBUG Nio2Acceptor [] - bind(localhost/[0:0:0:0:0:0:0:1]:29559) binding to address
2024-12-09T10:48:32.0362982Z 09 Dec 2024 10:48:32,008 [main] DEBUG Nio2Acceptor [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2024-12-09T10:48:32.0364768Z 09 Dec 2024 10:48:32,008 [main] DEBUG Nio2Acceptor [] - bind(localhost/[0:0:0:0:0:0:0:1]:29559) bound to /[0:0:0:0:0:0:0:1]:29559
2024-12-09T10:48:32.1452662Z 09 Dec 2024 10:48:32,100 [main] DEBUG Nio2Connector [] - Connecting to localhost/127.0.0.1:29559
2024-12-09T10:48:32.1453857Z 09 Dec 2024 10:48:32,105 [main] DEBUG Nio2Connector [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2024-12-09T10:48:44.8356913Z 09 Dec 2024 10:48:44,803 [main] DEBUG DefaultConnectFuture [] - Connected to localhost/127.0.0.1:29559 after 12692614400 nanos
2024-12-09T10:49:14.9138726Z 09 Dec 2024 10:49:14,871 [main] DEBUG Nio2Connector [] - Connecting to localhost/127.0.0.1:29559
2024-12-09T10:49:14.9710156Z 09 Dec 2024 10:49:14,872 [main] DEBUG Nio2Connector [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2024-12-09T10:49:44.9223968Z 09 Dec 2024 10:49:44,889 [main] DEBUG Nio2Connector [] - Connecting to localhost/127.0.0.1:29559
2024-12-09T10:49:44.9225278Z 09 Dec 2024 10:49:44,889 [main] DEBUG Nio2Connector [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2024-12-09T10:50:14.9208085Z 09 Dec 2024 10:50:14,903 [main] DEBUG Nio2Connector [] - Connecting to localhost/127.0.0.1:29559
2024-12-09T10:50:14.9209364Z 09 Dec 2024 10:50:14,904 [main] DEBUG Nio2Connector [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2024-12-09T10:50:45.0010565Z 09 Dec 2024 10:50:44,909 [main] DEBUG Nio2Connector [] - Connecting to localhost/127.0.0.1:29559
2024-12-09T10:50:45.0011924Z 09 Dec 2024 10:50:44,910 [main] DEBUG Nio2Connector [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2024-12-09T10:51:14.9986745Z 09 Dec 2024 10:51:14,924 [main] DEBUG Nio2Connector [] - Connecting to localhost/127.0.0.1:29559
2024-12-09T10:51:15.0086031Z 09 Dec 2024 10:51:14,925 [main] DEBUG Nio2Connector [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]

ClientLog

2024-12-09T10:48:32.1458749Z 09 Dec 2024 10:48:32,111 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG Nio2Connector [] - connect(localhost/127.0.0.1:29559): waiting for connection (timeout=60000ms)
2024-12-09T10:48:32.2489452Z 09 Dec 2024 10:48:32,116 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG Nio2Session [] - Creating IoSession on /127.0.0.1:48616 from localhost/127.0.0.1:29559 via null
2024-12-09T10:48:32.2491925Z 09 Dec 2024 10:48:32,189 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - Client session created: Nio2Session[local=/127.0.0.1:48616, remote=localhost/127.0.0.1:29559]
2024-12-09T10:48:32.2664559Z 09 Dec 2024 10:48:32,196 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG ClientUserAuthService [] - ClientUserAuthService(ClientSessionImpl[null@localhost/127.0.0.1:29559]) client methods: [publickey, keyboard-interactive, password]
2024-12-09T10:48:32.2691599Z 09 Dec 2024 10:48:32,214 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG SessionTimeoutListener [] - sessionCreated(ClientSessionImpl[null@localhost/127.0.0.1:29559]) tracking
2024-12-09T10:48:32.2844742Z 09 Dec 2024 10:48:32,215 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - initializeProxyConnector(ClientSessionImpl[null@localhost/127.0.0.1:29559]) no proxy to initialize
2024-12-09T10:48:32.3044216Z 09 Dec 2024 10:48:32,216 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - sendIdentification(ClientSessionImpl[null@localhost/127.0.0.1:29559]): SSH-2.0-APACHE-SSHD-2.14.0
2024-12-09T10:48:32.3048538Z 09 Dec 2024 10:48:32,216 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:48616, remote=localhost/127.0.0.1:29559]) writing 28 bytes
2024-12-09T10:48:32.3052010Z 09 Dec 2024 10:48:32,221 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - sendKexInit(ClientSessionImpl[null@localhost/127.0.0.1:29559]) Send SSH_MSG_KEXINIT
2024-12-09T10:48:32.3613887Z 09 Dec 2024 10:48:32,298 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - encode(ClientSessionImpl[null@localhost/127.0.0.1:29559]) packet #0 sending command=20[SSH_MSG_KEXINIT] len=1263
2024-12-09T10:48:44.8351518Z 09 Dec 2024 10:48:44,787 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:48616, remote=localhost/127.0.0.1:29559]) writing 1280 bytes
2024-12-09T10:48:44.8354389Z 09 Dec 2024 10:48:44,798 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG SshClient [] - setupDefaultSessionIdentities(ClientSessionImpl[test@localhost/127.0.0.1:29559]) key identity provider override in session listener
2024-12-09T10:48:44.8358970Z 09 Dec 2024 10:48:44,806 [sshd-SshClient[7b332b23]-nio2-thread-3] DEBUG ClientSessionImpl [] - doReadIdentification(ClientSessionImpl[test@localhost/127.0.0.1:29559]) line='SSH-2.0-APACHE-SSHD-2.14.0'
2024-12-09T10:48:44.8362241Z 09 Dec 2024 10:48:44,806 [sshd-SshClient[7b332b23]-nio2-thread-3] DEBUG ClientSessionImpl [] - readIdentification(ClientSessionImpl[test@localhost/127.0.0.1:29559]) Server version string: SSH-2.0-APACHE-SSHD-2.14.0
2024-12-09T10:49:14.9749744Z 09 Dec 2024 10:49:14,874 [sshd-SshClient[7b332b23]-nio2-resume-thread-2] DEBUG Nio2Connector [] - connect(localhost/127.0.0.1:29559): waiting for connection (timeout=60000ms)
2024-12-09T10:49:14.9774080Z 09 Dec 2024 10:49:14,877 [sshd-SshClient[7b332b23]-nio2-resume-thread-2] DEBUG Nio2Session [] - Creating IoSession on /127.0.0.1:47188 from localhost/127.0.0.1:29559 via null
2024-12-09T10:49:44.9231375Z 09 Dec 2024 10:49:44,903 [sshd-SshClient[7b332b23]-nio2-resume-thread-3] DEBUG Nio2Connector [] - connect(localhost/127.0.0.1:29559): waiting for connection (timeout=60000ms)
2024-12-09T10:49:44.9233266Z 09 Dec 2024 10:49:44,903 [sshd-SshClient[7b332b23]-nio2-resume-thread-3] DEBUG Nio2Session [] - Creating IoSession on /127.0.0.1:33510 from localhost/127.0.0.1:29559 via null
2024-12-09T10:49:50.2039132Z 09 Dec 2024 10:49:50,150 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG ClientSessionImpl [] - doHandleMessage(ClientSessionImpl[test@localhost/127.0.0.1:29559]) process #0 SSH_MSG_KEXINIT
2024-12-09T10:49:50.2043346Z 09 Dec 2024 10:49:50,150 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG ClientSessionImpl [] - handleKexInit(ClientSessionImpl[test@localhost/127.0.0.1:29559]) SSH_MSG_KEXINIT
2024-12-09T10:49:50.2060365Z 09 Dec 2024 10:49:50,158 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG ClientSessionImpl [] - negotiate(ClientSessionImpl[test@localhost/127.0.0.1:29559]) strict KEX=true client=true server=true
2024-12-09T10:49:50.2094142Z 09 Dec 2024 10:49:50,174 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:29559]) Kex: kex algorithms = curve25519-sha256
2024-12-09T10:49:50.2097967Z 09 Dec 2024 10:49:50,175 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:29559]) Kex: server host key algorithms = ecdsa-sha2-nistp521
2024-12-09T10:49:50.2100881Z 09 Dec 2024 10:49:50,175 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:29559]) Kex: encryption algorithms (client to server) = [email protected]
2024-12-09T10:49:50.2103567Z 09 Dec 2024 10:49:50,175 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:29559]) Kex: encryption algorithms (server to client) = [email protected]
2024-12-09T10:49:50.2106588Z 09 Dec 2024 10:49:50,175 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:29559]) Kex: mac algorithms (client to server) = [email protected]
2024-12-09T10:49:50.2108962Z 09 Dec 2024 10:49:50,175 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:29559]) Kex: mac algorithms (server to client) = [email protected]
2024-12-09T10:49:50.2111109Z 09 Dec 2024 10:49:50,175 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:29559]) Kex: compression algorithms (client to server) = none
2024-12-09T10:49:50.2113120Z 09 Dec 2024 10:49:50,175 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:29559]) Kex: compression algorithms (server to client) = none
2024-12-09T10:49:50.2115545Z 09 Dec 2024 10:49:50,188 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG DHGClient [] - init(DHGClient[curve25519-sha256])[ClientSessionImpl[test@localhost/127.0.0.1:29559]] Send SSH_MSG_KEXDH_INIT
2024-12-09T10:49:50.2118281Z 09 Dec 2024 10:49:50,189 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG ClientSessionImpl [] - encode(ClientSessionImpl[test@localhost/127.0.0.1:29559]) packet #1 sending command=30[30] len=37
2024-12-09T10:50:14.9214371Z 09 Dec 2024 10:50:14,907 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG Nio2Connector [] - connect(localhost/127.0.0.1:29559): waiting for connection (timeout=60000ms)
2024-12-09T10:50:14.9215917Z 09 Dec 2024 10:50:14,908 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG Nio2Session [] - Creating IoSession on /127.0.0.1:40908 from localhost/127.0.0.1:29559 via null
2024-12-09T10:50:19.9584232Z 09 Dec 2024 10:50:19,876 [sshd-SshClient[7b332b23]-nio2-resume-thread-2] DEBUG ClientSessionImpl [] - Client session created: Nio2Session[local=/127.0.0.1:47188, remote=localhost/127.0.0.1:29559]
2024-12-09T10:50:19.9621500Z 09 Dec 2024 10:50:19,877 [sshd-SshClient[7b332b23]-nio2-resume-thread-2] DEBUG ClientUserAuthService [] - ClientUserAuthService(ClientSessionImpl[null@localhost/127.0.0.1:29559]) client methods: [publickey, keyboard-interactive, password]
2024-12-09T10:50:19.9830598Z 09 Dec 2024 10:50:19,892 [sshd-SshClient[7b332b23]-nio2-resume-thread-2] DEBUG SessionTimeoutListener [] - sessionCreated(ClientSessionImpl[null@localhost/127.0.0.1:29559]) tracking
2024-12-09T10:50:19.9940390Z 09 Dec 2024 10:50:19,892 [sshd-SshClient[7b332b23]-nio2-resume-thread-2] DEBUG ClientSessionImpl [] - initializeProxyConnector(ClientSessionImpl[null@localhost/127.0.0.1:29559]) no proxy to initialize
2024-12-09T10:50:20.0017664Z 09 Dec 2024 10:50:19,893 [sshd-SshClient[7b332b23]-nio2-resume-thread-2] DEBUG ClientSessionImpl [] - sendIdentification(ClientSessionImpl[null@localhost/127.0.0.1:29559]): SSH-2.0-APACHE-SSHD-2.14.0
2024-12-09T10:50:20.0110953Z 09 Dec 2024 10:50:19,893 [sshd-SshClient[7b332b23]-nio2-resume-thread-2] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:47188, remote=localhost/127.0.0.1:29559]) writing 28 bytes
2024-12-09T10:50:20.0113180Z 09 Dec 2024 10:50:19,894 [sshd-SshClient[7b332b23]-nio2-resume-thread-2] DEBUG ClientSessionImpl [] - sendKexInit(ClientSessionImpl[null@localhost/127.0.0.1:29559]) Send SSH_MSG_KEXINIT
2024-12-09T10:50:33.1346026Z 09 Dec 2024 10:50:33,086 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientSessionImpl [] - checkForTimeouts(ClientSessionImpl[test@localhost/127.0.0.1:29559]) disconnect - reason=TimeoutIndicator[status=AuthTimeout, threshold=120000, expired=120889]
2024-12-09T10:50:33.1348569Z 09 Dec 2024 10:50:33,086 [sshd-SshClient[7b332b23]-timer-thread-1] INFO  ClientSessionImpl [] - Disconnecting(ClientSessionImpl[test@localhost/127.0.0.1:29559]): SSH2_DISCONNECT_PROTOCOL_ERROR - Detected AuthTimeout after 120889/120000 ms.
2024-12-09T10:50:34.2312785Z 09 Dec 2024 10:50:34,197 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - Client session created: Nio2Session[local=/127.0.0.1:40908, remote=localhost/127.0.0.1:29559]
2024-12-09T10:50:34.2315049Z 09 Dec 2024 10:50:34,198 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG ClientUserAuthService [] - ClientUserAuthService(ClientSessionImpl[null@localhost/127.0.0.1:29559]) client methods: [publickey, keyboard-interactive, password]
2024-12-09T10:50:34.2317055Z 09 Dec 2024 10:50:34,199 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG SessionTimeoutListener [] - sessionCreated(ClientSessionImpl[null@localhost/127.0.0.1:29559]) tracking
2024-12-09T10:50:34.2319052Z 09 Dec 2024 10:50:34,199 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - initializeProxyConnector(ClientSessionImpl[null@localhost/127.0.0.1:29559]) no proxy to initialize
2024-12-09T10:50:34.2320818Z 09 Dec 2024 10:50:34,199 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - sendIdentification(ClientSessionImpl[null@localhost/127.0.0.1:29559]): SSH-2.0-APACHE-SSHD-2.14.0
2024-12-09T10:50:34.2323173Z 09 Dec 2024 10:50:34,199 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:40908, remote=localhost/127.0.0.1:29559]) writing 28 bytes
2024-12-09T10:50:34.2325437Z 09 Dec 2024 10:50:34,200 [sshd-SshClient[7b332b23]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - sendKexInit(ClientSessionImpl[null@localhost/127.0.0.1:29559]) Send SSH_MSG_KEXINIT
2024-12-09T10:50:48.4249618Z 09 Dec 2024 10:50:48,375 [sshd-SshClient[7b332b23]-nio2-thread-1] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:48616, remote=localhost/127.0.0.1:29559]) writing 56 bytes
2024-12-09T10:50:48.4251752Z 09 Dec 2024 10:50:48,376 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientSessionImpl [] - encode(ClientSessionImpl[test@localhost/127.0.0.1:29559]) packet #2 sending command=1[SSH_MSG_DISCONNECT] len=45
2024-12-09T10:51:00.6521089Z 09 Dec 2024 10:51:00,559 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:48616, remote=localhost/127.0.0.1:29559]) writing 64 bytes
2024-12-09T10:51:00.6528496Z 09 Dec 2024 10:51:00,567 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientSessionImpl [] - disconnect(ClientSessionImpl[test@localhost/127.0.0.1:29559]) operation successfully completed for reason=SSH2_DISCONNECT_PROTOCOL_ERROR [Detected AuthTimeout after 120889/120000 ms.]
2024-12-09T10:51:00.6726638Z 09 Dec 2024 10:51:00,567 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientSessionImpl [] - close(ClientSessionImpl[test@localhost/127.0.0.1:29559]) Closing immediately
2024-12-09T10:51:00.7015972Z 09 Dec 2024 10:51:00,568 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientSessionImpl [] - signalAuthFailure(ClientSessionImpl[test@localhost/127.0.0.1:29559]) type=SshException, signalled=true, first=false: Session is being closed
2024-12-09T10:51:00.7065737Z 09 Dec 2024 10:51:00,569 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG SessionTimeoutListener [] - sessionClosed(ClientSessionImpl[test@localhost/127.0.0.1:29559]) un-tracked
2024-12-09T10:51:00.7473779Z 09 Dec 2024 10:51:00,639 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientUserAuthService [] - close(org.apache.sshd.client.session.ClientUserAuthService@7729b966) Closing immediately
2024-12-09T10:51:00.7489974Z 09 Dec 2024 10:51:00,639 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientUserAuthService [] - close(org.apache.sshd.client.session.ClientUserAuthService@7729b966)[Immediately] closed
2024-12-09T10:51:00.7492538Z 09 Dec 2024 10:51:00,640 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientConnectionService [] - close(ClientConnectionService[ClientSessionImpl[test@localhost/127.0.0.1:29559]]) Closing immediately
2024-12-09T10:51:00.7495076Z 09 Dec 2024 10:51:00,640 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientConnectionService [] - stopHeartBeat(ClientSessionImpl[test@localhost/127.0.0.1:29559]) no heartbeat to stop
2024-12-09T10:51:00.7497721Z 09 Dec 2024 10:51:00,641 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientConnectionService [] - close(ClientConnectionService[ClientSessionImpl[test@localhost/127.0.0.1:29559]])[Immediately] closed
2024-12-09T10:51:00.7500797Z 09 Dec 2024 10:51:00,642 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG Nio2Session [] - close(Nio2Session[local=/127.0.0.1:48616, remote=localhost/127.0.0.1:29559]) Closing immediately
2024-12-09T10:51:00.7503658Z 09 Dec 2024 10:51:00,643 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG Nio2Session [] - doCloseImmediately(Nio2Session[local=/127.0.0.1:48616, remote=localhost/127.0.0.1:29559]) closing socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/127.0.0.1:48616 remote=localhost/127.0.0.1:29559]
2024-12-09T10:51:00.7507314Z 09 Dec 2024 10:51:00,643 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG Nio2Session [] - doCloseImmediately(Nio2Session[local=/127.0.0.1:48616, remote=localhost/127.0.0.1:29559]) socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[closed] closed
2024-12-09T10:51:00.7510022Z 09 Dec 2024 10:51:00,644 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG Nio2Connector [] - unmapSession(id=102): Nio2Session[local=/127.0.0.1:48616, remote=localhost/127.0.0.1:29559]
2024-12-09T10:51:00.7512367Z 09 Dec 2024 10:51:00,644 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientSessionImpl [] - close(ClientSessionImpl[test@localhost/127.0.0.1:29559])[Immediately] state already Immediate
2024-12-09T10:51:00.7515355Z 09 Dec 2024 10:51:00,644 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG Nio2Session [] - close(Nio2Session[local=/127.0.0.1:48616, remote=localhost/127.0.0.1:29559])[Immediately] closed
2024-12-09T10:51:00.7517929Z 09 Dec 2024 10:51:00,644 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG SequentialCloseable [] - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@3622fb86) signal close complete immediately=true
2024-12-09T10:51:00.7520596Z 09 Dec 2024 10:51:00,645 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientSessionImpl [] - close(ClientSessionImpl[test@localhost/127.0.0.1:29559])[Immediately] closed
2024-12-09T10:51:00.7523569Z 09 Dec 2024 10:51:00,651 [sshd-SshClient[7b332b23]-nio2-thread-3] DEBUG Nio2Session [] - handleReadCycleFailure(Nio2Session[local=/127.0.0.1:48616, remote=localhost/127.0.0.1:29559]) AsynchronousCloseException after 12274780560 nanos at read cycle=3: null
2024-12-09T10:52:20.1781160Z 09 Dec 2024 10:52:20,085 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientSessionImpl [] - checkForTimeouts(ClientSessionImpl[null@localhost/127.0.0.1:29559]) disconnect - reason=TimeoutIndicator[status=AuthTimeout, threshold=120000, expired=120207]
2024-12-09T10:52:20.1785418Z 09 Dec 2024 10:52:20,086 [sshd-SshClient[7b332b23]-timer-thread-1] INFO  ClientSessionImpl [] - Disconnecting(ClientSessionImpl[null@localhost/127.0.0.1:29559]): SSH2_DISCONNECT_PROTOCOL_ERROR - Detected AuthTimeout after 120207/120000 ms.
2024-12-09T10:52:20.1997213Z 09 Dec 2024 10:52:20,086 [sshd-SshClient[7b332b23]-timer-thread-1] DEBUG ClientSessionImpl [] - encode(ClientSessionImpl[null@localhost/127.0.0.1:29559]) packet #0 sending command=1[SSH_MSG_DISCONNECT] len=45
2024-12-09T10:52:48.6245151Z 09 Dec 2024 10:52:48,535 [sshd-SshClient[7b332b23]-nio2-resume-thread-3] DEBUG ClientSessionImpl [] - Client session created: Nio2Session[local=/127.0.0.1:33510, remote=localhost/127.0.0.1:29559]
2024-12-09T10:52:48.6247198Z 09 Dec 2024 10:52:48,535 [sshd-SshClient[7b332b23]-nio2-resume-thread-3] DEBUG ClientUserAuthService [] - ClientUserAuthService(ClientSessionImpl[null@localhost/127.0.0.1:29559]) client methods: [publickey, keyboard-interactive, password]
2024-12-09T10:52:48.6249047Z 09 Dec 2024 10:52:48,536 [sshd-SshClient[7b332b23]-nio2-resume-thread-3] DEBUG SessionTimeoutListener [] - sessionCreated(ClientSessionImpl[null@localhost/127.0.0.1:29559]) tracking
2024-12-09T10:52:48.6250780Z 09 Dec 2024 10:52:48,536 [sshd-SshClient[7b332b23]-nio2-resume-thread-3] DEBUG ClientSessionImpl [] - initializeProxyConnector(ClientSessionImpl[null@localhost/127.0.0.1:29559]) no proxy to initialize
2024-12-09T10:52:48.6252423Z 09 Dec 2024 10:52:48,536 [sshd-SshClient[7b332b23]-nio2-resume-thread-3] DEBUG ClientSessionImpl [] - sendIdentification(ClientSessionImpl[null@localhost/127.0.0.1:29559]): SSH-2.0-APACHE-SSHD-2.14.0
2024-12-09T10:52:48.6254552Z 09 Dec 2024 10:52:48,536 [sshd-SshClient[7b332b23]-nio2-resume-thread-3] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:33510, remote=localhost/127.0.0.1:29559]) writing 28 bytes
2024-12-09T10:52:48.6256032Z 09 Dec 2024 10:52:48,537 [sshd-SshClient[7b332b23]-nio2-resume-thread-3] DEBUG ClientSessionImpl [] - sendKexInit(ClientSessionImpl[null@localhost/127.0.0.1:29559]) Send SSH_MSG_KEXINIT

ServerLog

2024-12-09T10:48:32.1456320Z 09 Dec 2024 10:48:32,108 [sshd-SshServer[708769b7](port=29559)-nio2-thread-1] DEBUG Nio2Acceptor [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2024-12-09T10:48:32.2486929Z 09 Dec 2024 10:48:32,116 [sshd-SshServer[708769b7](port=29559)-nio2-thread-1] DEBUG Nio2Session [] - Creating IoSession on /127.0.0.1:29559 from /127.0.0.1:48616 via /127.0.0.1:29559
2024-12-09T10:48:32.2600316Z 09 Dec 2024 10:48:32,189 [sshd-SshServer[708769b7](port=29559)-nio2-thread-1] DEBUG SessionTimeoutListener [] - sessionCreated(ServerSessionImpl[null@/127.0.0.1:48616]) tracking
2024-12-09T10:48:32.2675471Z 09 Dec 2024 10:48:32,199 [sshd-SshServer[708769b7](port=29559)-nio2-thread-1] DEBUG ServerSessionImpl [] - sendIdentification(ServerSessionImpl[null@/127.0.0.1:48616]): SSH-2.0-APACHE-SSHD-2.14.0
2024-12-09T10:48:32.2678566Z 09 Dec 2024 10:48:32,199 [sshd-SshServer[708769b7](port=29559)-nio2-thread-1] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:29559, remote=/127.0.0.1:48616]) writing 28 bytes
2024-12-09T10:48:32.3054829Z 09 Dec 2024 10:48:32,225 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - doReadIdentification(ServerSessionImpl[null@/127.0.0.1:48616]) line='SSH-2.0-APACHE-SSHD-2.14.0'
2024-12-09T10:48:32.3057952Z 09 Dec 2024 10:48:32,226 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - readIdentification(ServerSessionImpl[null@/127.0.0.1:48616]) client version string: SSH-2.0-APACHE-SSHD-2.14.0
2024-12-09T10:48:32.3542110Z 09 Dec 2024 10:48:32,262 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] WARN  SimpleGeneratorHostKeyProvider [] - resolveKeyPair(/tmp/host11768225815377241290.ser) Failed (StreamCorruptedException) to load: File /tmp/host11768225815377241290.ser is not a host key
2024-12-09T10:48:32.3617165Z 09 Dec 2024 10:48:32,298 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] INFO  SimpleGeneratorHostKeyProvider [] - generateKeyPair(EC) generating host key=nistp521
2024-12-09T10:48:32.4448481Z 09 Dec 2024 10:48:32,385 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG SimpleGeneratorHostKeyProvider [] - resolveKeyPair(/tmp/host11768225815377241290.ser) generated EC key=ecdsa-sha2-nistp521-SHA256:BdxTdpqmNLMeiyhYfNP1uGUz6oeZrFY9tu/T4jxeo6g
2024-12-09T10:49:00.0263107Z 09 Dec 2024 10:48:59,997 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - sendKexInit(ServerSessionImpl[null@/127.0.0.1:48616]) Send SSH_MSG_KEXINIT
2024-12-09T10:49:14.9778456Z 09 Dec 2024 10:49:14,877 [sshd-SshServer[708769b7](port=29559)-nio2-thread-3] DEBUG Nio2Acceptor [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2024-12-09T10:49:14.9780928Z 09 Dec 2024 10:49:14,880 [sshd-SshServer[708769b7](port=29559)-nio2-thread-3] DEBUG Nio2Session [] - Creating IoSession on /127.0.0.1:29559 from /127.0.0.1:47188 via /127.0.0.1:29559
2024-12-09T10:49:18.4370606Z 09 Dec 2024 10:49:18,415 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - encode(ServerSessionImpl[null@/127.0.0.1:48616]) packet #0 sending command=20[SSH_MSG_KEXINIT] len=941
2024-12-09T10:49:35.2128352Z 09 Dec 2024 10:49:35,118 [sshd-SshServer[708769b7](port=29559)-nio2-thread-3] DEBUG SessionTimeoutListener [] - sessionCreated(ServerSessionImpl[null@/127.0.0.1:47188]) tracking
2024-12-09T10:49:35.2133710Z 09 Dec 2024 10:49:35,133 [sshd-SshServer[708769b7](port=29559)-nio2-thread-3] DEBUG ServerSessionImpl [] - sendIdentification(ServerSessionImpl[null@/127.0.0.1:47188]): SSH-2.0-APACHE-SSHD-2.14.0
2024-12-09T10:49:35.2135439Z 09 Dec 2024 10:49:35,133 [sshd-SshServer[708769b7](port=29559)-nio2-thread-3] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:29559, remote=/127.0.0.1:47188]) writing 28 bytes
2024-12-09T10:49:44.9226978Z 09 Dec 2024 10:49:44,894 [sshd-SshServer[708769b7](port=29559)-nio2-thread-1] DEBUG Nio2Acceptor [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2024-12-09T10:49:44.9229402Z 09 Dec 2024 10:49:44,894 [sshd-SshServer[708769b7](port=29559)-nio2-thread-1] DEBUG Nio2Session [] - Creating IoSession on /127.0.0.1:29559 from /127.0.0.1:33510 via /127.0.0.1:29559
2024-12-09T10:49:50.2022979Z 09 Dec 2024 10:49:50,146 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:29559, remote=/127.0.0.1:48616]) writing 960 bytes
2024-12-09T10:49:50.2024748Z 09 Dec 2024 10:49:50,148 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - doHandleMessage(ServerSessionImpl[null@/127.0.0.1:48616]) process #0 SSH_MSG_KEXINIT
2024-12-09T10:49:50.2031634Z 09 Dec 2024 10:49:50,149 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - handleKexInit(ServerSessionImpl[null@/127.0.0.1:48616]) SSH_MSG_KEXINIT
2024-12-09T10:49:50.2050605Z 09 Dec 2024 10:49:50,155 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - negotiate(ServerSessionImpl[null@/127.0.0.1:48616]) strict KEX=true client=true server=true
2024-12-09T10:49:50.2069767Z 09 Dec 2024 10:49:50,171 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:48616]) Kex: kex algorithms = curve25519-sha256
2024-12-09T10:49:50.2073040Z 09 Dec 2024 10:49:50,172 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:48616]) Kex: server host key algorithms = ecdsa-sha2-nistp521
2024-12-09T10:49:50.2079510Z 09 Dec 2024 10:49:50,172 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:48616]) Kex: encryption algorithms (client to server) = [email protected]
2024-12-09T10:49:50.2081860Z 09 Dec 2024 10:49:50,172 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:48616]) Kex: encryption algorithms (server to client) = [email protected]
2024-12-09T10:49:50.2083836Z 09 Dec 2024 10:49:50,172 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:48616]) Kex: mac algorithms (client to server) = [email protected]
2024-12-09T10:49:50.2086042Z 09 Dec 2024 10:49:50,172 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:48616]) Kex: mac algorithms (server to client) = [email protected]
2024-12-09T10:49:50.2088256Z 09 Dec 2024 10:49:50,172 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:48616]) Kex: compression algorithms (client to server) = none
2024-12-09T10:49:50.2090049Z 09 Dec 2024 10:49:50,172 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:48616]) Kex: compression algorithms (server to client) = none
2024-12-09T10:50:04.6684515Z 09 Dec 2024 10:50:04,635 [sshd-SshServer[708769b7](port=29559)-nio2-thread-1] DEBUG SessionTimeoutListener [] - sessionCreated(ServerSessionImpl[null@/127.0.0.1:33510]) tracking
2024-12-09T10:50:04.6688674Z 09 Dec 2024 10:50:04,636 [sshd-SshServer[708769b7](port=29559)-nio2-thread-1] DEBUG ServerSessionImpl [] - sendIdentification(ServerSessionImpl[null@/127.0.0.1:33510]): SSH-2.0-APACHE-SSHD-2.14.0
2024-12-09T10:50:04.6692397Z 09 Dec 2024 10:50:04,636 [sshd-SshServer[708769b7](port=29559)-nio2-thread-1] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:29559, remote=/127.0.0.1:33510]) writing 28 bytes
2024-12-09T10:50:14.9210906Z 09 Dec 2024 10:50:14,907 [sshd-SshServer[708769b7](port=29559)-nio2-thread-3] DEBUG Nio2Acceptor [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
2024-12-09T10:50:14.9212787Z 09 Dec 2024 10:50:14,907 [sshd-SshServer[708769b7](port=29559)-nio2-thread-3] DEBUG Nio2Session [] - Creating IoSession on /127.0.0.1:29559 from /127.0.0.1:40908 via /127.0.0.1:29559
2024-12-09T10:50:20.0115475Z 09 Dec 2024 10:50:19,903 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - doReadIdentification(ServerSessionImpl[null@/127.0.0.1:47188]) line='SSH-2.0-APACHE-SSHD-2.14.0'
2024-12-09T10:50:20.0118921Z 09 Dec 2024 10:50:19,903 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - readIdentification(ServerSessionImpl[null@/127.0.0.1:47188]) client version string: SSH-2.0-APACHE-SSHD-2.14.0
2024-12-09T10:50:20.0120629Z 09 Dec 2024 10:50:19,924 [sshd-SshServer[708769b7](port=29559)-nio2-thread-2] DEBUG ServerSessionImpl [] - sendKexInit(ServerSessionImpl[null@/127.0.0.1:47188]) Send SSH_MSG_KEXINIT
2024-12-09T10:50:33.0273303Z 09 Dec 2024 10:50:32,990 [sshd-SshServer[708769b7](port=29559)-timer-thread-1] DEBUG ServerSessionImpl [] - checkForTimeouts(ServerSessionImpl[null@/127.0.0.1:48616]) disconnect - reason=TimeoutIndicator[status=AuthTimeout, threshold=120000, expired=120853]
2024-12-09T10:50:33.0421855Z 09 Dec 2024 10:50:32,993 [sshd-SshServer[708769b7](port=29559)-timer-thread-1] INFO  ServerSessionImpl [] - Disconnecting(ServerSessionImpl[null@/127.0.0.1:48616]): SSH2_DISCONNECT_PROTOCOL_ERROR - Detected AuthTimeout after 120853/120000 ms.
2024-12-09T10:50:33.0424693Z 09 Dec 2024 10:50:33,008 [sshd-SshServer[708769b7](port=29559)-timer-thread-1] DEBUG ServerSessionImpl [] - encode(ServerSessionImpl[null@/127.0.0.1:48616]) packet #1 sending command=1[SSH_MSG_DISCONNECT] len=45
2024-12-09T10:50:48.4254020Z 09 Dec 2024 10:50:48,389 [sshd-SshServer[708769b7](port=29559)-nio2-thread-1] DEBUG ServerSessionImpl [] - doHandleMessage(ServerSessionImpl[null@/127.0.0.1:48616]) process #1 30
2024-12-09T10:50:48.4255979Z 09 Dec 2024 10:50:48,390 [sshd-SshServer[708769b7](port=29559)-nio2-thread-1] DEBUG DHGServer [] - next(DHGServer[curve25519-sha256])[ServerSessionImpl[null@/127.0.0.1:48616]] process command=SSH_MSG_KEXDH_INIT
2024-12-09T10:50:48.5341106Z 09 Dec 2024 10:50:48,431 [sshd-SshServer[708769b7](port=29559)-nio2-thread-1] DEBUG DHGServer [] - next(DHGServer[curve25519-sha256])[ServerSessionImpl[null@/127.0.0.1:48616]] Send SSH_MSG_KEXDH_REPLY
2024-12-09T10:51:13.5448808Z 09 Dec 2024 10:51:13,472 [sshd-SshServer[708769b7](port=29559)-nio2-thread-3] DEBUG SessionTimeoutListener [] - sessionCreated(ServerSessionImpl[null@/127.0.0.1:40908]) tracking
2024-12-09T10:51:13.5587020Z 09 Dec 2024 10:51:13,473 [sshd-SshServer[708769b7](port=29559)-nio2-thread-3] DEBUG ServerSessionImpl [] - sendIdentification(ServerSessionImpl[null@/127.0.0.1:40908]): SSH-2.0-APACHE-SSHD-2.14.0
2024-12-09T10:51:13.5612039Z 09 Dec 2024 10:51:13,473 [sshd-SshServer[708769b7](port=29559)-nio2-thread-3] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:29559, remote=/127.0.0.1:40908]) writing 28 bytes
2024-12-09T10:51:13.5866320Z 09 Dec 2024 10:51:13,474 [sshd-SshServer[708769b7](port=29559)-nio2-thread-3] DEBUG ServerSessionImpl [] - doReadIdentification(ServerSessionImpl[null@/127.0.0.1:40908]) line='SSH-2.0-APACHE-SSHD-2.14.0'
2024-12-09T10:51:13.5980964Z 09 Dec 2024 10:51:13,475 [sshd-SshServer[708769b7](port=29559)-nio2-thread-3] DEBUG ServerSessionImpl [] - readIdentification(ServerSessionImpl[null@/127.0.0.1:40908]) client version string: SSH-2.0-APACHE-SSHD-2.14.0
2024-12-09T10:51:13.6063552Z 09 Dec 2024 10:51:13,476 [sshd-SshServer[708769b7](port=29559)-nio2-thread-3] DEBUG ServerSessionImpl [] - sendKexInit(ServerSessionImpl[null@/127.0.0.1:40908]) Send SSH_MSG_KEXINIT
2024-12-09T10:51:26.5672879Z 09 Dec 2024 10:51:26,557 [sshd-SshServer[708769b7](port=29559)-timer-thread-1] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:29559, remote=/127.0.0.1:48616]) writing 64 bytes

Expected behavior

With 2.13.2 we have the next logs

Main log

09 Dec 2024 11:27:16,979 [main] DEBUG SecurityUtils [] - register(BC) not registered - enabled=true, supported=false
09 Dec 2024 11:27:17,051 [main] DEBUG SecurityUtils [] - register(EdDSA) not registered - enabled=true, supported=false
09 Dec 2024 11:27:18,016 [main] INFO  DefaultIoServiceFactoryFactory [] - No detected/configured IoServiceFactoryFactory; using Nio2ServiceFactoryFactory
09 Dec 2024 11:27:18,091 [main] DEBUG SshServer [] - start() - resolve bind host=localhost
09 Dec 2024 11:27:18,092 [main] DEBUG Nio2Acceptor [] - bind(localhost/127.0.0.1:9626) binding to address
09 Dec 2024 11:27:18,097 [main] DEBUG Nio2Acceptor [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
09 Dec 2024 11:27:18,098 [main] DEBUG Nio2Acceptor [] - bind(localhost/127.0.0.1:9626) bound to /127.0.0.1:9626
09 Dec 2024 11:27:18,101 [main] DEBUG Nio2Acceptor [] - bind(localhost/[0:0:0:0:0:0:0:1]:9626) binding to address
09 Dec 2024 11:27:18,102 [main] DEBUG Nio2Acceptor [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
09 Dec 2024 11:27:18,102 [main] DEBUG Nio2Acceptor [] - bind(localhost/[0:0:0:0:0:0:0:1]:9626) bound to /[0:0:0:0:0:0:0:1]:9626
09 Dec 2024 11:27:18,223 [main] DEBUG Nio2Connector [] - Connecting to localhost/127.0.0.1:9626
09 Dec 2024 11:27:18,227 [main] DEBUG Nio2Connector [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
09 Dec 2024 11:27:18,508 [main] DEBUG DefaultConnectFuture [] - Connected to localhost/127.0.0.1:9626 after 276989620 nanos

Client Log

09 Dec 2024 11:27:18,231 [sshd-SshClient[11cc9e1e]-nio2-resume-thread-1] DEBUG Nio2Connector [] - connect(localhost/127.0.0.1:9626): waiting for connection (timeout=60000ms)
09 Dec 2024 11:27:18,238 [sshd-SshClient[11cc9e1e]-nio2-resume-thread-1] DEBUG Nio2Session [] - Creating IoSession on /127.0.0.1:49934 from localhost/127.0.0.1:9626 via null
09 Dec 2024 11:27:18,285 [sshd-SshClient[11cc9e1e]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - Client session created: Nio2Session[local=/127.0.0.1:49934, remote=localhost/127.0.0.1:9626]
09 Dec 2024 11:27:18,290 [sshd-SshClient[11cc9e1e]-nio2-resume-thread-1] DEBUG ClientUserAuthService [] - ClientUserAuthService(ClientSessionImpl[null@localhost/127.0.0.1:9626]) client methods: [publickey, keyboard-interactive, password]
09 Dec 2024 11:27:18,312 [sshd-SshClient[11cc9e1e]-nio2-resume-thread-1] DEBUG SessionTimeoutListener [] - sessionCreated(ClientSessionImpl[null@localhost/127.0.0.1:9626]) tracking
09 Dec 2024 11:27:18,313 [sshd-SshClient[11cc9e1e]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - initializeProxyConnector(ClientSessionImpl[null@localhost/127.0.0.1:9626]) no proxy to initialize
09 Dec 2024 11:27:18,343 [sshd-SshClient[11cc9e1e]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - sendIdentification(ClientSessionImpl[null@localhost/127.0.0.1:9626]): SSH-2.0-APACHE-SSHD-2.13.2
09 Dec 2024 11:27:18,344 [sshd-SshClient[11cc9e1e]-nio2-resume-thread-1] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:49934, remote=localhost/127.0.0.1:9626]) writing 28 bytes
09 Dec 2024 11:27:18,371 [sshd-SshClient[11cc9e1e]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - sendKexInit(ClientSessionImpl[null@localhost/127.0.0.1:9626]) Send SSH_MSG_KEXINIT
09 Dec 2024 11:27:18,406 [sshd-SshClient[11cc9e1e]-nio2-resume-thread-1] DEBUG ClientSessionImpl [] - encode(ClientSessionImpl[null@localhost/127.0.0.1:9626]) packet #0 sending command=20[SSH_MSG_KEXINIT] len=1263
09 Dec 2024 11:27:18,407 [sshd-SshClient[11cc9e1e]-nio2-resume-thread-1] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:49934, remote=localhost/127.0.0.1:9626]) writing 1280 bytes
09 Dec 2024 11:27:18,502 [sshd-SshClient[11cc9e1e]-nio2-resume-thread-1] DEBUG SshClient [] - setupDefaultSessionIdentities(ClientSessionImpl[test@localhost/127.0.0.1:9626]) key identity provider override in session listener
09 Dec 2024 11:27:18,585 [sshd-SshClient[11cc9e1e]-nio2-thread-3] DEBUG ClientSessionImpl [] - doReadIdentification(ClientSessionImpl[test@localhost/127.0.0.1:9626]) line='SSH-2.0-APACHE-SSHD-2.13.2'
09 Dec 2024 11:27:18,586 [sshd-SshClient[11cc9e1e]-nio2-thread-3] DEBUG ClientSessionImpl [] - readIdentification(ClientSessionImpl[test@localhost/127.0.0.1:9626]) Server version string: SSH-2.0-APACHE-SSHD-2.13.2
09 Dec 2024 11:27:18,694 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientSessionImpl [] - doHandleMessage(ClientSessionImpl[test@localhost/127.0.0.1:9626]) process #0 SSH_MSG_KEXINIT
09 Dec 2024 11:27:18,694 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientSessionImpl [] - handleKexInit(ClientSessionImpl[test@localhost/127.0.0.1:9626]) SSH_MSG_KEXINIT
09 Dec 2024 11:27:18,707 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientSessionImpl [] - negotiate(ClientSessionImpl[test@localhost/127.0.0.1:9626]) strict KEX=true client=true server=true
09 Dec 2024 11:27:18,718 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:9626]) Kex: kex algorithms = curve25519-sha256
09 Dec 2024 11:27:18,719 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:9626]) Kex: server host key algorithms = ecdsa-sha2-nistp521
09 Dec 2024 11:27:18,719 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:9626]) Kex: encryption algorithms (client to server) = [email protected]
09 Dec 2024 11:27:18,719 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:9626]) Kex: encryption algorithms (server to client) = [email protected]
09 Dec 2024 11:27:18,719 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:9626]) Kex: mac algorithms (client to server) = [email protected]
09 Dec 2024 11:27:18,720 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:9626]) Kex: mac algorithms (server to client) = [email protected]
09 Dec 2024 11:27:18,720 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:9626]) Kex: compression algorithms (client to server) = none
09 Dec 2024 11:27:18,720 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientSessionImpl [] - setNegotiationResult(ClientSessionImpl[test@localhost/127.0.0.1:9626]) Kex: compression algorithms (server to client) = none
09 Dec 2024 11:27:18,725 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG DHGClient [] - init(DHGClient[curve25519-sha256])[ClientSessionImpl[test@localhost/127.0.0.1:9626]] Send SSH_MSG_KEXDH_INIT
09 Dec 2024 11:27:18,725 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientSessionImpl [] - encode(ClientSessionImpl[test@localhost/127.0.0.1:9626]) packet #1 sending command=30[30] len=37
09 Dec 2024 11:27:18,726 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:49934, remote=localhost/127.0.0.1:9626]) writing 56 bytes
09 Dec 2024 11:27:18,819 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - doHandleMessage(ClientSessionImpl[test@localhost/127.0.0.1:9626]) process #1 31
09 Dec 2024 11:27:18,819 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG DHGClient [] - next(DHGClient[curve25519-sha256])[ClientSessionImpl[test@localhost/127.0.0.1:9626]] process command=SSH_MSG_KEXDH_REPLY
09 Dec 2024 11:27:18,851 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - setServerKey(ClientSessionImpl[test@localhost/127.0.0.1:9626]) keyType=ecdsa-sha2-nistp521, digest=SHA256:uHLr4hArOf925KQXXrVp7j7Zxr/XL5ed3W7ZXkq+nes
09 Dec 2024 11:27:18,851 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - handleKexMessage(ClientSessionImpl[test@localhost/127.0.0.1:9626])[curve25519-sha256] KEX processing complete after cmd=31
09 Dec 2024 11:27:18,852 [sshd-SshClient[11cc9e1e]-nio2-thread-2] WARN  AcceptAllServerKeyVerifier [] - Server at localhost/127.0.0.1:9626 presented unverified EC key: SHA256:uHLr4hArOf925KQXXrVp7j7Zxr/XL5ed3W7ZXkq+nes
09 Dec 2024 11:27:18,852 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - checkKeys(ClientSessionImpl[test@localhost/127.0.0.1:9626]) key=ecdsa-sha2-nistp521-SHA256:uHLr4hArOf925KQXXrVp7j7Zxr/XL5ed3W7ZXkq+nes, verified=true
09 Dec 2024 11:27:18,852 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - sendNewKeys(ClientSessionImpl[test@localhost/127.0.0.1:9626]) Send SSH_MSG_NEWKEYS
09 Dec 2024 11:27:18,852 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - prepareNewKeys(ClientSessionImpl[test@localhost/127.0.0.1:9626]) session ID=98:09:46:f8:2c:5b:fa:41:72:a1:a3:a8:36:b3:92:74:5f:0d:a2:cb:ec:91:fe:de:f0:3a:f9:57:c6:75:ed:24
09 Dec 2024 11:27:18,863 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - encode(ClientSessionImpl[test@localhost/127.0.0.1:9626]) packet #2 sending command=21[SSH_MSG_NEWKEYS] len=1
09 Dec 2024 11:27:18,864 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:49934, remote=localhost/127.0.0.1:9626]) writing 16 bytes
09 Dec 2024 11:27:18,865 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - setOutputEncoding(ClientSessionImpl[test@localhost/127.0.0.1:9626]): strict KEX resets output message sequence number from 3 to 0
09 Dec 2024 11:27:18,865 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - setOutputEncoding(ClientSessionImpl[test@localhost/127.0.0.1:9626]): cipher org.apache.sshd.common.cipher.ChaCha20Cipher@71a2433b; mac null; compression none[Deflater/-1]; blocks limit 134217728
09 Dec 2024 11:27:18,866 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - handleNewKeys(ClientSessionImpl[test@localhost/127.0.0.1:9626]) No pending packets to flush at end of KEX
09 Dec 2024 11:27:18,866 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - doHandleMessage(ClientSessionImpl[test@localhost/127.0.0.1:9626]) process #2 SSH_MSG_NEWKEYS
09 Dec 2024 11:27:18,866 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - handleNewKeys(ClientSessionImpl[test@localhost/127.0.0.1:9626]) SSH_MSG_NEWKEYS command=SSH_MSG_NEWKEYS
09 Dec 2024 11:27:18,867 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - setInputEncoding(ClientSessionImpl[test@localhost/127.0.0.1:9626]): strict KEX resets input message sequence number from 3 to 0
09 Dec 2024 11:27:18,867 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - setInputEncoding(ClientSessionImpl[test@localhost/127.0.0.1:9626]): cipher org.apache.sshd.common.cipher.ChaCha20Cipher@70ede6d; mac null; compression none[Inflater/-1]; blocks limit 134217728
09 Dec 2024 11:27:18,867 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - sendInitialServiceRequest(ClientSessionImpl[test@localhost/127.0.0.1:9626]) Send SSH_MSG_SERVICE_REQUEST for ssh-userauth
09 Dec 2024 11:27:18,868 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - encode(ClientSessionImpl[test@localhost/127.0.0.1:9626]) packet #0 sending command=5[SSH_MSG_SERVICE_REQUEST] len=17
09 Dec 2024 11:27:18,868 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:49934, remote=localhost/127.0.0.1:9626]) writing 52 bytes
09 Dec 2024 11:27:18,870 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientUserAuthService [] - auth(ClientSessionImpl[test@localhost/127.0.0.1:9626])[ssh-connection] send SSH_MSG_USERAUTH_REQUEST for 'none'
09 Dec 2024 11:27:18,870 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - encode(ClientSessionImpl[test@localhost/127.0.0.1:9626]) packet #1 sending command=50[SSH_MSG_USERAUTH_REQUEST] len=35
09 Dec 2024 11:27:18,871 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:49934, remote=localhost/127.0.0.1:9626]) writing 68 bytes
09 Dec 2024 11:27:18,873 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG ClientSessionImpl [] - doHandleMessage(ClientSessionImpl[test@localhost/127.0.0.1:9626]) process #0 7
09 Dec 2024 11:27:18,873 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG DefaultClientKexExtensionHandler [] - handleServerSignatureAlgorithms(ClientSessionImpl[test@localhost/127.0.0.1:9626]): [[email protected], [email protected], [email protected], [email protected], [email protected], ecdsa-sha2-nistp256, ecdsa-sha2-nistp384, ecdsa-sha2-nistp521, [email protected], rsa-sha2-512, rsa-sha2-256, ssh-rsa]
09 Dec 2024 11:27:18,874 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG DefaultClientKexExtensionHandler [] - handleServerSignatureAlgorithms(ClientSessionImpl[test@localhost/127.0.0.1:9626]): PubkeyAcceptedAlgorithms before: [[email protected], [email protected], [email protected], [email protected], [email protected], ecdsa-sha2-nistp256, ecdsa-sha2-nistp384, ecdsa-sha2-nistp521, [email protected], rsa-sha2-512, rsa-sha2-256, ssh-rsa]
09 Dec 2024 11:27:18,875 [sshd-SshClient[11cc9e1e]-nio2-thread-2] DEBUG DefaultClientKexExtensionHandler [] - handleServerSignatureAlgorithms(ClientSessionImpl[test@localhost/127.0.0.1:9626]): PubkeyAcceptedAlgorithms after: [[email protected], [email protected], [email protected], [email protected], [email protected], ecdsa-sha2-nistp256, ecdsa-sha2-nistp384, ecdsa-sha2-nistp521, [email protected], rsa-sha2-512, rsa-sha2-256, ssh-rsa]
09 Dec 2024 11:27:18,902 [sshd-SshClient[11cc9e1e]-nio2-thread-3] DEBUG ClientSessionImpl [] - doHandleMessage(ClientSessionImpl[test@localhost/127.0.0.1:9626]) process #1 SSH_MSG_SERVICE_ACCEPT
09 Dec 2024 11:27:18,902 [sshd-SshClient[11cc9e1e]-nio2-thread-3] DEBUG ClientSessionImpl [] - handleServiceAccept(ClientSessionImpl[test@localhost/127.0.0.1:9626]) SSH_MSG_SERVICE_ACCEPT service=ssh-userauth
09 Dec 2024 11:27:18,941 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientSessionImpl [] - doHandleMessage(ClientSessionImpl[test@localhost/127.0.0.1:9626]) process #2 SSH_MSG_USERAUTH_FAILURE
09 Dec 2024 11:27:18,942 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientUserAuthService [] - processUserAuth(ClientSessionImpl[test@localhost/127.0.0.1:9626]) Received SSH_MSG_USERAUTH_FAILURE - partial=false, methods=password,keyboard-interactive,publickey
09 Dec 2024 11:27:18,942 [sshd-SshClient[11cc9e1e]-nio2-thread-1] DEBUG ClientUserAuthService [] - tryNext(ClientSessionImpl[test@localhost/127.0.0.1:9626]) starting authentication mechanisms: client=[publickey, keyboard-interactive, password], server=[password, keyboard-interactive, publickey]

Server Log

09 Dec 2024 11:27:18,291 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG Nio2Acceptor [] - setOption(SO_REUSEADDR)[true] from property=Property[socket-reuseaddr](Boolean]
09 Dec 2024 11:27:18,299 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG Nio2Session [] - Creating IoSession on /127.0.0.1:9626 from /127.0.0.1:49934 via /127.0.0.1:9626
09 Dec 2024 11:27:18,302 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG SessionTimeoutListener [] - sessionCreated(ServerSessionImpl[null@/127.0.0.1:49934]) tracking
09 Dec 2024 11:27:18,339 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - sendIdentification(ServerSessionImpl[null@/127.0.0.1:49934]): SSH-2.0-APACHE-SSHD-2.13.2
09 Dec 2024 11:27:18,340 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:9626, remote=/127.0.0.1:49934]) writing 28 bytes
09 Dec 2024 11:27:18,351 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - doReadIdentification(ServerSessionImpl[null@/127.0.0.1:49934]) line='SSH-2.0-APACHE-SSHD-2.13.2'
09 Dec 2024 11:27:18,352 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - readIdentification(ServerSessionImpl[null@/127.0.0.1:49934]) client version string: SSH-2.0-APACHE-SSHD-2.13.2
09 Dec 2024 11:27:18,363 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] WARN  SimpleGeneratorHostKeyProvider [] - resolveKeyPair(/tmp/host8892828814704532440.ser) Failed (StreamCorruptedException) to load: File /tmp/host8892828814704532440.ser is not a host key
09 Dec 2024 11:27:18,421 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] INFO  SimpleGeneratorHostKeyProvider [] - generateKeyPair(EC) generating host key=nistp521
09 Dec 2024 11:27:18,627 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG SimpleGeneratorHostKeyProvider [] - resolveKeyPair(/tmp/host8892828814704532440.ser) generated EC key=ecdsa-sha2-nistp521-SHA256:uHLr4hArOf925KQXXrVp7j7Zxr/XL5ed3W7ZXkq+nes
09 Dec 2024 11:27:18,682 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - sendKexInit(ServerSessionImpl[null@/127.0.0.1:49934]) Send SSH_MSG_KEXINIT
09 Dec 2024 11:27:18,683 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - encode(ServerSessionImpl[null@/127.0.0.1:49934]) packet #0 sending command=20[SSH_MSG_KEXINIT] len=941
09 Dec 2024 11:27:18,683 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:9626, remote=/127.0.0.1:49934]) writing 960 bytes
09 Dec 2024 11:27:18,684 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - doHandleMessage(ServerSessionImpl[null@/127.0.0.1:49934]) process #0 SSH_MSG_KEXINIT
09 Dec 2024 11:27:18,685 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - handleKexInit(ServerSessionImpl[null@/127.0.0.1:49934]) SSH_MSG_KEXINIT
09 Dec 2024 11:27:18,700 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - negotiate(ServerSessionImpl[null@/127.0.0.1:49934]) strict KEX=true client=true server=true
09 Dec 2024 11:27:18,713 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:49934]) Kex: kex algorithms = curve25519-sha256
09 Dec 2024 11:27:18,713 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:49934]) Kex: server host key algorithms = ecdsa-sha2-nistp521
09 Dec 2024 11:27:18,713 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:49934]) Kex: encryption algorithms (client to server) = [email protected]
09 Dec 2024 11:27:18,713 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:49934]) Kex: encryption algorithms (server to client) = [email protected]
09 Dec 2024 11:27:18,713 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:49934]) Kex: mac algorithms (client to server) = [email protected]
09 Dec 2024 11:27:18,714 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:49934]) Kex: mac algorithms (server to client) = [email protected]
09 Dec 2024 11:27:18,714 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:49934]) Kex: compression algorithms (client to server) = none
09 Dec 2024 11:27:18,714 [sshd-SshServer[156324b](port=9626)-nio2-thread-1] DEBUG ServerSessionImpl [] - setNegotiationResult(ServerSessionImpl[null@/127.0.0.1:49934]) Kex: compression algorithms (server to client) = none
09 Dec 2024 11:27:18,728 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG ServerSessionImpl [] - doHandleMessage(ServerSessionImpl[null@/127.0.0.1:49934]) process #1 30
09 Dec 2024 11:27:18,747 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG DHGServer [] - next(DHGServer[curve25519-sha256])[ServerSessionImpl[null@/127.0.0.1:49934]] process command=SSH_MSG_KEXDH_INIT
09 Dec 2024 11:27:18,811 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG DHGServer [] - next(DHGServer[curve25519-sha256])[ServerSessionImpl[null@/127.0.0.1:49934]] Send SSH_MSG_KEXDH_REPLY
09 Dec 2024 11:27:18,812 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG ServerSessionImpl [] - encode(ServerSessionImpl[null@/127.0.0.1:49934]) packet #1 sending command=31[31] len=383
09 Dec 2024 11:27:18,812 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:9626, remote=/127.0.0.1:49934]) writing 400 bytes
09 Dec 2024 11:27:18,813 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG ServerSessionImpl [] - handleKexMessage(ServerSessionImpl[null@/127.0.0.1:49934])[curve25519-sha256] KEX processing complete after cmd=30
09 Dec 2024 11:27:18,813 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG ServerSessionImpl [] - sendNewKeys(ServerSessionImpl[null@/127.0.0.1:49934]) Send SSH_MSG_NEWKEYS
09 Dec 2024 11:27:18,813 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG ServerSessionImpl [] - prepareNewKeys(ServerSessionImpl[null@/127.0.0.1:49934]) session ID=98:09:46:f8:2c:5b:fa:41:72:a1:a3:a8:36:b3:92:74:5f:0d:a2:cb:ec:91:fe:de:f0:3a:f9:57:c6:75:ed:24
09 Dec 2024 11:27:18,821 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG ServerSessionImpl [] - encode(ServerSessionImpl[null@/127.0.0.1:49934]) packet #2 sending command=21[SSH_MSG_NEWKEYS] len=1
09 Dec 2024 11:27:18,821 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:9626, remote=/127.0.0.1:49934]) writing 16 bytes
09 Dec 2024 11:27:18,822 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG ServerSessionImpl [] - setOutputEncoding(ServerSessionImpl[null@/127.0.0.1:49934]): strict KEX resets output message sequence number from 3 to 0
09 Dec 2024 11:27:18,823 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG ServerSessionImpl [] - setOutputEncoding(ServerSessionImpl[null@/127.0.0.1:49934]): cipher org.apache.sshd.common.cipher.ChaCha20Cipher@18535504; mac null; compression none[Deflater/-1]; blocks limit 134217728
09 Dec 2024 11:27:18,826 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG DefaultServerKexExtensionHandler [] - collectExtensions(ServerSessionImpl[null@/127.0.0.1:49934])[NEWKEYS]: extension info server-sig-algs: [email protected],[email protected],[email protected],[email protected],[email protected],ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,[email protected],rsa-sha2-512,rsa-sha2-256,ssh-rsa
09 Dec 2024 11:27:18,826 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG DefaultServerKexExtensionHandler [] - sendKexExtensions(ServerSessionImpl[null@/127.0.0.1:49934])[NEWKEYS]: sending SSH_MSG_EXT_INFO with 1 info records
09 Dec 2024 11:27:18,826 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG ServerSessionImpl [] - encode(ServerSessionImpl[null@/127.0.0.1:49934]) packet #0 sending command=7[7] len=347
09 Dec 2024 11:27:18,827 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:9626, remote=/127.0.0.1:49934]) writing 380 bytes
09 Dec 2024 11:27:18,828 [sshd-SshServer[156324b](port=9626)-nio2-thread-2] DEBUG ServerSessionImpl [] - handleNewKeys(ServerSessionImpl[null@/127.0.0.1:49934]) No pending packets to flush at end of KEX
09 Dec 2024 11:27:18,885 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerSessionImpl [] - doHandleMessage(ServerSessionImpl[null@/127.0.0.1:49934]) process #2 SSH_MSG_NEWKEYS
09 Dec 2024 11:27:18,886 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerSessionImpl [] - handleNewKeys(ServerSessionImpl[null@/127.0.0.1:49934]) SSH_MSG_NEWKEYS command=SSH_MSG_NEWKEYS
09 Dec 2024 11:27:18,886 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerSessionImpl [] - setInputEncoding(ServerSessionImpl[null@/127.0.0.1:49934]): strict KEX resets input message sequence number from 3 to 0
09 Dec 2024 11:27:18,886 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerSessionImpl [] - setInputEncoding(ServerSessionImpl[null@/127.0.0.1:49934]): cipher org.apache.sshd.common.cipher.ChaCha20Cipher@787b0c70; mac null; compression none[Inflater/-1]; blocks limit 134217728
09 Dec 2024 11:27:18,887 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerSessionImpl [] - doHandleMessage(ServerSessionImpl[null@/127.0.0.1:49934]) process #0 SSH_MSG_SERVICE_REQUEST
09 Dec 2024 11:27:18,887 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerSessionImpl [] - handleServiceRequest(ServerSessionImpl[null@/127.0.0.1:49934]) SSH_MSG_SERVICE_REQUEST 'ssh-userauth'
09 Dec 2024 11:27:18,896 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerUserAuthService [] - ServerUserAuthService(ServerSessionImpl[null@/127.0.0.1:49934]) authorized authentication methods: password,keyboard-interactive,publickey
09 Dec 2024 11:27:18,896 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerSessionImpl [] - handleServiceRequest(ServerSessionImpl[null@/127.0.0.1:49934]) Accepted service ssh-userauth
09 Dec 2024 11:27:18,897 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerSessionImpl [] - encode(ServerSessionImpl[null@/127.0.0.1:49934]) packet #1 sending command=6[SSH_MSG_SERVICE_ACCEPT] len=17
09 Dec 2024 11:27:18,897 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:9626, remote=/127.0.0.1:49934]) writing 52 bytes
09 Dec 2024 11:27:18,898 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerSessionImpl [] - doHandleMessage(ServerSessionImpl[null@/127.0.0.1:49934]) process #1 SSH_MSG_USERAUTH_REQUEST
09 Dec 2024 11:27:18,899 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerUserAuthService [] - handleUserAuthRequestMessage(ServerSessionImpl[null@/127.0.0.1:49934]) Received SSH_MSG_USERAUTH_REQUEST user=test, service=ssh-connection, method=none
09 Dec 2024 11:27:18,899 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerUserAuthService [] - handleUserAuthRequestMessage(ServerSessionImpl[null@/127.0.0.1:49934]) Authenticating user 'test' with service 'ssh-connection' and method 'none' (attempt 0 / 20)
09 Dec 2024 11:27:18,899 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerUserAuthService [] - handleUserAuthRequestMessage(ServerSessionImpl[null@/127.0.0.1:49934]) no authentication factory for method=none
09 Dec 2024 11:27:18,899 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerUserAuthService [] - handleAuthenticationFailure(null@ServerSessionImpl[null@/127.0.0.1:49934]) SSH_MSG_USERAUTH_REQUEST
09 Dec 2024 11:27:18,900 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerUserAuthService [] - handleAuthenticationFailure(null@ServerSessionImpl[null@/127.0.0.1:49934]) remaining methods: password,keyboard-interactive,publickey
09 Dec 2024 11:27:18,900 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG ServerSessionImpl [] - encode(ServerSessionImpl[null@/127.0.0.1:49934]) packet #2 sending command=51[SSH_MSG_USERAUTH_FAILURE] len=45
09 Dec 2024 11:27:18,900 [sshd-SshServer[156324b](port=9626)-nio2-thread-3] DEBUG Nio2Session [] - writeBuffer(Nio2Session[local=/127.0.0.1:9626, remote=/127.0.0.1:49934]) writing 76 bytes

Relevant log output

No response

Other information

We also test to disable SunJCEWrapper to check if the new feature is related

System.setProperty("org.apache.sshd.security.provider.SunJCEWrapper.enabled", "false");

But we see the timeout and it seem not related to the issue.

The issue only happend in Docker image execution. In local with windows or wsl2 is not reproduced
@proprietary
Copy link

I encountered this issue also. It stalled on kexinit and timed out. This only happened in Docker (but not even all Docker runtimes, because it worked on Docker on macOS but not on Linux).

Downgrading to 2.13.2 fixed it.

@tomaswolf
Copy link
Member

If this occurs only in some dockerized runs it stands to reason that the OS inside the docker container as well as the Java version inside the container might have an influence.

@rgarciapariente , @proprietary : What OS is running inside your docker containers, and what Java version is being used?

@tomaswolf
Copy link
Member

The interesting thing in the failing logs is that between encoding the KEX_INIT message and actually sending it a lot of time passes. If we take just one session, we have in the failing server log

  • 2024-12-09T10:49:00.0263107Z 09 Dec 2024 10:48:59,997 sendKexInit
  • 2024-12-09T10:49:18.4370606Z 09 Dec 2024 10:49:18,415 encode
  • 2024-12-09T10:49:50.2022979Z 09 Dec 2024 10:49:50,146 writeBuffer

That is... strange. Could that be because of using a strong random since to commit 3cc9d48?

Can you try with that commit reverted?

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
3 participants
@tomaswolf @proprietary @rgarciapariente