Repository navigation
fix(context): fall back to the container logger when logging on a hand-built Context - #4436
PiyushSingh-ZS wants to merge 5 commits into
Conversation
NitinKumar004
left a comment
There was a problem hiding this comment.
Thanks @PiyushSingh-ZS, this is a real bug and the fix works. I checked it at 6e1b9b6b locally and with the gRPC unary example from examples/grpc running for real, built from development and from this branch.
What I verified
-
The bug is real for generated gRPC code. Both generated wrappers in
examples/grpcbuild&gofr.Context{Context, Container, Request}without aContextLogger. I addedctx.Errorf(...)andctx.Info(...)toSayHelloand called it with a real gRPC client:development this PR SayHellorpc error: code = Unknown desc = panic caught: runtime error: invalid memory address or nil pointer dereference(plus the full server stack in the message)Hello gofr!handler log lines none both written; the error line carries trace_id -
Framework path unchanged. I ran the framework-context
Infofbenchmark interleaved on both trees. It's 96 B/op and 4 allocs/op on both, at about 47–52 ns/op, within noise. -
Tests are real guards. Seven mutations all fail the new tests:
- always rebuilding the
ContextLogger; - always using the embedded one;
- dropping the trace context in the fallback;
IsInitializedalways true;Warnflogging at INFO;- removing
Notice; - removing
ChangeLevel.
- always rebuilding the
-
Gates. gofmt and
go vetare clean, golangci-lint v2.12.2 reports 0 new issues, andgo test -race ./pkg/gofr/ ./pkg/gofr/logging/passes.
Should fix
-
File placement.
- The methods. Every other method on
*gofr.Contextlives inpkg/gofr/context.go. The 16 new methods are in a newpkg/gofr/context_logger.go, which reads almost the same aspkg/gofr/logging/ctx_logger.gobut holds different code. Someone looking for "the context logger" will open the wrong one. Movinglogger()and the forwarding methods intocontext.gokeepsContext's API in one place. - The tests. They would then go in
context_test.go, which is where GoFr keeps tests for the code under test. - The comment. The block on
logger()(Decision:/Context:/Choice:/Reason:/Alternatives rejected:, with the indented continuation lines) is a design record, not a godoc comment, and it doesn't match the rest of the package. The PR description already carries that reasoning. Two or three lines saying whatlogger()returns and why are enough in the code.
- The methods. Every other method on
-
A
logging.Loggermethod added later would silently reopen the panic.var _ logging.Logger = (*Context)(nil)still compiles if a method is missing from*Context, because it is promoted from the embeddedContextLogger. That promoted method panics on a hand-built context.- A test that walks the interface catches that automatically. I ran this one: it passes on this branch, and it fails if any method is removed, e.g.
Noticef:
// Every logging.Logger method must work on a hand-built Context. A method added to the interface // later but not defined on *Context would be promoted from the zero ContextLogger and panic. func TestContext_HandBuiltContextHandlesEveryLoggerMethod(t *testing.T) { ctx := reflect.ValueOf(&Context{Context: t.Context(), Container: &container.Container{Logger: discardLogger{}}}) loggerType := reflect.TypeFor[logging.Logger]() for i := range loggerType.NumMethod() { m := loggerType.Method(i) if strings.HasPrefix(m.Name, "Fatal") { continue // exits the process } method := ctx.MethodByName(m.Name) args := make([]reflect.Value, method.Type().NumIn()) for i := range args { args[i] = reflect.Zero(method.Type().In(i)) } assert.NotPanics(t, func() { method.Call(args) }, m.Name) } }
Smaller notes
-
The description says this fixes "every hand-built Context". These shapes still panic with a nil dereference, the same as on
development:- no
Container(&gofr.Context{Context: ctx}); - a
Containerwithout aLogger(&container.Container{}); - a zero
Context{}.
There's nothing to log to in those cases, so panicking may be fine. Either narrow the wording to "a Context with a Container", or make
logger()fail with a clear message instead of a nil dereference. - no
-
nit:
IsInitializedis a new exported method inloggingwhose only caller ispkg/gofr. It's small and reads fine, but it is public API now, so it's worth being sure it's the shape you want to keep.
Nothing blocking from my side. The two should-fix items are about keeping this maintainable rather than about correctness.
…ery Logger method
|
@NitinKumar004 thanks for the thorough review, especially the real gRPC run and the mutation pass. Addressed in 547e833:
Lint (v2.12.2, new code) is clean, and |
Umang01-hash
left a comment
There was a problem hiding this comment.
Reviewed in depth and re-verified at the current head (547e833, after the colocate-into-context.go refactor).
Confirmed the bug behaviorally: on development, ctx.Errorf on a gofr-cli-generated gRPC-shaped Context (Context+Container+Request, zero ContextLogger) panics with a nil-pointer; on this branch it logs through the container logger. Also ran a live http-server and saw c.Log carry exactly one correlation trace_id.
No exported API change — the methods shadow the promoted ones with identical signatures, guarded by var _ logging.Logger = (*Context)(nil). Framework hot path unaffected (same alloc profile). Build/vet/gofmt/-race/golangci-lint all clean at head; tests are thorough and fail-on-revert. LGTM.
aryanmehrotra
left a comment
There was a problem hiding this comment.
Thanks @PiyushSingh-ZS. The fix is correct, and the tests guard it. I reviewed head 547e833d6.
What I checked
- I ran 4 mutations against the new tests, and each one fails them: remove
Context.Noticef, always rebuild theContextLogger, build the fallback fromcontext.Background(), and never fall back. - The new tests pass with
-raceinpkg/gofrandpkg/gofr/logging. - The benchmark matches the description: 96 B/op and 4 allocs/op on a framework-built context, 176 B/op and 5 allocs/op on a hand-built one.
ContextLoggermethods already had pointer receivers, so aContextvalue satisfies the same interfaces as before.
Should fix
-
IsInitializedbecomes a method ofgofr.Context.Contextembedslogging.ContextLogger, so each exported method ofContextLoggeris promoted. With this PR,ctx.IsInitialized()compiles on every*gofr.Context:c := &gofr.Context{Context: ctx, Container: cont} c.IsInitialized() // false, but logging on c works
This is public API on
Contextthat we cannot remove later, and its answer is misleading: it reportsfalsefor a context that this PR makes usable. A package-level function inloggingis not promoted, for examplelogging.IsInitialized(&c.ContextLogger). That keeps the check available topkg/gofrand adds nothing toContext.
Notes
-
The "Breaking Changes: None" line needs one exception. The log methods move from depth 1 (promoted from
ContextLogger) to depth 0 (declared on*Context). A struct that embeds*gofr.Contextnext to a type that declares the same method directly compiled before and does not compile now:type myLog struct{} func (myLog) Errorf(string, ...any) {} type wrap struct { *gofr.Context myLog } w.Errorf("x") // development: resolves to myLog. This PR: ambiguous selector w.Errorf
I confirmed this with
go vetondevelopmentand on this branch. The shape is unusual and the failure is a compile error, not a silent change, so I do not think it should block the fix. Please add it to the Breaking Changes section so that it appears in the release notes. -
The generated gRPC wrappers in this repository still build the context without a
ContextLogger(examples/grpc/grpc-unary-server/server/hello_gofr.go:122,examples/grpc/grpc-streaming-server/server/chatservice_gofr.go:279). They no longer panic, but each log line in a gRPC handler now builds a newContextLogger(one more allocation, 80 B more). A follow-up in the gofr-cli template that setsContextLoggermoves gRPC handlers to the fast path. This PR does not need it.
CI
Example Unit Testing (v1.26) failed in go mod download: proxy.golang.org returned 502 Bad Gateway. The code did not cause it. The job needs a re-run, and Code Coverage was skipped because of it.
|
@aryanmehrotra thanks, good catch on the promotion. Fixed in 09fb092:
Could a maintainer re-run |
aryanmehrotra
left a comment
There was a problem hiding this comment.
Thanks @PiyushSingh-ZS. I reviewed head 09fb092ff again. All three items are resolved, and I found nothing new.
My earlier items
IsInitializedongofr.Context: fixed. It is now the package-level functionlogging.IsInitialized(*ContextLogger), soContextdoes not get a new method.TestContext_DoesNotExposeIsInitializedguards this: I added the method back toContextLogger, and the test failed.- Breaking Changes: fixed. The description now names the
ambiguous selectorcase. - gRPC wrappers: recorded. The description lists the gofr-cli template change as a follow-up. That is sufficient for this PR.
What I checked on this head
- The change since
547e833d6is 4 files, +32/−11, and it touches onlyIsInitializedand its tests. - The new tests pass with
-raceinpkg/gofrandpkg/gofr/logging.go vetandgofmtreport nothing on the 4 files. - I ran 3 mutations, and each one fails the tests: add the method back, always rebuild the
ContextLogger, and makeIsInitializedignore the base logger. - CI is green on this head: 15 checks pass, and the
Example Unit Testing (v1.26)job that failed on the proxy error now passes.
I have no open comments on this PR.
aryanmehrotra
left a comment
There was a problem hiding this comment.
One more observation from a second pass at 09fb092ff. This PR does not cause it, and it does not block this PR. I record it here because the PR makes it visible.
A framework-built Context keeps the trace ID from the moment it was built. ContextLogger reads the span one time, in ContextLoggerFor. If c.Context gets a span after that, ctx.Infof does not attach a trace ID. The fallback added in this PR reads c.Context on each call, so a hand-built Context now gives the correct trace ID in the same situation where a framework-built one gives none.
The framework does this itself in two places:
- Cron jobs.
pkg/gofr/cron.go:171-176starts the span, callsnewContext(nil, &noopRequest{}, cntnr)(no span in that request), and then setsc.Context = ctx. All logs of a cron job have no trace ID. ctx.Trace.pkg/gofr/context.go:64-73setsc.Contextto the new span's context. On a context that was built without a span (cron, CMD, start-up hooks), logs afterctx.Trace(...)have no trace ID.
Proof. I ran the real (*job).run with a capturing logger and the SDK tracer provider, on this head and on development (6e9bf3cd0):
development |
this PR | |
|---|---|---|
ctx.GetCorrelationID() inside the job |
valid trace ID | valid trace ID |
Starting cron job, the log inside the job, Finished cron job |
0 trace markers | 0 trace markers |
&gofr.Context{Context: ctx.Context, Container: ctx.Container} then Infof |
panic | 1 trace marker |
ctx.Infof after ctx.Trace("work") on a context built without a span |
0 trace markers | 0 trace markers |
So GetCorrelationID() and the log line disagree for the same context.
A child span keeps its parent's trace ID, so an HTTP handler that calls ctx.Trace is not affected. The problem occurs only when the context had no span when it was built, or when c.Context is replaced with a context from a different trace.
I suggest a separate PR for this, because the correct fix is a design choice: rebuild the ContextLogger at the places that replace c.Context, or read the span from c.Context on each call (that adds work to the hot path that this PR kept unchanged).
|
@aryanmehrotra thanks for the second pass and the cron repro. Agreed that it's separate from this PR. I'll take it as a follow-up issue and PR. My leaning is your first option: refresh the @Umang01-hash your approval was auto-dismissed by the push of 09fb092 (the |
aryanmehrotra
left a comment
There was a problem hiding this comment.
Approved at 09fb092ff. All my review items are resolved, and CI is green on this head. The trace ID observation for cron contexts is for a separate PR.
Umang01-hash
left a comment
There was a problem hiding this comment.
Re-reviewed in full at the current head (09fb092) — the head moved twice during review, so flagging that this approval pins 09fb092 specifically.
The refactor since my first pass is a genuine improvement and resolves two nits I'd raised: IsInitialized is now a free function logging.IsInitialized(l) (so it is no longer promoted onto *Context), enforced by TestContext_DoesNotExposeIsInitialized; and the nil-Container precondition is now documented on logger(). TestContext_HandBuiltContextHandlesEveryLoggerMethod reflectively exercises every logging.Logger method on a hand-built Context — a nice forward guard.
Verified locally at this head: build/vet/gofmt/-race/golangci-lint all clean; benchmark hot path unchanged (framework 63ns, same alloc profile). Live gRPC E2E: enabled ctx.Log in the grpc-unary-server example handler, called Hello/SayHello via grpcurl → logged at INFO with a trace_id and no panic (the same path nil-panics on development). Framework http path re-confirmed too.
One non-blocking nit: the refactor dropped the compile-time var _ logging.Logger = (*Context)(nil) assertion. Nothing in-tree passes a *Context as a logging.Logger, and the reflection test covers method presence, but it builds args from each method's own signature so it would not catch a signature drift that breaks interface conformance. Cheap to re-add the one-liner if you want to keep that guarantee pinned. LGTM.
aryanmehrotra
left a comment
There was a problem hiding this comment.
One suggestion at 09fb092ff. It is optional, and my approval does not depend on it.
We can remove logging.IsInitialized completely if ContextLogger is comparable. Then pkg/gofr uses ==, and this PR adds no exported symbol.
ContextLogger is not comparable today only because it stores the full trace.SpanContext, which holds a TraceState. The logger reads one thing from it: the trace ID. trace.TraceID is a [16]byte, so it is comparable and it does not allocate.
// pkg/gofr/logging/ctx_logger.go
type ContextLogger struct {
base Logger
traceID trace.TraceID // zero when the context has no valid span
}
func ContextLoggerFor(ctx context.Context, base Logger) ContextLogger {
cl := ContextLogger{base: base}
if sc := trace.SpanFromContext(ctx).SpanContext(); sc.IsValid() {
cl.traceID = sc.TraceID()
}
return cl
}
func (l *ContextLogger) withTraceInfo(args ...any) []any {
if !l.traceID.IsValid() {
return args
}
return append(args, traceIDMarker(l.traceID.String()))
}// pkg/gofr/context.go
func (c *Context) logger() *logging.ContextLogger {
if c.ContextLogger != (logging.ContextLogger{}) {
return &c.ContextLogger
}
...
}The trace ID is still formatted on each log call, so a handler that does not log pays nothing, as it does now.
I made this change locally on this head and measured it (Apple M-series, -count 3):
| this PR | with the change | |
|---|---|---|
| New exported symbols | 1 (logging.IsInitialized) |
0 |
unsafe.Sizeof(ContextLogger) |
80 | 32 |
unsafe.Sizeof(gofr.Context) |
152 | 104 |
BenchmarkContext_Infof/framework_context |
~68 ns/op, 96 B/op, 4 allocs/op | ~61 ns/op, 96 B/op, 4 allocs/op |
BenchmarkContext_Infof/hand-built_context |
~108 ns/op, 176 B/op, 5 allocs/op | ~80 ns/op, 96 B/op, 4 allocs/op |
The hand-built path loses its extra allocation, because the smaller logger does not move to the heap.
What I checked on the change
go vetreports nothing, and the tests pass with-raceinpkg/gofr/loggingand for theContexttests inpkg/gofr.- The tests in this PR still guard the behaviour. Two mutations each fail them: never fall back, and always rebuild the
ContextLogger. ==does not panic when the base logger has a non-comparable dynamic type. I tested a value-type logger that holds a slice. The comparison is against a nil interface, so the dynamic types are different and Go does not compare the values.
What it costs
- Three lines in
ctx_logger_test.goread the privatespanCtxfield (lines 245, 293, 302). They must usetraceID. TestIsInitializedandTestContext_DoesNotExposeIsInitializedare removed with the function. No method exists to promote.pkg/gofrthen depends onContextLoggerbeing comparable. If a later change adds a non-comparable field,pkg/gofrdoes not compile. That failure is immediate, but a comment on the struct is useful.- One edge case is different: a
ContextLoggerthat has a trace ID and a nil base is not the zero value, sologger()uses it and the call panics on the nil base.developmenthas the same behaviour for that value.
If you prefer to keep the PR as it is and do this in a follow-up, that is also fine.
479e805
|
@aryanmehrotra thanks, I took this in 479e805.
@Umang01-hash sorry for the churn: this push dismissed the approvals again. Could you both take another look when you have a moment? |
aryanmehrotra
left a comment
There was a problem hiding this comment.
Approved at 479e805df. The PR now adds no exported symbol, and CI is green on this head.
I also ran it end to end on this head and on development. I added ctx.Errorf to SayHello in the gRPC unary example and called it with a real client: development returns panic caught: nil pointer dereference, and this branch returns Hello gofr! and writes both log lines with trace_id. A hand-built context inside an HTTP handler logs with the same trace_id as the request.
One optional note: no test covers a base logger with a non-comparable dynamic type. I checked that case by hand and == does not panic.
NitinKumar004
left a comment
There was a problem hiding this comment.
Re-reviewed at 479e805d. Thanks @PiyushSingh-ZS, all four of my earlier points are addressed:
| Point | Status |
|---|---|
Methods in a separate context_logger.go, design-record comment |
fixed: in context.go, tests in context_test.go, short godoc |
A future logging.Logger method silently reopening the panic |
fixed: TestContext_HandBuiltContextHandlesEveryLoggerMethod (I removed Warnf, ChangeLevel, Fatal and Fatalf in turn, and each removal fails it) |
| "every hand-built Context" overstated | fixed: logger() documents the Container / Logger precondition |
IsInitialized as new public API |
gone: the PR adds no exported symbol |
What I checked on this head:
apidiffreports no API change inpkg/gofrorpkg/gofr/logging.- 11 mutations of the fallback, the trace handling and the forwarding methods all fail the tests.
-racewith 200 goroutines logging on framework-built and hand-built contexts, plusctx.Tracerunning concurrently: no races.- The new tests pass in random order with
-race -count=5. - Every build-tag combination passes vet and the tests, and lint reports 0 new issues.
- The real gRPC example handler returns
Hello gofr!and logs withtrace_id.
LGTM.
Description:
ctx.Errorf(...)(and every other logging method called directly on*gofr.Context) panics with a nil pointer dereference when theContextwas built as a struct literal, whilectx.Logger.Errorf(...)on the very same context works:Why:
Contextembedslogging.ContextLogger, whose methods win selector resolution over theContainer's embeddedLogger(depth 1 vs depth 2). Only GoFr's own constructors (newContext,newHTTPContext,newCMDContext) initialize it. A struct literal leaves itsbaselogger nil.Where this happens in practice — it is not limited to user tests:
ContextLogger(gofr-cli: wrap/template.go,getGofrContext), soctx.Errorf/ctx.Infoinside any generated gRPC handler panics at runtime. The same shape is inexamples/grpc/*/server/*_gofr.go.docs/references/testing/page.md) show building&gofr.Context{...}withoutContextLogger.This is the same failure as #2083, which was fixed for CMD apps by initializing the logger in
newContext. That covered framework-built contexts only, so hand-built ones are still affected.Fix: define the
logging.Loggermethods on*Contextitself. They shadow the embeddedContextLogger:ContextLoggeris initialized (every framework-built context), it is used exactly as before. The hot path is unchanged.ContextLoggeris built on the fly from the context's owncontext.Contextand the injectedContainer.Logger, so trace IDs are still attached. Trace correlation was the requirement raised when removingContextLoggerwas attempted in Removes the redundantContextLoggerfield from theContextstruct as requested in issue #2874 #2960.Contexttells the two cases apart by comparing its embeddedContextLoggerwith the zero value. To make that possible,ContextLoggernow stores only the trace ID (trace.TraceID, a[16]byte) instead of the fulltrace.SpanContext, whoseTraceStatemade the struct non-comparable. The logger only ever used the trace ID, and it is stored only when the span is valid, as before. So this PR adds no exported symbol, andContextLoggershrinks from 80 to 32 bytes (gofr.Contextfrom 152 to 104). A comment on the field records thatgofr.Contextrelies onContextLoggerstaying comparable; a non-comparable field added later fails to compile.Scope: this covers a
Contextthat has aContainerwith aLogger. AContextwithout aContainerorContainer.Loggerhas nothing to log to and still panics, the same asctx.Loggerdoes today.This also moves #2874 forward:
Contextno longer depends on theContextLoggerfield being set, which makes it possible to deprecate the field later without losing trace correlation.Alternatives considered and rejected:
ContextLoggerfield: breaks callers that set it in struct literals (severalexamples/*_test.godo) and drops trace correlation.ContextLoggera no-op: removes the panic but silently drops logs.Breaking Changes (if applicable):
ContextLoggerkeep working and keep using it.*Contextstill satisfieslogging.Logger.ContextLogger) to depth 0 (declared on*Context). A struct that embeds*gofr.Contextalongside another type that declares the same method directly, e.g.Errorf, previously resolved to that other type and now fails to compile withambiguous selector. This is a compile error, not a silent behavior change; resolve it by calling the intended method explicitly (e.g.w.myLog.Errorf(...)).ctx.Fatal/ctx.Fatalfnow log via the container logger (and exit) instead of panicking.Additional Information:
The methods and
logger()live inpkg/gofr/context.gonext to the rest ofContext's API.Tests (
pkg/gofr/context_test.go, table-driven):context.Context: every method reachesContainer.Logger, and the trace ID is attached only when a span is present. These tests panic without the fix.ctx.Errorfworks and carries the trace ID.ContextLoggerand never throughContainer.Logger, with exactly one trace marker (no double wrapping).logging.Logger, found by reflection, works on a hand-built context, so a method added to the interface later without a*Contextoverride fails the test instead of silently reopening the panic.ChangeLevelon both paths.Benchmark (
BenchmarkContext_Infof, Apple M-series,-count 6):newHTTPContext)Note:
go test -race ./pkg/gofr/logging/remotelogger/fails ondevelopmentalready (pre-existing data races inTestRemoteLogger_UpdateLevel,TestHTTPLogFilter_ConcurrentAccess,TestRemoteLogger_ConcurrentLevelAccess,TestLogLevelChangeToFatal_NoExit). It is unrelated to this change.Follow-up (separate PR, not required here): the gofr-cli gRPC wrapper template (and the generated
examples/grpc/*/server/*_gofr.go) should setContextLoggerso gRPC handlers take the fast path instead of building aContextLoggerper log call.Refs #2083, #2874
Checklist:
goimportandgolangci-lint.Thank you for your contribution!
🤖 Generated with Claude Code