diff --git a/pkg/gofr/context.go b/pkg/gofr/context.go index 6ab96291aa..ebb592a572 100644 --- a/pkg/gofr/context.go +++ b/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) } diff --git a/pkg/gofr/context_test.go b/pkg/gofr/context_test.go index bbace4c45c..636688e168 100644 --- a/pkg/gofr/context_test.go +++ b/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") + } + }) +} diff --git a/pkg/gofr/logging/ctx_logger.go b/pkg/gofr/logging/ctx_logger.go index 0239a9b4c9..7a9898b95b 100644 --- a/pkg/gofr/logging/ctx_logger.go +++ b/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,7 +47,13 @@ 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). @@ -53,11 +61,11 @@ func ContextLoggerFor(ctx context.Context, base Logger) ContextLogger { // 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) { diff --git a/pkg/gofr/logging/ctx_logger_test.go b/pkg/gofr/logging/ctx_logger_test.go index d457c2a8df..5ab4392bca 100644 --- a/pkg/gofr/logging/ctx_logger_test.go +++ b/pkg/gofr/logging/ctx_logger_test.go @@ -242,7 +242,7 @@ func TestContextLogger_NoTrace_NoMarker(t *testing.T) { base := newBufLogger(buf) cl := NewContextLogger(context.Background(), base) - assert.False(t, cl.spanCtx.IsValid(), "no valid span means no marker will be attached") + assert.False(t, cl.traceID.IsValid(), "no valid span means no marker will be attached") cl.Info("x") @@ -289,8 +289,8 @@ func TestContextLoggerForMatchesPointerConstructor(t *testing.T) { ptr := NewContextLogger(ctx, base) val := ContextLoggerFor(ctx, base) - require.Equal(t, ptr.spanCtx, val.spanCtx) - require.True(t, val.spanCtx.IsValid()) + require.Equal(t, ptr.traceID, val.traceID) + require.True(t, val.traceID.IsValid()) require.Equal(t, ptr.withTraceInfo("m"), val.withTraceInfo("m"), "both constructors must attach the same marker") } @@ -299,7 +299,7 @@ func TestContextLoggerForMatchesPointerConstructor(t *testing.T) { func TestContextLoggerForNoTrace(t *testing.T) { val := ContextLoggerFor(context.Background(), newBufLogger(&bytes.Buffer{})) - require.False(t, val.spanCtx.IsValid()) + require.False(t, val.traceID.IsValid()) require.Equal(t, []any{"m"}, val.withTraceInfo("m"), "no marker without a valid span") }