x/crypto/ssh: unexpected message type 3 (expected 0)

[pquerna]

Unable to complete KEX: unexpected message type 3 (expected 0)

Version of crypto/sssh

Since golang/crypto@77014cf was merged, we have had this issue

What did you do?

Connecting to OpenSSH_6.6.1p1 Ubuntu-2ubuntu2.8, OpenSSL 1.0.1f 6 Jan 2014 (Ubuntu 14.04):

Output from handshakeDebug:

2017/03/21 08:39:13 client sent *ssh.kexInitMsg &{[219 201 254 246 107 208 41 93 18 242 138 109 69 172 221 211] [curve25519-sha256@libssh.org ecdh-sha2-nistp256 ecdh-sha2-nistp384 ecdh-sha2-nistp521 diffie-hellman-group14-sha1] [ssh-rsa-cert-v01@openssh.com ssh-dss-cert-v01@openssh.com ecdsa-sha2-nistp256-cert-v01@openssh.com ecdsa-sha2-nistp384-cert-v01@openssh.com ecdsa-sha2-nistp521-cert-v01@openssh.com ssh-ed25519-cert-v01@openssh.com ecdsa-sha2-nistp256 ecdsa-sha2-nistp384 ecdsa-sha2-nistp521 ssh-rsa ssh-dss ssh-ed25519] [aes128-ctr aes256-ctr aes192-ctr aes128-gcm@openssh.com] [aes128-ctr aes256-ctr aes192-ctr aes128-gcm@openssh.com] [hmac-sha2-256 hmac-sha1] [hmac-sha2-256 hmac-sha1] [none] [none] [] [] false 0} (<nil>)
2017/03/21 08:39:13 client got *ssh.kexInitMsg &{[188 229 8 82 129 196 249 3 108 192 5 108 146 151 203 26] [curve25519-sha256@libssh.org ecdh-sha2-nistp256 ecdh-sha2-nistp384 ecdh-sha2-nistp521 diffie-hellman-group-exchange-sha256 diffie-hellman-group-exchange-sha1 diffie-hellman-group14-sha1 diffie-hellman-group1-sha1] [ssh-rsa ssh-dss ecdsa-sha2-nistp256 ssh-ed25519] [aes128-ctr aes192-ctr aes256-ctr arcfour256 arcfour128 aes128-gcm@openssh.com aes256-gcm@openssh.com chacha20-poly1305@openssh.com aes128-cbc 3des-cbc blowfish-cbc cast128-cbc aes192-cbc aes256-cbc arcfour rijndael-cbc@lysator.liu.se] [aes128-ctr aes192-ctr aes256-ctr arcfour256 arcfour128 aes128-gcm@openssh.com aes256-gcm@openssh.com chacha20-poly1305@openssh.com aes128-cbc 3des-cbc blowfish-cbc cast128-cbc aes192-cbc aes256-cbc arcfour rijndael-cbc@lysator.liu.se] [hmac-md5-etm@openssh.com hmac-sha1-etm@openssh.com umac-64-etm@openssh.com umac-128-etm@openssh.com hmac-sha2-256-etm@openssh.com hmac-sha2-512-etm@openssh.com hmac-ripemd160-etm@openssh.com hmac-sha1-96-etm@openssh.com hmac-md5-96-etm@openssh.com hmac-md5 hmac-sha1 umac-64@openssh.com umac-128@openssh.com hmac-sha2-256 hmac-sha2-512 hmac-ripemd160 hmac-ripemd160@openssh.com hmac-sha1-96 hmac-md5-96] [hmac-md5-etm@openssh.com hmac-sha1-etm@openssh.com umac-64-etm@openssh.com umac-128-etm@openssh.com hmac-sha2-256-etm@openssh.com hmac-sha2-512-etm@openssh.com hmac-ripemd160-etm@openssh.com hmac-sha1-96-etm@openssh.com hmac-md5-96-etm@openssh.com hmac-md5 hmac-sha1 umac-64@openssh.com umac-128@openssh.com hmac-sha2-256 hmac-sha2-512 hmac-ripemd160 hmac-ripemd160@openssh.com hmac-sha1-96 hmac-md5-96] [none zlib@openssh.com] [none zlib@openssh.com] [] [] false 0} (<nil>)
2017/03/21 08:39:13 client entered key exchange
2017/03/21 08:39:13 client exited key exchange (first true), err <nil>
2017/03/21 08:39:13 client sent *ssh.serviceRequestMsg &{ssh-userauth} (<nil>)
2017/03/21 08:39:13 client sent *ssh.kexInitMsg &{[255 183 233 3 0 190 186 115 180 104 102 192 14 61 99 10] [curve25519-sha256@libssh.org ecdh-sha2-nistp256 ecdh-sha2-nistp384 ecdh-sha2-nistp521 diffie-hellman-group14-sha1] [ssh-rsa-cert-v01@openssh.com ssh-dss-cert-v01@openssh.com ecdsa-sha2-nistp256-cert-v01@openssh.com ecdsa-sha2-nistp384-cert-v01@openssh.com ecdsa-sha2-nistp521-cert-v01@openssh.com ssh-ed25519-cert-v01@openssh.com ecdsa-sha2-nistp256 ecdsa-sha2-nistp384 ecdsa-sha2-nistp521 ssh-rsa ssh-dss ssh-ed25519] [aes128-ctr aes256-ctr aes192-ctr aes128-gcm@openssh.com] [aes128-ctr aes256-ctr aes192-ctr aes128-gcm@openssh.com] [hmac-sha2-256 hmac-sha1] [hmac-sha2-256 hmac-sha1] [none] [none] [] [] false 0} (<nil>)
2017/03/21 08:39:13 client got *ssh.serviceAcceptMsg &{ssh-userauth} (<nil>)

sshd logs on DEBUG:

Mar 21 15:39:13 bastion sshd[29276]: debug1: Forked child 2595.
Mar 21 15:39:13 bastion sshd[2595]: Set /proc/self/oom_score_adj to 0
Mar 21 15:39:13 bastion sshd[2595]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Mar 21 15:39:13 bastion sshd[2595]: debug1: inetd sockets after dupping: 3, 3
Mar 21 15:39:13 bastion sshd[2595]: Connection from 52.XX.XX.XX port 59982 on 10.XX.XX.XX port 22
Mar 21 15:39:13 bastion sshd[2595]: debug1: Client protocol version 2.0; client software version Go
Mar 21 15:39:13 bastion sshd[2595]: debug1: no match: Go
Mar 21 15:39:13 bastion sshd[2595]: debug1: Enabling compatibility mode for protocol 2.0
Mar 21 15:39:13 bastion sshd[2595]: debug1: Local version string SSH-2.0-OpenSSH_6.6.1p1 Ubuntu-2ubuntu2.8
Mar 21 15:39:13 bastion sshd[2595]: debug1: permanently_set_uid: 104/65534 [preauth]
Mar 21 15:39:13 bastion sshd[2595]: debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Mar 21 15:39:13 bastion sshd[2595]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Mar 21 15:39:13 bastion sshd[2595]: debug1: SSH2_MSG_KEXINIT received [preauth]
Mar 21 15:39:13 bastion sshd[2595]: debug1: kex: client->server aes128-ctr hmac-sha2-256 none [preauth]
Mar 21 15:39:13 bastion sshd[2595]: debug1: kex: server->client aes128-ctr hmac-sha2-256 none [preauth]
Mar 21 15:39:13 bastion sshd[2595]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
Mar 21 15:39:13 bastion sshd[2595]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Mar 21 15:39:13 bastion sshd[2595]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Mar 21 15:39:13 bastion sshd[2595]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Mar 21 15:39:13 bastion sshd[2595]: debug1: KEX done [preauth]
Mar 21 15:39:13 bastion sshd[2595]: dispatch_protocol_error: type 20 seq 4 [preauth]
Mar 21 15:39:13 bastion sshd[2595]: Connection closed by 50.XX.XX.XX [preauth]
Mar 21 15:39:13 bastion sshd[2595]: debug1: do_cleanup [preauth]
Mar 21 15:39:13 bastion sshd[2595]: debug1: monitor_read_log: child log fd closed
Mar 21 15:39:13 bastion sshd[2595]: debug1: do_cleanup
Mar 21 15:39:13 bastion sshd[2595]: debug1: Killing privsep child 2596
Mar 21 15:39:13 bastion sshd[2595]: debug1: audit_event: unhandled event 12

Seems related to the race conditions discussed in #18861 but the "fix" broke it for us.

[hanwen]

&@%&@% !

[hanwen]

can you confirm you have no overrides for rekeyThreshold?

[hanwen]

I still can't see how this can happen, but can you see if https://go-review.googlesource.com/c/38697/ and https://go-review.googlesource.com/c/38696/ help with this issue?

[pquerna]

@hanwen Wow. Thank you. You are right about the RekeyThreshold being whack.

We have a bunch of code for parsing OpenSSH config files, and if RekeyLimit wasn't present, it would store it as a -1 in our configuration object, as an int64. When we were converting our config object into an ssh.ClientConfig, we just uint64(c.RekeyThreshold).. so it was getting set to 0xffffffffffffffff.

By fixing our client configuration parser to handle this, we set ssh.ClientConfig.RekeyThreshold to zero, and the current master of x/crypto/ssh works in some basic testing so far.

This is squarely something we did wrong. I'm not sure if it would make sense to have the client return an error if RekeyThreshold is above some reasonable value?

[hanwen]

I should sanitize this configuration more carefully.

[gopherbot]

CL https://golang.org/cl/39431 mentions this issue.