grpc-go icon indicating copy to clipboard operation
grpc-go copied to clipboard

testing: add tests covering races in server settings handshake

Open wladh opened this issue 7 years ago • 9 comments
trafficstars

Please answer these questions before submitting your issue.

What version of gRPC are you using?

HEAD as of today (65c901e)

What version of Go are you using (go version)?

go version go1.9.2 darwin/amd64

What operating system (Linux, Windows, …) and version?

Linux, macOS

What did you do?

Connecting to a server, passing grpc.WithWaitForHandshake() option.

What did you expect to see?

Connection succeeding and staying up.

What did you see instead?

Connection comes up, and data gets exchanged, but after 20 seconds the connection gets terminated with:

WARNING: 2017/12/29 00:23:01 grpc: addrConn.transportMonitor didn't get server preface after waiting. Closing the new transport now.

(GRPC_GO_LOG_SEVERITY_LEVEL was set to info)

The connection seems to be closed in addrConn.transportMonitor after the connection deadline passes, because ac.backoffDeadline is not zero. The reason why it isn't zero, although the preface has been received (and actually RPC calls were done over that connection) is because the code that sets/resets it is racy. We seem to reset it in onPrefaceReceipt closure (in addrConn.createTransport) which gets passed to transport.NewClientTransport, but that closure is called from a different goroutine (see http2Client.reader). It might happen that this closure gets called before we set ac.backoffDeadline at the end of the loop in addrConn.createTransport, so ac.backoffDeadline will remain set even though the connection has succeeded. This race is made a lot more likely by setting WithWaitForHandshake because in that case we wait for done to be closed, which means that we wait for onPrefaceReceipt to be called before we proceed further and set ac.backoffDeadline.

The issue was introduced in #1648.

wladh avatar Dec 29 '17 08:12 wladh