diff --git a/go/context.go b/go/context.go index 04543fba..b0fd5f39 100644 --- a/go/context.go +++ b/go/context.go @@ -16,6 +16,7 @@ const ( KeyCorrelationID = "correlationId" KeyRequestID = "requestId" KeyTraceID = "traceId" + KeySpanID = "spanId" KeyNamespace = "namespace" KeyService = "service" KeyDuration = "duration" diff --git a/go/go.mod b/go/go.mod index d734e176..6d8ccdc5 100644 --- a/go/go.mod +++ b/go/go.mod @@ -1,8 +1,14 @@ module github.com/SmooAI/logger/go/v3 -go 1.22 +go 1.25.0 require ( github.com/aws/aws-lambda-go v1.47.0 github.com/google/uuid v1.6.0 + go.opentelemetry.io/otel/trace v1.44.0 +) + +require ( + github.com/cespare/xxhash/v2 v2.3.0 // indirect + go.opentelemetry.io/otel v1.44.0 // indirect ) diff --git a/go/go.sum b/go/go.sum index 73fdda73..eaff62d0 100644 --- a/go/go.sum +++ b/go/go.sum @@ -1,12 +1,20 @@ github.com/aws/aws-lambda-go v1.47.0 h1:0H8s0vumYx/YKs4sE7YM0ktwL2eWse+kfopsRI1sXVI= github.com/aws/aws-lambda-go v1.47.0/go.mod h1:dpMpZgvWx5vuQJfBt0zqBha60q7Dd7RfgJv23DymV8A= +github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs= +github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/google/go-cmp v0.7.0 h1:wk8382ETsv4JYUZwIsn6YpYiWiBsYLSJiTsyBybVuN8= +github.com/google/go-cmp v0.7.0/go.mod h1:pXiqmnSA92OHEEa9HXL2W4E7lf9JzCmGVUdgjX3N/iU= github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0= github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= -github.com/stretchr/testify v1.7.2 h1:4jaiDzPyXQvSd7D0EjG45355tLlV3VOECpq10pLC+8s= -github.com/stretchr/testify v1.7.2/go.mod h1:R6va5+xMeoiuVRoj+gSkQ7d3FALtqAAGI1FQKckRals= +github.com/stretchr/testify v1.11.1 h1:7s2iGBzp5EwR7/aIZr8ao5+dra3wiQyKjjFuvgVKu7U= +github.com/stretchr/testify v1.11.1/go.mod h1:wZwfW3scLgRK+23gO65QZefKpKQRnfz6sD981Nm4B6U= +go.opentelemetry.io/otel v1.44.0 h1:JjwHmHpA4iZ3wBxluu2fbbE7j4kqlE8jXyAyPXH7HqU= +go.opentelemetry.io/otel v1.44.0/go.mod h1:BMgjTHL9WPRlRjL2oZCBTL4whCGtXch2H4BhOPIAyYc= +go.opentelemetry.io/otel/trace v1.44.0 h1:jxF5CsGYCe74MCRx2X4g7WsY/VBKRqqpNvXlX/6gtIk= +go.opentelemetry.io/otel/trace v1.44.0/go.mod h1:oLl1jrMQAVo6v3GAggN+1VH9VIz9iUSvW53sW1Q8PIE= gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= diff --git a/go/logger.go b/go/logger.go index 2a0f05b8..e4887745 100644 --- a/go/logger.go +++ b/go/logger.go @@ -7,6 +7,7 @@ package logger import ( + "context" "encoding/json" "fmt" "io" @@ -303,7 +304,9 @@ func (l *Logger) ContextConfigValue() *ContextConfig { } // buildLogObject constructs the log payload from the current context and args. -func (l *Logger) buildLogObject(level Level, msg string, args []any) Map { +// When ctx carries an active OTel span, the span's real trace_id/span_id +// replace the fabricated correlation uuid on this line (SMOODEV / th-de3805). +func (l *Logger) buildLogObject(ctx context.Context, level Level, msg string, args []any) Map { payload := getGlobalContext() if msg != "" { @@ -377,8 +380,14 @@ func (l *Logger) buildLogObject(level Level, msg string, args []any) Map { payload[KeyTime] = time.Now().UTC().Format(time.RFC3339Nano) payload[KeyName] = l.name + // Prefer the active span's real ids over the fabricated correlation uuid. + if traceID, spanID, ok := correlationFromContext(ctx); ok { + payload[KeyTraceID] = traceID + payload[KeySpanID] = spanID + } + // Add caller info - caller := getCallerInfo(3) // skip buildLogObject → log method → caller + caller := getCallerInfo(4) // skip buildLogObject → logWith → log method → caller if caller != nil { payload["caller"] = Map{ "file": caller.File, @@ -434,52 +443,76 @@ func (l *Logger) isEnabled(level Level) bool { return level >= l.level } -// Trace logs at TRACE level. -func (l *Logger) Trace(msg string, args ...any) error { - if !l.isEnabled(LevelTrace) { +// logWith is the single core log path. When ctx carries an active OTel span the +// line is stamped with its real trace/span id, and the line is mirrored to the +// installed slog.Handler (if any) so it can become an OTLP log record. +func (l *Logger) logWith(ctx context.Context, level Level, msg string, args []any) error { + if !l.isEnabled(level) { return nil } - return l.emit(l.buildLogObject(LevelTrace, msg, args)) + payload := l.buildLogObject(ctx, level, msg, args) + forwardToSlog(ctx, level, msg, payload) + return l.emit(payload) +} + +// Trace logs at TRACE level. +func (l *Logger) Trace(msg string, args ...any) error { + return l.logWith(context.Background(), LevelTrace, msg, args) } // Debug logs at DEBUG level. func (l *Logger) Debug(msg string, args ...any) error { - if !l.isEnabled(LevelDebug) { - return nil - } - return l.emit(l.buildLogObject(LevelDebug, msg, args)) + return l.logWith(context.Background(), LevelDebug, msg, args) } // Info logs at INFO level. func (l *Logger) Info(msg string, args ...any) error { - if !l.isEnabled(LevelInfo) { - return nil - } - return l.emit(l.buildLogObject(LevelInfo, msg, args)) + return l.logWith(context.Background(), LevelInfo, msg, args) } // Warn logs at WARN level. func (l *Logger) Warn(msg string, args ...any) error { - if !l.isEnabled(LevelWarn) { - return nil - } - return l.emit(l.buildLogObject(LevelWarn, msg, args)) + return l.logWith(context.Background(), LevelWarn, msg, args) } // Error logs at ERROR level. func (l *Logger) Error(msg string, args ...any) error { - if !l.isEnabled(LevelError) { - return nil - } - return l.emit(l.buildLogObject(LevelError, msg, args)) + return l.logWith(context.Background(), LevelError, msg, args) } // Fatal logs at FATAL level. func (l *Logger) Fatal(msg string, args ...any) error { - if !l.isEnabled(LevelFatal) { - return nil - } - return l.emit(l.buildLogObject(LevelFatal, msg, args)) + return l.logWith(context.Background(), LevelFatal, msg, args) +} + +// TraceContext logs at TRACE level, correlating to the active span in ctx. +func (l *Logger) TraceContext(ctx context.Context, msg string, args ...any) error { + return l.logWith(ctx, LevelTrace, msg, args) +} + +// DebugContext logs at DEBUG level, correlating to the active span in ctx. +func (l *Logger) DebugContext(ctx context.Context, msg string, args ...any) error { + return l.logWith(ctx, LevelDebug, msg, args) +} + +// InfoContext logs at INFO level, correlating to the active span in ctx. +func (l *Logger) InfoContext(ctx context.Context, msg string, args ...any) error { + return l.logWith(ctx, LevelInfo, msg, args) +} + +// WarnContext logs at WARN level, correlating to the active span in ctx. +func (l *Logger) WarnContext(ctx context.Context, msg string, args ...any) error { + return l.logWith(ctx, LevelWarn, msg, args) +} + +// ErrorContext logs at ERROR level, correlating to the active span in ctx. +func (l *Logger) ErrorContext(ctx context.Context, msg string, args ...any) error { + return l.logWith(ctx, LevelError, msg, args) +} + +// FatalContext logs at FATAL level, correlating to the active span in ctx. +func (l *Logger) FatalContext(ctx context.Context, msg string, args ...any) error { + return l.logWith(ctx, LevelFatal, msg, args) } // Silent is a no-op log method. diff --git a/go/otel_correlation.go b/go/otel_correlation.go new file mode 100644 index 00000000..e8373c98 --- /dev/null +++ b/go/otel_correlation.go @@ -0,0 +1,107 @@ +package logger + +import ( + "context" + "log/slog" + "sync" + "time" + + "go.opentelemetry.io/otel/trace" +) + +// OTel correlation (SMOODEV / th-de3805). +// +// Historically every log line's traceId was a fabricated uuid (equal to the +// correlationId), so logs could not be joined to their trace. When the caller +// threads a context.Context that carries an active OTel span (the *Context log +// methods), we instead stamp the span's real W3C trace_id + span_id onto the +// line, matching whatever /v1/traces recorded. With no active span we fall back +// to the prior uuid behavior untouched. +// +// This package depends ONLY on the OTel trace API (go.opentelemetry.io/otel/ +// trace) — never on @smooai/observability — to avoid a circular dependency. +// The observability SDK's otelslog bridge is wired in by the application via +// SetSlogHandler, so a logger line becomes an OTLP log record when obs is active. + +// correlationFromContext returns the active span's trace_id and span_id when +// ctx carries a valid span context, else ("", "", false). +func correlationFromContext(ctx context.Context) (traceID, spanID string, ok bool) { + if ctx == nil { + return "", "", false + } + sc := trace.SpanContextFromContext(ctx) + if !sc.IsValid() { + return "", "", false + } + return sc.TraceID().String(), sc.SpanID().String(), true +} + +var ( + slogHandlerMu sync.RWMutex + slogHandler slog.Handler +) + +// SetSlogHandler installs an slog.Handler that every subsequent log line is +// additionally forwarded to, carrying the call's context.Context. A handler +// that reads the active span from ctx — e.g. the @smooai/observability otelslog +// bridge (observability.SlogHandler(...)) — turns each line into an OTLP log +// record correlated to the enclosing trace and ships it to /v1/logs. +// +// The logger's own stdout/file JSON output is unaffected. Pass nil to detach. +// Wiring is done by the application (not this package) to keep the dependency +// on @smooai/observability out of the logger and avoid a cycle. +func SetSlogHandler(h slog.Handler) { + slogHandlerMu.Lock() + defer slogHandlerMu.Unlock() + slogHandler = h +} + +func getSlogHandler() slog.Handler { + slogHandlerMu.RLock() + defer slogHandlerMu.RUnlock() + return slogHandler +} + +// forwardToSlog mirrors a log line into the installed slog.Handler (if any), +// passing ctx so a span-aware handler can correlate the record. No-op when no +// handler is set or the handler is not enabled for the level. +func forwardToSlog(ctx context.Context, level Level, msg string, payload Map) { + h := getSlogHandler() + if h == nil { + return + } + sl := toSlogLevel(level) + if !h.Enabled(ctx, sl) { + return + } + rec := slog.NewRecord(time.Now(), sl, msg, 0) + // Carry the correlation-relevant scalars as attributes → parsed_fields. + for _, k := range []string{KeyCorrelationID, KeyRequestID, KeyName, KeyNamespace} { + if v, ok := payload[k]; ok { + if s, isStr := v.(string); isStr && s != "" { + rec.AddAttrs(slog.String(k, s)) + } + } + } + _ = h.Handle(ctx, rec) +} + +// toSlogLevel maps the logger's severity onto slog's numeric levels. +func toSlogLevel(level Level) slog.Level { + switch level { + case LevelTrace: + return slog.LevelDebug - 4 + case LevelDebug: + return slog.LevelDebug + case LevelInfo: + return slog.LevelInfo + case LevelWarn: + return slog.LevelWarn + case LevelError: + return slog.LevelError + case LevelFatal: + return slog.LevelError + 4 + default: + return slog.LevelInfo + } +} diff --git a/go/otel_correlation_test.go b/go/otel_correlation_test.go new file mode 100644 index 00000000..191176f2 --- /dev/null +++ b/go/otel_correlation_test.go @@ -0,0 +1,147 @@ +package logger + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "testing" + + "go.opentelemetry.io/otel/trace" +) + +// ctxWithSpan builds a context carrying a valid (non-recording) span context +// using only the OTel trace API — no SDK dependency. +func ctxWithSpan(t *testing.T) (context.Context, string, string) { + t.Helper() + traceID, err := trace.TraceIDFromHex("0123456789abcdef0123456789abcdef") + if err != nil { + t.Fatal(err) + } + spanID, err := trace.SpanIDFromHex("0123456789abcdef") + if err != nil { + t.Fatal(err) + } + sc := trace.NewSpanContext(trace.SpanContextConfig{ + TraceID: traceID, + SpanID: spanID, + TraceFlags: trace.FlagsSampled, + }) + ctx := trace.ContextWithSpanContext(context.Background(), sc) + return ctx, traceID.String(), spanID.String() +} + +func logJSON(t *testing.T, buf *bytes.Buffer) map[string]any { + t.Helper() + var payload map[string]any + if err := json.Unmarshal(buf.Bytes(), &payload); err != nil { + t.Fatalf("parse log output: %v (%s)", err, buf.String()) + } + return payload +} + +// With an active span in ctx, the line carries the span's real trace/span id +// instead of the fabricated correlation uuid. +func TestInfoContextUsesActiveSpanIDs(t *testing.T) { + resetGlobalContext() + var buf bytes.Buffer + l := Default() + l.output = &buf + l.prettyPrint = false + + ctx, wantTrace, wantSpan := ctxWithSpan(t) + _ = l.InfoContext(ctx, "with span") + + p := logJSON(t, &buf) + if p[KeyTraceID] != wantTrace { + t.Errorf("traceId = %v, want %s (active span not read)", p[KeyTraceID], wantTrace) + } + if p[KeySpanID] != wantSpan { + t.Errorf("spanId = %v, want %s", p[KeySpanID], wantSpan) + } + // correlationId keeps the fabricated uuid — distinct from the trace id. + if p[KeyCorrelationID] == wantTrace { + t.Error("correlationId should remain the fabricated uuid, not the span trace id") + } +} + +// No active span → prior behavior: traceId is the fabricated correlation uuid, +// no spanId is added. +func TestInfoWithoutSpanFallsBack(t *testing.T) { + resetGlobalContext() + var buf bytes.Buffer + l := Default() + l.output = &buf + l.prettyPrint = false + + _ = l.Info("no span") + + p := logJSON(t, &buf) + corr, _ := p[KeyCorrelationID].(string) + if corr == "" { + t.Fatal("expected a correlationId") + } + if p[KeyTraceID] != corr { + t.Errorf("traceId = %v, want fabricated uuid %s", p[KeyTraceID], corr) + } + if _, ok := p[KeySpanID]; ok { + t.Errorf("spanId should be absent without an active span, got %v", p[KeySpanID]) + } +} + +// captureHandler records the ctx + record it was handed. +type captureHandler struct { + ctx context.Context + record slog.Record + called bool +} + +func (h *captureHandler) Enabled(context.Context, slog.Level) bool { return true } +func (h *captureHandler) Handle(ctx context.Context, r slog.Record) error { + h.ctx, h.record, h.called = ctx, r, true + return nil +} +func (h *captureHandler) WithAttrs([]slog.Attr) slog.Handler { return h } +func (h *captureHandler) WithGroup(string) slog.Handler { return h } + +// A logger line flows through the installed slog.Handler carrying the call's +// ctx, so a span-aware handler (the obs otelslog bridge) can correlate it — +// proven here by reading the span back out of the forwarded ctx. +func TestSlogForwardCarriesSpanContext(t *testing.T) { + resetGlobalContext() + h := &captureHandler{} + SetSlogHandler(h) + defer SetSlogHandler(nil) + + l := Default() + l.output = &bytes.Buffer{} + l.prettyPrint = false + + ctx, wantTrace, _ := ctxWithSpan(t) + _ = l.InfoContext(ctx, "bridge me") + + if !h.called { + t.Fatal("slog handler was not invoked") + } + if h.record.Message != "bridge me" { + t.Errorf("record msg = %q, want %q", h.record.Message, "bridge me") + } + if h.record.Level != slog.LevelInfo { + t.Errorf("record level = %v, want Info", h.record.Level) + } + sc := trace.SpanContextFromContext(h.ctx) + if !sc.IsValid() || sc.TraceID().String() != wantTrace { + t.Errorf("forwarded ctx lost the active span: valid=%v trace=%s", sc.IsValid(), sc.TraceID()) + } +} + +// No handler installed → forwarding is a silent no-op (does not panic). +func TestSlogForwardNoHandlerIsNoOp(t *testing.T) { + SetSlogHandler(nil) + l := Default() + l.output = &bytes.Buffer{} + l.prettyPrint = false + if err := l.Info("no handler"); err != nil { + t.Errorf("unexpected error: %v", err) + } +}