transport/server: fix race that could cause a stray header to be sent #5513

dfawley · 2022-07-19T17:00:59Z

RELEASE NOTES:

transport/server: fix race that could cause a stray header to be sent

zasweq · 2022-07-22T01:10:32Z

internal/transport/http2_server.go

@@ -1013,17 +1012,19 @@ func (t *http2Server) writeHeaderLocked(s *Stream) error {
 // TODO(zhaoq): Now it indicates the end of entire stream. Revisit if early
 // OK is adopted.
 func (t *http2Server) WriteStatus(s *Stream, st *status.Status) error {
+	s.hdrMu.Lock()


So what you wrote in issue -" It should be fine to hold the stream's header mutex during these entire functions; they are very infrequently called" is why it is ok for this unlock to be past stuff like stats handlers which would block any operations waiting on the mutex?

We could unlock before calling the stats handler (we technically just need to call updateHeaderSent and finishStream to prevent any races), but this should be okay considering a race between multiple calls to WriteStatus and/or WriteHeader should be extremely rare.

Sg. Seems very minimal, but was just wondering your thought process.

zasweq · 2022-07-22T01:20:13Z

internal/transport/http2_server.go

-	}
-
+	s.hdrMu.Lock()
+	defer s.hdrMu.Unlock()


This is orthogonal to the bug fix right? I get that this fixes a correctness issue with s.updateHeaderSent, but you could provide me a concrete example of what this fixes?

We want to hold the lock while calling s.updateHeaderSent and checking/setting s.getState at least. Otherwise it races with WriteStatus doing similar operations. So while this is not exactly the original bug, it's another related race that is possible if trying to send headers while returning from the method handler.

Yeah makes sense to me. Although you need to hold mutex for writeHeaderLocked() too right? (What you have currently...but your comment just mentions updateHeaderSent and getState).

Ah yes, that too.

zasweq · 2022-07-22T01:27:24Z

test/end2end_test.go

+		t.Fatalf("Error starting endpoint server: %v", err)
+	}
+	defer ss.Stop()
+	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)


Nit: 10 * time.Second

Spaces?

We have a pretty healthy existing mix of spaces/no spaces, and gofmt is OK with either.

$ grep -r '\* time.Second' . | wc -l 235 $ grep -r '\*time.Second' . | wc -l 134

I'm inclined to just leave this.

Yeah, talked about offline, this was thought carried over from two of my internship's linters. Didn't realize we have both for some reason. This is fine.

zasweq · 2022-07-22T01:36:40Z

test/end2end_test.go

@@ -8077,3 +8077,33 @@ func (s) TestUnexpectedEOF(t *testing.T) {
 		}
 	}
 }
+
+// TestRecvWhileReturningStatus performs a Recv in a service handler while the
+// handler returns its status.  A race condition could result in the server


"A race condition could result in the server sending headers twice (once as a result of the status and once as a result of the failed Recv call)." This doesn't seem like the race to me? Isn't the race the bit where instead of writing the header with result from status first it writes the header from failed Recv call without status first due to s.updateHeaderSent is true). Regardless of ordering, both headers get sent out anyway? Hence your comment in issue "E.g. to ignore the extra headers on a stream after END_STREAM was already sent".

Isn't the race the bit where instead of writing the header with result from status first it writes the header from failed Recv call without status first due to s.updateHeaderSent is true

I'm not sure of the order -- it probably doesn't matter. The failed Recv call will also write a status, though, here:

grpc-go/stream.go

Lines 1586 to 1588 in b695a7f

if err != nil && err != io.EOF {

st, _ := status.FromError(toRPCErr(err))

ss.t.WriteStatus(ss.s, st)

Is there something you think needs to change here?

Yeah, I saw that line when triaging. All I was getting at with this comment was that I think the explanation of the race in the comment is wrong. The race is the fact that the second WriteStatus call reads updateHeaderSent as true, doesn't attach :status, and then sends that BEFORE the first WriteStatus call on the wire without the Status, which is what broke howardjohn. Saying the race is sending headers twice is accurate but not the explanation as to why it broke client in this scenario. (And yes it also breaks HTTP_2 because sends another frame after END_STREAM)

Aha, I hadn't completely linked the reason for the failure on the client side, actually, but that makes more sense than my original thought that two :status headers were written and the client saw the second one and errored. So my comment about "ignore the extra headers on a stream after END_STREAM was already sent" is probably bogus. Updated this comment.

Cool thanks comment LGTM.

zasweq · 2022-07-27T16:55:28Z

internal/transport/http2_server.go

@@ -1013,17 +1012,19 @@ func (t *http2Server) writeHeaderLocked(s *Stream) error {
 // TODO(zhaoq): Now it indicates the end of entire stream. Revisit if early
 // OK is adopted.
 func (t *http2Server) WriteStatus(s *Stream, st *status.Status) error {
+	s.hdrMu.Lock()


Sg. Seems very minimal, but was just wondering your thought process.

zasweq · 2022-07-27T16:56:04Z

internal/transport/http2_server.go

@@ -1052,7 +1053,7 @@ func (t *http2Server) WriteStatus(s *Stream, st *status.Status) error {
 		endStream: true,
 		onWrite:   t.setResetPingStrikes,
 	}
-	s.hdrMu.Unlock()
+


Nit: do we want this blank line (used to have no blanks)

I think so. Helps to visually separate building the frame from writing it.

zasweq · 2022-07-27T17:00:00Z

test/end2end_test.go

@@ -8077,3 +8077,33 @@ func (s) TestUnexpectedEOF(t *testing.T) {
 		}
 	}
 }
+
+// TestRecvWhileReturningStatus performs a Recv in a service handler while the
+// handler returns its status.  A race condition could result in the server


Yeah, I saw that line when triaging. All I was getting at with this comment was that I think the explanation of the race in the comment is wrong. The race is the fact that the second WriteStatus call reads updateHeaderSent as true, doesn't attach :status, and then sends that BEFORE the first WriteStatus call on the wire without the Status, which is what broke howardjohn. Saying the race is sending headers twice is accurate but not the explanation as to why it broke client in this scenario. (And yes it also breaks HTTP_2 because sends another frame after END_STREAM)

zasweq · 2022-07-27T17:10:22Z

internal/transport/http2_server.go

-	}
-
+	s.hdrMu.Lock()
+	defer s.hdrMu.Unlock()


Yeah makes sense to me. Although you need to hold mutex for writeHeaderLocked() too right? (What you have currently...but your comment just mentions updateHeaderSent and getState).

zasweq · 2022-07-27T17:11:31Z

test/end2end_test.go

+		t.Fatalf("Error starting endpoint server: %v", err)
+	}
+	defer ss.Stop()
+	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)


Yeah, talked about offline, this was thought carried over from two of my internship's linters. Didn't realize we have both for some reason. This is fine.

zasweq

LGTM!

transport/server: fix race that could cause a stray header to be sent

87c5a88

dfawley added the Cherry Pick label Jul 19, 2022

dfawley added this to the 1.49 Release milestone Jul 19, 2022

dfawley requested a review from zasweq July 19, 2022 17:00

dfawley assigned zasweq Jul 19, 2022

dfawley mentioned this pull request Jul 19, 2022

Race condition in WriteStatus seems to lead to invalid responses from server #5511

Closed

dfawley added the Type: Bug label Jul 21, 2022

zasweq reviewed Jul 22, 2022

View reviewed changes

zasweq assigned dfawley and unassigned zasweq Jul 22, 2022

dfawley assigned zasweq and unassigned dfawley Jul 27, 2022

zasweq reviewed Jul 27, 2022

View reviewed changes

comment

abc33d5

zasweq approved these changes Jul 28, 2022

View reviewed changes

zasweq assigned dfawley and unassigned zasweq Jul 28, 2022

dfawley merged commit 1ec054b into grpc:master Jul 28, 2022

dfawley deleted the stream_close_bug branch July 29, 2022 17:45

This was referenced Aug 24, 2022

Flaky sdsv3 test TestStreamSecrets/Default_All_bundles:_RootCA spiffe/spire#3275

Closed

Flaky unit test in spire/pkg/agent/endpoints/sdsv3: TestStreamSecrets spiffe/spire#3229

Closed

moul-bot mentioned this pull request Oct 7, 2022

chore(deps): bump google.golang.org/grpc from 1.38.0 to 1.50.0 moul/depviz#581

Closed

moul-bot mentioned this pull request Oct 17, 2022

chore(deps): bump google.golang.org/grpc from 1.38.0 to 1.50.1 moul/depviz#586

Closed

dfawley removed the Cherry Pick label Jan 24, 2023

github-actions bot locked as resolved and limited conversation to collaborators Jul 24, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

transport/server: fix race that could cause a stray header to be sent #5513

transport/server: fix race that could cause a stray header to be sent #5513

dfawley commented Jul 19, 2022

zasweq Jul 22, 2022

dfawley Jul 22, 2022

zasweq Jul 27, 2022

zasweq Jul 22, 2022

dfawley Jul 27, 2022

zasweq Jul 27, 2022

dfawley Jul 27, 2022

zasweq Jul 22, 2022

dfawley Jul 22, 2022

zasweq Jul 27, 2022

zasweq Jul 22, 2022

dfawley Jul 27, 2022

zasweq Jul 27, 2022

dfawley Jul 28, 2022

zasweq Jul 28, 2022

zasweq Jul 27, 2022

zasweq Jul 27, 2022

dfawley Jul 28, 2022

zasweq Jul 27, 2022

zasweq Jul 27, 2022

zasweq Jul 27, 2022

zasweq left a comment

	if err != nil && err != io.EOF {
	st, _ := status.FromError(toRPCErr(err))
	ss.t.WriteStatus(ss.s, st)

transport/server: fix race that could cause a stray header to be sent #5513

transport/server: fix race that could cause a stray header to be sent #5513

Conversation

dfawley commented Jul 19, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

zasweq left a comment

Choose a reason for hiding this comment