1Haz
What could cause "Bad packet length" with sshd?
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,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com
KexAlgorithms curve25519-sha256@libssh.org,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 curve25519-sha256@libssh.org,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: curve25519-sha256@libssh.org,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,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com [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,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: none,zlib@openssh.com [preauth]
Jun 06 07:16:29 server sshd[15573]: debug2: kex_parse_kexinit: none,zlib@openssh.com [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: curve25519-sha256@libssh.org,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,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com [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,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: none,zlib@openssh.com [preauth]
Jun 06 07:16:57 server sshd[15611]: debug2: kex_parse_kexinit: none,zlib@openssh.com [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
