Bad packet received by server when hearbeat is enabled

[rasantel]

Occasionally, when enabling the default keep-alive (the heartbeater) and then connecting, the ssh server receives a bad packet immediately after the key exchange and closes the connection.

The sshd server logs show:

Nov  9 16:19:28 raul-dev sshd[399917]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Nov  9 16:19:28 raul-dev sshd[399917]: debug3: receive packet: type 21 [preauth]
Nov  9 16:19:28 raul-dev sshd[399917]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Nov  9 16:19:28 raul-dev sshd[399917]: debug2: set_newkeys: mode 0 [preauth]
Nov  9 16:19:28 raul-dev sshd[399917]: debug1: rekey in after 134217728 blocks [preauth]
Nov  9 16:19:28 raul-dev sshd[399917]: debug1: KEX done [preauth]
Nov  9 16:19:28 raul-dev sshd[399917]: Bad packet length 2412619996. [preauth]
Nov  9 16:19:28 raul-dev sshd[399917]: debug3: send packet: type 1 [preauth]
Nov  9 16:19:28 raul-dev sshd[399917]: ssh_dispatch_run_fatal: Connection from 127.0.0.1 port 57466: Connection corrupted [preauth]

and the SSHJ logs show:

[2023-11-09T16:19:28,937][DEBUG][net.schmizz.sshj.transport.KeyExchanger][sshj-Reader-localhost/127.0.0.1:22-1699546768919][KeyExchanger.sendNewKeys] Sending SSH_MSG_NEWKEYS
[2023-11-09T16:19:28,937][TRACE][net.schmizz.sshj.transport.Encoder][sshj-Reader-localhost/127.0.0.1:22-1699546768919][Encoder.encode] Encoding packet #2: 15
[2023-11-09T16:19:28,937][TRACE][net.schmizz.sshj.transport.Decoder][sshj-Reader-localhost/127.0.0.1:22-1699546768919][Decoder.decode] Received packet #2: 15
[2023-11-09T16:19:28,937][TRACE][net.schmizz.sshj.transport.TransportImpl][sshj-Reader-localhost/127.0.0.1:22-1699546768919][TransportImpl.handle] Received packet NEWKEYS
[2023-11-09T16:19:28,937][DEBUG][net.schmizz.sshj.transport.KeyExchanger][sshj-Reader-localhost/127.0.0.1:22-1699546768919][KeyExchanger.handle] Received SSH_MSG_NEWKEYS
[2023-11-09T16:19:28,938][DEBUG][net.schmizz.keepalive.Heartbeater][sshj-Heartbeater-localhost/127.0.0.1:22-1699546768919][KeepAlive.run] Heartbeater Started with interval [60 seconds]
[2023-11-09T16:19:28,938][DEBUG][net.schmizz.keepalive.Heartbeater][sshj-Heartbeater-localhost/127.0.0.1:22-1699546768919][KeepAlive.run] Heartbeater Sending after interval [60 seconds]
[2023-11-09T16:19:28,938][TRACE][net.schmizz.sshj.transport.Encoder][sshj-Heartbeater-localhost/127.0.0.1:22-1699546768919][Encoder.encode] Encoding packet #3: 02
[2023-11-09T16:19:28,943][DEBUG][net.schmizz.concurrent.Promise][sshj-Reader-localhost/127.0.0.1:22-1699546768919][Promise.deliver] Setting <<kexinit sent>> to `null`
[2023-11-09T16:19:28,943][DEBUG][net.schmizz.concurrent.Promise][sshj-Reader-localhost/127.0.0.1:22-1699546768919][Promise.deliver] Setting <<kex done>> to `SOME`
[2023-11-09T16:19:28,943][DEBUG][net.schmizz.sshj.SSHClient][Test worker][SSHClient.doKex] Key exchange took 0.011 seconds
[2023-11-09T16:19:28,943][DEBUG][com.delphix.appliance.server.dhm.impl.SshManagerImpl$SshClientImpl][Test worker][SshManagerImpl$SshClientImpl.connectWithAuthMethod] Connected with client: net.schmizz.sshj.SSHClient@743fad70 - LA: /127.0.0.1 LP: 57466 RA: localhost/127.0.0.1
[2023-11-09T16:19:28,944][DEBUG][net.schmizz.concurrent.Promise][Test worker][Promise.deliver] Setting <<service accept>> to `null`
[2023-11-09T16:19:28,944][DEBUG][net.schmizz.sshj.transport.TransportImpl][Test worker][TransportImpl.sendServiceRequest] Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
[2023-11-09T16:19:28,944][DEBUG][net.schmizz.concurrent.Promise][Test worker][Promise.tryRetrieve] Awaiting <<service accept>>
[2023-11-09T16:19:28,945][DEBUG][net.schmizz.sshj.transport.TransportImpl][sshj-Reader-localhost/127.0.0.1:22-1699546768919][TransportImpl.handle] Received SSH_MSG_EXT_INFO
[2023-11-09T16:19:28,982][ERROR][net.schmizz.sshj.transport.TransportImpl][sshj-Reader-localhost/127.0.0.1:22-1699546768919][TransportImpl.die] Dying because - Broken transport; encountered EOF
net.schmizz.sshj.transport.TransportException: Broken transport; encountered EOF
        at net.schmizz.sshj.transport.Reader.run(Reader.java:58)

Based on the timings of these messages, I conjectured that the hearbeat (SSH_MSG_IGNORE=2) is sent by SSHJ to the server right after the server has sent and received SSG_MSG_NEWKEYS and thus switched to the new keys (according to https://www.ietf.org/rfc/rfc4253.txt) but right before SSHJ itself has updated its keys, which happens at KeyExchanger.gotNewKeys, when handling the SSG_MSG_NEWKEYS from the server. As a consequence, the heartbeat is encoded with the old keys and the server tries to decode it with the new keys, which results in garbage (e.g. Bad packet length 2412619996 in the server log).

I am able to reproduce the issue consistently by:

1. Attaching a debugger to my java program that uses SSHJ.
2. Setting a breakpoint at HeartBeater.doKeepAlive.
3. Setting another breakpoint at the entrance of KeyExchanger.gotNewKeys. Once this breakpoint is hit, the server has switched to the new keys but the SSHJ client hasn't yet.
4. Once both breakpoints are hit, resume the hearbeat thread so that it sends the heartbeat to the server using the old keys.
5. Resume the reader thread that was stopped at KeyExchanger.gotNewKeys.

After 4, the server logs will show Bad packet length <garbage> and after 5 the SSHJ client's reader thread or the hearbeater thread will detect a broken transport and close the connection.

[hierynomus]

I definitely think you're right about the timiwlng issue. Will have a look into it!