Repository navigation
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
Closed
PiyushSingh-ZS wants to merge 1 commit into
PiyushSingh-ZS wants to merge 1 commit into
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Pull Request Template
Description:
Follow-up to #4436, where @aryanmehrotra found this in review.
A framework-built
gofr.Contextreads the trace ID for its logs once, when the context is built (ContextLoggerFor). Ifc.Contextis later replaced with a context from a different trace, log lines keep the old trace ID, or none at all. Meanwhilectx.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:
(*job).runbuilds the context throughnewContext(nil, &noopRequest{}, cntnr), which has no span, and then setsc.Contextto the job's span context. Every cron log line has notrace_id:Starting cron job, everything the job logs,Panic in cron job, andFinished cron job.ctx.Traceon a context built without a span (CMD subcommands, cron before this fix). Logs afterctx.Trace(...)have notrace_id.HTTP handlers are not affected. A span started with
ctx.Tracethere is a child in the same trace, so the trace ID doesn't change.Fix:
(*Context).setContext(ctx). It replacesc.Context. It rebinds theContextLoggeronly when the new context belongs to a different trace than the current one.ctx.Traceand the cron job runner use it instead of assigningc.Contextdirectly.logging.ContextLoggerWithSpan(ctx, *ContextLogger) ContextLogger. It returns a copy that keeps the base logger and takes the span fromctx. A zero-valueContextLoggerstays zero. It is a package-level function rather than a method so it is not promoted ontogofr.Context, which embedsContextLogger.Why rebind only on a trace change:
ctx.Tracestays in the request's trace, so onlyc.Contextis written, as before. The cost is twoSpanContextFromContextlookups perctx.Tracecall.ctxwhile another goroutine callsctx.Tracedoes not race, because logging never readsc.Context. Rewriting theContextLoggeron everyctx.Tracewould introduce that race.TestContext_Trace_SameTraceDoesNotRaceWithLoggingpins this: under-race, it reports 2 data races if the condition is removed.Alternatives considered:
c.Contexton every log call. Always correct, but it adds a context lookup to every log line on the hot path, which the per-requestContextLoggerexists to avoid.ctx.Traceon span-less contexts (CMD) broken.Sites that replace
c.Contextwith a context of the same trace are left unchanged: the request-timeout and WebSocket paths inhandler.go, and the WebSocket value context inwebsocket.go. Also unchanged: the OnStart hooks context ingofr.go, which carries no span, so no trace ID is lost there.Breaking Changes (if applicable):
ContextLoggerWithSpanis a new function,setContextis unexported, and no existing signature changes.ctx.Traceon a span-less context, now carry atrace_id.Additional Information:
Tests:
TestJob_run_LogsCarryJobTraceID: trace markers on Starting / inside the job / Finished[0 0 0][1 1 1], equal toGetCorrelationID()TestContext_Trace_LogsCarryNewTraceID: span-less context, thenctx.TraceGetCorrelationID()TestContext_Trace_SameTraceKeepsTraceID: HTTP context, child spanTestContext_Trace_SameTraceDoesNotRaceWithLogging(-race)TestContextLoggerWithSpan: keeps base, takes new span, drops trace for a span-less ctx, zero value stays zerogo build ./...,go vet(includingexamples/...), andgo test -race ./pkg/gofr/ ./pkg/gofr/logging/pass. golangci-lint v2.12.2 reports 0 new issues. Coverage is 100% onsetContext,Trace,(*job).runandContextLoggerWithSpan.development. I applied this change on top of fix(context): fall back to the container logger when logging on a hand-built Context #4436's branch, and it compiles and passes-race. The test helpers use different names, so nothing clashes. Whichever PR merges second will have append-only conflicts at the end ofcontext_test.go,logging/ctx_logger.goandlogging/ctx_logger_test.go; keeping both sides resolves them.Refs #4436
Checklist:
goimportandgolangci-lint.Thank you for your contribution!
🤖 Generated with Claude Code