fix(context): fall back to the container logger when logging on a hand-built Context

pkg/gofr/context.go

@@ -232,3 +232,63 @@ func newCMDContext(w Responder, r Request, c *container.Container, out terminal.
 func (c *Context) GetCorrelationID() string {
 	return trace.SpanFromContext(c).SpanContext().TraceID().String()
 }
+
+// logger returns the embedded ContextLogger when GoFr initialized it. A Context built as a struct
+// literal (in tests, or by gofr-cli generated gRPC wrappers) leaves it zero-valued, so one is built
+// from the Context's own context and Container.Logger, keeping the trace ID instead of panicking.
+// A Context without a Container or Container.Logger has nothing to log to and panics, as ctx.Logger does.
+func (c *Context) logger() *logging.ContextLogger {
+	if c.ContextLogger != (logging.ContextLogger{}) {
+		return &c.ContextLogger
+	}
+
+	cl := logging.ContextLoggerFor(c.Context, c.Container.Logger)
+
+	return &cl
+}
+
+// Debug logs at DEBUG level, attaching the request's trace ID when one is present.
+func (c *Context) Debug(args ...any) { c.logger().Debug(args...) }
+
+// Debugf logs a formatted message at DEBUG level, attaching the request's trace ID when one is present.
+func (c *Context) Debugf(format string, args ...any) { c.logger().Debugf(format, args...) }
+
+// Log logs at INFO level, attaching the request's trace ID when one is present.
+func (c *Context) Log(args ...any) { c.logger().Log(args...) }
+
+// Logf logs a formatted message at INFO level, attaching the request's trace ID when one is present.
+func (c *Context) Logf(format string, args ...any) { c.logger().Logf(format, args...) }
+
+// Info logs at INFO level, attaching the request's trace ID when one is present.
+func (c *Context) Info(args ...any) { c.logger().Info(args...) }
+
+// Infof logs a formatted message at INFO level, attaching the request's trace ID when one is present.
+func (c *Context) Infof(format string, args ...any) { c.logger().Infof(format, args...) }
+
+// Notice logs at NOTICE level, attaching the request's trace ID when one is present.
+func (c *Context) Notice(args ...any) { c.logger().Notice(args...) }
+
+// Noticef logs a formatted message at NOTICE level, attaching the request's trace ID when one is present.
+func (c *Context) Noticef(format string, args ...any) { c.logger().Noticef(format, args...) }
+
+// Warn logs at WARN level, attaching the request's trace ID when one is present.
+func (c *Context) Warn(args ...any) { c.logger().Warn(args...) }
+
+// Warnf logs a formatted message at WARN level, attaching the request's trace ID when one is present.
+func (c *Context) Warnf(format string, args ...any) { c.logger().Warnf(format, args...) }
+
+// Error logs at ERROR level, attaching the request's trace ID when one is present.
+func (c *Context) Error(args ...any) { c.logger().Error(args...) }
+
+// Errorf logs a formatted message at ERROR level, attaching the request's trace ID when one is present.
+func (c *Context) Errorf(format string, args ...any) { c.logger().Errorf(format, args...) }
+
+// Fatal logs at FATAL level, attaching the request's trace ID when one is present, and exits the application.
+func (c *Context) Fatal(args ...any) { c.logger().Fatal(args...) }
+
+// Fatalf logs a formatted message at FATAL level, attaching the request's trace ID when one is present,
+// and exits the application.
+func (c *Context) Fatalf(format string, args ...any) { c.logger().Fatalf(format, args...) }
+
+// ChangeLevel changes the level of the underlying logger.
+func (c *Context) ChangeLevel(level logging.Level) { c.logger().ChangeLevel(level) }

pkg/gofr/context_test.go

@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"net/http"
 	"net/http/httptest"
+	"reflect"
 	"sync"
 	"testing"
 	"time"
@@ -18,6 +19,7 @@ import (
 	"go.opentelemetry.io/otel"
 	"go.opentelemetry.io/otel/sdk/trace"
 	"go.opentelemetry.io/otel/sdk/trace/tracetest"
+	oteltrace "go.opentelemetry.io/otel/trace"
 
 	"gofr.dev/pkg/gofr/config"
 	"gofr.dev/pkg/gofr/container"
@@ -552,3 +554,268 @@ func firstMessageBeforeEnd(t *testing.T, conn *gofrWebsocket.Connection, receive
 		return ""
 	}
 }
+
+// recordedLog is a single call captured by recordingLogger.
+type recordedLog struct {
+	method string
+	format string
+	args   []any
+}
+
+// recordingLogger captures every call so tests can assert which logger received
+// a message and which arguments (including the trace ID marker) were passed.
+type recordingLogger struct {
+	logs  []recordedLog
+	level logging.Level
+}
+
+func (r *recordingLogger) recordf(method, format string, args ...any) {
+	r.logs = append(r.logs, recordedLog{method: method, format: format, args: args})
+}
+
+func (r *recordingLogger) Debug(args ...any)             { r.recordf("Debug", "", args...) }
+func (r *recordingLogger) Debugf(f string, args ...any)  { r.recordf("Debugf", f, args...) }
+func (r *recordingLogger) Log(args ...any)               { r.recordf("Log", "", args...) }
+func (r *recordingLogger) Logf(f string, args ...any)    { r.recordf("Logf", f, args...) }
+func (r *recordingLogger) Info(args ...any)              { r.recordf("Info", "", args...) }
+func (r *recordingLogger) Infof(f string, args ...any)   { r.recordf("Infof", f, args...) }
+func (r *recordingLogger) Notice(args ...any)            { r.recordf("Notice", "", args...) }
+func (r *recordingLogger) Noticef(f string, args ...any) { r.recordf("Noticef", f, args...) }
+func (r *recordingLogger) Warn(args ...any)              { r.recordf("Warn", "", args...) }
+func (r *recordingLogger) Warnf(f string, args ...any)   { r.recordf("Warnf", f, args...) }
+func (r *recordingLogger) Error(args ...any)             { r.recordf("Error", "", args...) }
+func (r *recordingLogger) Errorf(f string, args ...any)  { r.recordf("Errorf", f, args...) }
+func (r *recordingLogger) Fatal(args ...any)             { r.recordf("Fatal", "", args...) }
+func (r *recordingLogger) Fatalf(f string, args ...any)  { r.recordf("Fatalf", f, args...) }
+func (r *recordingLogger) ChangeLevel(level logging.Level) {
+	r.level = level
+	r.recordf("ChangeLevel", "")
+}
+
+func tracedTestContext() (ctx context.Context, traceID string) {
+	sc := oteltrace.NewSpanContext(oteltrace.SpanContextConfig{
+		TraceID:    oteltrace.TraceID{0x0a, 0x0b, 0x0c, 0x0d, 0x0e, 0x0f, 0x10, 0x11, 0x12, 0x13, 0x14, 0x15, 0x16, 0x17, 0x18, 0x19},
+		SpanID:     oteltrace.SpanID{0x01, 0x02, 0x03, 0x04, 0x05, 0x06, 0x07, 0x08},
+		TraceFlags: oteltrace.FlagsSampled,
+	})
+
+	return oteltrace.ContextWithSpanContext(context.Background(), sc), sc.TraceID().String()
+}
+
+// countTraceMarkers counts the args that render as the given trace ID; the marker
+// type is unexported in the logging package, so it is matched by its value.
+func countTraceMarkers(args []any, traceID string) int {
+	n := 0
+
+	for _, a := range args {
+		if fmt.Sprint(a) == traceID {
+			n++
+		}
+	}
+
+	return n
+}
+
+// callAllLogMethods invokes every logging.Logger method once on ctx.
+func callAllLogMethods(ctx *Context) {
+	ctx.Debug("m")
+	ctx.Debugf("m %s", "a")
+	ctx.Log("m")
+	ctx.Logf("m %s", "a")
+	ctx.Info("m")
+	ctx.Infof("m %s", "a")
+	ctx.Notice("m")
+	ctx.Noticef("m %s", "a")
+	ctx.Warn("m")
+	ctx.Warnf("m %s", "a")
+	ctx.Error("m")
+	ctx.Errorf("m %s", "a")
+	ctx.Fatal("m")
+	ctx.Fatalf("m %s", "a")
+}
+
+func allLogMethods() []string {
+	return []string{
+		"Debug", "Debugf", "Log", "Logf", "Info", "Infof", "Notice", "Noticef",
+		"Warn", "Warnf", "Error", "Errorf", "Fatal", "Fatalf",
+	}
+}
+
+func methodsOf(logs []recordedLog) []string {
+	out := make([]string, 0, len(logs))
+	for _, l := range logs {
+		out = append(out, l.method)
+	}
+
+	return out
+}
+
+// Hand-built contexts (tests, background jobs, gofr-cli generated gRPC wrappers)
+// leave ContextLogger zero-valued. Logging through the context must fall back to
+// the container's logger instead of dereferencing a nil base logger.
+func TestContext_Logging_HandBuiltContextFallsBackToContainerLogger(t *testing.T) {
+	tracedCtx, traceID := tracedTestContext()
+
+	tests := []struct {
+		desc        string
+		stdCtx      context.Context
+		wantMarkers int
+	}{
+		{desc: "background context logs without a trace marker", stdCtx: context.Background(), wantMarkers: 0},
+		{desc: "traced context keeps the trace ID", stdCtx: tracedCtx, wantMarkers: 1},
+		{desc: "nil context logs without a trace marker", stdCtx: nil, wantMarkers: 0},
+	}
+
+	for _, tc := range tests {
+		t.Run(tc.desc, func(t *testing.T) {
+			rec := &recordingLogger{}
+			ctx := &Context{Context: tc.stdCtx, Container: &container.Container{Logger: rec}}
+
+			require.NotPanics(t, func() { callAllLogMethods(ctx) })
+
+			require.Equal(t, allLogMethods(), methodsOf(rec.logs))
+
+			for _, l := range rec.logs {
+				assert.Equal(t, tc.wantMarkers, countTraceMarkers(l.args, traceID), "method %s", l.method)
+			}
+		})
+	}
+}
+
+// The gRPC wrapper generated by gofr-cli builds the context with exactly these
+// fields; ctx.Errorf in a gRPC handler must not panic.
+func TestContext_Logging_GRPCWrapperShapedContext(t *testing.T) {
+	tracedCtx, traceID := tracedTestContext()
+	rec := &recordingLogger{}
+
+	ctx := &Context{
+		Context:   tracedCtx,
+		Container: &container.Container{Logger: rec},
+		Request:   nil,
+	}
+
+	require.NotPanics(t, func() { ctx.Errorf("failed: %v", "boom") })
+	require.Len(t, rec.logs, 1)
+	assert.Equal(t, "Errorf", rec.logs[0].method)
+	assert.Equal(t, "failed: %v", rec.logs[0].format)
+	assert.Equal(t, 1, countTraceMarkers(rec.logs[0].args, traceID))
+}
+
+// Framework-built contexts must keep logging through their ContextLogger: one
+// trace marker per call, delivered to the logger the ContextLogger wraps.
+func TestContext_Logging_FrameworkContextUsesContextLogger(t *testing.T) {
+	tracedCtx, traceID := tracedTestContext()
+
+	containerLog := &recordingLogger{}
+	ctxLog := &recordingLogger{}
+
+	ctx := &Context{
+		Context:       tracedCtx,
+		Container:     &container.Container{Logger: containerLog},
+		ContextLogger: logging.ContextLoggerFor(tracedCtx, ctxLog),
+	}
+
+	callAllLogMethods(ctx)
+
+	assert.Empty(t, containerLog.logs, "an initialized ContextLogger must not be bypassed")
+	require.Equal(t, allLogMethods(), methodsOf(ctxLog.logs))
+
+	for _, l := range ctxLog.logs {
+		assert.Equal(t, 1, countTraceMarkers(l.args, traceID), "method %s", l.method)
+	}
+}
+
+func TestContext_Logging_NewHTTPContextKeepsSingleTraceMarker(t *testing.T) {
+	tracedCtx, traceID := tracedTestContext()
+	rec := &recordingLogger{}
+
+	req := httptest.NewRequestWithContext(tracedCtx, http.MethodGet, "/", http.NoBody)
+	ctx := newHTTPContext(httptest.NewRecorder(), req, &container.Container{Logger: rec})
+
+	ctx.Infof("hello %s", "world")
+
+	require.Len(t, rec.logs, 1)
+	assert.Equal(t, 1, countTraceMarkers(rec.logs[0].args, traceID))
+}
+
+func TestContext_ChangeLevel(t *testing.T) {
+	t.Run("hand-built context changes the container logger level", func(t *testing.T) {
+		rec := &recordingLogger{}
+		ctx := &Context{Context: context.Background(), Container: &container.Container{Logger: rec}}
+
+		require.NotPanics(t, func() { ctx.ChangeLevel(logging.WARN) })
+		assert.Equal(t, logging.WARN, rec.level)
+	})
+
+	t.Run("framework context changes the wrapped logger level", func(t *testing.T) {
+		rec := &recordingLogger{}
+		ctx := newContext(nil, &noopRequest{}, &container.Container{Logger: rec})
+
+		ctx.ChangeLevel(logging.ERROR)
+		assert.Equal(t, logging.ERROR, rec.level)
+	})
+}
+
+type discardLogger struct{}
+
+func (discardLogger) Debug(...any)              {}
+func (discardLogger) Debugf(string, ...any)     {}
+func (discardLogger) Log(...any)                {}
+func (discardLogger) Logf(string, ...any)       {}
+func (discardLogger) Info(...any)               {}
+func (discardLogger) Infof(string, ...any)      {}
+func (discardLogger) Notice(...any)             {}
+func (discardLogger) Noticef(string, ...any)    {}
+func (discardLogger) Warn(...any)               {}
+func (discardLogger) Warnf(string, ...any)      {}
+func (discardLogger) Error(...any)              {}
+func (discardLogger) Errorf(string, ...any)     {}
+func (discardLogger) Fatal(...any)              {}
+func (discardLogger) Fatalf(string, ...any)     {}
+func (discardLogger) ChangeLevel(logging.Level) {}
+
+// 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() {
+		name := loggerType.Method(i).Name
+		method := ctx.MethodByName(name)
+		args := make([]reflect.Value, method.Type().NumIn())
+
+		for j := range args {
+			args[j] = reflect.Zero(method.Type().In(j))
+		}
+
+		// Fatal and Fatalf are included: the discard logger does not exit the process.
+		assert.NotPanics(t, func() { method.Call(args) }, name)
+	}
+}
+
+func BenchmarkContext_Infof(b *testing.B) {
+	tracedCtx, _ := tracedTestContext()
+	req := httptest.NewRequestWithContext(tracedCtx, http.MethodGet, "/", http.NoBody)
+	c := &container.Container{Logger: discardLogger{}}
+
+	b.Run("framework context", func(b *testing.B) {
+		ctx := newHTTPContext(httptest.NewRecorder(), req, c)
+
+		b.ReportAllocs()
+
+		for b.Loop() {
+			ctx.Infof("hello %s", "world")
+		}
+	})
+
+	b.Run("hand-built context", func(b *testing.B) {
+		ctx := &Context{Context: tracedCtx, Container: c}
+
+		b.ReportAllocs()
+
+		for b.Loop() {
+			ctx.Infof("hello %s", "world")
+		}
+	})
+}

pkg/gofr/logging/ctx_logger.go

@@ -13,8 +13,10 @@ import (
 // trace information is available.
 type ContextLogger struct {
 	base Logger
-	// spanCtx is the request's SpanContext, kept as a value (it allocates
-	// nothing) rather than a formatted trace ID.
+	// traceID is the request's trace ID, zero when the context has no valid span. It is kept as
+	// the raw [16]byte (it allocates nothing) rather than a formatted string, and rather than the
+	// full SpanContext, whose TraceState would make ContextLogger non-comparable: gofr.Context
+	// compares its embedded ContextLogger with the zero value to detect a hand-built Context.
 	//
 	// Formatting the trace ID costs a 32-character string, and wrapping it for
 	// the log args costs another allocation. Both were paid when the logger was
@@ -25,7 +27,7 @@ type ContextLogger struct {
 	// They are now built in withTraceInfo, per log call. A handler logging once
 	// pays exactly what it did before; one logging repeatedly pays per call,
 	// which is the deliberate trade for making the silent path free.
-	spanCtx trace.SpanContext
+	traceID trace.TraceID
 }
 
 // NewContextLogger creates a new ContextLogger that wraps the provided base logger
@@ -45,19 +47,25 @@ func NewContextLogger(ctx context.Context, base Logger) *ContextLogger {
 // that need a pointer keep using NewContextLogger; callers that store a value
 // use this and allocate nothing for the wrapper itself.
 func ContextLoggerFor(ctx context.Context, base Logger) ContextLogger {
-	return ContextLogger{base: base, spanCtx: trace.SpanFromContext(ctx).SpanContext()}
+	cl := ContextLogger{base: base}
+
+	if sc := trace.SpanFromContext(ctx).SpanContext(); sc.IsValid() {
+		cl.traceID = sc.TraceID()
+	}
+
+	return cl
 }
 
 // withTraceInfo appends the trace ID from the context (if available).
 // This allows trace IDs to be extracted later during formatting or filtering.
 // The marker map is precomputed once per ContextLogger, so this only pays for
 // the slice append, not a fresh map allocation on every call.
 func (l *ContextLogger) withTraceInfo(args ...any) []any {
-	if !l.spanCtx.IsValid() {
+	if !l.traceID.IsValid() {
 		return args
 	}
 
-	return append(args, traceIDMarker(l.spanCtx.TraceID().String()))
+	return append(args, traceIDMarker(l.traceID.String()))
 }
 
 func (l *ContextLogger) logWithTraceID(lf func(args ...any), args ...any) {