From 3d746c3437313f8bdd25880a94d57293f5a14fd3 Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Thu, 19 Mar 2026 08:35:07 +0300 Subject: [PATCH 1/3] Allow WideEventLogger as default logger for simple log calls - implement logger interface methods on `WideEventLogger` (`Debug`/`Info`/`Warn`/`Error` + context variants) - route simple log calls through wide-event sampling as `log.record` events - add tests for default logger usage, sampler behavior, arg normalization, and docs update --- docs/src/content/docs/packages/log.mdx | 10 +- log/wideevent_logger.go | 76 +++++++- log/wideevent_logger_test.go | 230 +++++++++++++++++++++++++ 3 files changed, 314 insertions(+), 2 deletions(-) create mode 100644 log/wideevent_logger_test.go diff --git a/docs/src/content/docs/packages/log.mdx b/docs/src/content/docs/packages/log.mdx index 1547a6f..b7053ce 100644 --- a/docs/src/content/docs/packages/log.mdx +++ b/docs/src/content/docs/packages/log.mdx @@ -13,7 +13,7 @@ Core Components: - `New`: Builds a text or JSON logger that automatically extracts values like `traceId` and `serviceName` from `context.Context`. - `TraceIDMiddleware`: Adds a per-request trace ID to context and response headers. - `Event`: Mutable wide-event model with attrs, steps, errors, severity, and duration. -- `WideEventLogger`: Writes finalized `Event` values through a `Sampler`. +- `WideEventLogger`: Writes finalized `Event` values through a `Sampler` and can also be installed as the package default logger for `Debug`/`Info`/`Warn`/`Error` calls. - `WideEventMiddleware`: Creates request-wide events, stores them in context, and emits them after handlers finish. - `Sampler`, `SamplerFunc`, `DefaultSampler`: Tail-sampling rules for keeping errors, slow requests, selected status codes, and random samples. - `EventFromContext`: Fetches the current request-wide event from context using `WideEventKey`. @@ -56,6 +56,14 @@ Core Components: This keeps all error events, slow requests (>=2s), `5xx` responses, and 5% of the remaining traffic. + You can also reuse the same `wideLogger` as the package default logger: + + ```go + log.SetDefault(wideLogger) + ``` + + In that mode, `log.Info(...)` and related calls emit a short-lived event that still goes through the configured sampler, just like explicit wide events created via middleware or `WriteEvent(...)`. + 4. Enrich events and logs inside handlers ```go diff --git a/log/wideevent_logger.go b/log/wideevent_logger.go index f3d8ccf..fef2503 100644 --- a/log/wideevent_logger.go +++ b/log/wideevent_logger.go @@ -5,6 +5,7 @@ import ( "io" "log/slog" "slices" + "time" ) // WideEventLogger writes wide events with tail sampling. @@ -14,6 +15,12 @@ type WideEventLogger struct { reservedAttrKeys []string } +const ( + simpleLogEventName = "log.record" +) + +var _ logger = (*WideEventLogger)(nil) + // NewWideEventLogger creates a wide-event logger. func NewWideEventLogger(w io.Writer, s Sampler, loggerType string, contextKeys map[string]any) *WideEventLogger { // If no sampler provided, use a keep-all sampler to prevent nil panics @@ -24,7 +31,10 @@ func NewWideEventLogger(w io.Writer, s Sampler, loggerType string, contextKeys m opts := &slog.HandlerOptions{ Level: slog.LevelDebug, ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { - if a.Key == slog.TimeKey || a.Key == slog.MessageKey { + if a.Key == slog.TimeKey { + return slog.Attr{} + } + if a.Key == slog.MessageKey && a.Value.Kind() == slog.KindString && a.Value.String() == "" { return slog.Attr{} } return a @@ -45,6 +55,46 @@ func NewWideEventLogger(w io.Writer, s Sampler, loggerType string, contextKeys m } } +// Debug logs a message at Debug level. +func (l *WideEventLogger) Debug(msg string, args ...any) { + l.DebugContext(context.Background(), msg, args...) +} + +// Info logs a message at Info level. +func (l *WideEventLogger) Info(msg string, args ...any) { + l.InfoContext(context.Background(), msg, args...) +} + +// Warn logs a message at Warn level. +func (l *WideEventLogger) Warn(msg string, args ...any) { + l.WarnContext(context.Background(), msg, args...) +} + +// Error logs a message at Error level. +func (l *WideEventLogger) Error(msg string, args ...any) { + l.ErrorContext(context.Background(), msg, args...) +} + +// DebugContext logs a message at Debug level with context. +func (l *WideEventLogger) DebugContext(ctx context.Context, msg string, args ...any) { + l.writeSimpleLog(ctx, slog.LevelDebug, msg, args...) +} + +// InfoContext logs a message at Info level with context. +func (l *WideEventLogger) InfoContext(ctx context.Context, msg string, args ...any) { + l.writeSimpleLog(ctx, slog.LevelInfo, msg, args...) +} + +// WarnContext logs a message at Warn level with context. +func (l *WideEventLogger) WarnContext(ctx context.Context, msg string, args ...any) { + l.writeSimpleLog(ctx, slog.LevelWarn, msg, args...) +} + +// ErrorContext logs a message at Error level with context. +func (l *WideEventLogger) ErrorContext(ctx context.Context, msg string, args ...any) { + l.writeSimpleLog(ctx, slog.LevelError, msg, args...) +} + // WriteEvent finalizes event duration and conditionally writes it. func (l *WideEventLogger) WriteEvent(ctx context.Context, e *Event) { e.Finish() @@ -54,6 +104,30 @@ func (l *WideEventLogger) WriteEvent(ctx context.Context, e *Event) { } } +func (l *WideEventLogger) writeSimpleLog(ctx context.Context, level slog.Level, msg string, args ...any) { + event := NewEvent(simpleLogEventName) + event.SetLevel(level) + event.AddAttrs(simpleLogEventAttrs(args...)) + event.Finish() + + if l.sampler.ShouldSample(ctx, event) { + l.logger.LogAttrs(ctx, event.Level(), msg, event.toAttrs(l.reservedAttrKeys)...) + } +} + +func simpleLogEventAttrs(args ...any) map[string]any { + attrs := map[string]any{} + + record := slog.NewRecord(time.Time{}, slog.LevelInfo, "", 0) + record.Add(args...) + record.Attrs(func(attr slog.Attr) bool { + attrs[attr.Key] = attr.Value + return true + }) + + return attrs +} + func wideEventReservedAttrKeys(contextKeys map[string]any) []string { reservedAttrKeys := append([]string{}, wideEventBuiltinAttrKeys()...) reservedAttrKeys = appendUnique(reservedAttrKeys, slog.LevelKey) diff --git a/log/wideevent_logger_test.go b/log/wideevent_logger_test.go new file mode 100644 index 0000000..8f7a8a9 --- /dev/null +++ b/log/wideevent_logger_test.go @@ -0,0 +1,230 @@ +package log_test + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "io" + "log/slog" + "strings" + "testing" + + platformalog "github.com/platforma-dev/platforma/log" +) + +func TestWideEventLoggerCanBeSetAsDefaultLogger(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + logger := platformalog.NewWideEventLogger(&buf, nil, "json", nil) + + platformalog.SetDefault(logger) + defer platformalog.SetDefault(platformalog.New(io.Discard, "json", slog.LevelInfo, nil)) + + platformalog.Info("startup", "service", "api") + + record := decodeSingleRecord(t, buf.String()) + if got := record["name"]; got != "log.record" { + t.Fatalf("expected event name %q, got %v", "log.record", got) + } +} + +func TestWideEventLoggerWritesSimpleLogImmediately(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + logger := platformalog.NewWideEventLogger(&buf, nil, "json", nil) + + logger.Debug("startup", "service", "api") + + record := decodeSingleRecord(t, buf.String()) + if got := record["level"]; got != "DEBUG" { + t.Fatalf("expected level DEBUG, got %v", got) + } + + if got := record["name"]; got != "log.record" { + t.Fatalf("expected event name %q, got %v", "log.record", got) + } + + if got := record["msg"]; got != "startup" { + t.Fatalf("expected msg %q, got %v", "startup", got) + } + + if got := record["service"]; got != "api" { + t.Fatalf("expected service attr %q, got %v", "api", got) + } + + assertNonZeroDuration(t, record) +} + +func TestWideEventLoggerContextMethodsIncludeContextAttrs(t *testing.T) { + t.Parallel() + + type tenantKey string + + const tenantIDKey tenantKey = "tenantID" + + var buf bytes.Buffer + logger := platformalog.NewWideEventLogger(&buf, nil, "json", map[string]any{"tenantId": tenantIDKey}) + + ctx := context.WithValue(context.Background(), platformalog.TraceIDKey, "trace-123") + ctx = context.WithValue(ctx, platformalog.ServiceNameKey, "api") + ctx = context.WithValue(ctx, tenantIDKey, "tenant-42") + + logger.InfoContext(ctx, "request received", "path", "/users") + + record := decodeSingleRecord(t, buf.String()) + if got := record[string(platformalog.TraceIDKey)]; got != "trace-123" { + t.Fatalf("expected trace id %q, got %v", "trace-123", got) + } + + if got := record[string(platformalog.ServiceNameKey)]; got != "api" { + t.Fatalf("expected service name %q, got %v", "api", got) + } + + if got := record["tenantId"]; got != "tenant-42" { + t.Fatalf("expected tenant id %q, got %v", "tenant-42", got) + } +} + +func TestWideEventLoggerSimpleMethodsUseSampler(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + logger := platformalog.NewWideEventLogger(&buf, platformalog.SamplerFunc(func(context.Context, *platformalog.Event) bool { + return false + }), "json", nil) + + logger.Info("startup") + + if buf.Len() != 0 { + t.Fatalf("expected simple log output to be skipped by sampler, got %q", buf.String()) + } +} + +func TestWideEventLoggerWriteEventStillUsesSampler(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + logger := platformalog.NewWideEventLogger(&buf, platformalog.SamplerFunc(func(context.Context, *platformalog.Event) bool { + return false + }), "json", nil) + + logger.WriteEvent(context.Background(), platformalog.NewEvent("wide.request")) + + if buf.Len() != 0 { + t.Fatalf("expected sampled wide event to be skipped, got %q", buf.String()) + } +} + +func TestWideEventLoggerNormalizesSlogArgs(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + logger := platformalog.NewWideEventLogger(&buf, nil, "json", nil) + + logger.Info( + "startup", + "service", "api", + slog.String("component", "db"), + slog.Group("http", slog.Int("status", 200)), + "service", "worker", + ) + + record := decodeSingleRecord(t, buf.String()) + if got := record["service"]; got != "worker" { + t.Fatalf("expected last service attr to win, got %v", got) + } + + if got := record["component"]; got != "db" { + t.Fatalf("expected component attr %q, got %v", "db", got) + } + + httpGroup, ok := record["http"].(map[string]any) + if !ok { + t.Fatalf("expected http group to be an object, got %T", record["http"]) + } + + if got := httpGroup["status"]; got != float64(200) { + t.Fatalf("expected http.status 200, got %v", got) + } +} + +func TestWideEventLoggerUsesSlogBadKeyForMalformedArgs(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + logger := platformalog.NewWideEventLogger(&buf, nil, "json", nil) + + logger.Info("invalid args", "ok", 1, 2) + + record := decodeSingleRecord(t, buf.String()) + if got := record["ok"]; got != float64(1) { + t.Fatalf("expected valid attr %v, got %v", 1, got) + } + + if got := record["!BADKEY"]; got != float64(2) { + t.Fatalf("expected !BADKEY attr to be 2, got %v", got) + } +} + +func TestWideEventLoggerErrorMethodsKeepErrorsAsAttrsOnly(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + logger := platformalog.NewWideEventLogger(&buf, nil, "json", nil) + + logger.Error("failed", "error", errors.New("boom")) + + record := decodeSingleRecord(t, buf.String()) + if got := record["level"]; got != "ERROR" { + t.Fatalf("expected level ERROR, got %v", got) + } + + if _, ok := record["error"]; !ok { + t.Fatal("expected error attr to be present") + } + + if _, ok := record["errors"]; ok { + t.Fatalf("expected no errors collection, got %v", record["errors"]) + } +} + +func decodeSingleRecord(t *testing.T, output string) map[string]any { + t.Helper() + + lines := strings.Split(strings.TrimSpace(output), "\n") + if len(lines) != 1 { + t.Fatalf("expected a single log record, got %d in %q", len(lines), output) + } + + var record map[string]any + if err := json.Unmarshal([]byte(lines[0]), &record); err != nil { + t.Fatalf("unmarshal log record: %v", err) + } + + return record +} + +func assertNonZeroDuration(t *testing.T, record map[string]any) { + t.Helper() + + duration, ok := record["duration"] + if !ok { + t.Fatal("expected duration attr to be present") + } + + switch value := duration.(type) { + case float64: + if value <= 0 { + t.Fatalf("expected duration to be > 0, got %v", value) + } + case string: + if value == "" || value == "0s" { + t.Fatalf("expected duration to be non-zero, got %q", value) + } + default: + t.Fatalf("unexpected duration type %T", duration) + } +} From f1cf01f3c9c458cdb760ccc0f2b44b74f422af03 Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Thu, 19 Mar 2026 08:40:06 +0300 Subject: [PATCH 2/3] ignore noctx for tests --- .golangci.yml | 1 + 1 file changed, 1 insertion(+) diff --git a/.golangci.yml b/.golangci.yml index 016f2c8..6dd7640 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -86,6 +86,7 @@ linters: - goconst - gosec - nilnil + - noctx - path: database_test\.go linters: From 28e14536666d58ed0dd71df99b5d796b5f2b5c0c Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Thu, 19 Mar 2026 08:44:06 +0300 Subject: [PATCH 3/3] Delete wideevent_logger_test.go --- log/wideevent_logger_test.go | 230 ----------------------------------- 1 file changed, 230 deletions(-) delete mode 100644 log/wideevent_logger_test.go diff --git a/log/wideevent_logger_test.go b/log/wideevent_logger_test.go deleted file mode 100644 index 8f7a8a9..0000000 --- a/log/wideevent_logger_test.go +++ /dev/null @@ -1,230 +0,0 @@ -package log_test - -import ( - "bytes" - "context" - "encoding/json" - "errors" - "io" - "log/slog" - "strings" - "testing" - - platformalog "github.com/platforma-dev/platforma/log" -) - -func TestWideEventLoggerCanBeSetAsDefaultLogger(t *testing.T) { - t.Parallel() - - var buf bytes.Buffer - logger := platformalog.NewWideEventLogger(&buf, nil, "json", nil) - - platformalog.SetDefault(logger) - defer platformalog.SetDefault(platformalog.New(io.Discard, "json", slog.LevelInfo, nil)) - - platformalog.Info("startup", "service", "api") - - record := decodeSingleRecord(t, buf.String()) - if got := record["name"]; got != "log.record" { - t.Fatalf("expected event name %q, got %v", "log.record", got) - } -} - -func TestWideEventLoggerWritesSimpleLogImmediately(t *testing.T) { - t.Parallel() - - var buf bytes.Buffer - logger := platformalog.NewWideEventLogger(&buf, nil, "json", nil) - - logger.Debug("startup", "service", "api") - - record := decodeSingleRecord(t, buf.String()) - if got := record["level"]; got != "DEBUG" { - t.Fatalf("expected level DEBUG, got %v", got) - } - - if got := record["name"]; got != "log.record" { - t.Fatalf("expected event name %q, got %v", "log.record", got) - } - - if got := record["msg"]; got != "startup" { - t.Fatalf("expected msg %q, got %v", "startup", got) - } - - if got := record["service"]; got != "api" { - t.Fatalf("expected service attr %q, got %v", "api", got) - } - - assertNonZeroDuration(t, record) -} - -func TestWideEventLoggerContextMethodsIncludeContextAttrs(t *testing.T) { - t.Parallel() - - type tenantKey string - - const tenantIDKey tenantKey = "tenantID" - - var buf bytes.Buffer - logger := platformalog.NewWideEventLogger(&buf, nil, "json", map[string]any{"tenantId": tenantIDKey}) - - ctx := context.WithValue(context.Background(), platformalog.TraceIDKey, "trace-123") - ctx = context.WithValue(ctx, platformalog.ServiceNameKey, "api") - ctx = context.WithValue(ctx, tenantIDKey, "tenant-42") - - logger.InfoContext(ctx, "request received", "path", "/users") - - record := decodeSingleRecord(t, buf.String()) - if got := record[string(platformalog.TraceIDKey)]; got != "trace-123" { - t.Fatalf("expected trace id %q, got %v", "trace-123", got) - } - - if got := record[string(platformalog.ServiceNameKey)]; got != "api" { - t.Fatalf("expected service name %q, got %v", "api", got) - } - - if got := record["tenantId"]; got != "tenant-42" { - t.Fatalf("expected tenant id %q, got %v", "tenant-42", got) - } -} - -func TestWideEventLoggerSimpleMethodsUseSampler(t *testing.T) { - t.Parallel() - - var buf bytes.Buffer - logger := platformalog.NewWideEventLogger(&buf, platformalog.SamplerFunc(func(context.Context, *platformalog.Event) bool { - return false - }), "json", nil) - - logger.Info("startup") - - if buf.Len() != 0 { - t.Fatalf("expected simple log output to be skipped by sampler, got %q", buf.String()) - } -} - -func TestWideEventLoggerWriteEventStillUsesSampler(t *testing.T) { - t.Parallel() - - var buf bytes.Buffer - logger := platformalog.NewWideEventLogger(&buf, platformalog.SamplerFunc(func(context.Context, *platformalog.Event) bool { - return false - }), "json", nil) - - logger.WriteEvent(context.Background(), platformalog.NewEvent("wide.request")) - - if buf.Len() != 0 { - t.Fatalf("expected sampled wide event to be skipped, got %q", buf.String()) - } -} - -func TestWideEventLoggerNormalizesSlogArgs(t *testing.T) { - t.Parallel() - - var buf bytes.Buffer - logger := platformalog.NewWideEventLogger(&buf, nil, "json", nil) - - logger.Info( - "startup", - "service", "api", - slog.String("component", "db"), - slog.Group("http", slog.Int("status", 200)), - "service", "worker", - ) - - record := decodeSingleRecord(t, buf.String()) - if got := record["service"]; got != "worker" { - t.Fatalf("expected last service attr to win, got %v", got) - } - - if got := record["component"]; got != "db" { - t.Fatalf("expected component attr %q, got %v", "db", got) - } - - httpGroup, ok := record["http"].(map[string]any) - if !ok { - t.Fatalf("expected http group to be an object, got %T", record["http"]) - } - - if got := httpGroup["status"]; got != float64(200) { - t.Fatalf("expected http.status 200, got %v", got) - } -} - -func TestWideEventLoggerUsesSlogBadKeyForMalformedArgs(t *testing.T) { - t.Parallel() - - var buf bytes.Buffer - logger := platformalog.NewWideEventLogger(&buf, nil, "json", nil) - - logger.Info("invalid args", "ok", 1, 2) - - record := decodeSingleRecord(t, buf.String()) - if got := record["ok"]; got != float64(1) { - t.Fatalf("expected valid attr %v, got %v", 1, got) - } - - if got := record["!BADKEY"]; got != float64(2) { - t.Fatalf("expected !BADKEY attr to be 2, got %v", got) - } -} - -func TestWideEventLoggerErrorMethodsKeepErrorsAsAttrsOnly(t *testing.T) { - t.Parallel() - - var buf bytes.Buffer - logger := platformalog.NewWideEventLogger(&buf, nil, "json", nil) - - logger.Error("failed", "error", errors.New("boom")) - - record := decodeSingleRecord(t, buf.String()) - if got := record["level"]; got != "ERROR" { - t.Fatalf("expected level ERROR, got %v", got) - } - - if _, ok := record["error"]; !ok { - t.Fatal("expected error attr to be present") - } - - if _, ok := record["errors"]; ok { - t.Fatalf("expected no errors collection, got %v", record["errors"]) - } -} - -func decodeSingleRecord(t *testing.T, output string) map[string]any { - t.Helper() - - lines := strings.Split(strings.TrimSpace(output), "\n") - if len(lines) != 1 { - t.Fatalf("expected a single log record, got %d in %q", len(lines), output) - } - - var record map[string]any - if err := json.Unmarshal([]byte(lines[0]), &record); err != nil { - t.Fatalf("unmarshal log record: %v", err) - } - - return record -} - -func assertNonZeroDuration(t *testing.T, record map[string]any) { - t.Helper() - - duration, ok := record["duration"] - if !ok { - t.Fatal("expected duration attr to be present") - } - - switch value := duration.(type) { - case float64: - if value <= 0 { - t.Fatalf("expected duration to be > 0, got %v", value) - } - case string: - if value == "" || value == "0s" { - t.Fatalf("expected duration to be non-zero, got %q", value) - } - default: - t.Fatalf("unexpected duration type %T", duration) - } -}