Race condition in WriteStatus seems to lead to invalid responses from server #5511
Comments
|
Actually was able to put together a minimal reproducer: package main
import (
"context"
"fmt"
"log"
"net"
"strings"
"testing"
discovery "github.com/envoyproxy/go-control-plane/envoy/service/discovery/v3"
sds "github.com/envoyproxy/go-control-plane/envoy/service/secret/v3"
"google.golang.org/grpc"
"google.golang.org/grpc/credentials/insecure"
)
type service struct {
}
func (s *service) DeltaSecrets(server sds.SecretDiscoveryService_DeltaSecretsServer) error {
//TODO implement me
panic("implement me")
}
func (s *service) FetchSecrets(ctx context.Context, request *discovery.DiscoveryRequest) (*discovery.DiscoveryResponse, error) {
//TODO implement me
panic("implement me")
}
func (s *service) StreamSecrets(stream sds.SecretDiscoveryService_StreamSecretsServer) error {
go func() {
_, err := stream.Recv()
log.Println(err)
}()
return fmt.Errorf("test error")
}
func TestGRPCRace(t *testing.T) {
srv := &service{}
rpcs := grpc.NewServer()
sds.RegisterSecretDiscoveryServiceServer(rpcs, srv)
l, err := net.Listen("tcp", "127.0.0.1:0")
if err != nil {
t.Fatal(err)
}
go func() {
rpcs.Serve(l)
}()
con, err := grpc.Dial(l.Addr().String(), grpc.WithTransportCredentials(insecure.NewCredentials()))
if err != nil {
t.Fatal(err)
}
xds := sds.NewSecretDiscoveryServiceClient(con)
c, err := xds.StreamSecrets(context.Background())
if err != nil {
t.Fatal(err)
}
_, err = c.Recv()
if !strings.Contains(err.Error(), "test error") {
t.Fatalf("unxpected error %v", err)
}
}
|
|
bisect leads to #5292 as the regression cc @idiamond-stripe |
|
Thank you for the report and the reproduction case @howardjohn. I'll work on a fix for this today. |
|
#5513 sent to fix it. It should be fine to hold the stream's header mutex during these entire functions; they are very infrequently called and the mutex is very limited in scope. |
|
I wonder if we need a client-side change here, too... E.g. to ignore the extra headers on a stream after END_STREAM was already sent, but possibly to kill the connection or send a RST_STREAM or both since the server seems to be violating the HTTP/2 protocol in this case. |
Sign up for free
to subscribe to this conversation on GitHub.
Already have an account?
Sign in.
What version of gRPC are you using?
I ran into this on v1.47.0. The same issue was reported spiffe/spire#3229 on v1.48.0 though.
What version of Go are you using (
go version)?1.18
What operating system (Linux, Windows, …) and version?
Linux
What did you do?
I don't yet have a trivial reproducer - I think it should be possible to setup but I wanted to get this written up before I forget.
We have a bi-di stream. It happens to be serving XDS, but I don't think that is relevant. Our server code is essentially:
The real logic is a lot more complicated, but basically we send an error back and are calling Recv() concurrently seem to be the two important aspects.
What did you expect to see?
We expect the client to get the error "bad!"
What did you see instead?
Clients get
Status code="Internal" msg="malformed header: missing HTTP status; malformed header: missing HTTP content-type"I did some debugging here, and I believe I understand what is going on here. However, every time I think there is a gRPC bug its usually a bug in our app, so take it with a grain of salt...
I annotated some key points in the grpc code with some extra logs. The results are below:
What we see is we get two calls to WriteStatus. One is from our application returning the error, and then a later from Recv (
grpc-go/stream.go
Line 1588 in f601dfa
We have a mutex here:
grpc-go/internal/transport/http2_server.go
Line 1055 in f601dfa
:statusheader:grpc-go/internal/transport/http2_server.go
Line 1023 in f601dfa
The order of events that happens is (t1/t2 are different goroutines):
At this point, we sent an initial header frame without
status. This ends up being rejected on the client side:grpc-go/internal/transport/http2_client.go
Line 1322 in f601dfa
To validate this idea, I added a mutex covering
finishStream. This is probably a bad idea for real world performance, but was just for testing this. With this, I was unable to reproduceThe text was updated successfully, but these errors were encountered: