stats: peer is not populated for all HandleRPC client callbacks

[pellared]

What version of gRPC are you using?

v1.61.0

What version of Go are you using (go version)?

go version go1.21.4 windows/amd64

What operating system (Linux, Windows, …) and version?

go version go1.21.4 windows/amd64 (was not working on Linux as well)

What did you do?

package main_test

import (
	"context"
	"net"
	"testing"

	"google.golang.org/grpc"
	"google.golang.org/grpc/credentials/insecure"
	"google.golang.org/grpc/interop"
	"google.golang.org/grpc/interop/grpc_testing"
	"google.golang.org/grpc/peer"
	"google.golang.org/grpc/stats"
)

func TestPeerForClientStatsHandler(t *testing.T) {
	spy := &handlerSpy{}

	// Start server.
	l, err := net.Listen("tcp", "127.0.0.1:0")
	if err != nil {
		t.Fatal(err)
	}
	grpcServer := grpc.NewServer()
	grpc_testing.RegisterTestServiceServer(grpcServer, interop.NewTestServer())
	errCh := make(chan error)
	go func() {
		errCh <- grpcServer.Serve(l)
	}()
	t.Cleanup(func() {
		grpcServer.Stop()
		if err := <-errCh; err != nil {
			t.Error(err)
		}
	})

	// Create client with stats handler and do some calls.
	conn, err := grpc.Dial(
		l.Addr().String(),
		grpc.WithBlock(),
		grpc.WithTransportCredentials(insecure.NewCredentials()),
		grpc.WithStatsHandler(spy),
	)
	if err != nil {
		t.Fatal(err)
	}
	t.Cleanup(func() {
		if err := conn.Close(); err != nil {
			t.Error(err)
		}
	})

	client := grpc_testing.NewTestServiceClient(conn)
	interop.DoEmptyUnaryCall(client)
	interop.DoLargeUnaryCall(client)
	interop.DoClientStreaming(client)
	interop.DoServerStreaming(client)
	interop.DoPingPong(client)

	// Assert if peer is populated for each stats type.
	for _, callbackArgs := range spy.Args {
		if callbackArgs.Peer == nil {
			t.Errorf("peer not populated for: %T", callbackArgs.RPCStats)
		} else {
			t.Logf("passed for: %T", callbackArgs.RPCStats)
		}
	}
}

type peerStats struct {
	RPCStats stats.RPCStats
	Peer     *peer.Peer
}

type handlerSpy struct {
	Args []peerStats
}

func (h *handlerSpy) TagRPC(ctx context.Context, info *stats.RPCTagInfo) context.Context {
	return ctx
}

func (h *handlerSpy) HandleRPC(ctx context.Context, rs stats.RPCStats) {
	p, _ := peer.FromContext(ctx)
	h.Args = append(h.Args, peerStats{rs, p})
}

func (h *handlerSpy) TagConn(ctx context.Context, info *stats.ConnTagInfo) context.Context {
	return ctx
}

func (h *handlerSpy) HandleConn(context.Context, stats.ConnStats) {
}

What did you expect to see?

According to #6897 (comment):

It works in every HandleRPC call, since it is populated before.

Therefore, the test should pass.

What did you see instead?

$ go test
--- FAIL: TestPeerForClientStatsHandler (0.01s)
    grpc_test.go:63: peer not populated for: *stats.Begin
    grpc_test.go:65: passed for: *stats.OutHeader
    grpc_test.go:63: peer not populated for: *stats.OutPayload
    grpc_test.go:65: passed for: *stats.InHeader
    grpc_test.go:63: peer not populated for: *stats.InPayload
    grpc_test.go:65: passed for: *stats.InTrailer
    grpc_test.go:63: peer not populated for: *stats.End
    grpc_test.go:63: peer not populated for: *stats.Begin
    grpc_test.go:65: passed for: *stats.OutHeader
    grpc_test.go:63: peer not populated for: *stats.OutPayload
    grpc_test.go:65: passed for: *stats.InHeader
    grpc_test.go:65: passed for: *stats.InTrailer
    grpc_test.go:63: peer not populated for: *stats.InPayload
    grpc_test.go:63: peer not populated for: *stats.End
    grpc_test.go:63: peer not populated for: *stats.Begin
    grpc_test.go:65: passed for: *stats.OutHeader
    grpc_test.go:63: peer not populated for: *stats.OutPayload
    grpc_test.go:63: peer not populated for: *stats.OutPayload
    grpc_test.go:63: peer not populated for: *stats.OutPayload
    grpc_test.go:63: peer not populated for: *stats.OutPayload
    grpc_test.go:65: passed for: *stats.InHeader
    grpc_test.go:65: passed for: *stats.InTrailer
    grpc_test.go:63: peer not populated for: *stats.InPayload
    grpc_test.go:63: peer not populated for: *stats.End
    grpc_test.go:63: peer not populated for: *stats.Begin
    grpc_test.go:65: passed for: *stats.OutHeader
    grpc_test.go:63: peer not populated for: *stats.OutPayload
    grpc_test.go:65: passed for: *stats.InHeader
    grpc_test.go:63: peer not populated for: *stats.InPayload
    grpc_test.go:65: passed for: *stats.InTrailer
    grpc_test.go:63: peer not populated for: *stats.InPayload
    grpc_test.go:63: peer not populated for: *stats.InPayload
    grpc_test.go:63: peer not populated for: *stats.InPayload
    grpc_test.go:63: peer not populated for: *stats.End
    grpc_test.go:63: peer not populated for: *stats.Begin
    grpc_test.go:65: passed for: *stats.OutHeader
    grpc_test.go:63: peer not populated for: *stats.OutPayload
    grpc_test.go:65: passed for: *stats.InHeader
    grpc_test.go:63: peer not populated for: *stats.InPayload
    grpc_test.go:63: peer not populated for: *stats.OutPayload
    grpc_test.go:63: peer not populated for: *stats.InPayload
    grpc_test.go:63: peer not populated for: *stats.OutPayload
    grpc_test.go:63: peer not populated for: *stats.InPayload
    grpc_test.go:63: peer not populated for: *stats.OutPayload
    grpc_test.go:63: peer not populated for: *stats.InPayload
    grpc_test.go:65: passed for: *stats.InTrailer
    grpc_test.go:63: peer not populated for: *stats.End
FAIL
exit status 1

[zasweq]

grpc-go/internal/transport/http2_client.go

Line 356 in d41b01d

t.ctx = peer.NewContext(t.ctx, t.getPeer())

this populates the peer at transport creation time. All the stats handler callouts happen derived from this context. I ran a local test and every stats handler callout had the peer.

[pellared]

@zasweq Do you mean that the test passed for you on main?

[pellared]

@zasweq I have the same problem on main. I just had to add context.Background() to interop. calls.

EDIT: I created #6971

[arvindbr8]

@aranjans -- Ping; This might something to look at after issue you are currently looking at.

[aranjans]

Sure

…

On Wed, Feb 28, 2024 at 11:59 PM Arvind Bright ***@***.***> wrote: @aranjans <https://github.com/aranjans> -- Ping; This might something to look at after issue you are currently looking at. — Reply to this email directly, view it on GitHub <#6947 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/BGCZU2SZR6GSG6N3432L2VDYV5ZO5AVCNFSM6AAAAABCQDERS6VHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSNRZGU4TAMBQG4> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[aranjans]

@pellared We are able to reproduce the issue and would be working on the fix. We would be able to fix all the InPayload and OutPayload, however there is no peer available at Begin and End might not have the peer populated in the case where the RPC was ended even before we got a peer. So we should be able to get End wherever possible.

[pellared]

Makes sense