Skip to content

fix(context): rebind the logger's trace ID when the context moves to a new trace - #4438

Closed
PiyushSingh-ZS wants to merge 1 commit into
gofr-dev:developmentfrom
PiyushSingh-ZS:fix/context-logger-trace-refresh
Closed

PiyushSingh-ZS wants to merge 1 commit into
gofr-dev:developmentfrom
PiyushSingh-ZS:fix/context-logger-trace-refresh

Conversation

@PiyushSingh-ZS

Copy link
Copy Markdown
Contributor

Pull Request Template

Description:

Follow-up to #4436, where @aryanmehrotra found this in review.

A framework-built gofr.Context reads the trace ID for its logs once, when the context is built (ContextLoggerFor). If c.Context is later replaced with a context from a different trace, log lines keep the old trace ID, or none at all. Meanwhile ctx.GetCorrelationID() reports the new one, so the log line and the correlation ID disagree for the same context.

The framework does this in two places:

  • Cron jobs. (*job).run builds the context through newContext(nil, &noopRequest{}, cntnr), which has no span, and then sets c.Context to the job's span context. Every cron log line has no trace_id: Starting cron job, everything the job logs, Panic in cron job, and Finished cron job.
  • ctx.Trace on a context built without a span (CMD subcommands, cron before this fix). Logs after ctx.Trace(...) have no trace_id.

HTTP handlers are not affected. A span started with ctx.Trace there is a child in the same trace, so the trace ID doesn't change.

Fix:

  • New unexported (*Context).setContext(ctx). It replaces c.Context. It rebinds the ContextLogger only when the new context belongs to a different trace than the current one. ctx.Trace and the cron job runner use it instead of assigning c.Context directly.
  • New logging.ContextLoggerWithSpan(ctx, *ContextLogger) ContextLogger. It returns a copy that keeps the base logger and takes the span from ctx. A zero-value ContextLogger stays zero. It is a package-level function rather than a method so it is not promoted onto gofr.Context, which embeds ContextLogger.

Why rebind only on a trace change:

  • No extra work on the request path. Inside an HTTP handler, ctx.Trace stays in the request's trace, so only c.Context is written, as before. The cost is two SpanContextFromContext lookups per ctx.Trace call.
  • No new data race. Today, a goroutine that only logs through ctx while another goroutine calls ctx.Trace does not race, because logging never reads c.Context. Rewriting the ContextLogger on every ctx.Trace would introduce that race. TestContext_Trace_SameTraceDoesNotRaceWithLogging pins this: under -race, it reports 2 data races if the condition is removed.

Alternatives considered:

  • Read the span from c.Context on every log call. Always correct, but it adds a context lookup to every log line on the hot path, which the per-request ContextLogger exists to avoid.
  • Fix only the cron job, e.g. by building its context from the span context. That leaves ctx.Trace on span-less contexts (CMD) broken.

Sites that replace c.Context with a context of the same trace are left unchanged: the request-timeout and WebSocket paths in handler.go, and the WebSocket value context in websocket.go. Also unchanged: the OnStart hooks context in gofr.go, which carries no span, so no trace ID is lost there.

Breaking Changes (if applicable):

  • None. ContextLoggerWithSpan is a new function, setContext is unexported, and no existing signature changes.
  • Behavior change: cron job log lines, and logs after ctx.Trace on a span-less context, now carry a trace_id.

Additional Information:

Tests:

Test development this PR
TestJob_run_LogsCarryJobTraceID: trace markers on Starting / inside the job / Finished [0 0 0] [1 1 1], equal to GetCorrelationID()
TestContext_Trace_LogsCarryNewTraceID: span-less context, then ctx.Trace 0 1, equal to GetCorrelationID()
TestContext_Trace_SameTraceKeepsTraceID: HTTP context, child span 1 1 (guard)
TestContext_Trace_SameTraceDoesNotRaceWithLogging (-race) pass pass; fails with 2 data races if the logger is always rebound
TestContextLoggerWithSpan: keeps base, takes new span, drops trace for a span-less ctx, zero value stays zero n/a pass

Refs #4436

Checklist:

  • I have formatted my code using goimport and golangci-lint.
  • All new code is covered by unit tests.
  • This PR does not decrease the overall code coverage.
  • I have reviewed the code comments and documentation for clarity.

Thank you for your contribution!

🤖 Generated with Claude Code

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant