transport: fix error handling on Stream deletion #1275

gyuho · 2017-06-01T22:51:42Z

This patch writes client-side error before closing the active stream
to fix blocking RecvMsg issue on grpc.ClientStream [1].

Previous gRPC client stream just exits on ClientTransport.Error [2].
And latest gRPC added another select case on client connection context
cancel [3]. Now when client stream closes from client connection context
cancel, it calls CloseStream with ErrClientConnClosing error. And then
the stream gets deleted from *http2Client.activeStreams, without processing
the error [4]. Then in-flight RecvMsg call on this client will block on
*parser.Reader.recvMsg [5].

In short,

ClientConn.Close.
in-flight streams will receive case <-cc.ctx.Done() https://github.com/grpc/grpc-go/blob/master/stream.go#L253-L255.
cs.closeTransportStream(ErrClientConnClosing) calls cs.t.CloseStream(cs.s, err).
CloseStream(cs.s, err) calls delete(t.activeStreams, s.id) without handling the error.
in-flight streams will never receive error, left hanging.

I can reproduce in etcd tests with in-flight recvMsg calls to Observe RPC.

[1] etcd-io/etcd#7896 (comment)
[2] https://github.com/grpc/grpc-go/blob/v1.2.x/stream.go#L235-L238
[3] #1136
[4] https://github.com/grpc/grpc-go/blob/master/transport/http2_client.go#L569
[5] https://github.com/grpc/grpc-go/blob/master/rpc_util.go#L280

/cc @xiang90 @heyitsanthony

fixes #1293

MakMukhi · 2017-06-01T23:20:42Z

So I understand that this issue comes up when the code exits from this path: https://github.com/grpc/grpc-go/blob/master/stream.go#L253

Does this happen when the user application calls Close() on client conn and doesn't cancel the the stream's context?

gyuho · 2017-06-01T23:38:33Z

Does this happen when the user application calls Close() on client conn and doesn't cancel the the stream's context?

Yes.

If I understand your question correctly, we get the server stream context first, and launch the Recv call on the stream [1]. And since the Recv call blocks, the cancel function never gets called, while we still close the client connection when terminating the cluster.

func (ep *electionProxy) Observe(req *v3electionpb.LeaderRequest, s v3electionpb.Election_ObserveServer) error {
	conn := ep.client.ActiveConnection()
	ctx, cancel := context.WithCancel(s.Context())
	_ = cancel
	sc, err := v3electionpb.NewElectionClient(conn).Observe(ctx, req)
	if err != nil {
		return err
	}
	for {
                // blocks here...
		rr, err := sc.Recv()
                ...

[1] https://github.com/coreos/etcd/blob/master/proxy/grpcproxy/election.go#L46-L53

MakMukhi · 2017-06-01T23:45:24Z

I see. Thanks for link to the code. I want to discuss this with the team a bit (possible other ways to tackle the problem). Let's try and wrap this is up by tomorrow.

MakMukhi · 2017-06-02T20:22:58Z

So this is in someway related to code changes made in the past. Looking at which your change does make sense. However, this also requires some more thought.

We all are in meetings all day today. This will have to go to Monday. Hope that's alright.

MakMukhi · 2017-06-05T21:05:27Z

Hey,
So we agreed on the change that you're proposing. Can you also please add a test for it?

MakMukhi · 2017-06-12T19:01:52Z

transport/http2_client.go

+		if _, ok := err.(StreamError); ok {
+			// trigger server to send GoAway
+			s.rstStream = true
+			s.rstError = http2.ErrCodeCancel


This doesn't trigger the server to send GoAway. Moreover, what's the rationale behind triggering it? It is a connection level concept; closing of a stream with some error shouldn't trigger closing of a connection, right?

We liked your original change, any specific reasons for updating it?

MakMukhi · 2017-06-12T19:05:22Z

transport/transport_test.go

+	serverConfig := &ServerConfig{
+		KeepaliveParams: keepalive.ServerParameters{
+			MaxConnectionIdle: 2 * time.Second,
+		},


If we rely on keepalive related goaways, we don't test the code you wrote s.write(recvMsg{err: err}) .
The test should be a simple reproduction of your prod issue; a goroutine is blocked on stream.Read() while clientconn.Close() is called, with your change in place this goroutine should unblock.

Agree. Let me rework on the test with original change. Thanks.

MakMukhi

Just a nitpick. LGTM otherwise.

MakMukhi · 2017-06-14T20:55:56Z

transport/transport_test.go

+	serverConfig := &ServerConfig{
+		InitialWindowSize:     defaultWindowSize,
+		InitialConnWindowSize: defaultWindowSize,
+	}


For this test, we don't really need to set custom window sizes.

MakMukhi · 2017-06-14T20:58:00Z

transport/transport_test.go

@@ -382,6 +382,47 @@ func setUpWithNoPingServer(t *testing.T, copts ConnectOptions, done chan net.Con
 	return tr
 }

+// TestInflightStreamClosing ensures that closing in-flight stream
+// sends StreamError to concurrent stream reader.
+func TestInflightStreamClosing(t *testing.T) {


The test looks good. I was expecting an end2end test with clientconn.Close() being called(like your prod issue) but this is essentially the same thing.
Can you make sure that this test fails without your changes in place.

All fixed.

I can confirm this test fails without the patch.
Our production blocking issue is fixed by this as well.

Thanks!

Looks good. Thanks for your time and effort @gyuho

This patch writes client-side error before closing the active stream to fix blocking `RecvMsg` issue on `grpc.ClientStream` [1]. Previous gRPC client stream just exits on `ClientTransport.Error` [2]. And latest gRPC added another select case on client connection context cancel [3]. Now when client stream closes from client connection context cancel, it calls `CloseStream` with `ErrClientConnClosing` error. And then the stream gets deleted from `*http2Client.activeStreams`, without processing the error [4]. Then in-flight `RecvMsg` call on this client will block on `*parser.Reader.recvMsg` [5]. In short, 1. `ClientConn.Close`. 2. in-flight streams will receive case `<-cc.ctx.Done()` https://github.com/grpc/grpc-go/blob/master/stream.go#L253-L255. 3. `cs.closeTransportStream(ErrClientConnClosing)` calls `cs.t.CloseStream(cs.s, err)`. 4. `CloseStream(cs.s, err)` calls `delete(t.activeStreams, s.id)` without handling the error. 5. in-flight streams will never receive error, left hanging. I can reproduce in etcd tests with in-flight `recvMsg` calls to `Observe` RPC. --- [1] etcd-io/etcd#7896 (comment) [2] https://github.com/grpc/grpc-go/blob/v1.2.x/stream.go#L235-L238 [3] #1136 [4] https://github.com/grpc/grpc-go/blob/master/transport/http2_client.go#L569 [5] https://github.com/grpc/grpc-go/blob/master/rpc_util.go#L280 Signed-off-by: Gyu-Ho Lee <gyuhox@gmail.com>

gyuho · 2017-06-14T21:36:01Z

@MakMukhi

Could we have another release with this patch?
Just cut from master branch would work for us.
We will wait if there are other pending PRs.

Thanks!

MakMukhi · 2017-06-14T21:36:57Z

@menghanl What do you think ?

menghanl · 2017-06-14T21:40:59Z

We can backport this PR to the 1.4 branch and do a 1.4.1 release.

This patch writes client-side error before closing the active stream to fix blocking `RecvMsg` issue on `grpc.ClientStream` [1]. Previous gRPC client stream just exits on `ClientTransport.Error` [2]. And latest gRPC added another select case on client connection context cancel [3]. Now when client stream closes from client connection context cancel, it calls `CloseStream` with `ErrClientConnClosing` error. And then the stream gets deleted from `*http2Client.activeStreams`, without processing the error [4]. Then in-flight `RecvMsg` call on this client will block on `*parser.Reader.recvMsg` [5]. In short, 1. `ClientConn.Close`. 2. in-flight streams will receive case `<-cc.ctx.Done()` https://github.com/grpc/grpc-go/blob/master/stream.go#L253-L255. 3. `cs.closeTransportStream(ErrClientConnClosing)` calls `cs.t.CloseStream(cs.s, err)`. 4. `CloseStream(cs.s, err)` calls `delete(t.activeStreams, s.id)` without handling the error. 5. in-flight streams will never receive error, left hanging. I can reproduce in etcd tests with in-flight `recvMsg` calls to `Observe` RPC. --- [1] etcd-io/etcd#7896 (comment) [2] https://github.com/grpc/grpc-go/blob/v1.2.x/stream.go#L235-L238 [3] grpc#1136 [4] https://github.com/grpc/grpc-go/blob/master/transport/http2_client.go#L569 [5] https://github.com/grpc/grpc-go/blob/master/rpc_util.go#L280 Signed-off-by: Gyu-Ho Lee <gyuhox@gmail.com>

menghanl · 2017-06-14T22:04:55Z

@gyuho Just released 1.4.1 with this change.

gyuho · 2017-06-15T00:46:23Z

@menghanl Thanks!

MakMukhi self-requested a review June 1, 2017 23:10

gyuho changed the title ~~transport: write error on Stream before deletion~~ transport: fix error handling on Stream deletion Jun 6, 2017

dfawley assigned MakMukhi Jun 9, 2017

MakMukhi mentioned this pull request Jun 10, 2017

ClientConn.Close() doesn't always make Recv() end #1293

Closed

MakMukhi suggested changes Jun 12, 2017

View reviewed changes

MakMukhi approved these changes Jun 14, 2017

View reviewed changes

MakMukhi merged commit 7df48be into grpc:master Jun 14, 2017

gyuho deleted the write-recv-err-on-close-stream branch June 14, 2017 21:36

menghanl added 1.5 Type: Bug labels Jun 14, 2017

lock bot locked as resolved and limited conversation to collaborators Jan 18, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

transport: fix error handling on Stream deletion #1275

transport: fix error handling on Stream deletion #1275

gyuho commented Jun 1, 2017 •

edited

MakMukhi commented Jun 1, 2017

gyuho commented Jun 1, 2017 •

edited

MakMukhi commented Jun 1, 2017

MakMukhi commented Jun 2, 2017

MakMukhi commented Jun 5, 2017

MakMukhi Jun 12, 2017

MakMukhi Jun 12, 2017

gyuho Jun 12, 2017

MakMukhi left a comment

MakMukhi Jun 14, 2017

MakMukhi Jun 14, 2017

gyuho Jun 14, 2017

MakMukhi Jun 14, 2017

gyuho commented Jun 14, 2017

MakMukhi commented Jun 14, 2017

menghanl commented Jun 14, 2017

menghanl commented Jun 14, 2017 •

edited

gyuho commented Jun 15, 2017

transport: fix error handling on Stream deletion #1275

transport: fix error handling on Stream deletion #1275

Conversation

gyuho commented Jun 1, 2017 • edited

MakMukhi commented Jun 1, 2017

gyuho commented Jun 1, 2017 • edited

MakMukhi commented Jun 1, 2017

MakMukhi commented Jun 2, 2017

MakMukhi commented Jun 5, 2017

MakMukhi Jun 12, 2017

Choose a reason for hiding this comment

MakMukhi Jun 12, 2017

Choose a reason for hiding this comment

gyuho Jun 12, 2017

Choose a reason for hiding this comment

MakMukhi left a comment

Choose a reason for hiding this comment

MakMukhi Jun 14, 2017

Choose a reason for hiding this comment

MakMukhi Jun 14, 2017

Choose a reason for hiding this comment

gyuho Jun 14, 2017

Choose a reason for hiding this comment

MakMukhi Jun 14, 2017

Choose a reason for hiding this comment

gyuho commented Jun 14, 2017

MakMukhi commented Jun 14, 2017

menghanl commented Jun 14, 2017

menghanl commented Jun 14, 2017 • edited

gyuho commented Jun 15, 2017

gyuho commented Jun 1, 2017 •

edited

gyuho commented Jun 1, 2017 •

edited

menghanl commented Jun 14, 2017 •

edited