rgarciapariente opened a new issue, #642: URL: https://github.com/apache/mina-sshd/issues/642
### 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 ```java System.setProperty("org.apache.sshd.security.provider.SunJCEWrapper.enabled", "false"); ``` But we see the timeout and it seem not related to the issue -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected] --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
