feat(grpc): log per-request [REQ] line for #92 evidence slice

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")
+}

servers/grpc/authentication.go

@@ -20,18 +20,29 @@ 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"
 )
 
 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)
 	}
 }

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