Skip to content

fix(grpc+consumer): preserve context logger enrichment end-to-end#130

Open
ruangervasi-altpay wants to merge 1 commit into
gothunder:mainfrom
ruangervasi-altpay:fix/trace-id-interceptor-ordering
Open

fix(grpc+consumer): preserve context logger enrichment end-to-end#130
ruangervasi-altpay wants to merge 1 commit into
gothunder:mainfrom
ruangervasi-altpay:fix/trace-id-interceptor-ordering

Conversation

@ruangervasi-altpay

Copy link
Copy Markdown

Context

Found during the trace_id rollout at Alternative Payments (review by @CassioRoos on getalternative/svc-notification#219).

Problem 1 — gRPC interceptor ordering drops enrichment

NewServer appended grpcLoggerInterceptor(params.Logger) AFTER all supplied interceptors. Supplied interceptors that enrich the context logger (audit fields, trace_id via backend-commons logs.UnaryServerInterceptor()) had their enrichment silently replaced by the base logger before the handler ran. Reproduced with a real traced request through NewThunderGrpcServer: client had a valid trace ID, handler log had neither trace_id nor grpc_method.

Fix: attach the base logger BEFORE supplied interceptors:

metadata -> base logger -> supplied (audit, trace logging, ...) -> handler

Regression test: pkg/grpc/server_test.go chains the interceptors exactly like NewServer and asserts the handler's actual log line carries the enriched trace_id + grpc_method (not a helper-in-isolation test).

Problem 2 — consumer lifecycle logs missing trace_id

The RabbitMQ consumer builds its lifecycle logger before invoking the handler, but never added the OTEL trace_id (already extracted from message headers via ExtractTrace). Unknown-topic, decode, ack/nack, retry, and dead-letter logs had no trace_id — only handler logs enriched by downstream middleware did.

Fix: enrich the lifecycle logger with trace_id from the span context at the consumer boundary, so the ENTIRE message lifecycle inherits it.

Test plan

  • go build ./... clean
  • go test ./... — all packages pass (5 ok)
  • New regression test for interceptor ordering
  • Release + bump in a Thunder-based service (svc-notification) proving handler logs carry trace_id end-to-end

Two fixes for trace_id propagation into logs:

1. gRPC server: the base logger interceptor ran AFTER supplied
   interceptors, replacing the context logger and silently dropping any
   enrichment (trace_id, audit fields) before the handler executed.
   Reordered to metadata -> base logger -> supplied interceptors ->
   handler, so supplied interceptors (e.g. backend-commons
   logs.UnaryServerInterceptor) enrich a logger that actually reaches
   the handler. Regression test asserts the handler's log line carries
   the enriched trace_id and grpc_method through the full chain.

2. RabbitMQ consumer: the lifecycle logger (built before the handler
   runs) now includes the OTEL trace_id extracted from the message
   headers. This covers decode errors, ack/nack failures, retries and
   the application handler itself -- not just handler logs enriched by
   downstream middleware.
@github-actions github-actions Bot added the fix label Jul 16, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant