Data race in SetDeadline

[jjiang-stripe]

Hello!

I have a test that runs with the -race flag that started to fail with v0.6.1. I've created a minimal repro here: https://github.com/jjiang-stripe/proxyproto-race/blob/master/main.go

That example is just running a super basic SSH server and client and it looks like Go's SSH server's running into a race when trying to update deadlines in its readLoop and kexLoop goroutines:

$ go run -race main.go 
==================
WARNING: DATA RACE
Write at 0x00c0000da058 by goroutine 27:
  github.com/pires/go-proxyproto.(*Conn).SetDeadline()
      /Users/jjiang/go/pkg/mod/github.com/pires/go-proxyproto@v0.6.1/protocol.go:218 +0x4f
  github.com/gliderlabs/ssh.(*serverConn).updateDeadline()
      /Users/jjiang/go/pkg/mod/github.com/gliderlabs/ssh@v0.3.3/conn.go:53 +0x2f9
  github.com/gliderlabs/ssh.(*serverConn).Write()
      /Users/jjiang/go/pkg/mod/github.com/gliderlabs/ssh@v0.3.3/conn.go:18 +0x44
  bufio.(*Writer).Flush()
      /usr/local/Cellar/go/1.17.2/libexec/src/bufio/bufio.go:607 +0xf0
  golang.org/x/crypto/ssh.(*connectionState).writePacket()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/transport.go:182 +0x12b
  golang.org/x/crypto/ssh.(*transport).writePacket()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/transport.go:172 +0x98
  golang.org/x/crypto/ssh.(*handshakeTransport).pushPacket()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/handshake.go:223 +0x84d
  golang.org/x/crypto/ssh.(*handshakeTransport).sendKexInit()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/handshake.go:472 +0x84e
  golang.org/x/crypto/ssh.(*handshakeTransport).kexLoop()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/handshake.go:278 +0x77d
  golang.org/x/crypto/ssh.newServerTransport·dwrap·10()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/handshake.go:143 +0x39

Previous write at 0x00c0000da058 by goroutine 25:
  github.com/pires/go-proxyproto.(*Conn).SetDeadline()
      /Users/jjiang/go/pkg/mod/github.com/pires/go-proxyproto@v0.6.1/protocol.go:218 +0x4f
  github.com/gliderlabs/ssh.(*serverConn).updateDeadline()
      /Users/jjiang/go/pkg/mod/github.com/gliderlabs/ssh@v0.3.3/conn.go:53 +0x2f9
  github.com/gliderlabs/ssh.(*serverConn).Read()
      /Users/jjiang/go/pkg/mod/github.com/gliderlabs/ssh@v0.3.3/conn.go:27 +0x44
  bufio.(*Reader).Read()
      /usr/local/Cellar/go/1.17.2/libexec/src/bufio/bufio.go:227 +0x4da
  io.ReadAtLeast()
      /usr/local/Cellar/go/1.17.2/libexec/src/io/io.go:328 +0xdd
  io.ReadFull()
      /usr/local/Cellar/go/1.17.2/libexec/src/io/io.go:347 +0x8d
  golang.org/x/crypto/ssh.(*streamPacketCipher).readCipherPacket()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/cipher.go:153 +0x55
  golang.org/x/crypto/ssh.(*connectionState).readPacket()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/transport.go:130 +0xa1
  golang.org/x/crypto/ssh.(*transport).readPacket()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/transport.go:114 +0x4a
  golang.org/x/crypto/ssh.(*handshakeTransport).readOnePacket()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/handshake.go:374 +0x71
  golang.org/x/crypto/ssh.(*handshakeTransport).readLoop()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/handshake.go:197 +0x4a
  golang.org/x/crypto/ssh.newServerTransport·dwrap·9()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/handshake.go:142 +0x39

Goroutine 27 (running) created at:
  golang.org/x/crypto/ssh.newServerTransport()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/handshake.go:143 +0x238
  golang.org/x/crypto/ssh.(*connection).serverHandshake()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/server.go:249 +0x665
  golang.org/x/crypto/ssh.NewServerConn()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/server.go:206 +0x239
  github.com/gliderlabs/ssh.(*Server).HandleConn()
      /Users/jjiang/go/pkg/mod/github.com/gliderlabs/ssh@v0.3.3/server.go:281 +0x3b1
  github.com/gliderlabs/ssh.(*Server).Serve·dwrap·12()
      /Users/jjiang/go/pkg/mod/github.com/gliderlabs/ssh@v0.3.3/server.go:258 +0x58

Goroutine 25 (running) created at:
  golang.org/x/crypto/ssh.newServerTransport()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/handshake.go:142 +0x1d0
  golang.org/x/crypto/ssh.(*connection).serverHandshake()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/server.go:249 +0x665
  golang.org/x/crypto/ssh.NewServerConn()
      /Users/jjiang/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210616213533-5ff15b29337e/ssh/server.go:206 +0x239
  github.com/gliderlabs/ssh.(*Server).HandleConn()
      /Users/jjiang/go/pkg/mod/github.com/gliderlabs/ssh@v0.3.3/server.go:281 +0x3b1
  github.com/gliderlabs/ssh.(*Server).Serve·dwrap·12()
      /Users/jjiang/go/pkg/mod/github.com/gliderlabs/ssh@v0.3.3/server.go:258 +0x58
==================
Found 1 data race(s)
exit status 66

I believe this was introduced in #76 because there's a local variable being set in SetDeadline().

Unfortunately I'm not familiar enough with what's going on here to tell if this is actually an issue or propose a fix beyond maybe throwing a lock in there. I'd appreciate a fix here (or if this isn't actually a concern, an explanation would be nice).

Happy to provide more details, but given that I'm in very unfamiliar territory, I'm not sure how much help I can be 😅

[pires]

Hey @jjiang-stripe! Thanks for taking the time to report this. It does make sense to enable race-detection in tests and fix any failures. I will pick this up unless you want to - or someone else.

[mschneider82]

i have tested the fix against the code sample https://github.com/jjiang-stripe/proxyproto-race/blob/master/main.go

[pires]

Fixed by #87! Thanks a lot for reporting @jjiang-stripe and bow to you @mschneider82 for another sweet contribution!

[pires]

v0.6.2 is tagged.