Metadata context changes are not backwards compatible/break existing code

[bufdev]

Note the example here is not just propagating contexts in memory, this is a full client/server interaction that should be serialized and work properly, ie this is not a dup of #1178. This should get into transport/http2_client.go and transport/http2_server.go, and work properly per the implementation in those files, we are not doing something like FromContext(NewContext(ctx, md)).

I understand that the API was written so that existing users of NewContext and FromContext would not be affected, but items are explicitly not being propagated now. See comment below to reproduce.

I think this is a pretty serious bug. We're not doing anything THAT fancy with grpc-go, we effectively bring up a vanilla grpc.Server and install handlers on it, and then use grpc.Invoke with vanilla grpc.ClientConns. I don't think the implementation is working as intended - maybe I'm doing something wrong, but we are doing these calls across the wire and updating makes this break, I wanted to make sure everyone is alerted ASAP.

[bufdev]

I've put together two branches to make this more easily reproducible.

Setup steps:

go get -u go.uber.org/yarpc
cd "${GOPATH}/src/go.uber.org/yarpc" # assuming your GOPATH has one directory

I pushed a branch grpc-metadata-bug-pre that just adds log statements to show the metadata before grpc.Invoke, and then inside the handler.

To run:

git checkout grpc-metadata-bug-pre
SUPPRESS_DOCKER=1 make -C internal/examples protobuf-grpc

Output:

$ SUPPRESS_DOCKER=1 make -C internal/examples protobuf-grpc
go install ../service-test
go build -o protobuf/protobuf protobuf/main.go
TRANSPORT=grpc service-test  --dir protobuf
2017/05/04 15:11:33 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:11:33 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1] user-agent:[yarpc-go/1.9.0-dev] yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:11:33 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-service:[example] yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf]]
2017/05/04 15:11:33 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1] user-agent:[yarpc-go/1.9.0-dev] yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:11:33 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:11:33 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1] user-agent:[yarpc-go/1.9.0-dev] yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:11:33 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:11:33 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1] user-agent:[yarpc-go/1.9.0-dev] yarpc-grpc-reserved-service:[example] yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf]]
2017/05/04 15:11:33 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:11:33 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1] user-agent:[yarpc-go/1.9.0-dev] yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:11:33 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:11:33 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[user-agent:[yarpc-go/1.9.0-dev] yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example] :authority:[127.0.0.1]]
2017/05/04 15:11:33 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example] yarpc-grpc-reserved-caller:[example-client]]
2017/05/04 15:11:33 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1] user-agent:[yarpc-go/1.9.0-dev] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example] yarpc-grpc-reserved-caller:[example-client]]
2017/05/04 15:11:33 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:11:33 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1] user-agent:[yarpc-go/1.9.0-dev] yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:11:33 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:11:33 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1] user-agent:[yarpc-go/1.9.0-dev] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example] yarpc-grpc-reserved-caller:[example-client]]

I pushed another branch grpc-metadata-bug that has the same log statements, but also does glide update, which pulls in 1.3.0.

To run:

git checkout grpc-metadata-bug
SUPPRESS_DOCKER=1 make -C internal/examples protobuf-grpc

Output:

$ SUPPRESS_DOCKER=1 make -C internal/examples protobuf-grpc
go install ../service-test
go build -o protobuf/protobuf protobuf/main.go
TRANSPORT=grpc service-test  --dir protobuf
2017/05/04 15:08:34 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-service:[example] yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf]]
2017/05/04 15:08:34 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1:57527] user-agent:[yarpc-go/1.9.0-dev grpc-go/1.3.0]]
2017/05/04 15:08:34 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-service:[example] yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf]]
2017/05/04 15:08:34 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1:57527] user-agent:[yarpc-go/1.9.0-dev grpc-go/1.3.0]]
2017/05/04 15:08:34 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:08:34 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1:57527] user-agent:[yarpc-go/1.9.0-dev grpc-go/1.3.0]]
2017/05/04 15:08:34 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:08:34 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1:57527] user-agent:[yarpc-go/1.9.0-dev grpc-go/1.3.0]]
2017/05/04 15:08:34 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:08:34 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1:57527] user-agent:[yarpc-go/1.9.0-dev grpc-go/1.3.0]]
2017/05/04 15:08:34 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-service:[example] yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf]]
2017/05/04 15:08:34 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1:57527] user-agent:[yarpc-go/1.9.0-dev grpc-go/1.3.0]]
2017/05/04 15:08:34 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf] yarpc-grpc-reserved-service:[example]]
2017/05/04 15:08:34 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1:57527] user-agent:[yarpc-go/1.9.0-dev grpc-go/1.3.0]]
2017/05/04 15:08:34 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-service:[example] yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf]]
2017/05/04 15:08:34 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[:authority:[127.0.0.1:57527] user-agent:[yarpc-go/1.9.0-dev grpc-go/1.3.0]]
2017/05/04 15:08:34 HERE IS THE OUTGOING METADATA THAT IS ADDED TO CONTEXT USING metadata.NewOutgoingContext: map[yarpc-grpc-reserved-service:[example] yarpc-grpc-reserved-caller:[example-client] yarpc-grpc-reserved-encoding:[protobuf]]
2017/05/04 15:08:34 HERE IS THE INCOMING METADATA FROM metadata.FromIncomingContext: map[user-agent:[yarpc-go/1.9.0-dev grpc-go/1.3.0] :authority:[127.0.0.1:57527]]

[bufdev]

I think I have begun to identify the problem - if NewOutgoingContext is called twice before serialization in http2_client.go, you end up with an outgoing context along the lines of:

context.Background.WithDeadline(2017-05-04 15:54:14.289231314 +0200 CEST [999.772844ms]).WithValue(metadata.mdOutgoingKey{}, metadata.MD{"yarpc-grpc-reserved-caller":[]string{"example-client"}, "yarpc-grpc-reserved-encoding":[]string{"protobuf"}, "yarpc-grpc-reserved-service":[]string{"example"}}).WithValue(metadata.mdOutgoingKey{}, metadata.MD{}).WithValue(grpc.rpcInfoContextKey{}, &grpc.rpcInfo{bytesSent:false, bytesReceived:false}).WithValue(peer.peerKey{}, &peer.Peer{Addr:(*net.TCPAddr)(0xc420360300), AuthInfo:credentials.AuthInfo(nil)})

Note the two WithValue calls with mdOutgoingKey{}, with the second key having nothing for a value. metadata.NewOutgoingContext is called both in our code, and in github.com/grpc-ecosystem/grpc-opentracing/go/otgrpc/client.go:65, ie we use github.com/grpc-ecosystem/grpc-opentracing. grpc-opentracing is not adding anything, but when metadata.FromOutgoingContext is called in http2_client.go for serialization, the second (empty) value is being returned, not the earlier value that we did in our own code that set yarpc-grpc-reserved-encoding etc.

In the old version pre-1.3.0, there are still two WithValue calls, but the metadata is copied to the second call, ie calling metadata.NewContext twice properly propagated the information:

context.Background.WithDeadline(2017-05-04 16:02:25.348512784 +0200 CEST [999.435702ms]).WithValue(metadata.mdKey{}, metadata.MD{"yarpc-grpc-reserved-caller":[]string{"example-client"}, "yarpc-grpc-reserved-encoding":[]string{"protobuf"}, "yarpc-grpc-reserved-service":[]string{"example"}}).WithValue(metadata.mdKey{}, metadata.MD{"yarpc-grpc-reserved-encoding":[]string{"protobuf"}, "yarpc-grpc-reserved-service":[]string{"example"}, "yarpc-grpc-reserved-caller":[]string{"example-client"}}).WithValue(peer.peerKey{}, &peer.Peer{Addr:(*net.TCPAddr)(0xc4203ee030), AuthInfo:credentials.AuthInfo(nil)})

Note this is printed from adding log.Printf("%+v", ctx) right before the call to metadata.FromOutgoingContext (or metadata.FromContext in the old code) in http2_client.go around line 430.

[bufdev]

Well and there we go: it's because grpc-opentracing needs to be updated, so this was an in-memory issue: https://github.com/grpc-ecosystem/grpc-opentracing/blob/master/go/otgrpc/client.go#L53

grpc-ecosystem repos should be updated to reflect grpc-go changes, can we do this?

This is going to be problematic (and why this breaking metadata change is really tough on consumers) because grpc-opentracing must update to the new metadata API, however this means that when users update grpc-opentracing, they must also update grpc-go (which may have other changes they do not want). grpc-opentracing does not have any releases/doesn't use semvar, so this is even tougher. I think as part of this, it would be great if we could get grpc-opentracing on semvar too?

I hope this issue helps, let me know if there's anything I can do to assist.

[dfawley]

Thanks for the report and debugging info. This is definitely a problem, but I don't see any way this can be handled gracefully at this point. We are planning to remove the NewContext and FromContext functions from the metadata package completely in order to force users to decide which metadata they intended to set/get. Unfortunately, an API breakage is necessary here, because this is a security problem with the API itself.

[bufdev]

Yea I get it, just wanted to alert. Let me know if I can help in any way, I've tried to go through a few of the grpc-ecosystem repositories and send PRs.