From 11ff88237a48f2280a56be72c390068b582e3b38 Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Thu, 19 Mar 2026 08:55:45 +0300 Subject: [PATCH] Fix #73: add forced info log level --- docs/src/content/docs/packages/log.mdx | 5 +- log/event.go | 2 +- log/forced_level_test.go | 156 +++++++++++++++++++++++++ log/level.go | 27 +++++ log/log.go | 15 ++- log/sampler.go | 4 + log/wideevent_logger.go | 6 +- 7 files changed, 210 insertions(+), 5 deletions(-) create mode 100644 log/forced_level_test.go create mode 100644 log/level.go diff --git a/docs/src/content/docs/packages/log.mdx b/docs/src/content/docs/packages/log.mdx index b7053ce..9cf8a76 100644 --- a/docs/src/content/docs/packages/log.mdx +++ b/docs/src/content/docs/packages/log.mdx @@ -16,6 +16,7 @@ Core Components: - `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. +- `LevelInfoForced`: Marks an otherwise-successful event as always-retained while still rendering its severity as `INFO`. - `EventFromContext`: Fetches the current request-wide event from context using `WideEventKey`. [Full package docs at pkg.go.dev](https://pkg.go.dev/github.com/platforma-dev/platforma/log) @@ -62,7 +63,9 @@ Core Components: 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(...)`. + In that mode, `Debug`/`Info`/`Warn`/`Error` calls emit short-lived events through the same wide-event pipeline. `Info(...)` uses `log.LevelInfoForced`, so explicit info logs are retained while still rendering as `INFO`. + + When a specific request-wide event must always be retained even though it is not slow and has no errors, set its level to `log.LevelInfoForced`. `DefaultSampler` treats that level as always-keep, but the emitted log line still shows `INFO`. 4. Enrich events and logs inside handlers diff --git a/log/event.go b/log/event.go index 27f7d5b..6fdb669 100644 --- a/log/event.go +++ b/log/event.go @@ -147,7 +147,7 @@ func (e *Event) toAttrs(additionalReservedAttrKeys []string) []slog.Attr { for _, step := range e.steps { steps = append(steps, map[string]any{ "timestamp": step.Timestamp, - "level": step.Level.String(), + "level": formatLevel(step.Level), "name": step.Name, }) } diff --git a/log/forced_level_test.go b/log/forced_level_test.go new file mode 100644 index 0000000..172b3f1 --- /dev/null +++ b/log/forced_level_test.go @@ -0,0 +1,156 @@ +package log_test + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "testing" + "time" + + platformalog "github.com/platforma-dev/platforma/log" +) + +func TestDefaultSamplerForcedInfoLevel(t *testing.T) { + t.Parallel() + + sampler := platformalog.NewDefaultSampler(time.Hour, 500, 0) + + t.Run("forced info is always sampled", func(t *testing.T) { + t.Parallel() + + event := platformalog.NewEvent("background.job") + event.SetLevel(platformalog.LevelInfoForced) + + if !sampler.ShouldSample(context.Background(), event) { + t.Fatal("expected forced info event to be sampled") + } + }) + + t.Run("regular info still depends on sampler rules", func(t *testing.T) { + t.Parallel() + + event := platformalog.NewEvent("background.job") + event.SetLevel(slog.LevelInfo) + + if sampler.ShouldSample(context.Background(), event) { + t.Fatal("expected regular info event to be dropped when no sampler rule matches") + } + }) +} + +func TestEventToAttrsFormatsForcedInfoStep(t *testing.T) { + t.Parallel() + + event := platformalog.NewEvent("background.job") + event.AddStep(platformalog.LevelInfoForced, "marked for retention") + + attrs := event.ToAttrs() + + for _, attr := range attrs { + if attr.Key != "steps" { + continue + } + + steps, ok := attr.Value.Any().([]map[string]any) + if !ok { + t.Fatalf("expected steps attr to be []map[string]any, got %T", attr.Value.Any()) + } + + if len(steps) != 1 { + t.Fatalf("expected 1 step, got %d", len(steps)) + } + + level, ok := steps[0]["level"].(string) + if !ok { + t.Fatalf("expected step level to be string, got %T", steps[0]["level"]) + } + + if level != "INFO" { + t.Fatalf("expected forced info step level to render as INFO, got %q", level) + } + + return + } + + t.Fatal("expected steps attr to be present") +} + +func TestWideEventLoggerRendersForcedInfoLevelAsInfo(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + logger := platformalog.NewWideEventLogger(&buf, platformalog.SamplerFunc(func(_ context.Context, _ *platformalog.Event) bool { + return true + }), "json", nil) + + event := platformalog.NewEvent("background.job") + event.SetLevel(platformalog.LevelInfoForced) + + logger.WriteEvent(context.Background(), event) + + var payload map[string]any + if err := json.Unmarshal(buf.Bytes(), &payload); err != nil { + t.Fatalf("unmarshal log output: %v", err) + } + + level, ok := payload["level"].(string) + if !ok { + t.Fatalf("expected level field to be string, got %T", payload["level"]) + } + + if level != "INFO" { + t.Fatalf("expected forced info event to render as INFO, got %q", level) + } +} + +func TestWideEventLoggerInfoContextUsesForcedInfoLevel(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + logger := platformalog.NewWideEventLogger( + &buf, + platformalog.NewDefaultSampler(time.Hour, 500, 0), + "json", + nil, + ) + + logger.InfoContext(context.Background(), "forced info") + + var payload map[string]any + if err := json.Unmarshal(buf.Bytes(), &payload); err != nil { + t.Fatalf("unmarshal log output: %v", err) + } + + level, ok := payload["level"].(string) + if !ok { + t.Fatalf("expected level field to be string, got %T", payload["level"]) + } + + if level != "INFO" { + t.Fatalf("expected forced info log to render as INFO, got %q", level) + } +} + +func TestNewLoggerRendersForcedInfoLevelAsInfo(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + logger := platformalog.New(&buf, "json", slog.LevelDebug, nil) + + logger.Log(context.Background(), platformalog.LevelInfoForced, "forced info") + + var payload map[string]any + if err := json.Unmarshal(buf.Bytes(), &payload); err != nil { + t.Fatalf("unmarshal log output: %v", err) + } + + level, ok := payload["level"].(string) + if !ok { + t.Fatalf("expected level field to be string, got %T", payload["level"]) + } + + if level != "INFO" { + t.Fatalf("expected forced info log to render as INFO, got %q", level) + } +} diff --git a/log/level.go b/log/level.go new file mode 100644 index 0000000..3d46dd0 --- /dev/null +++ b/log/level.go @@ -0,0 +1,27 @@ +package log + +import "log/slog" + +const ( + // LevelInfoForced keeps an event regardless of tail-sampling rules while rendering as INFO in output. + LevelInfoForced slog.Level = slog.LevelInfo + 1 +) + +func formatLevel(level slog.Level) string { + if level == LevelInfoForced { + return slog.LevelInfo.String() + } + + return level.String() +} + +func replaceLevelAttr(a slog.Attr) slog.Attr { + switch level := a.Value.Any().(type) { + case slog.Level: + return slog.String(a.Key, formatLevel(level)) + case slog.Leveler: + return slog.String(a.Key, formatLevel(level.Level())) + default: + return a + } +} diff --git a/log/log.go b/log/log.go index 4b8ccb5..43636c6 100644 --- a/log/log.go +++ b/log/log.go @@ -83,11 +83,22 @@ func (h *contextHandler) Handle(ctx context.Context, r slog.Record) error { // New creates a new slog.Logger with the specified type (json/text), log level, and additional context keys to include. func New(w io.Writer, loggerType string, level slog.Level, contextKeys map[string]any) *slog.Logger { + opts := &slog.HandlerOptions{ + Level: level, + ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { + if a.Key == slog.LevelKey { + return replaceLevelAttr(a) + } + + return a + }, + } + if loggerType == "json" { - return slog.New(&contextHandler{slog.NewJSONHandler(w, &slog.HandlerOptions{Level: level}), contextKeys}) + return slog.New(&contextHandler{slog.NewJSONHandler(w, opts), contextKeys}) } - return slog.New(&contextHandler{slog.NewTextHandler(w, &slog.HandlerOptions{Level: level}), contextKeys}) + return slog.New(&contextHandler{slog.NewTextHandler(w, opts), contextKeys}) } // Debug logs a message at Debug level. diff --git a/log/sampler.go b/log/sampler.go index 2b1d03c..b2b7aec 100644 --- a/log/sampler.go +++ b/log/sampler.go @@ -37,6 +37,10 @@ func NewDefaultSampler(slowThreshold time.Duration, keepHTTPStatusAtLeast int, r // ShouldSample decides if event should be logged. func (s *DefaultSampler) ShouldSample(_ context.Context, e *Event) bool { + if e.Level() >= LevelInfoForced { + return true + } + if e.HasErrors() { return true } diff --git a/log/wideevent_logger.go b/log/wideevent_logger.go index fef2503..5b91274 100644 --- a/log/wideevent_logger.go +++ b/log/wideevent_logger.go @@ -31,6 +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.LevelKey { + return replaceLevelAttr(a) + } + if a.Key == slog.TimeKey { return slog.Attr{} } @@ -82,7 +86,7 @@ func (l *WideEventLogger) DebugContext(ctx context.Context, msg string, 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...) + l.writeSimpleLog(ctx, LevelInfoForced, msg, args...) } // WarnContext logs a message at Warn level with context.