[go: up one dir, main page]

feat(log): added gRPC access logs

What?

Added gRPC access logs support

Why?

Part of: gitlab-com/gl-infra/tenant-scale/cells-infrastructure/team#457 (closed)

Testing

Testing suite: https://gitlab.com/vglafirov/grpc-access-logs/-/tree/main?ref_type=heads

Testing results

make test
protoc --go_out=. --go_opt=paths=source_relative \
                --go-grpc_out=. --go-grpc_opt=paths=source_relative \
                proto/test.proto
cd server && go build .
cd client && go build .
Starting gRPC server in background...
server/grpc-access-logs-server & \
        SERVER_PID=$!; \
        echo "Server PID: $SERVER_PID"; \
        sleep 2; \
        echo "Running client tests..."; \
        client/grpc-access-logs-client; \
        CLIENT_EXIT_CODE=$?; \
        echo "Stopping server..."; \
        kill $SERVER_PID 2>/dev/null || true; \
        exit $CLIENT_EXIT_CODE
Server PID: 51777
{"level":"info","msg":"gRPC server starting on :8080","time":"2025-08-22T12:09:27+02:00"}
Running client tests...
{"level":"info","msg":"Starting gRPC client tests","time":"2025-08-22T12:09:29+02:00"}
{"level":"info","msg":"=== Test 1: SayHello ===","time":"2025-08-22T12:09:29+02:00"}
{"correlation_id":"01K38M2ES0BEEEHZQ3SAJ55G4V","level":"info","msg":"SayHello called with name: World","time":"2025-08-22T12:09:29+02:00"}
{"correlation_id":"01K38M2ES0BEEEHZQ3SAJ55G4V","duration_ms":51,"level":"info","method":"/test.TestService/SayHello","msg":"access","status":"OK","system":"grpc","time":"2025-08-22T12:09:29+02:00"}
{"grpc.code":"OK","grpc.method":"SayHello","grpc.request.deadline":"2025-08-22T12:09:34+02:00","grpc.service":"test.TestService","grpc.start_time":"2025-08-22T12:09:29+02:00","grpc.time_ms":51.464,"level":"info","msg":"finished unary call with code OK","span.kind":"server","system":"grpc","time":"2025-08-22T12:09:29+02:00"}
{"level":"info","msg":"SayHello response: Hello, World!","time":"2025-08-22T12:09:29+02:00"}
{"level":"info","msg":"=== Test 2: GetInfo (success) ===","time":"2025-08-22T12:09:29+02:00"}
{"correlation_id":"01K38M2EVC8SVWN2GSPNR9VA33","level":"info","msg":"GetInfo called with query: golang","time":"2025-08-22T12:09:29+02:00"}
{"correlation_id":"01K38M2EVC8SVWN2GSPNR9VA33","duration_ms":100,"level":"info","method":"/test.TestService/GetInfo","msg":"access","status":"OK","system":"grpc","time":"2025-08-22T12:09:30+02:00"}
{"grpc.code":"OK","grpc.method":"GetInfo","grpc.request.deadline":"2025-08-22T12:09:34+02:00","grpc.service":"test.TestService","grpc.start_time":"2025-08-22T12:09:29+02:00","grpc.time_ms":100.843,"level":"info","msg":"finished unary call with code OK","span.kind":"server","system":"grpc","time":"2025-08-22T12:09:30+02:00"}
{"level":"info","msg":"GetInfo response: Information about: golang (count: 6)","time":"2025-08-22T12:09:30+02:00"}
{"level":"info","msg":"=== Test 3: GetInfo (error) ===","time":"2025-08-22T12:09:30+02:00"}
{"correlation_id":"01K38M2EYJDC5TN6TDF2418RNN","level":"info","msg":"GetInfo called with query: error","time":"2025-08-22T12:09:30+02:00"}
{"correlation_id":"01K38M2EYJDC5TN6TDF2418RNN","duration_ms":101,"level":"info","method":"/test.TestService/GetInfo","msg":"access","status":"InvalidArgument","system":"grpc","time":"2025-08-22T12:09:30+02:00"}
{"error":"rpc error: code = InvalidArgument desc = error query not supported","grpc.code":"InvalidArgument","grpc.method":"GetInfo","grpc.request.deadline":"2025-08-22T12:09:35+02:00","grpc.service":"test.TestService","grpc.start_time":"2025-08-22T12:09:30+02:00","grpc.time_ms":101.184,"level":"info","msg":"finished unary call with code InvalidArgument","span.kind":"server","system":"grpc","time":"2025-08-22T12:09:30+02:00"}
{"level":"error","msg":"GetInfo failed: rpc error: code = InvalidArgument desc = error query not supported","time":"2025-08-22T12:09:30+02:00"}
{"level":"info","msg":"=== Test 4: StreamData ===","time":"2025-08-22T12:09:30+02:00"}
{"correlation_id":"01K38M2F1RV6E60G9DADXQQ7SV","level":"info","msg":"StreamData called with count: 3","time":"2025-08-22T12:09:30+02:00"}
{"level":"info","msg":"StreamData response: Stream data item 1 (index: 0)","time":"2025-08-22T12:09:30+02:00"}
{"level":"info","msg":"StreamData response: Stream data item 2 (index: 1)","time":"2025-08-22T12:09:30+02:00"}
{"level":"info","msg":"StreamData response: Stream data item 3 (index: 2)","time":"2025-08-22T12:09:30+02:00"}
{"correlation_id":"01K38M2F1RV6E60G9DADXQQ7SV","duration_ms":80,"level":"info","method":"/test.TestService/StreamData","msg":"access","status":"OK","system":"grpc","time":"2025-08-22T12:09:30+02:00"}
{"grpc.code":"OK","grpc.method":"StreamData","grpc.request.deadline":"2025-08-22T12:09:40+02:00","grpc.service":"test.TestService","grpc.start_time":"2025-08-22T12:09:30+02:00","grpc.time_ms":80.627,"level":"info","msg":"finished streaming call with code OK","span.kind":"server","system":"grpc","time":"2025-08-22T12:09:30+02:00"}
{"level":"info","msg":"StreamData completed","time":"2025-08-22T12:09:30+02:00"}
{"level":"info","msg":"All tests completed","time":"2025-08-22T12:09:30+02:00"}
Stopping server...
Edited by Vladimir Glafirov

Merge request reports

Loading