From bbfcb9f8e8eacbe44225888f0567769588328732 Mon Sep 17 00:00:00 2001 From: SyniRon <66834451+SyniRon@users.noreply.github.com> Date: Thu, 28 May 2026 23:55:34 -0400 Subject: [PATCH] feat(grpc): log per-request [REQ] line in auth interceptor Evidence slice for #92. Adds a defer'd log line on every unary gRPC call (auth-success and auth-failure paths both emit) carrying transport, full method, peer address, and resolved key_id (or "none" for unauthenticated requests). Loopback peer disambiguates the in-process gateway dial from external traffic, unblocking the "is anyone hitting :10000 externally" question for #94/#95. Co-Authored-By: Claude Opus 4.7 (1M context) --- servers/grpc/auth_test.go | 76 +++++++++++++++++++++++++++++ servers/grpc/authentication.go | 12 +++++ servers/grpc/fake_datastore_test.go | 8 ++- 3 files changed, 95 insertions(+), 1 deletion(-) diff --git a/servers/grpc/auth_test.go b/servers/grpc/auth_test.go index 5655270..84d2e7f 100644 --- a/servers/grpc/auth_test.go +++ b/servers/grpc/auth_test.go @@ -1,16 +1,32 @@ package grpc import ( + "bytes" "context" + "net" "testing" "github.com/7cav/api/datastores" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + "google.golang.org/grpc" "google.golang.org/grpc/codes" + "google.golang.org/grpc/metadata" + "google.golang.org/grpc/peer" "google.golang.org/grpc/status" ) +// captureInfo redirects the package Info logger to a buffer for the duration +// of the test and restores it on cleanup. +func captureInfo(t *testing.T) *bytes.Buffer { + t.Helper() + buf := &bytes.Buffer{} + prev := Info.Writer() + Info.SetOutput(buf) + t.Cleanup(func() { Info.SetOutput(prev) }) + return buf +} + func TestKeyFromContext_NilWhenAbsent(t *testing.T) { got := KeyFromContext(context.Background()) assert.Nil(t, got) @@ -56,3 +72,63 @@ func TestRequireScope_RejectsWhenKeyAbsent(t *testing.T) { require.True(t, ok) assert.Equal(t, codes.PermissionDenied, st.Code()) } + +// buildAuthCtx returns an incoming-gRPC context populated with a bearer token +// and a peer address — the two things the interceptor reads off the wire. +func buildAuthCtx(token, peerIP string) context.Context { + ctx := metadata.NewIncomingContext( + context.Background(), + metadata.Pairs("authorization", "Bearer "+token), + ) + return peer.NewContext(ctx, &peer.Peer{ + Addr: &net.TCPAddr{IP: net.ParseIP(peerIP), Port: 4242}, + }) +} + +func TestAuthInterceptor_LogsRequestOnSuccess(t *testing.T) { + ds := &fakeDatastore{ + validateApiKey: func(token string) (*datastores.ApiKeyResult, error) { + return &datastores.ApiKeyResult{KeyId: 17}, nil + }, + } + buf := captureInfo(t) + interceptor := NewAuthInterceptor(ds) + ctx := buildAuthCtx("cav7_abc", "10.0.0.5") + info := &grpc.UnaryServerInfo{FullMethod: "/proto.MilpacService/GetProfile"} + resp, err := interceptor(ctx, "req", info, func(ctx context.Context, req any) (any, error) { + return "ok", nil + }) + require.NoError(t, err) + assert.Equal(t, "ok", resp) + + logged := buf.String() + assert.Contains(t, logged, "[REQ] transport=grpc") + assert.Contains(t, logged, "method=/proto.MilpacService/GetProfile") + assert.Contains(t, logged, "peer=10.0.0.5:4242") + assert.Contains(t, logged, "key_id=17") +} + +func TestAuthInterceptor_LogsRequestOnAuthFailure(t *testing.T) { + ds := &fakeDatastore{ + validateApiKey: func(token string) (*datastores.ApiKeyResult, error) { + return nil, status.Errorf(codes.Unauthenticated, "bad") + }, + } + buf := captureInfo(t) + interceptor := NewAuthInterceptor(ds) + ctx := buildAuthCtx("cav7_bogus", "10.0.0.5") + info := &grpc.UnaryServerInfo{FullMethod: "/proto.MilpacService/GetProfile"} + handlerCalled := false + _, err := interceptor(ctx, "req", info, func(ctx context.Context, req any) (any, error) { + handlerCalled = true + return nil, nil + }) + require.Error(t, err) + assert.False(t, handlerCalled, "handler must not run on auth failure") + + logged := buf.String() + assert.Contains(t, logged, "[REQ] transport=grpc") + assert.Contains(t, logged, "method=/proto.MilpacService/GetProfile") + assert.Contains(t, logged, "peer=10.0.0.5:4242") + assert.Contains(t, logged, "key_id=none") +} diff --git a/servers/grpc/authentication.go b/servers/grpc/authentication.go index 3261424..fd32cd0 100644 --- a/servers/grpc/authentication.go +++ b/servers/grpc/authentication.go @@ -20,11 +20,13 @@ package grpc import ( "context" + "strconv" "github.com/7cav/api/datastores" "google.golang.org/grpc" "google.golang.org/grpc/codes" "google.golang.org/grpc/metadata" + "google.golang.org/grpc/peer" "google.golang.org/grpc/status" ) @@ -32,6 +34,15 @@ const maxTokenLen = 128 func NewAuthInterceptor(ds datastores.Datastore) grpc.UnaryServerInterceptor { return func(ctx context.Context, req any, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (any, error) { + peerAddr := "unknown" + if p, ok := peer.FromContext(ctx); ok && p.Addr != nil { + peerAddr = p.Addr.String() + } + keyID := "none" + defer func() { + Info.Printf("[REQ] transport=grpc method=%s peer=%s key_id=%s", info.FullMethod, peerAddr, keyID) + }() + md, ok := metadata.FromIncomingContext(ctx) if !ok { return nil, status.Errorf(codes.Unauthenticated, "missing metadata") @@ -52,6 +63,7 @@ func NewAuthInterceptor(ds datastores.Datastore) grpc.UnaryServerInterceptor { return nil, status.Errorf(codes.Unauthenticated, "invalid api key") } + keyID = strconv.FormatUint(uint64(key.KeyId), 10) return handler(ContextWithKey(ctx, key), req) } } diff --git a/servers/grpc/fake_datastore_test.go b/servers/grpc/fake_datastore_test.go index 9c4f3b0..c5b8ccf 100644 --- a/servers/grpc/fake_datastore_test.go +++ b/servers/grpc/fake_datastore_test.go @@ -33,6 +33,9 @@ type fakeDatastore struct { findRosterByType func(proto.RosterType) (*proto.Roster, error) findLiteRosterByType func(proto.RosterType) (*proto.LiteRoster, error) findS1UniformsRosterByType func(proto.RosterType) (*proto.S1UniformsRoster, error) + + // Auth — used by auth_test.go to drive the interceptor end-to-end. + validateApiKey func(string) (*datastores.ApiKeyResult, error) } func (f *fakeDatastore) ListTickets(_ context.Context, _ datastores.TicketReferenceCache, fi *datastores.ListTicketsFilter) ([]*proto.Ticket, string, bool, error) { @@ -85,7 +88,10 @@ func (f *fakeDatastore) FindAllRanks() ([]*proto.RankExpanded, error) func (f *fakeDatastore) FindAllPositionGroups() ([]*proto.PositionGroup, error) { panic("unused") } func (f *fakeDatastore) FindAwol() ([]*proto.Awol, error) { panic("unused") } func (f *fakeDatastore) GetTableUpdates() ([]xenforo.TableInfo, error) { panic("unused") } -func (f *fakeDatastore) ValidateApiKey(string) (*datastores.ApiKeyResult, error) { panic("unused") } + +func (f *fakeDatastore) ValidateApiKey(token string) (*datastores.ApiKeyResult, error) { + return f.validateApiKey(token) +} // makeKeyCtx builds a context carrying an ApiKeyResult with the given scope // set. The withTicketsKey / withMilpacsKey wrappers stay as named entry