testing: add tests covering races in server settings handshake

[wladh]

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.

[MakMukhi]

Ah man! I missed that possibility. I'll try and have a fix out by tomorrow ( traveling today). Also, thanks a lot for digging up the root cause.

…

On Fri, Dec 29, 2017, 2:25 AM Vlad Hanciuta ***@***.***> wrote: Please answer these questions before submitting your issue. What version of gRPC are you using? HEAD as of today (65c901e <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 <#1648>. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#1772>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ATtnR8lGMEdBtGfbMjHR6SM5AXYBsqbLks5tFKHegaJpZM4RO8WX> .

[pawelkowalak]

A new version has been tagged (1.9.0) with this issue. Maybe it should be added to Known issues in release notes :)

[RichiH]

@fhibler - it's fixed.
@MakMukhi / @vIRu - thanks!

[wladh]

@RichiH I think you misunderstood @vIRu’s message. He meant that the version that was just released (1.9.0) is affected by this issue, not that it’s fixed in that version.

[RichiH]

@wladh Ah, thanks for clearing that up.

[dfawley]

@MakMukhi is there any way to attempt to stimulate this race in a regression test? Why didn't our tests ever run into this problem?

[dfawley]

I'm going to reopen this to track adding regression test cases as discussed offline:

1. Use WithWaitForHandshake() in a case where the remote server never sends the preface, and ensure RPCs are never assigned to that connection (i.e. its state never becomes Ready). Without WithWaitForHandshake(), RPCs should be assigned to it (i.e. its state does become Ready after Accepting the connection).
2. Add a sleep after the server handshake is received in TestDialWaitsForServerSettings, longer than the minConnectTimeout, and make sure the connection is still valid.

EDIT: 1 doesn't really need to be a separate case that TestDialWaitsForServerSettings isn't already covering. That one ensures Dial doesn't return until the handshake happens, which is essential the same thing.

[dfawley]

FYI: v1.9.1 has been released with the fix to this issue.

[stale]

This issue is labeled as requiring an update from the reporter, and no update has been received after 7 days. If no update is provided in the next 7 days, this issue will be automatically closed.