What could cause "Bad packet length" with sshd?

Question

I am getting a lot of failed ssh login attempts by one specific IP-Address with a strange error. I cannot make sense of the information found through google, so I was thinking it is maybe a new form of attack??

Basically every 25 seconds I get the following two rows in my journal log (the packet length differs every time):

Jun 01 08:35:14 k002271d sshd[10615]: Bad packet length 516882381. [preauth]
Jun 01 08:35:25 k002271d sshd[10540]: Connection closed by 62.210.XXX.XXX [preauth]

I don't have problems logging in using a key, I am using the latest OpenSSH (OpenSSH_6.7p1 Debian-5+deb8u2, OpenSSL 1.0.1k 8 Jan 2015) but I have enabled some additional ciphers to enable connections from an older server using the proposed string from here:

Ciphers 3des-cbc,blowfish-cbc,cast128-cbc,arcfour,arcfour128,arcfour256,aes128-cbc,aes192-cbc,aes256-cbc,[email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected],[email protected]
KexAlgorithms [email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1

Update, 2016-06-21:

As proposed by @Castaglia I removed the diffie-hellman-group1 and diffie-hellman-group14 key exchange methods (mentioned in libssh-0.7.3 release notes) resulting to this string:

KexAlgorithms [email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1

The error messages stopped to show up, still I am not 100% sure it was the solution because of the rare occurrence of the errors. For now I am leaving the question unanswered.

Update, 2016-06-06:

Finally after almost one week I was able to detect the same attack and log with LogLevel DEBUG3 as suggested by Jakuje. The following log shows two consecutive attempts by a different server than the first time:

Jun 06 07:16:29 server sshd[565]: debug3: fd 5 is not O_NONBLOCK
Jun 06 07:16:29 server sshd[565]: debug1: Forked child 15573.
Jun 06 07:16:29 server sshd[565]: debug3: send_rexec_state: entering fd = 10 config len 1263
Jun 06 07:16:29 server sshd[565]: debug3: ssh_msg_send: type 0
Jun 06 07:16:29 server sshd[565]: debug3: send_rexec_state: done
Jun 06 07:16:29 server sshd[15573]: debug3: oom_adjust_restore
Jun 06 07:16:29 server sshd[15573]: Set /proc/self/oom_score_adj to 0
Jun 06 07:16:29 server sshd[15573]: debug1: rexec start in 5 out 5 newsock 5 pipe 9 sock 10
Jun 06 07:16:29 server sshd[15573]: debug1: inetd sockets after dupping: 3, 3
Jun 06 07:16:29 server sshd[15573]: Connection from 125.212.XXX.XXX port 46328 on XXX.XXX.XXX.XXX port 22
Jun 06 07:16:29 server sshd[15573]: debug1: Client protocol version 2.0; client software version libssh-0.2
Jun 06 07:16:29 server sshd[15573]: debug1: no match: libssh-0.2
Jun 06 07:16:29 server sshd[15573]: debug1: Enabling compatibility mode for protocol 2.0
Jun 06 07:16:29 server sshd[15573]: debug1: Local version string SSH-2.0-OpenSSH_6.7p1 Debian-5+deb8u2
Jun 06 07:16:29 server sshd[15573]: debug2: fd 3 setting O_NONBLOCK
Jun 06 07:16:29 server sshd[15573]: debug2: Network child is on pid 15574
Jun 06 07:16:29 server sshd[15573]: debug3: preauth child monitor started
Jun 06 07:16:29 server sshd[15573]: debug3: privsep user:group 104:65534 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug1: permanently_set_uid: 104/65534 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Jun 06 07:16:29 server sshd[15573]: debug1: SSH2_MSG_KEXINIT received [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: [email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: 3des-cbc,blowfish-cbc,cast128-cbc,arcfour,arcfour128,arcfour256,aes128-cbc,aes192-cbc,aes256-cbc,[email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected],[email protected] [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: 3des-cbc,blowfish-cbc,cast128-cbc,arcfour,arcfour128,arcfour256,aes128-cbc,aes192-cbc,aes256-cbc,[email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected],[email protected] [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: [email protected],[email protected],[email protected],[email protected],[email protected],umac-[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: none,[email protected] [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: none,[email protected] [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit:  [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit:  [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: first_kex_follows 0  [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: reserved 0  [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: diffie-hellman-group1-sha1 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: ssh-rsa [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: 3des-cbc [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: 3des-cbc [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: hmac-sha1 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: hmac-sha1 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: none [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: none [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit:  [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit:  [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: first_kex_follows 0  [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: reserved 0  [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: mac_setup: setup hmac-sha1 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug1: kex: client->server 3des-cbc hmac-sha1 none [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: mac_setup: setup hmac-sha1 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug1: kex: server->client 3des-cbc hmac-sha1 none [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: bits set: 505/1024 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug1: expecting SSH2_MSG_KEXDH_INIT [preauth]
Jun 06 07:16:30 server sshd[15573]: debug2: bits set: 506/1024 [preauth]
Jun 06 07:16:30 server sshd[15573]: debug3: mm_key_sign entering [preauth]
Jun 06 07:16:30 server sshd[15573]: debug3: mm_request_send entering: type 6 [preauth]
Jun 06 07:16:30 server sshd[15573]: debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN [preauth]
Jun 06 07:16:30 server sshd[15573]: debug3: mm_request_receive_expect entering: type 7 [preauth]
Jun 06 07:16:30 server sshd[15573]: debug3: mm_request_receive entering [preauth]
Jun 06 07:16:30 server sshd[15573]: debug3: mm_request_receive entering
Jun 06 07:16:30 server sshd[15573]: debug3: monitor_read: checking request 6
Jun 06 07:16:30 server sshd[15573]: debug3: mm_answer_sign
Jun 06 07:16:30 server sshd[15573]: debug3: mm_answer_sign: signature 0x7ff127ec8ce0(271)
Jun 06 07:16:30 server sshd[15573]: debug3: mm_request_send entering: type 7
Jun 06 07:16:30 server sshd[15573]: debug2: monitor_read: 6 used once, disabling now
Jun 06 07:16:30 server sshd[15573]: debug2: kex_derive_keys [preauth]
Jun 06 07:16:30 server sshd[15573]: debug2: set_newkeys: mode 1 [preauth]
Jun 06 07:16:30 server sshd[15573]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Jun 06 07:16:30 server sshd[15573]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Jun 06 07:16:30 server sshd[15573]: debug2: set_newkeys: mode 0 [preauth]
Jun 06 07:16:30 server sshd[15573]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Jun 06 07:16:30 server sshd[15573]: debug1: KEX done [preauth]
Jun 06 07:16:30 server sshd[15573]: Bad packet length 2295582317. [preauth]
Jun 06 07:16:34 server sshd[15498]: Connection closed by 125.212.XXX.XXX [preauth]
Jun 06 07:16:34 server sshd[15498]: debug1: do_cleanup [preauth]
Jun 06 07:16:34 server sshd[15498]: debug3: PAM: sshpam_thread_cleanup entering [preauth]
Jun 06 07:16:34 server sshd[15498]: debug1: monitor_read_log: child log fd closed
Jun 06 07:16:34 server sshd[15498]: debug3: mm_request_receive entering
Jun 06 07:16:34 server sshd[15498]: debug1: do_cleanup
Jun 06 07:16:34 server sshd[15498]: debug3: PAM: sshpam_thread_cleanup entering
Jun 06 07:16:34 server sshd[15498]: debug1: Killing privsep child 15499
Jun 06 07:16:57 server sshd[565]: debug3: fd 5 is not O_NONBLOCK
Jun 06 07:16:57 server sshd[565]: debug1: Forked child 15611.
Jun 06 07:16:57 server sshd[565]: debug3: send_rexec_state: entering fd = 10 config len 1263
Jun 06 07:16:57 server sshd[565]: debug3: ssh_msg_send: type 0
Jun 06 07:16:57 server sshd[565]: debug3: send_rexec_state: done
Jun 06 07:16:57 server sshd[15611]: debug3: oom_adjust_restore
Jun 06 07:16:57 server sshd[15611]: Set /proc/self/oom_score_adj to 0
Jun 06 07:16:57 server sshd[15611]: debug1: rexec start in 5 out 5 newsock 5 pipe 9 sock 10
Jun 06 07:16:57 server sshd[15611]: debug1: inetd sockets after dupping: 3, 3
Jun 06 07:16:57 server sshd[15611]: Connection from 125.212.XXX.XXX port 49390 on XXX.XXX.XXX.XXX port 22
Jun 06 07:16:57 server sshd[15611]: debug1: Client protocol version 2.0; client software version libssh-0.2
Jun 06 07:16:57 server sshd[15611]: debug1: no match: libssh-0.2
Jun 06 07:16:57 server sshd[15611]: debug1: Enabling compatibility mode for protocol 2.0
Jun 06 07:16:57 server sshd[15611]: debug1: Local version string SSH-2.0-OpenSSH_6.7p1 Debian-5+deb8u2
Jun 06 07:16:57 server sshd[15611]: debug2: fd 3 setting O_NONBLOCK
Jun 06 07:16:57 server sshd[15611]: debug2: Network child is on pid 15612
Jun 06 07:16:57 server sshd[15611]: debug3: preauth child monitor started
Jun 06 07:16:57 server sshd[15611]: debug3: privsep user:group 104:65534 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug1: permanently_set_uid: 104/65534 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Jun 06 07:16:57 server sshd[15611]: debug1: SSH2_MSG_KEXINIT received [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: [email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: 3des-cbc,blowfish-cbc,cast128-cbc,arcfour,arcfour128,arcfour256,aes128-cbc,aes192-cbc,aes256-cbc,[email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected],[email protected] [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: 3des-cbc,blowfish-cbc,cast128-cbc,arcfour,arcfour128,arcfour256,aes128-cbc,aes192-cbc,aes256-cbc,[email protected],aes128-ctr,aes192-ctr,aes256-ctr,aes128-[email protected],[email protected],[email protected] [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: none,[email protected] [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: none,[email protected] [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit:  [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit:  [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: first_kex_follows 0  [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: reserved 0  [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: diffie-hellman-group1-sha1 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: ssh-rsa [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: 3des-cbc [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: 3des-cbc [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: hmac-sha1 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: hmac-sha1 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: none [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: none [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit:  [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit:  [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: first_kex_follows 0  [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: reserved 0  [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: mac_setup: setup hmac-sha1 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug1: kex: client->server 3des-cbc hmac-sha1 none [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: mac_setup: setup hmac-sha1 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug1: kex: server->client 3des-cbc hmac-sha1 none [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: bits set: 511/1024 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug1: expecting SSH2_MSG_KEXDH_INIT [preauth]
Jun 06 07:16:58 server sshd[15611]: debug2: bits set: 516/1024 [preauth]
Jun 06 07:16:58 server sshd[15611]: debug3: mm_key_sign entering [preauth]
Jun 06 07:16:58 server sshd[15611]: debug3: mm_request_send entering: type 6 [preauth]
Jun 06 07:16:58 server sshd[15611]: debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN [preauth]
Jun 06 07:16:58 server sshd[15611]: debug3: mm_request_receive_expect entering: type 7 [preauth]
Jun 06 07:16:58 server sshd[15611]: debug3: mm_request_receive entering [preauth]
Jun 06 07:16:58 server sshd[15611]: debug3: mm_request_receive entering
Jun 06 07:16:58 server sshd[15611]: debug3: monitor_read: checking request 6
Jun 06 07:16:58 server sshd[15611]: debug3: mm_answer_sign
Jun 06 07:16:58 server sshd[15611]: debug3: mm_answer_sign: signature 0x7fb75f3b5690(271)
Jun 06 07:16:58 server sshd[15611]: debug3: mm_request_send entering: type 7
Jun 06 07:16:58 server sshd[15611]: debug2: monitor_read: 6 used once, disabling now
Jun 06 07:16:58 server sshd[15611]: debug2: kex_derive_keys [preauth]
Jun 06 07:16:58 server sshd[15611]: debug2: set_newkeys: mode 1 [preauth]
Jun 06 07:16:58 server sshd[15611]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Jun 06 07:16:58 server sshd[15611]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Jun 06 07:16:58 server sshd[15611]: debug2: set_newkeys: mode 0 [preauth]
Jun 06 07:16:58 server sshd[15611]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Jun 06 07:16:58 server sshd[15611]: debug1: KEX done [preauth]
Jun 06 07:16:58 server sshd[15611]: Bad packet length 1877023791. [preauth]
Jun 06 07:17:02 server sshd[15535]: Connection closed by 125.212.XXX.XXX [preauth]
Jun 06 07:17:02 server sshd[15535]: debug1: do_cleanup [preauth]
Jun 06 07:17:02 server sshd[15535]: debug3: PAM: sshpam_thread_cleanup entering [preauth]
Jun 06 07:17:02 server sshd[15535]: debug1: monitor_read_log: child log fd closed
Jun 06 07:17:02 server sshd[15535]: debug3: mm_request_receive entering
Jun 06 07:17:02 server sshd[15535]: debug1: do_cleanup
Jun 06 07:17:02 server sshd[15535]: debug3: PAM: sshpam_thread_cleanup entering
Jun 06 07:17:02 server sshd[15535]: debug1: Killing privsep child 15536

Answer 1

This has been extensively explained but here is the summary:

This problem happens when either party decrypts the first cipher block of the SSH packet and checks the packet length. Obviously, the packet length must be at least 5 bytes. RFC 4253 specifies that any implementation must support the length of the whole packet to be at least 35000 bytes. Anyway, SSH implementations usually allow for longer packets. OpenSSH/SunSSH accepts length field to be up to 256KB (256 * 1024). So, this must be true otherwise we have a bad packet length:

5 <= length <= 256 * 1024 Possible reasons for "Bad packet length"

There is usually only one reason for this error message - bad encryption or decryption. In that case the peer decrypts the 1st cipher block and gets some rubbish in those 4 bytes. The probability that the rubbish will fit into the correct packet length is (256 * 1024)/2\^32. That's roughly 0.006%, meaning 6 badly processed cipher blocks out of 100000 of them will pass the initial length test. And even after that, only 1 of 16 succeeds in case of the mostly used cipher - AES; all in all, on average only 4 random cipher blocks out of 1 milion pass the initial packet length field tests (1/2\^18). We will talk a little bit more about that later.

Could it be just a corruption on the wire? Could be but the chance that it happened in those specific 4 bytes for the first time during the SSH TCP connection is also very small. Note that if the corruption happened during the initial key exchange the connection would have been closed - the protocol is protected against such situation. So, if the problem is the encryption or decryption it usually happens right after the key exhange when the first encrypted message, SSH_MSG_SERVICE_REQUEST, is sent.

Obviously, it could be a bug in the SSH implementation itself but that's usually not the case, here it would probably either work or not.

Answer 2

I can't make comments yet, as most of security-related answers are on reverse-engineering stackexhange . com.

It sounds as though someone is trying to bruteforce your ssh server (happened a lot last year from TK, RU and CN to my amazon EC2 instance). Like munkeyoto stated, if the attacker's MTU is set too high it can cause runts, which means the packet size is too large for intermediary hops (routers) so they have to truncate the packet and split it up into smaller packets.

Its usually caused by high noise-to-signal ratio over the wire (attenuation), intermediary nodes (routers) that have varying MTUs which will truncate packets, asymmetric routing, etc.