x/crypto ssh.Dial fails to create client and hangs in clientAuthenticate, indefinitely

[mfridman]

go version go1.9
darwin/amd64
go get -u golang.org/x/crypto/ssh

What did you do?

Note, one does not need a username, password or keys to reproduce the issue.
ssh user@<redacted> should return a host key fingerprint and a password prompt. This issue occurs during client authentication.

What did you expect to see?

An error, given Timeout: time.Duration(2) * time.Second:

• for an IP with a server listening on port:
  ssh: handshake failed: ssh: unable to authenticate, attempted methods [none password], no supported methods remain

• for a random IP:
  dial tcp <redacted>:22: i/o timeout

What did you see instead?

ssh.Dial hangs indefinitely. No amount of error handling could get the program to return from ssh.Dial for the above IP.

I believe the issue begins here:
packet, err := c.transport.readPacket() in client_auth.go clientAuthenticate()

no packet or err is returned.

Although this is likely an issue with the host, the client (via ssh.Dial) should still be able to "escape". I.e., hosts should not be able to hijack a client during clientAuthenticate.

[hanwen]

ClientConf.Timeout sets the arg for net.DialWithTimeout(). Maybe we should also set the timout on the resulting net.Conn.

[mfridman]

I think the client should be able to terminate at both the initial dial and the subsequent authentication step.

For backwards compatibility, would it be worth adding ssh.ClientConfig.AuthTimeout and letting it propagate down?

For the above host, once the program makes it to clientAuthenticate() it hangs there. It's possible there is a workaround, but I could not terminate ssh.Dial and skip this host. Ended up taking it out of the pool.

Oddly, SSH and Python's Paramiko package successfully establish a connection. So there must be a difference in Go's implementation of the SSH authentication that's throwing it off. But that's beyond the scope of this ticket

[hanwen]

I'd rather fix the hang than add another feature.

Can you see if you can put some traces with debugHandshake=true and/or debugTransport=true on the bugreport? Also, repro the hang, and do C-\ , and post the stacktraces.

[mfridman]

I'd like to get more involved in Go and potentially contribute, so if I'm doing something wrong with this ticket please DM me and let me know of ways to improve.

This is the code used:

Here is the trace with debugHandshake=true and debugTransport=true, C-\

2017/11/08 09:07:21 client sent *ssh.kexInitMsg &{[128 101 123 92 191 58 153 151 153 229 181 118 136 69 71 152] [curve25519-sha256@libssh.org ecdh-sha2-nistp256 ecdh-sha2-nistp384 ecdh-sha2-nistp521 diffie-hellman-group14-sha1 diffie-hellman-group1-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 aes192-ctr aes256-ctr aes128-gcm@openssh.com arcfour256 arcfour128] [aes128-ctr aes192-ctr aes256-ctr aes128-gcm@openssh.com arcfour256 arcfour128] [hmac-sha2-256-etm@openssh.com hmac-sha2-256 hmac-sha1 hmac-sha1-96] [hmac-sha2-256-etm@openssh.com hmac-sha2-256 hmac-sha1 hmac-sha1-96] [none] [none] [] [] false 0} (<nil>)
2017/11/08 09:07:21 write client 20
2017/11/08 09:07:21 read client 20
2017/11/08 09:07:21 client got *ssh.kexInitMsg &{[41 198 194 77 198 188 217 113 247 29 206 120 30 39 134 212] [diffie-hellman-group-exchange-sha256 diffie-hellman-group-exchange-sha1 diffie-hellman-group14-sha1 diffie-hellman-group1-sha1] [ssh-rsa ssh-dss] [aes128-ctr aes192-ctr aes256-ctr arcfour256 arcfour128 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-cbc 3des-cbc blowfish-cbc cast128-cbc aes192-cbc aes256-cbc arcfour rijndael-cbc@lysator.liu.se] [hmac-md5 hmac-sha1 umac-64@openssh.com hmac-ripemd160 hmac-ripemd160@openssh.com hmac-sha1-96 hmac-md5-96] [hmac-md5 hmac-sha1 umac-64@openssh.com hmac-ripemd160 hmac-ripemd160@openssh.com hmac-sha1-96 hmac-md5-96] [none zlib@openssh.com] [none zlib@openssh.com] [] [] false 0} (<nil>)
2017/11/08 09:07:21 client entered key exchange
2017/11/08 09:07:21 write client 30
2017/11/08 09:07:21 read client 31
2017/11/08 09:07:21 write client 21
2017/11/08 09:07:21 read client 21
2017/11/08 09:07:21 client exited key exchange (first true), err <nil>
2017/11/08 09:07:21 client sent *ssh.serviceRequestMsg &{ssh-userauth} (<nil>)
2017/11/08 09:07:21 write client 5
^\SIGQUIT: quit
PC=0x105800b m=0 sigcode=0

goroutine 0 [idle]:
runtime.mach_semaphore_wait(0xf03, 0xe, 0x0, 0x7ffeefbff320, 0x10225aa, 0x128b9a0, 0x7ffeefbff320, 0x1052863, 0xffffffffffffffff, 0x140c698, ...)
        /usr/local/go/src/runtime/sys_darwin_amd64.s:445 +0xb
runtime.semasleep1(0xffffffffffffffff, 0x140c698)
        /usr/local/go/src/runtime/os_darwin.go:413 +0x52
runtime.semasleep.func1()
        /usr/local/go/src/runtime/os_darwin.go:432 +0x33
runtime.systemstack(0x7ffeefbff348)
        /usr/local/go/src/runtime/asm_amd64.s:360 +0xab
runtime.semasleep(0xffffffffffffffff, 0x1)
        /usr/local/go/src/runtime/os_darwin.go:431 +0x44
runtime.notesleep(0x128bfb0)
        /usr/local/go/src/runtime/lock_sema.go:167 +0xe9
runtime.stopm()
        /usr/local/go/src/runtime/proc.go:1670 +0xe5
runtime.findrunnable(0xc420022000, 0x0)
        /usr/local/go/src/runtime/proc.go:2125 +0x4d2
runtime.schedule()
        /usr/local/go/src/runtime/proc.go:2245 +0x12c
runtime.park_m(0xc420000180)
        /usr/local/go/src/runtime/proc.go:2308 +0xb6
runtime.mcall(0x7ffeefbff530)
        /usr/local/go/src/runtime/asm_amd64.s:286 +0x5b

goroutine 1 [chan receive]:
golang.org/x/crypto/ssh.(*handshakeTransport).readPacket(...)
        /Users/MFair/development/go/src/golang.org/x/crypto/ssh/handshake.go:181
golang.org/x/crypto/ssh.(*connection).clientAuthenticate(0xc42009a180, 0xc42009c000, 0x0, 0xa)
        /Users/MFair/development/go/src/golang.org/x/crypto/ssh/client_auth.go:20 +0x112
golang.org/x/crypto/ssh.(*connection).clientHandshake(0xc42009a180, 0x11ae9d1, 0x11, 0xc42009c000, 0x77359400, 0x0)
        /Users/MFair/development/go/src/golang.org/x/crypto/ssh/client.go:112 +0x2d9
golang.org/x/crypto/ssh.NewClientConn(0x12766c0, 0xc42000e030, 0x11ae9d1, 0x11, 0xc42004feb0, 0x12766c0, 0xc42000e030, 0x0, 0x0, 0xc42000ca01, ...)
        /Users/MFair/development/go/src/golang.org/x/crypto/ssh/client.go:82 +0xfd
golang.org/x/crypto/ssh.Dial(0x11aca73, 0x3, 0x11ae9d1, 0x11, 0xc42004feb0, 0x12aa3d8, 0xc42004fe60, 0x1011678)
        /Users/MFair/development/go/src/golang.org/x/crypto/ssh/client.go:176 +0xb3
main.main()
        /Users/MFair/development/go/src/debug/conn.go:17 +0x151

goroutine 7 [IO wait]:
internal/poll.runtime_pollWait(0x146af70, 0x72, 0x0)
        /usr/local/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc42009a098, 0x72, 0xffffffffffffff00, 0x1274000, 0x1272228)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0xae
internal/poll.(*pollDesc).waitRead(0xc42009a098, 0xc42009e000, 0x1000, 0x1000)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc42009a080, 0xc42009e000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /usr/local/go/src/internal/poll/fd_unix.go:125 +0x18a
net.(*netFD).Read(0xc42009a080, 0xc42009e000, 0x1000, 0x1000, 0x107a870, 0xc4200820a0, 0xc4200aa700)
        /usr/local/go/src/net/fd_unix.go:202 +0x52
net.(*conn).Read(0xc42000e030, 0xc42009e000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /usr/local/go/src/net/net.go:176 +0x6d
bufio.(*Reader).Read(0xc42005e1e0, 0xc42009a4a1, 0x5, 0x5, 0xc42004bc48, 0xc4200aa700, 0xc42004bc38)
        /usr/local/go/src/bufio/bufio.go:213 +0x30b
io.ReadAtLeast(0x1273340, 0xc42005e1e0, 0xc42009a4a1, 0x5, 0x5, 0x5, 0x0, 0x0, 0x0)
        /usr/local/go/src/io/io.go:309 +0x86
io.ReadFull(0x1273340, 0xc42005e1e0, 0xc42009a4a1, 0x5, 0x5, 0x47, 0x380, 0x47)
        /usr/local/go/src/io/io.go:327 +0x58
golang.org/x/crypto/ssh.(*streamPacketCipher).readPacket(0xc42009a480, 0x3, 0x1273340, 0xc42005e1e0, 0xc42004bd80, 0xc42004be20, 0x10a627b, 0xc4200820f0, 0xc4200aa700)
        /Users/MFair/development/go/src/golang.org/x/crypto/ssh/cipher.go:150 +0x7c
golang.org/x/crypto/ssh.(*connectionState).readPacket(0xc42008c360, 0xc42005e1e0, 0xc420082120, 0xc42004be58, 0x100573b, 0x102bf2b, 0xc42004be40)
        /Users/MFair/development/go/src/golang.org/x/crypto/ssh/transport.go:129 +0x68
golang.org/x/crypto/ssh.(*transport).readPacket(0xc42008c360, 0xc420000180, 0xc42005e1a0, 0xc42004bf30, 0x1005448, 0xc42005e300)
        /Users/MFair/development/go/src/golang.org/x/crypto/ssh/transport.go:113 +0x3b
golang.org/x/crypto/ssh.(*handshakeTransport).readOnePacket(0xc4200a0000, 0xc42004bf00, 0xc420014a5b, 0x1, 0x1, 0x0, 0x0)
        /Users/MFair/development/go/src/golang.org/x/crypto/ssh/handshake.go:368 +0x48
golang.org/x/crypto/ssh.(*handshakeTransport).readLoop(0xc4200a0000)
        /Users/MFair/development/go/src/golang.org/x/crypto/ssh/handshake.go:191 +0x3c
created by golang.org/x/crypto/ssh.newClientTransport
        /Users/MFair/development/go/src/golang.org/x/crypto/ssh/handshake.go:128 +0x183

goroutine 8 [select]:
golang.org/x/crypto/ssh.(*handshakeTransport).kexLoop(0xc4200a0000)
        /Users/MFair/development/go/src/golang.org/x/crypto/ssh/handshake.go:262 +0x13a
created by golang.org/x/crypto/ssh.newClientTransport
        /Users/MFair/development/go/src/golang.org/x/crypto/ssh/handshake.go:129 +0x1a5

rax    0xe
rbx    0x128bea0
rcx    0x7ffeefbff2c0
rdx    0x7ffeefbff348
rdi    0xf03
rsi    0x1
rbp    0x7ffeefbff2f8
rsp    0x7ffeefbff2c0
r8     0xc42005e1d8
r9     0xc420000208
r10    0xc42005e340
r11    0x246
r12    0xc42005e338
r13    0xaef18321
r14    0xa1ab176e
r15    0x843a2ddd
rip    0x105800b
rflags 0x246
cs     0x7
fs     0x0
gs     0x0
exit status 2

[hanwen]

It's waiting for the remote side to say something back. What is the remote site running?

[mfridman]

OpenSSH. Indeed, the host likely has an improperly configured SSH server that isn't responding correctly towards the end of the authentication exchange, causing the client to hang. But, I don't think the client should hang when it encounters such as case.

[mfridman]

@hanwen I propose closing this ticket. The issue is an edge case that isn't easily reproducible, unless one has a host that fails the authentication sequence and leaves the client hanging. It's also solvable with currently available tools.

To mitigate the issue one could request the sys admin to reinstall or upgrade openSSH on host.

From the client's perspective, one could wrap ssh.Dial in a goroutine with a buffered channel and have an app-specific timeout. We actually like this approach much better, as we don't care if the client fails during initial connection or subsequent authentication.

[Greyh4t]

This problem is reproduced when the service on port 22 is redis

[initialed85]

@mfridman Not sure if you still had an outstanding issue to be solved with this- I came across the same issue in an environment where I was unable to propose changing any details about the SSH servers (customer's Ubiquiti and Motorola wireless access points with poor connectivity).

My workaround was to create my own TCP connection (rather than using ssh.Dial) and make heavy use of the .SetDeadline() method.

Before each call that could potentially hang forever under flaky circumstances I'd set the deadline to be time.Now() + timeout and then on completion, I'd return the deadline to time.Time{}.

It's showing good results, no more hanging on those few edge cases.

[sponeil]

If you never resolved this problem, I just ran into a similar problem with Go's SSH server handshake when I enabled older ciphers like aes128-cbc and 3des-cbc, and the workaround I found might shed some light onto your original problem.

The clue to the workaround was that I have a very old Putty SSH/SFTP client that connected just fine using those older ciphers, but the current Linux SSH/SFTP client hung connecting to Go's SSH server when I tried to use them.

A packet trace showed the Putty client used older key exchanges and HMAC algorithms, so I tried limiting the key exchange and HMAC algorithms in my Go server's SSH config, and the problem vanished for the other SFTP/SSH clients. So there seems to be a bug in Go's SSH implementation, but only when certain combinations of cipher, key exchange, and HMAC algorithms are selected.

Note: On the Go SSH server side, it didn't seem to notice the client had sent the SSH2_MSG_SERVICE_REQUEST message. A packet trace showed it being sent, but the Go server was stuck waiting on that "packet" to come.

[qiangli]

One of my project started to fail since go 1.9 unless built with vendored old version. Here is what I did to migrate to go 1.11 modules after init the project module (as workaround until we can identify and fix the issue)

go get golang.org/x/crypto/ssh@81e9090cd6fd217b62423c0908922eadb30
(other old comits may also work)

make sure your go.mod file has an entry similiar to the following:

golang.org/x/crypto v0.0.0-20170825220121-81e9090