From 7c7b314b196680bc2fff8c4d446b41f9bacaa7b8 Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Sat, 14 Feb 2026 22:05:51 +0300 Subject: [PATCH 01/13] log2 first iteration --- log2/config.go | 42 ++++ log2/context.go | 27 +++ log2/context_test.go | 92 +++++++++ log2/event.go | 373 +++++++++++++++++++++++++++++++++++ log2/event_test.go | 197 ++++++++++++++++++ log2/http_middleware.go | 99 ++++++++++ log2/http_middleware_test.go | 140 +++++++++++++ log2/logger.go | 123 ++++++++++++ log2/sampling.go | 204 +++++++++++++++++++ log2/sampling_test.go | 166 ++++++++++++++++ log2/test_helpers_test.go | 70 +++++++ 11 files changed, 1533 insertions(+) create mode 100644 log2/config.go create mode 100644 log2/context.go create mode 100644 log2/context_test.go create mode 100644 log2/event.go create mode 100644 log2/event_test.go create mode 100644 log2/http_middleware.go create mode 100644 log2/http_middleware_test.go create mode 100644 log2/logger.go create mode 100644 log2/sampling.go create mode 100644 log2/sampling_test.go create mode 100644 log2/test_helpers_test.go diff --git a/log2/config.go b/log2/config.go new file mode 100644 index 0000000..928449f --- /dev/null +++ b/log2/config.go @@ -0,0 +1,42 @@ +// Package log2 provides wide-event logging with tail sampling. +package log2 + +import ( + "io" + "log/slog" + "os" + "time" +) + +const ( + defaultFormat = "json" + defaultKeepStatus = 500 + defaultMaxSteps = 100 + defaultRandomKeepRate = 0.05 + defaultSlowThreshold = 2 * time.Second +) + +// Config configures logger behavior. +type Config struct { + Writer io.Writer + Format string + Level slog.Level + ContextKeys map[string]any + Sampler TailSampler + MaxSteps int +} + +// DefaultConfig returns default logger configuration. +func DefaultConfig() Config { + return Config{ + Writer: os.Stdout, + Format: defaultFormat, + Level: slog.LevelInfo, + Sampler: NewDefaultTailSampler(DefaultTailSamplerConfig{ + SlowThreshold: defaultSlowThreshold, + RandomKeepRate: defaultRandomKeepRate, + KeepStatusAtLeast: defaultKeepStatus, + }), + MaxSteps: defaultMaxSteps, + } +} diff --git a/log2/context.go b/log2/context.go new file mode 100644 index 0000000..a704ac6 --- /dev/null +++ b/log2/context.go @@ -0,0 +1,27 @@ +package log2 + +import "context" + +type contextKey string + +// LogEventContextKey is used to store Event in context. +var LogEventContextKey any = contextKey("platformaLog2Event") //nolint:gochecknoglobals + +// EventFromContext gets an event from context. +func EventFromContext(ctx context.Context) (*Event, bool) { + if ctx == nil { + return nil, false + } + + ev, ok := ctx.Value(LogEventContextKey).(*Event) + if !ok || ev == nil { + return nil, false + } + + return ev, true +} + +// WithEvent stores an event in context. +func WithEvent(ctx context.Context, ev *Event) context.Context { + return context.WithValue(ctx, LogEventContextKey, ev) +} diff --git a/log2/context_test.go b/log2/context_test.go new file mode 100644 index 0000000..2bc2f74 --- /dev/null +++ b/log2/context_test.go @@ -0,0 +1,92 @@ +package log2_test + +import ( + "bytes" + "context" + "log/slog" + "testing" + + "github.com/platforma-dev/platforma/log" + "github.com/platforma-dev/platforma/log2" +) + +func TestEventFromContextMiss(t *testing.T) { + t.Parallel() + + ev, ok := log2.EventFromContext(context.Background()) + if ok { + t.Fatalf("expected ok=false, got true with event=%v", ev) + } + if ev != nil { + t.Fatalf("expected nil event, got %v", ev) + } +} + +func TestEventFromContextWithRawContextValue(t *testing.T) { + t.Parallel() + + logger := log2.New(log2.Config{Writer: &bytes.Buffer{}}) + ev := logger.Start(context.Background(), "ctx") + + ctx := context.WithValue(context.Background(), log2.LogEventContextKey, ev) + got, ok := log2.EventFromContext(ctx) + if !ok { + t.Fatalf("expected ok=true") + } + if got != ev { + t.Fatalf("expected the same event pointer") + } +} + +func TestWithEvent(t *testing.T) { + t.Parallel() + + logger := log2.New(log2.Config{Writer: &bytes.Buffer{}}) + ev := logger.Start(context.Background(), "ctx") + + ctx := log2.WithEvent(context.Background(), ev) + got, ok := log2.EventFromContext(ctx) + if !ok { + t.Fatalf("expected ok=true") + } + if got != ev { + t.Fatalf("expected the same event pointer") + } +} + +func TestStartCollectsDefaultContextKeys(t *testing.T) { + t.Parallel() + + buffer := &bytes.Buffer{} + logger := log2.New(log2.Config{ + Writer: buffer, + Format: "json", + Level: slog.LevelInfo, + Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), + }) + + ctx := context.WithValue(context.Background(), log.TraceIDKey, "trace-123") + ctx = context.WithValue(ctx, log.UserIDKey, "user-99") + + ev := logger.Start(ctx, "collect-keys") + if err := ev.Finish(); err != nil { + t.Fatalf("Finish() returned error: %v", err) + } + + events := readEvents(t, buffer) + if len(events) != 1 { + t.Fatalf("expected 1 event, got %d", len(events)) + } + + if events[0]["traceId"] != "trace-123" { + t.Fatalf("expected top-level traceId=trace-123, got %v", events[0]["traceId"]) + } + + attrs := requireMap(t, events[0], "attrs") + if attrs["traceId"] != "trace-123" { + t.Fatalf("expected attrs.traceId=trace-123, got %v", attrs["traceId"]) + } + if attrs["userId"] != "user-99" { + t.Fatalf("expected attrs.userId=user-99, got %v", attrs["userId"]) + } +} diff --git a/log2/event.go b/log2/event.go new file mode 100644 index 0000000..c0d4f14 --- /dev/null +++ b/log2/event.go @@ -0,0 +1,373 @@ +package log2 + +import ( + "context" + "errors" + "fmt" + "log/slog" + "math" + "strconv" + "sync" + "time" + + "github.com/platforma-dev/platforma/log" +) + +// ErrEventAlreadyFinished means Finish was called more than once. +var ErrEventAlreadyFinished = errors.New("event already finished") + +type stepRecord struct { + ts time.Time + level string + msg string + attrs map[string]any +} + +type errorRecord struct { + ts time.Time + err string + attrs map[string]any +} + +type eventPayload struct { + eventName string + level slog.Level + durationMs int64 + sampled bool + samplingReason string + traceID string + attrs map[string]any + steps []map[string]any + errors []map[string]any + stepsDropped int +} + +// Event is a mutable wide event. +type Event struct { + mu sync.Mutex + + logger *Logger + eventName string + startedAt time.Time + + attrs map[string]any + steps []stepRecord + errors []errorRecord + hasError bool + finished bool + stepsDropped int +} + +// Add adds persistent attributes to the event. +func (e *Event) Add(attrs ...any) { + if e == nil { + return + } + + normalized := normalizeAttrs(attrs...) + + e.mu.Lock() + defer e.mu.Unlock() + + if e.finished { + return + } + + mergeAttrs(e.attrs, normalized) +} + +// Step appends a timeline step to the event. +func (e *Event) Step(level slog.Level, msg string, attrs ...any) { + if e == nil { + return + } + + e.mu.Lock() + defer e.mu.Unlock() + + if e.finished { + return + } + + if len(e.steps) >= e.logger.maxSteps { + e.stepsDropped++ + return + } + + e.steps = append(e.steps, stepRecord{ + ts: nowUTC(), + level: level.String(), + msg: msg, + attrs: normalizeAttrs(attrs...), + }) +} + +// Error appends an error to the event. +func (e *Event) Error(err error, attrs ...any) { + if e == nil || err == nil { + return + } + + e.mu.Lock() + defer e.mu.Unlock() + + if e.finished { + return + } + + e.hasError = true + e.errors = append(e.errors, errorRecord{ + ts: nowUTC(), + err: err.Error(), + attrs: normalizeAttrs(attrs...), + }) +} + +// Finish finalizes and emits the event depending on sampling decision. +func (e *Event) Finish(attrs ...any) error { + if e == nil { + return nil + } + + e.mu.Lock() + if e.finished { + e.mu.Unlock() + return ErrEventAlreadyFinished + } + + mergeAttrs(e.attrs, normalizeAttrs(attrs...)) + + duration := nowUTC().Sub(e.startedAt) + status := inferStatus(e.attrs) + level := inferLevel(status, e.hasError) + attrsCopy := copyAttrs(e.attrs) + stepsCopy := copySteps(e.steps) + errorsCopy := copyErrors(e.errors) + stepsDropped := e.stepsDropped + traceID := extractString(attrsCopy, string(log.TraceIDKey)) + + decision := e.logger.sampler.ShouldSample(EventView{ + Status: status, + Duration: duration, + HasError: e.hasError, + Attrs: attrsCopy, + }) + + e.finished = true + logger := e.logger + e.mu.Unlock() + + if !decision.Keep { + return nil + } + + return logger.emit(context.Background(), eventPayload{ + eventName: e.eventName, + level: level, + durationMs: duration.Milliseconds(), + sampled: true, + samplingReason: decision.Reason, + traceID: traceID, + attrs: attrsCopy, + steps: stepsCopy, + errors: errorsCopy, + stepsDropped: stepsDropped, + }) +} + +func nowUTC() time.Time { + return time.Now().UTC() +} + +func collectContextAttrs(ctx context.Context, extraKeys map[string]any) map[string]any { + attrs := map[string]any{} + + defaultKeys := []struct { + name string + key any + }{ + {name: string(log.DomainNameKey), key: log.DomainNameKey}, + {name: string(log.TraceIDKey), key: log.TraceIDKey}, + {name: string(log.ServiceNameKey), key: log.ServiceNameKey}, + {name: string(log.StartupTaskKey), key: log.StartupTaskKey}, + {name: string(log.UserIDKey), key: log.UserIDKey}, + {name: string(log.WorkerIDKey), key: log.WorkerIDKey}, + } + + for _, item := range defaultKeys { + if value := ctx.Value(item.key); value != nil { + attrs[item.name] = value + } + } + + for outputKey, ctxKey := range extraKeys { + if value := ctx.Value(ctxKey); value != nil { + attrs[outputKey] = value + } + } + + return attrs +} + +func normalizeAttrs(attrs ...any) map[string]any { + normalized := make(map[string]any, len(attrs)/2) + + for i := 0; i < len(attrs); i++ { + if attr, ok := attrs[i].(slog.Attr); ok { + normalized[attr.Key] = attr.Value.Any() + continue + } + + if i+1 >= len(attrs) { + break + } + + key := fmt.Sprint(attrs[i]) + normalized[key] = attrs[i+1] + i++ + } + + return normalized +} + +func mergeAttrs(dst map[string]any, src map[string]any) { + for key, value := range src { + dst[key] = value + } +} + +func copyAttrs(src map[string]any) map[string]any { + if src == nil { + return nil + } + + dst := make(map[string]any, len(src)) + for key, value := range src { + dst[key] = value + } + + return dst +} + +func copySteps(src []stepRecord) []map[string]any { + steps := make([]map[string]any, 0, len(src)) + for _, step := range src { + entry := map[string]any{ + "ts": step.ts, + "level": step.level, + "msg": step.msg, + } + mergeAttrs(entry, step.attrs) + steps = append(steps, entry) + } + + return steps +} + +func copyErrors(src []errorRecord) []map[string]any { + errs := make([]map[string]any, 0, len(src)) + for _, item := range src { + entry := map[string]any{ + "ts": item.ts, + "error": item.err, + } + mergeAttrs(entry, item.attrs) + errs = append(errs, entry) + } + + return errs +} + +func inferLevel(status int, hasError bool) slog.Level { + if hasError || status >= defaultKeepStatus { + return slog.LevelError + } + + if status >= 400 { + return slog.LevelWarn + } + + return slog.LevelInfo +} + +func inferStatus(attrs map[string]any) int { + if status, ok := toInt(attrs["status"]); ok { + return status + } + + if status, ok := toInt(attrs["statusCode"]); ok { + return status + } + + if status, ok := toInt(attrs["response.status"]); ok { + return status + } + + if responseAny, ok := attrs["response"]; ok { + if response, okMap := responseAny.(map[string]any); okMap { + if status, okStatus := toInt(response["status"]); okStatus { + return status + } + } + } + + return 0 +} + +func toInt(value any) (int, bool) { + switch typed := value.(type) { + case int: + return typed, true + case int8: + return int(typed), true + case int16: + return int(typed), true + case int32: + return int(typed), true + case int64: + return int(typed), true + case uint: + if typed > uint(math.MaxInt) { + return 0, false + } + return int(typed), true + case uint8: + return int(typed), true + case uint16: + return int(typed), true + case uint32: + return int(typed), true + case uint64: + if typed > uint64(math.MaxInt) { + return 0, false + } + return int(typed), true + case float32: + return int(typed), true + case float64: + return int(typed), true + case string: + parsed, err := strconv.Atoi(typed) + if err != nil { + return 0, false + } + + return parsed, true + default: + return 0, false + } +} + +func extractString(attrs map[string]any, key string) string { + value, ok := attrs[key] + if !ok { + return "" + } + + stringValue, ok := value.(string) + if !ok { + return "" + } + + return stringValue +} diff --git a/log2/event_test.go b/log2/event_test.go new file mode 100644 index 0000000..fbff343 --- /dev/null +++ b/log2/event_test.go @@ -0,0 +1,197 @@ +package log2_test + +import ( + "bytes" + "context" + "errors" + "log/slog" + "sync" + "testing" + + "github.com/platforma-dev/platforma/log2" +) + +func TestEventLifecycle(t *testing.T) { + t.Parallel() + + buffer := &bytes.Buffer{} + logger := log2.New(log2.Config{ + Writer: buffer, + Format: "json", + Level: slog.LevelDebug, + Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), + MaxSteps: 10, + }) + + ev := logger.Start(context.Background(), "auth_request", "component", "handler") + ev.Add("userId", "u-1", "attempt", 2) + ev.Step(slog.LevelInfo, "request accepted") + ev.Error(errors.New("boom"), "phase", "validation") + + if err := ev.Finish("status", 500); err != nil { + t.Fatalf("Finish() returned error: %v", err) + } + + events := readEvents(t, buffer) + if len(events) != 1 { + t.Fatalf("expected 1 emitted event, got %d", len(events)) + } + + event := events[0] + if event["event"] != "auth_request" { + t.Fatalf("expected event name auth_request, got %v", event["event"]) + } + if event["samplingReason"] != "forced" { + t.Fatalf("expected sampling reason forced, got %v", event["samplingReason"]) + } + if event["sampled"] != true { + t.Fatalf("expected sampled=true, got %v", event["sampled"]) + } + + attrs := requireMap(t, event, "attrs") + if attrs["component"] != "handler" { + t.Fatalf("expected component=handler, got %v", attrs["component"]) + } + if attrs["userId"] != "u-1" { + t.Fatalf("expected userId=u-1, got %v", attrs["userId"]) + } + if attrs["attempt"] != float64(2) { + t.Fatalf("expected attempt=2, got %v", attrs["attempt"]) + } + if attrs["status"] != float64(500) { + t.Fatalf("expected status=500, got %v", attrs["status"]) + } + + steps := requireSlice(t, event, "steps") + if len(steps) != 1 { + t.Fatalf("expected 1 step, got %d", len(steps)) + } + + errorsList := requireSlice(t, event, "errors") + if len(errorsList) != 1 { + t.Fatalf("expected 1 error, got %d", len(errorsList)) + } +} + +func TestEventAttributeOverwrite(t *testing.T) { + t.Parallel() + + buffer := &bytes.Buffer{} + logger := log2.New(log2.Config{ + Writer: buffer, + Format: "json", + Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), + }) + + ev := logger.Start(context.Background(), "overwrite") + ev.Add("key", "first") + ev.Add("key", "second") + + if err := ev.Finish(); err != nil { + t.Fatalf("Finish() returned error: %v", err) + } + + events := readEvents(t, buffer) + if len(events) != 1 { + t.Fatalf("expected 1 event, got %d", len(events)) + } + + attrs := requireMap(t, events[0], "attrs") + if attrs["key"] != "second" { + t.Fatalf("expected key=second, got %v", attrs["key"]) + } +} + +func TestEventFinishCalledTwice(t *testing.T) { + t.Parallel() + + logger := log2.New(log2.Config{ + Writer: &bytes.Buffer{}, + Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), + }) + + ev := logger.Start(context.Background(), "double_finish") + if err := ev.Finish(); err != nil { + t.Fatalf("first Finish() returned error: %v", err) + } + + err := ev.Finish() + if !errors.Is(err, log2.ErrEventAlreadyFinished) { + t.Fatalf("expected ErrEventAlreadyFinished, got %v", err) + } +} + +func TestEventConcurrentAccessAndStepCap(t *testing.T) { + t.Parallel() + + buffer := &bytes.Buffer{} + logger := log2.New(log2.Config{ + Writer: buffer, + Format: "json", + Level: slog.LevelDebug, + Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), + MaxSteps: 5, + }) + + ev := logger.Start(context.Background(), "concurrent") + + var wg sync.WaitGroup + for i := range 20 { + wg.Add(1) + go func(i int) { + defer wg.Done() + ev.Add("counter", i) + ev.Step(slog.LevelInfo, "work", "i", i) + if i%3 == 0 { + ev.Error(errors.New("worker-error"), "i", i) + } + }(i) + } + + wg.Wait() + + if err := ev.Finish("status", 200); err != nil { + t.Fatalf("Finish() returned error: %v", err) + } + + events := readEvents(t, buffer) + if len(events) != 1 { + t.Fatalf("expected 1 event, got %d", len(events)) + } + + event := events[0] + steps := requireSlice(t, event, "steps") + if len(steps) != 5 { + t.Fatalf("expected 5 steps (cap), got %d", len(steps)) + } + + dropped, ok := event["stepsDropped"].(float64) + if !ok { + t.Fatalf("expected stepsDropped to exist") + } + if dropped != float64(15) { + t.Fatalf("expected stepsDropped=15, got %v", dropped) + } +} + +func TestEventDroppedBySampler(t *testing.T) { + t.Parallel() + + buffer := &bytes.Buffer{} + logger := log2.New(log2.Config{ + Writer: buffer, + Format: "json", + Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: false, Reason: "drop"} }), + }) + + ev := logger.Start(context.Background(), "drop_me") + ev.Add("k", "v") + if err := ev.Finish(); err != nil { + t.Fatalf("Finish() returned error: %v", err) + } + + events := readEvents(t, buffer) + if len(events) != 0 { + t.Fatalf("expected no emitted events, got %d", len(events)) + } +} diff --git a/log2/http_middleware.go b/log2/http_middleware.go new file mode 100644 index 0000000..a47624a --- /dev/null +++ b/log2/http_middleware.go @@ -0,0 +1,99 @@ +package log2 + +import ( + "errors" + "fmt" + "net/http" +) + +var errPanicRecovered = errors.New("panic recovered") //nolint:gochecknoglobals + +// HTTPMiddlewareConfig configures wide-event HTTP middleware. +type HTTPMiddlewareConfig struct { + EventName string + RouteAttr string +} + +// NewHTTPMiddleware creates middleware that builds one wide event per request. +func NewHTTPMiddleware(l *Logger, cfg HTTPMiddlewareConfig) func(http.Handler) http.Handler { + logger := l + if logger == nil { + logger = Default + } + + eventName := cfg.EventName + if eventName == "" { + eventName = "http_request" + } + + routeAttr := cfg.RouteAttr + if routeAttr == "" { + routeAttr = "route" + } + + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + ev := logger.Start(r.Context(), eventName) + ctx := WithEvent(r.Context(), ev) + r = r.WithContext(ctx) + + rec := &statusRecorder{ResponseWriter: w, status: http.StatusOK} + + defer func() { + panicValue := recover() + + route := r.Pattern + if route == "" { + route = r.URL.Path + } + + requestAttrs := map[string]any{ + "method": r.Method, + "path": r.URL.Path, + "route": route, + "remoteAddr": r.RemoteAddr, + } + responseAttrs := map[string]any{ + "status": rec.status, + "bytes": rec.bytes, + } + + ev.Add( + "request", requestAttrs, + "response", responseAttrs, + routeAttr, route, + ) + + if panicValue != nil { + ev.Error(fmt.Errorf("%w: %v", errPanicRecovered, panicValue)) + } + + _ = ev.Finish("status", rec.status) + + if panicValue != nil { + panic(panicValue) + } + }() + + next.ServeHTTP(rec, r) + }) + } +} + +type statusRecorder struct { + http.ResponseWriter + status int + bytes int +} + +func (r *statusRecorder) WriteHeader(statusCode int) { + r.status = statusCode + r.ResponseWriter.WriteHeader(statusCode) +} + +func (r *statusRecorder) Write(body []byte) (int, error) { + bytesWritten, err := r.ResponseWriter.Write(body) + r.bytes += bytesWritten + //nolint:wrapcheck // preserve exact error semantics from wrapped ResponseWriter. + return bytesWritten, err +} diff --git a/log2/http_middleware_test.go b/log2/http_middleware_test.go new file mode 100644 index 0000000..a881a23 --- /dev/null +++ b/log2/http_middleware_test.go @@ -0,0 +1,140 @@ +package log2_test + +import ( + "bytes" + "fmt" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/platforma-dev/platforma/log2" +) + +func TestHTTPMiddlewareEmitsSingleWideEvent(t *testing.T) { + t.Parallel() + + buffer := &bytes.Buffer{} + logger := log2.New(log2.Config{ + Writer: buffer, + Format: "json", + Level: slog.LevelInfo, + Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), + }) + + middleware := log2.NewHTTPMiddleware(logger, log2.HTTPMiddlewareConfig{}) + handler := middleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + ev, ok := log2.EventFromContext(r.Context()) + if !ok { + t.Fatalf("expected event in request context") + } + ev.Add("handler", "users") + + w.WriteHeader(http.StatusTeapot) + _, _ = w.Write([]byte("hello")) + })) + + req := httptest.NewRequest(http.MethodGet, "/users/42", nil) + rec := httptest.NewRecorder() + handler.ServeHTTP(rec, req) + + events := readEvents(t, buffer) + if len(events) != 1 { + t.Fatalf("expected 1 event, got %d", len(events)) + } + + event := events[0] + if event["event"] != "http_request" { + t.Fatalf("expected event=http_request, got %v", event["event"]) + } + + attrs := requireMap(t, event, "attrs") + if attrs["status"] != float64(http.StatusTeapot) { + t.Fatalf("expected status %d, got %v", http.StatusTeapot, attrs["status"]) + } + if attrs["route"] != "/users/42" { + t.Fatalf("expected fallback route /users/42, got %v", attrs["route"]) + } + + request := requireMap(t, attrs, "request") + if request["method"] != http.MethodGet { + t.Fatalf("expected method GET, got %v", request["method"]) + } + if request["path"] != "/users/42" { + t.Fatalf("expected path /users/42, got %v", request["path"]) + } + + response := requireMap(t, attrs, "response") + if response["status"] != float64(http.StatusTeapot) { + t.Fatalf("expected response.status=%d, got %v", http.StatusTeapot, response["status"]) + } + if response["bytes"] != float64(5) { + t.Fatalf("expected response.bytes=5, got %v", response["bytes"]) + } +} + +func TestHTTPMiddlewarePanicPath(t *testing.T) { + t.Parallel() + + buffer := &bytes.Buffer{} + logger := log2.New(log2.Config{ + Writer: buffer, + Format: "json", + Level: slog.LevelInfo, + Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), + }) + + middleware := log2.NewHTTPMiddleware(logger, log2.HTTPMiddlewareConfig{}) + handler := middleware(http.HandlerFunc(func(http.ResponseWriter, *http.Request) { + panic("boom") + })) + + req := httptest.NewRequest(http.MethodGet, "/panic", nil) + rec := httptest.NewRecorder() + + panicRecovered := false + func() { + defer func() { + if recovered := recover(); recovered != nil { + panicRecovered = true + if fmt.Sprint(recovered) != "boom" { + t.Fatalf("expected panic value boom, got %v", recovered) + } + } + }() + handler.ServeHTTP(rec, req) + }() + + if !panicRecovered { + t.Fatalf("expected panic to be rethrown by middleware") + } + + events := readEvents(t, buffer) + if len(events) != 1 { + t.Fatalf("expected 1 event, got %d", len(events)) + } + + event := events[0] + if event["level"] != "ERROR" { + t.Fatalf("expected level ERROR for panic path, got %v", event["level"]) + } + + errorsList := requireSlice(t, event, "errors") + if len(errorsList) != 1 { + t.Fatalf("expected exactly 1 recorded error, got %d", len(errorsList)) + } + + errorMap, ok := errorsList[0].(map[string]any) + if !ok { + t.Fatalf("expected errors[0] to be map, got %T", errorsList[0]) + } + + errorText, ok := errorMap["error"].(string) + if !ok { + t.Fatalf("expected errors[0].error string, got %T", errorMap["error"]) + } + if !strings.Contains(errorText, "panic recovered: boom") { + t.Fatalf("expected panic error text to include panic recovered: boom, got %q", errorText) + } +} diff --git a/log2/logger.go b/log2/logger.go new file mode 100644 index 0000000..f6fc6f9 --- /dev/null +++ b/log2/logger.go @@ -0,0 +1,123 @@ +package log2 + +import ( + "context" + "fmt" + "io" + "log/slog" +) + +// Logger writes sampled wide events. +type Logger struct { + handler slog.Handler + sampler TailSampler + contextKeys map[string]any + maxSteps int +} + +// Default is package-level default logger. +var Default = New(DefaultConfig()) //nolint:gochecknoglobals + +// New creates a new wide-event logger. +func New(cfg Config) *Logger { + writer := cfg.Writer + if writer == nil { + writer = io.Discard + } + + var handler slog.Handler + if cfg.Format == "text" { + handler = slog.NewTextHandler(writer, &slog.HandlerOptions{Level: cfg.Level}) + } else { + handler = slog.NewJSONHandler(writer, &slog.HandlerOptions{Level: cfg.Level}) + } + + sampler := cfg.Sampler + if sampler == nil { + sampler = NewDefaultTailSampler(DefaultTailSamplerConfig{}) + } + + maxSteps := cfg.MaxSteps + if maxSteps <= 0 { + maxSteps = defaultMaxSteps + } + + return &Logger{ + handler: handler, + sampler: sampler, + contextKeys: copyAttrs(cfg.ContextKeys), + maxSteps: maxSteps, + } +} + +// SetDefault sets the package-level default logger. +func SetDefault(l *Logger) { + if l == nil { + Default = New(DefaultConfig()) + return + } + + Default = l +} + +// Start creates a new event using the package-level default logger. +func Start(ctx context.Context, eventName string, attrs ...any) *Event { + return Default.Start(ctx, eventName, attrs...) +} + +// Start creates a new event using this logger. +func (l *Logger) Start(ctx context.Context, eventName string, attrs ...any) *Event { + if l == nil { + return Default.Start(ctx, eventName, attrs...) + } + + baseAttrs := collectContextAttrs(ctx, l.contextKeys) + mergeAttrs(baseAttrs, normalizeAttrs(attrs...)) + + return &Event{ + logger: l, + eventName: eventName, + startedAt: nowUTC(), + attrs: baseAttrs, + steps: make([]stepRecord, 0), + errors: make([]errorRecord, 0), + } +} + +func (l *Logger) emit(ctx context.Context, event eventPayload) error { + if l == nil { + return nil + } + + if !l.handler.Enabled(ctx, event.level) { + return nil + } + + rec := slog.NewRecord(nowUTC(), event.level, event.eventName, 0) + rec.AddAttrs( + slog.String("event", event.eventName), + slog.Int64("durationMs", event.durationMs), + slog.Bool("sampled", event.sampled), + slog.String("samplingReason", event.samplingReason), + ) + + if event.traceID != "" { + rec.AddAttrs(slog.String("traceId", event.traceID)) + } + + rec.AddAttrs( + slog.Any("attrs", event.attrs), + slog.Any("steps", event.steps), + slog.Any("errors", event.errors), + ) + + if event.stepsDropped > 0 { + rec.AddAttrs(slog.Int("stepsDropped", event.stepsDropped)) + } + + if err := l.handler.Handle(ctx, rec); err != nil { + return fmt.Errorf("failed to write log event: %w", err) + } + + return nil +} diff --git a/log2/sampling.go b/log2/sampling.go new file mode 100644 index 0000000..98cd363 --- /dev/null +++ b/log2/sampling.go @@ -0,0 +1,204 @@ +package log2 + +import ( + "math/rand" + "reflect" + "strings" + "time" +) + +// TailSampler decides whether a finished event should be emitted. +type TailSampler interface { + ShouldSample(EventView) SamplingDecision +} + +// SamplingDecision is the sampler decision. +type SamplingDecision struct { + Keep bool + Reason string +} + +// EventView is immutable event information for sampling. +type EventView struct { + Status int + Duration time.Duration + HasError bool + Attrs map[string]any +} + +// DefaultTailSamplerConfig configures the default tail sampler. +type DefaultTailSamplerConfig struct { + SlowThreshold time.Duration + RandomKeepRate float64 + KeepStatusAtLeast int + KeepRules []KeepRule + RandomFloat func() float64 +} + +// KeepRule defines a forced-keep rule. +type KeepRule struct { + Field string + Op string + Value any +} + +type defaultTailSampler struct { + slowThreshold time.Duration + randomKeepRate float64 + keepStatusAtLeast int + keepRules []KeepRule + randomFloat func() float64 +} + +// NewDefaultTailSampler creates a rule-based tail sampler. +// +//nolint:iface // public API returns TailSampler to allow custom implementations. +func NewDefaultTailSampler(cfg DefaultTailSamplerConfig) TailSampler { + slowThreshold := cfg.SlowThreshold + if slowThreshold <= 0 { + slowThreshold = defaultSlowThreshold + } + + keepStatusAtLeast := cfg.KeepStatusAtLeast + if keepStatusAtLeast <= 0 { + keepStatusAtLeast = defaultKeepStatus + } + + randomKeepRate := cfg.RandomKeepRate + if randomKeepRate <= 0 { + randomKeepRate = defaultRandomKeepRate + } + if randomKeepRate > 1 { + randomKeepRate = 1 + } + + randomFloat := cfg.RandomFloat + if randomFloat == nil { + randomFloat = rand.Float64 + } + + keepRules := make([]KeepRule, len(cfg.KeepRules)) + copy(keepRules, cfg.KeepRules) + + return &defaultTailSampler{ + slowThreshold: slowThreshold, + randomKeepRate: randomKeepRate, + keepStatusAtLeast: keepStatusAtLeast, + keepRules: keepRules, + randomFloat: randomFloat, + } +} + +func (s *defaultTailSampler) ShouldSample(view EventView) SamplingDecision { + if view.HasError { + return SamplingDecision{Keep: true, Reason: "error"} + } + + if view.Status >= s.keepStatusAtLeast { + return SamplingDecision{Keep: true, Reason: "status"} + } + + if view.Duration >= s.slowThreshold { + return SamplingDecision{Keep: true, Reason: "slow"} + } + + for _, rule := range s.keepRules { + if ruleMatches(view.Attrs, rule) { + return SamplingDecision{Keep: true, Reason: "rule"} + } + } + + if s.randomFloat() < s.randomKeepRate { + return SamplingDecision{Keep: true, Reason: "random"} + } + + return SamplingDecision{Keep: false, Reason: "drop"} +} + +func ruleMatches(attrs map[string]any, rule KeepRule) bool { + value, exists := lookupPath(attrs, rule.Field) + + switch strings.ToLower(rule.Op) { + case "eq": + if !exists { + return false + } + return valuesEqual(value, rule.Value) + case "in": + if !exists { + return false + } + return valueIn(value, rule.Value) + case "exists": + return exists + case "true": + if !exists { + return false + } + boolValue, ok := value.(bool) + return ok && boolValue + default: + return false + } +} + +func lookupPath(attrs map[string]any, path string) (any, bool) { + if attrs == nil { + return nil, false + } + + if direct, ok := attrs[path]; ok { + return direct, true + } + + current := any(attrs) + for _, part := range strings.Split(path, ".") { + asMap, ok := current.(map[string]any) + if !ok { + return nil, false + } + + next, ok := asMap[part] + if !ok { + return nil, false + } + + current = next + } + + return current, true +} + +func valueIn(value any, candidates any) bool { + candidateValue := reflect.ValueOf(candidates) + if !candidateValue.IsValid() { + return false + } + + kind := candidateValue.Kind() + if kind != reflect.Slice && kind != reflect.Array { + return false + } + + for i := range candidateValue.Len() { + if valuesEqual(value, candidateValue.Index(i).Interface()) { + return true + } + } + + return false +} + +func valuesEqual(a any, b any) bool { + if reflect.DeepEqual(a, b) { + return true + } + + ai, aok := toInt(a) + bi, bok := toInt(b) + if aok && bok { + return ai == bi + } + + return false +} diff --git a/log2/sampling_test.go b/log2/sampling_test.go new file mode 100644 index 0000000..1d23d00 --- /dev/null +++ b/log2/sampling_test.go @@ -0,0 +1,166 @@ +package log2_test + +import ( + "testing" + "time" + + "github.com/platforma-dev/platforma/log2" +) + +func TestDefaultTailSamplerKeepsError(t *testing.T) { + t.Parallel() + + sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ + RandomKeepRate: 0.01, + RandomFloat: func() float64 { return 0.99 }, + }) + + decision := sampler.ShouldSample(log2.EventView{HasError: true}) + if !decision.Keep { + t.Fatalf("expected keep for error") + } + if decision.Reason != "error" { + t.Fatalf("expected reason=error, got %q", decision.Reason) + } +} + +func TestDefaultTailSamplerKeepsByStatus(t *testing.T) { + t.Parallel() + + sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ + KeepStatusAtLeast: 500, + RandomKeepRate: 0.01, + RandomFloat: func() float64 { return 0.99 }, + }) + + decision := sampler.ShouldSample(log2.EventView{Status: 503}) + if !decision.Keep { + t.Fatalf("expected keep for status") + } + if decision.Reason != "status" { + t.Fatalf("expected reason=status, got %q", decision.Reason) + } +} + +func TestDefaultTailSamplerKeepsBySlowDuration(t *testing.T) { + t.Parallel() + + sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ + SlowThreshold: 100 * time.Millisecond, + RandomKeepRate: 0.01, + RandomFloat: func() float64 { return 0.99 }, + }) + + decision := sampler.ShouldSample(log2.EventView{Duration: 200 * time.Millisecond}) + if !decision.Keep { + t.Fatalf("expected keep for slow event") + } + if decision.Reason != "slow" { + t.Fatalf("expected reason=slow, got %q", decision.Reason) + } +} + +func TestDefaultTailSamplerKeepsByRule(t *testing.T) { + t.Parallel() + + t.Run("eq", func(t *testing.T) { + t.Parallel() + + sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ + KeepRules: []log2.KeepRule{{Field: "attrs.feature", Op: "eq", Value: "change_password"}}, + RandomKeepRate: 0.01, + RandomFloat: func() float64 { return 0.99 }, + }) + + decision := sampler.ShouldSample(log2.EventView{Attrs: map[string]any{ + "attrs": map[string]any{"feature": "change_password"}, + }}) + if !decision.Keep || decision.Reason != "rule" { + t.Fatalf("expected keep with reason=rule, got keep=%v reason=%q", decision.Keep, decision.Reason) + } + }) + + t.Run("in", func(t *testing.T) { + t.Parallel() + + sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ + KeepRules: []log2.KeepRule{{Field: "queue", Op: "in", Value: []string{"billing", "emails"}}}, + RandomKeepRate: 0.01, + RandomFloat: func() float64 { return 0.99 }, + }) + + decision := sampler.ShouldSample(log2.EventView{Attrs: map[string]any{"queue": "emails"}}) + if !decision.Keep || decision.Reason != "rule" { + t.Fatalf("expected keep with reason=rule, got keep=%v reason=%q", decision.Keep, decision.Reason) + } + }) + + t.Run("exists", func(t *testing.T) { + t.Parallel() + + sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ + KeepRules: []log2.KeepRule{{Field: "vip", Op: "exists"}}, + RandomKeepRate: 0.01, + RandomFloat: func() float64 { return 0.99 }, + }) + + decision := sampler.ShouldSample(log2.EventView{Attrs: map[string]any{"vip": "yes"}}) + if !decision.Keep || decision.Reason != "rule" { + t.Fatalf("expected keep with reason=rule, got keep=%v reason=%q", decision.Keep, decision.Reason) + } + }) + + t.Run("true", func(t *testing.T) { + t.Parallel() + + sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ + KeepRules: []log2.KeepRule{{Field: "security.risk", Op: "true"}}, + RandomKeepRate: 0.01, + RandomFloat: func() float64 { return 0.99 }, + }) + + decision := sampler.ShouldSample(log2.EventView{Attrs: map[string]any{"security": map[string]any{"risk": true}}}) + if !decision.Keep || decision.Reason != "rule" { + t.Fatalf("expected keep with reason=rule, got keep=%v reason=%q", decision.Keep, decision.Reason) + } + }) +} + +func TestDefaultTailSamplerRandomPath(t *testing.T) { + t.Parallel() + + t.Run("keep", func(t *testing.T) { + t.Parallel() + + sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ + SlowThreshold: 5 * time.Second, + KeepStatusAtLeast: 500, + RandomKeepRate: 0.10, + RandomFloat: func() float64 { return 0.09 }, + }) + + decision := sampler.ShouldSample(log2.EventView{}) + if !decision.Keep || decision.Reason != "random" { + t.Fatalf("expected random keep, got keep=%v reason=%q", decision.Keep, decision.Reason) + } + }) + + t.Run("drop", func(t *testing.T) { + t.Parallel() + + sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ + SlowThreshold: 5 * time.Second, + KeepStatusAtLeast: 500, + RandomKeepRate: 0.10, + RandomFloat: func() float64 { return 0.11 }, + }) + + decision := sampler.ShouldSample(log2.EventView{}) + if decision.Keep { + t.Fatalf("expected drop") + } + if decision.Reason != "drop" { + t.Fatalf("expected reason=drop, got %q", decision.Reason) + } + }) +} diff --git a/log2/test_helpers_test.go b/log2/test_helpers_test.go new file mode 100644 index 0000000..67bb4b6 --- /dev/null +++ b/log2/test_helpers_test.go @@ -0,0 +1,70 @@ +package log2_test + +import ( + "bytes" + "encoding/json" + "strings" + "testing" + + "github.com/platforma-dev/platforma/log2" +) + +type samplerFunc func(log2.EventView) log2.SamplingDecision + +func (f samplerFunc) ShouldSample(view log2.EventView) log2.SamplingDecision { + return f(view) +} + +func readEvents(t *testing.T, buffer *bytes.Buffer) []map[string]any { + t.Helper() + + trimmed := strings.TrimSpace(buffer.String()) + if trimmed == "" { + return nil + } + + lines := strings.Split(trimmed, "\n") + events := make([]map[string]any, 0, len(lines)) + + for _, line := range lines { + event := make(map[string]any) + if err := json.Unmarshal([]byte(line), &event); err != nil { + t.Fatalf("failed to parse event json: %v", err) + } + events = append(events, event) + } + + return events +} + +func requireMap(t *testing.T, source map[string]any, key string) map[string]any { + t.Helper() + + value, ok := source[key] + if !ok { + t.Fatalf("expected key %q to exist", key) + } + + asMap, ok := value.(map[string]any) + if !ok { + t.Fatalf("expected %q to be a map, got %T", key, value) + } + + return asMap +} + +func requireSlice(t *testing.T, source map[string]any, key string) []any { + t.Helper() + + value, ok := source[key] + if !ok { + t.Fatalf("expected key %q to exist", key) + } + + asSlice, ok := value.([]any) + if !ok { + t.Fatalf("expected %q to be a slice, got %T", key, value) + } + + return asSlice +} From 823440a979be4a6797caee1b669b7fb349b7d263 Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Sat, 14 Feb 2026 22:08:29 +0300 Subject: [PATCH 02/13] Update log.go --- log/log.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/log/log.go b/log/log.go index c9e8639..4b8ccb5 100644 --- a/log/log.go +++ b/log/log.go @@ -1,5 +1,5 @@ // Package log provides structured logging functionality with context support. -package log +package log //nolint:revive import ( "context" From 312f040dbcd1de368220fb1e1a09648b4eab5c24 Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Sat, 14 Feb 2026 22:18:14 +0300 Subject: [PATCH 03/13] Implement log2 tail sampling --- log2/context.go | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/log2/context.go b/log2/context.go index a704ac6..67230bc 100644 --- a/log2/context.go +++ b/log2/context.go @@ -23,5 +23,9 @@ func EventFromContext(ctx context.Context) (*Event, bool) { // WithEvent stores an event in context. func WithEvent(ctx context.Context, ev *Event) context.Context { + if ctx == nil { + ctx = context.Background() + } + return context.WithValue(ctx, LogEventContextKey, ev) } From 645fbfb9e5f9ba9161bd3ff12c9251f0d03efa1e Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Sun, 15 Feb 2026 10:12:43 +0300 Subject: [PATCH 04/13] move package-docs skill --- {.opencode => .agents}/skills/package-docs/SKILL.md | 0 1 file changed, 0 insertions(+), 0 deletions(-) rename {.opencode => .agents}/skills/package-docs/SKILL.md (100%) diff --git a/.opencode/skills/package-docs/SKILL.md b/.agents/skills/package-docs/SKILL.md similarity index 100% rename from .opencode/skills/package-docs/SKILL.md rename to .agents/skills/package-docs/SKILL.md From 6fd763c822052cf0e3c243abad8160ec5431ebd4 Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Sun, 15 Feb 2026 10:12:57 +0300 Subject: [PATCH 05/13] init log2 docs --- docs/astro.config.mjs | 1 + docs/src/content/docs/packages/log2.mdx | 195 ++++++++++++++++++++++++ 2 files changed, 196 insertions(+) create mode 100644 docs/src/content/docs/packages/log2.mdx diff --git a/docs/astro.config.mjs b/docs/astro.config.mjs index 811882f..6d34fe8 100644 --- a/docs/astro.config.mjs +++ b/docs/astro.config.mjs @@ -28,6 +28,7 @@ export default defineConfig({ "packages/database", "packages/httpserver", "packages/log", + "packages/log2", "packages/queue", "packages/scheduler", "packages/auth", diff --git a/docs/src/content/docs/packages/log2.mdx b/docs/src/content/docs/packages/log2.mdx new file mode 100644 index 0000000..37cc730 --- /dev/null +++ b/docs/src/content/docs/packages/log2.mdx @@ -0,0 +1,195 @@ +--- +title: log2 +--- +import { Steps } from '@astrojs/starlight/components'; + +The `log2` package provides wide-event logging with tail sampling, so each operation emits one structured event enriched with timeline steps, errors, and request context. + +Core Components: + +- `Config`: Logger configuration (`Writer`, `Format`, `Level`, `ContextKeys`, `Sampler`, `MaxSteps`). +- `DefaultConfig`: Returns defaults for output format, level, max steps, and sampler settings. +- `Logger`: Wide-event logger instance. +- `New`: Creates a logger from `Config`. +- `SetDefault`: Replaces package-level default logger. +- `Start`: Starts an event (`log2.Start` and `(*Logger).Start`). +- `Event`: Mutable event object. +- `Event.Add`, `Event.Step`, `Event.Error`, `Event.Finish`: Event lifecycle methods. +- `TailSampler`: Sampling interface. +- `SamplingDecision`: Keep/drop decision with reason. +- `EventView`: Immutable event view for sampling. +- `DefaultTailSamplerConfig`: Config for default sampler. +- `KeepRule`: Rule definition for forced-keep sampling. +- `NewDefaultTailSampler`: Builds default rule-based sampler. +- `HTTPMiddlewareConfig`, `NewHTTPMiddleware`: HTTP middleware that creates one event per request. +- `WithEvent`, `EventFromContext`, `LogEventContextKey`: Context helpers. +- `ErrEventAlreadyFinished`: Returned when `Finish` is called more than once. + +[Full package docs at pkg.go.dev](https://pkg.go.dev/github.com/platforma-dev/platforma/log2) + +## Step-by-step guide + + + +1. Create a logger + + ```go + cfg := log2.DefaultConfig() + cfg.Level = slog.LevelInfo + logger := log2.New(cfg) + log2.SetDefault(logger) + ``` + + `DefaultConfig` includes: + + - `Format: "json"` + - Default tail sampler (keep errors, 5xx, slow events, and a random sample) + - `MaxSteps: 100` + +2. Start and enrich an event + + ```go + ev := logger.Start(ctx, "auth_request", "component", "handler") + ev.Add("userId", "u-123") + ev.Step(slog.LevelInfo, "credentials_validated", "provider", "password") + ``` + + `Add` merges persistent attributes. `Step` appends timeline entries. + +3. Record errors and finish + + ```go + if err != nil { + ev.Error(err, "stage", "db_lookup") + } + + if finishErr := ev.Finish("status", 200); finishErr != nil { + if errors.Is(finishErr, log2.ErrEventAlreadyFinished) { + // finish was called twice + } + } + ``` + + `Finish` evaluates sampling using event status, duration, errors, and attributes. + +4. Configure custom tail sampling rules + + ```go + cfg := log2.DefaultConfig() + cfg.Sampler = log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ + KeepRules: []log2.KeepRule{ + {Field: "attrs.feature", Op: "eq", Value: "change_password"}, + {Field: "queue", Op: "in", Value: []string{"billing", "emails"}}, + {Field: "vip", Op: "exists"}, + {Field: "security.risk", Op: "true"}, + }, + RandomKeepRate: 0.01, + }) + logger := log2.New(cfg) + ``` + + Supported rule operators are `eq`, `in`, `exists`, and `true`. + +5. Add HTTP middleware and use event from request context + + ```go + logger := log2.New(log2.DefaultConfig()) + middleware := log2.NewHTTPMiddleware(logger, log2.HTTPMiddlewareConfig{ + EventName: "http_request", + RouteAttr: "route", + }) + + mux := http.NewServeMux() + mux.HandleFunc("/ping", func(w http.ResponseWriter, r *http.Request) { + if ev, ok := log2.EventFromContext(r.Context()); ok { + ev.Step(slog.LevelInfo, "handler_started", "path", r.URL.Path) + } + + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte("pong")) + }) + + handler := middleware(mux) + _ = handler + ``` + + Middleware stores the event in context using `WithEvent`, collects request/response metadata, and calls `Finish` automatically. + + + +## Behavior notes + +- `Finish` called twice returns `ErrEventAlreadyFinished`. +- Event log level is inferred: + - `ERROR` for event errors or 5xx status. + - `WARN` for 4xx status. + - `INFO` otherwise. +- Status is inferred from `status`, `statusCode`, `response.status`, or `response.status` inside a `response` map. +- If steps exceed `MaxSteps`, extra steps are dropped and counted in `stepsDropped`. + +## Integration with `log` context keys + +`log2.Start` extracts known context values from the `log` package and includes them in event attributes when present: + +- `traceId` +- `serviceName` +- `domainName` +- `startupTask` +- `userId` +- `workerId` + +This allows `log2` events to align with existing `log` and `httpserver` context propagation. + +## Complete example + +```go +package main + +import ( + "context" + "errors" + "log/slog" + "net/http" + "os" + "time" + + "github.com/platforma-dev/platforma/log2" +) + +func main() { + cfg := log2.DefaultConfig() + cfg.Writer = os.Stdout + cfg.Level = slog.LevelInfo + cfg.Sampler = log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ + SlowThreshold: 500 * time.Millisecond, + RandomKeepRate: 0.02, + }) + + logger := log2.New(cfg) + middleware := log2.NewHTTPMiddleware(logger, log2.HTTPMiddlewareConfig{}) + + mux := http.NewServeMux() + mux.HandleFunc("/users", func(w http.ResponseWriter, r *http.Request) { + ev, ok := log2.EventFromContext(r.Context()) + if ok { + ev.Step(slog.LevelInfo, "fetch_users_started") + defer func() { + if err := ev.Finish("status", http.StatusOK); err != nil && !errors.Is(err, log2.ErrEventAlreadyFinished) { + // Handle finish error. + } + }() + } + + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte(`{"users":[]}`)) + }) + + server := &http.Server{ + Addr: ":8080", + Handler: middleware(mux), + } + + _ = server.ListenAndServe() + _ = server.Shutdown(context.Background()) +} +``` From 1d9f14b50c6bbd2032496f1f2c7fdcaf000d007b Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Sun, 15 Feb 2026 19:56:36 +0300 Subject: [PATCH 06/13] expose docs on dev command --- Taskfile.dist.yml | 2 +- docs/package.json | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/Taskfile.dist.yml b/Taskfile.dist.yml index 5c19ff0..ca1481b 100644 --- a/Taskfile.dist.yml +++ b/Taskfile.dist.yml @@ -24,4 +24,4 @@ tasks: docs: dir: docs cmds: - - npm run dev + - bun run dev diff --git a/docs/package.json b/docs/package.json index 0b2d575..a86d185 100644 --- a/docs/package.json +++ b/docs/package.json @@ -3,7 +3,7 @@ "type": "module", "version": "0.0.1", "scripts": { - "dev": "astro dev", + "dev": "astro dev --host", "start": "astro dev", "build": "astro build", "preview": "astro preview", From 7edc5226ee703ecd3529f28ab11e4f45ca10028b Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Sun, 15 Feb 2026 22:49:39 +0300 Subject: [PATCH 07/13] cleaning up --- log2/context.go | 2 +- log2/context_test.go | 92 ---------- log2/event.go | 54 ++---- log2/event_test.go | 197 --------------------- log2/http_middleware_test.go | 140 --------------- log2/logger.go | 5 +- log2/{http_middleware.go => middleware.go} | 0 log2/sampling_test.go | 166 ----------------- log2/test_helpers_test.go | 70 -------- 9 files changed, 19 insertions(+), 707 deletions(-) delete mode 100644 log2/context_test.go delete mode 100644 log2/event_test.go delete mode 100644 log2/http_middleware_test.go rename log2/{http_middleware.go => middleware.go} (100%) delete mode 100644 log2/sampling_test.go delete mode 100644 log2/test_helpers_test.go diff --git a/log2/context.go b/log2/context.go index 67230bc..3a2da4f 100644 --- a/log2/context.go +++ b/log2/context.go @@ -5,7 +5,7 @@ import "context" type contextKey string // LogEventContextKey is used to store Event in context. -var LogEventContextKey any = contextKey("platformaLog2Event") //nolint:gochecknoglobals +const LogEventContextKey contextKey = "platformaLogEvent" // EventFromContext gets an event from context. func EventFromContext(ctx context.Context) (*Event, bool) { diff --git a/log2/context_test.go b/log2/context_test.go deleted file mode 100644 index 2bc2f74..0000000 --- a/log2/context_test.go +++ /dev/null @@ -1,92 +0,0 @@ -package log2_test - -import ( - "bytes" - "context" - "log/slog" - "testing" - - "github.com/platforma-dev/platforma/log" - "github.com/platforma-dev/platforma/log2" -) - -func TestEventFromContextMiss(t *testing.T) { - t.Parallel() - - ev, ok := log2.EventFromContext(context.Background()) - if ok { - t.Fatalf("expected ok=false, got true with event=%v", ev) - } - if ev != nil { - t.Fatalf("expected nil event, got %v", ev) - } -} - -func TestEventFromContextWithRawContextValue(t *testing.T) { - t.Parallel() - - logger := log2.New(log2.Config{Writer: &bytes.Buffer{}}) - ev := logger.Start(context.Background(), "ctx") - - ctx := context.WithValue(context.Background(), log2.LogEventContextKey, ev) - got, ok := log2.EventFromContext(ctx) - if !ok { - t.Fatalf("expected ok=true") - } - if got != ev { - t.Fatalf("expected the same event pointer") - } -} - -func TestWithEvent(t *testing.T) { - t.Parallel() - - logger := log2.New(log2.Config{Writer: &bytes.Buffer{}}) - ev := logger.Start(context.Background(), "ctx") - - ctx := log2.WithEvent(context.Background(), ev) - got, ok := log2.EventFromContext(ctx) - if !ok { - t.Fatalf("expected ok=true") - } - if got != ev { - t.Fatalf("expected the same event pointer") - } -} - -func TestStartCollectsDefaultContextKeys(t *testing.T) { - t.Parallel() - - buffer := &bytes.Buffer{} - logger := log2.New(log2.Config{ - Writer: buffer, - Format: "json", - Level: slog.LevelInfo, - Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), - }) - - ctx := context.WithValue(context.Background(), log.TraceIDKey, "trace-123") - ctx = context.WithValue(ctx, log.UserIDKey, "user-99") - - ev := logger.Start(ctx, "collect-keys") - if err := ev.Finish(); err != nil { - t.Fatalf("Finish() returned error: %v", err) - } - - events := readEvents(t, buffer) - if len(events) != 1 { - t.Fatalf("expected 1 event, got %d", len(events)) - } - - if events[0]["traceId"] != "trace-123" { - t.Fatalf("expected top-level traceId=trace-123, got %v", events[0]["traceId"]) - } - - attrs := requireMap(t, events[0], "attrs") - if attrs["traceId"] != "trace-123" { - t.Fatalf("expected attrs.traceId=trace-123, got %v", attrs["traceId"]) - } - if attrs["userId"] != "user-99" { - t.Fatalf("expected attrs.userId=user-99, got %v", attrs["userId"]) - } -} diff --git a/log2/event.go b/log2/event.go index c0d4f14..c9acb56 100644 --- a/log2/event.go +++ b/log2/event.go @@ -95,7 +95,7 @@ func (e *Event) Step(level slog.Level, msg string, attrs ...any) { } e.steps = append(e.steps, stepRecord{ - ts: nowUTC(), + ts: time.Now().UTC(), level: level.String(), msg: msg, attrs: normalizeAttrs(attrs...), @@ -117,7 +117,7 @@ func (e *Event) Error(err error, attrs ...any) { e.hasError = true e.errors = append(e.errors, errorRecord{ - ts: nowUTC(), + ts: time.Now().UTC(), err: err.Error(), attrs: normalizeAttrs(attrs...), }) @@ -137,9 +137,17 @@ func (e *Event) Finish(attrs ...any) error { mergeAttrs(e.attrs, normalizeAttrs(attrs...)) - duration := nowUTC().Sub(e.startedAt) - status := inferStatus(e.attrs) - level := inferLevel(status, e.hasError) + status := 0 + statusFromAttrs, ok := e.attrs["request.status"] + if ok { + status, ok = statusFromAttrs.(int) + if !ok { + status = 0 + } + } + + duration := time.Now().UTC().Sub(e.startedAt) + level := inferLevel(e.hasError) attrsCopy := copyAttrs(e.attrs) stepsCopy := copySteps(e.steps) errorsCopy := copyErrors(e.errors) @@ -175,10 +183,6 @@ func (e *Event) Finish(attrs ...any) error { }) } -func nowUTC() time.Time { - return time.Now().UTC() -} - func collectContextAttrs(ctx context.Context, extraKeys map[string]any) map[string]any { attrs := map[string]any{} @@ -278,42 +282,14 @@ func copyErrors(src []errorRecord) []map[string]any { return errs } -func inferLevel(status int, hasError bool) slog.Level { - if hasError || status >= defaultKeepStatus { +func inferLevel(hasError bool) slog.Level { + if hasError { return slog.LevelError } - if status >= 400 { - return slog.LevelWarn - } - return slog.LevelInfo } -func inferStatus(attrs map[string]any) int { - if status, ok := toInt(attrs["status"]); ok { - return status - } - - if status, ok := toInt(attrs["statusCode"]); ok { - return status - } - - if status, ok := toInt(attrs["response.status"]); ok { - return status - } - - if responseAny, ok := attrs["response"]; ok { - if response, okMap := responseAny.(map[string]any); okMap { - if status, okStatus := toInt(response["status"]); okStatus { - return status - } - } - } - - return 0 -} - func toInt(value any) (int, bool) { switch typed := value.(type) { case int: diff --git a/log2/event_test.go b/log2/event_test.go deleted file mode 100644 index fbff343..0000000 --- a/log2/event_test.go +++ /dev/null @@ -1,197 +0,0 @@ -package log2_test - -import ( - "bytes" - "context" - "errors" - "log/slog" - "sync" - "testing" - - "github.com/platforma-dev/platforma/log2" -) - -func TestEventLifecycle(t *testing.T) { - t.Parallel() - - buffer := &bytes.Buffer{} - logger := log2.New(log2.Config{ - Writer: buffer, - Format: "json", - Level: slog.LevelDebug, - Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), - MaxSteps: 10, - }) - - ev := logger.Start(context.Background(), "auth_request", "component", "handler") - ev.Add("userId", "u-1", "attempt", 2) - ev.Step(slog.LevelInfo, "request accepted") - ev.Error(errors.New("boom"), "phase", "validation") - - if err := ev.Finish("status", 500); err != nil { - t.Fatalf("Finish() returned error: %v", err) - } - - events := readEvents(t, buffer) - if len(events) != 1 { - t.Fatalf("expected 1 emitted event, got %d", len(events)) - } - - event := events[0] - if event["event"] != "auth_request" { - t.Fatalf("expected event name auth_request, got %v", event["event"]) - } - if event["samplingReason"] != "forced" { - t.Fatalf("expected sampling reason forced, got %v", event["samplingReason"]) - } - if event["sampled"] != true { - t.Fatalf("expected sampled=true, got %v", event["sampled"]) - } - - attrs := requireMap(t, event, "attrs") - if attrs["component"] != "handler" { - t.Fatalf("expected component=handler, got %v", attrs["component"]) - } - if attrs["userId"] != "u-1" { - t.Fatalf("expected userId=u-1, got %v", attrs["userId"]) - } - if attrs["attempt"] != float64(2) { - t.Fatalf("expected attempt=2, got %v", attrs["attempt"]) - } - if attrs["status"] != float64(500) { - t.Fatalf("expected status=500, got %v", attrs["status"]) - } - - steps := requireSlice(t, event, "steps") - if len(steps) != 1 { - t.Fatalf("expected 1 step, got %d", len(steps)) - } - - errorsList := requireSlice(t, event, "errors") - if len(errorsList) != 1 { - t.Fatalf("expected 1 error, got %d", len(errorsList)) - } -} - -func TestEventAttributeOverwrite(t *testing.T) { - t.Parallel() - - buffer := &bytes.Buffer{} - logger := log2.New(log2.Config{ - Writer: buffer, - Format: "json", - Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), - }) - - ev := logger.Start(context.Background(), "overwrite") - ev.Add("key", "first") - ev.Add("key", "second") - - if err := ev.Finish(); err != nil { - t.Fatalf("Finish() returned error: %v", err) - } - - events := readEvents(t, buffer) - if len(events) != 1 { - t.Fatalf("expected 1 event, got %d", len(events)) - } - - attrs := requireMap(t, events[0], "attrs") - if attrs["key"] != "second" { - t.Fatalf("expected key=second, got %v", attrs["key"]) - } -} - -func TestEventFinishCalledTwice(t *testing.T) { - t.Parallel() - - logger := log2.New(log2.Config{ - Writer: &bytes.Buffer{}, - Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), - }) - - ev := logger.Start(context.Background(), "double_finish") - if err := ev.Finish(); err != nil { - t.Fatalf("first Finish() returned error: %v", err) - } - - err := ev.Finish() - if !errors.Is(err, log2.ErrEventAlreadyFinished) { - t.Fatalf("expected ErrEventAlreadyFinished, got %v", err) - } -} - -func TestEventConcurrentAccessAndStepCap(t *testing.T) { - t.Parallel() - - buffer := &bytes.Buffer{} - logger := log2.New(log2.Config{ - Writer: buffer, - Format: "json", - Level: slog.LevelDebug, - Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), - MaxSteps: 5, - }) - - ev := logger.Start(context.Background(), "concurrent") - - var wg sync.WaitGroup - for i := range 20 { - wg.Add(1) - go func(i int) { - defer wg.Done() - ev.Add("counter", i) - ev.Step(slog.LevelInfo, "work", "i", i) - if i%3 == 0 { - ev.Error(errors.New("worker-error"), "i", i) - } - }(i) - } - - wg.Wait() - - if err := ev.Finish("status", 200); err != nil { - t.Fatalf("Finish() returned error: %v", err) - } - - events := readEvents(t, buffer) - if len(events) != 1 { - t.Fatalf("expected 1 event, got %d", len(events)) - } - - event := events[0] - steps := requireSlice(t, event, "steps") - if len(steps) != 5 { - t.Fatalf("expected 5 steps (cap), got %d", len(steps)) - } - - dropped, ok := event["stepsDropped"].(float64) - if !ok { - t.Fatalf("expected stepsDropped to exist") - } - if dropped != float64(15) { - t.Fatalf("expected stepsDropped=15, got %v", dropped) - } -} - -func TestEventDroppedBySampler(t *testing.T) { - t.Parallel() - - buffer := &bytes.Buffer{} - logger := log2.New(log2.Config{ - Writer: buffer, - Format: "json", - Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: false, Reason: "drop"} }), - }) - - ev := logger.Start(context.Background(), "drop_me") - ev.Add("k", "v") - if err := ev.Finish(); err != nil { - t.Fatalf("Finish() returned error: %v", err) - } - - events := readEvents(t, buffer) - if len(events) != 0 { - t.Fatalf("expected no emitted events, got %d", len(events)) - } -} diff --git a/log2/http_middleware_test.go b/log2/http_middleware_test.go deleted file mode 100644 index a881a23..0000000 --- a/log2/http_middleware_test.go +++ /dev/null @@ -1,140 +0,0 @@ -package log2_test - -import ( - "bytes" - "fmt" - "log/slog" - "net/http" - "net/http/httptest" - "strings" - "testing" - - "github.com/platforma-dev/platforma/log2" -) - -func TestHTTPMiddlewareEmitsSingleWideEvent(t *testing.T) { - t.Parallel() - - buffer := &bytes.Buffer{} - logger := log2.New(log2.Config{ - Writer: buffer, - Format: "json", - Level: slog.LevelInfo, - Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), - }) - - middleware := log2.NewHTTPMiddleware(logger, log2.HTTPMiddlewareConfig{}) - handler := middleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - ev, ok := log2.EventFromContext(r.Context()) - if !ok { - t.Fatalf("expected event in request context") - } - ev.Add("handler", "users") - - w.WriteHeader(http.StatusTeapot) - _, _ = w.Write([]byte("hello")) - })) - - req := httptest.NewRequest(http.MethodGet, "/users/42", nil) - rec := httptest.NewRecorder() - handler.ServeHTTP(rec, req) - - events := readEvents(t, buffer) - if len(events) != 1 { - t.Fatalf("expected 1 event, got %d", len(events)) - } - - event := events[0] - if event["event"] != "http_request" { - t.Fatalf("expected event=http_request, got %v", event["event"]) - } - - attrs := requireMap(t, event, "attrs") - if attrs["status"] != float64(http.StatusTeapot) { - t.Fatalf("expected status %d, got %v", http.StatusTeapot, attrs["status"]) - } - if attrs["route"] != "/users/42" { - t.Fatalf("expected fallback route /users/42, got %v", attrs["route"]) - } - - request := requireMap(t, attrs, "request") - if request["method"] != http.MethodGet { - t.Fatalf("expected method GET, got %v", request["method"]) - } - if request["path"] != "/users/42" { - t.Fatalf("expected path /users/42, got %v", request["path"]) - } - - response := requireMap(t, attrs, "response") - if response["status"] != float64(http.StatusTeapot) { - t.Fatalf("expected response.status=%d, got %v", http.StatusTeapot, response["status"]) - } - if response["bytes"] != float64(5) { - t.Fatalf("expected response.bytes=5, got %v", response["bytes"]) - } -} - -func TestHTTPMiddlewarePanicPath(t *testing.T) { - t.Parallel() - - buffer := &bytes.Buffer{} - logger := log2.New(log2.Config{ - Writer: buffer, - Format: "json", - Level: slog.LevelInfo, - Sampler: samplerFunc(func(log2.EventView) log2.SamplingDecision { return log2.SamplingDecision{Keep: true, Reason: "forced"} }), - }) - - middleware := log2.NewHTTPMiddleware(logger, log2.HTTPMiddlewareConfig{}) - handler := middleware(http.HandlerFunc(func(http.ResponseWriter, *http.Request) { - panic("boom") - })) - - req := httptest.NewRequest(http.MethodGet, "/panic", nil) - rec := httptest.NewRecorder() - - panicRecovered := false - func() { - defer func() { - if recovered := recover(); recovered != nil { - panicRecovered = true - if fmt.Sprint(recovered) != "boom" { - t.Fatalf("expected panic value boom, got %v", recovered) - } - } - }() - handler.ServeHTTP(rec, req) - }() - - if !panicRecovered { - t.Fatalf("expected panic to be rethrown by middleware") - } - - events := readEvents(t, buffer) - if len(events) != 1 { - t.Fatalf("expected 1 event, got %d", len(events)) - } - - event := events[0] - if event["level"] != "ERROR" { - t.Fatalf("expected level ERROR for panic path, got %v", event["level"]) - } - - errorsList := requireSlice(t, event, "errors") - if len(errorsList) != 1 { - t.Fatalf("expected exactly 1 recorded error, got %d", len(errorsList)) - } - - errorMap, ok := errorsList[0].(map[string]any) - if !ok { - t.Fatalf("expected errors[0] to be map, got %T", errorsList[0]) - } - - errorText, ok := errorMap["error"].(string) - if !ok { - t.Fatalf("expected errors[0].error string, got %T", errorMap["error"]) - } - if !strings.Contains(errorText, "panic recovered: boom") { - t.Fatalf("expected panic error text to include panic recovered: boom, got %q", errorText) - } -} diff --git a/log2/logger.go b/log2/logger.go index f6fc6f9..27e77e3 100644 --- a/log2/logger.go +++ b/log2/logger.go @@ -5,6 +5,7 @@ import ( "fmt" "io" "log/slog" + "time" ) // Logger writes sampled wide events. @@ -77,7 +78,7 @@ func (l *Logger) Start(ctx context.Context, eventName string, attrs ...any) *Eve return &Event{ logger: l, eventName: eventName, - startedAt: nowUTC(), + startedAt: time.Now().UTC(), attrs: baseAttrs, steps: make([]stepRecord, 0), errors: make([]errorRecord, 0), @@ -93,7 +94,7 @@ func (l *Logger) emit(ctx context.Context, event eventPayload) error { return nil } - rec := slog.NewRecord(nowUTC(), event.level, event.eventName, 0) + rec := slog.NewRecord(time.Now().UTC(), event.level, event.eventName, 0) rec.AddAttrs( slog.String("event", event.eventName), slog.Int64("durationMs", event.durationMs), diff --git a/log2/http_middleware.go b/log2/middleware.go similarity index 100% rename from log2/http_middleware.go rename to log2/middleware.go diff --git a/log2/sampling_test.go b/log2/sampling_test.go deleted file mode 100644 index 1d23d00..0000000 --- a/log2/sampling_test.go +++ /dev/null @@ -1,166 +0,0 @@ -package log2_test - -import ( - "testing" - "time" - - "github.com/platforma-dev/platforma/log2" -) - -func TestDefaultTailSamplerKeepsError(t *testing.T) { - t.Parallel() - - sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ - RandomKeepRate: 0.01, - RandomFloat: func() float64 { return 0.99 }, - }) - - decision := sampler.ShouldSample(log2.EventView{HasError: true}) - if !decision.Keep { - t.Fatalf("expected keep for error") - } - if decision.Reason != "error" { - t.Fatalf("expected reason=error, got %q", decision.Reason) - } -} - -func TestDefaultTailSamplerKeepsByStatus(t *testing.T) { - t.Parallel() - - sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ - KeepStatusAtLeast: 500, - RandomKeepRate: 0.01, - RandomFloat: func() float64 { return 0.99 }, - }) - - decision := sampler.ShouldSample(log2.EventView{Status: 503}) - if !decision.Keep { - t.Fatalf("expected keep for status") - } - if decision.Reason != "status" { - t.Fatalf("expected reason=status, got %q", decision.Reason) - } -} - -func TestDefaultTailSamplerKeepsBySlowDuration(t *testing.T) { - t.Parallel() - - sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ - SlowThreshold: 100 * time.Millisecond, - RandomKeepRate: 0.01, - RandomFloat: func() float64 { return 0.99 }, - }) - - decision := sampler.ShouldSample(log2.EventView{Duration: 200 * time.Millisecond}) - if !decision.Keep { - t.Fatalf("expected keep for slow event") - } - if decision.Reason != "slow" { - t.Fatalf("expected reason=slow, got %q", decision.Reason) - } -} - -func TestDefaultTailSamplerKeepsByRule(t *testing.T) { - t.Parallel() - - t.Run("eq", func(t *testing.T) { - t.Parallel() - - sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ - KeepRules: []log2.KeepRule{{Field: "attrs.feature", Op: "eq", Value: "change_password"}}, - RandomKeepRate: 0.01, - RandomFloat: func() float64 { return 0.99 }, - }) - - decision := sampler.ShouldSample(log2.EventView{Attrs: map[string]any{ - "attrs": map[string]any{"feature": "change_password"}, - }}) - if !decision.Keep || decision.Reason != "rule" { - t.Fatalf("expected keep with reason=rule, got keep=%v reason=%q", decision.Keep, decision.Reason) - } - }) - - t.Run("in", func(t *testing.T) { - t.Parallel() - - sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ - KeepRules: []log2.KeepRule{{Field: "queue", Op: "in", Value: []string{"billing", "emails"}}}, - RandomKeepRate: 0.01, - RandomFloat: func() float64 { return 0.99 }, - }) - - decision := sampler.ShouldSample(log2.EventView{Attrs: map[string]any{"queue": "emails"}}) - if !decision.Keep || decision.Reason != "rule" { - t.Fatalf("expected keep with reason=rule, got keep=%v reason=%q", decision.Keep, decision.Reason) - } - }) - - t.Run("exists", func(t *testing.T) { - t.Parallel() - - sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ - KeepRules: []log2.KeepRule{{Field: "vip", Op: "exists"}}, - RandomKeepRate: 0.01, - RandomFloat: func() float64 { return 0.99 }, - }) - - decision := sampler.ShouldSample(log2.EventView{Attrs: map[string]any{"vip": "yes"}}) - if !decision.Keep || decision.Reason != "rule" { - t.Fatalf("expected keep with reason=rule, got keep=%v reason=%q", decision.Keep, decision.Reason) - } - }) - - t.Run("true", func(t *testing.T) { - t.Parallel() - - sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ - KeepRules: []log2.KeepRule{{Field: "security.risk", Op: "true"}}, - RandomKeepRate: 0.01, - RandomFloat: func() float64 { return 0.99 }, - }) - - decision := sampler.ShouldSample(log2.EventView{Attrs: map[string]any{"security": map[string]any{"risk": true}}}) - if !decision.Keep || decision.Reason != "rule" { - t.Fatalf("expected keep with reason=rule, got keep=%v reason=%q", decision.Keep, decision.Reason) - } - }) -} - -func TestDefaultTailSamplerRandomPath(t *testing.T) { - t.Parallel() - - t.Run("keep", func(t *testing.T) { - t.Parallel() - - sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ - SlowThreshold: 5 * time.Second, - KeepStatusAtLeast: 500, - RandomKeepRate: 0.10, - RandomFloat: func() float64 { return 0.09 }, - }) - - decision := sampler.ShouldSample(log2.EventView{}) - if !decision.Keep || decision.Reason != "random" { - t.Fatalf("expected random keep, got keep=%v reason=%q", decision.Keep, decision.Reason) - } - }) - - t.Run("drop", func(t *testing.T) { - t.Parallel() - - sampler := log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ - SlowThreshold: 5 * time.Second, - KeepStatusAtLeast: 500, - RandomKeepRate: 0.10, - RandomFloat: func() float64 { return 0.11 }, - }) - - decision := sampler.ShouldSample(log2.EventView{}) - if decision.Keep { - t.Fatalf("expected drop") - } - if decision.Reason != "drop" { - t.Fatalf("expected reason=drop, got %q", decision.Reason) - } - }) -} diff --git a/log2/test_helpers_test.go b/log2/test_helpers_test.go deleted file mode 100644 index 67bb4b6..0000000 --- a/log2/test_helpers_test.go +++ /dev/null @@ -1,70 +0,0 @@ -package log2_test - -import ( - "bytes" - "encoding/json" - "strings" - "testing" - - "github.com/platforma-dev/platforma/log2" -) - -type samplerFunc func(log2.EventView) log2.SamplingDecision - -func (f samplerFunc) ShouldSample(view log2.EventView) log2.SamplingDecision { - return f(view) -} - -func readEvents(t *testing.T, buffer *bytes.Buffer) []map[string]any { - t.Helper() - - trimmed := strings.TrimSpace(buffer.String()) - if trimmed == "" { - return nil - } - - lines := strings.Split(trimmed, "\n") - events := make([]map[string]any, 0, len(lines)) - - for _, line := range lines { - event := make(map[string]any) - if err := json.Unmarshal([]byte(line), &event); err != nil { - t.Fatalf("failed to parse event json: %v", err) - } - events = append(events, event) - } - - return events -} - -func requireMap(t *testing.T, source map[string]any, key string) map[string]any { - t.Helper() - - value, ok := source[key] - if !ok { - t.Fatalf("expected key %q to exist", key) - } - - asMap, ok := value.(map[string]any) - if !ok { - t.Fatalf("expected %q to be a map, got %T", key, value) - } - - return asMap -} - -func requireSlice(t *testing.T, source map[string]any, key string) []any { - t.Helper() - - value, ok := source[key] - if !ok { - t.Fatalf("expected key %q to exist", key) - } - - asSlice, ok := value.([]any) - if !ok { - t.Fatalf("expected %q to be a slice, got %T", key, value) - } - - return asSlice -} From 61e01ea5f1ca10bf0f7ebbbfa8640afb22f1ca02 Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Sun, 15 Feb 2026 23:39:56 +0300 Subject: [PATCH 08/13] next try init --- log3/event.go | 104 +++++++++++++++++++++++++++++++++++++++++++++++++ log3/logger.go | 29 ++++++++++++++ 2 files changed, 133 insertions(+) create mode 100644 log3/event.go create mode 100644 log3/logger.go diff --git a/log3/event.go b/log3/event.go new file mode 100644 index 0000000..8e31e87 --- /dev/null +++ b/log3/event.go @@ -0,0 +1,104 @@ +package log3 + +import ( + "log/slog" + "maps" + "sync" + "time" +) + +type Event struct { + mu sync.Mutex + + name string + timestamp time.Time + level slog.Level + duration time.Duration + attrs map[string]any + steps []stepRecord + errors []errorRecord +} + +func NewEvent() *Event { + return &Event{ + timestamp: time.Now(), + level: slog.LevelDebug, + attrs: map[string]any{}, + } +} + +func (e *Event) SetLevel(level slog.Level) { + e.mu.Lock() + defer e.mu.Unlock() + + if level > e.level { + e.level = level + } +} + +func (e *Event) AddAttrs(attrs map[string]any) { + e.mu.Lock() + defer e.mu.Unlock() + + maps.Copy(e.attrs, attrs) +} + +func (e *Event) AddStep(level slog.Level, name string) { + e.mu.Lock() + defer e.mu.Unlock() + + e.SetLevel(level) + + e.steps = append(e.steps, stepRecord{ + timestamp: time.Now(), + level: level, + name: name, + }) +} + +func (e *Event) AddError(err error) { + e.mu.Lock() + defer e.mu.Unlock() + + e.SetLevel(slog.LevelError) + + e.errors = append(e.errors, errorRecord{ + timestamp: time.Now(), + err: err, + }) +} + +func (e *Event) Finish() { + e.mu.Lock() + defer e.mu.Unlock() + + e.duration = time.Since(e.timestamp) +} + +func (e *Event) ToAttrs() []slog.Attr { + e.mu.Lock() + defer e.mu.Unlock() + + e.duration = time.Since(e.timestamp) + + return []slog.Attr{ + slog.String("name", e.name), + slog.Time("timestamp", e.timestamp), + slog.Int("level", int(e.level)), + slog.Duration("duration", e.duration), + slog.Any("attrs", e.attrs), + slog.Any("steps", e.steps), + slog.Any("errors", e.errors), + } +} + +type stepRecord struct { + timestamp time.Time + level slog.Level + name string +} + +type errorRecord struct { + timestamp time.Time + err error +} diff --git a/log3/logger.go b/log3/logger.go new file mode 100644 index 0000000..89ff943 --- /dev/null +++ b/log3/logger.go @@ -0,0 +1,29 @@ +package log3 + +import ( + "context" + "io" + "log/slog" +) + +type Logger struct { + w io.Writer + sampler func(*Event) bool + logger *slog.Logger +} + +func (l *Logger) WriteEvent(ctx context.Context, e *Event) { + e.Finish() + + if l.sampler(e) { + l.logger.LogAttrs(ctx, e.level, "", e.ToAttrs()...) + } +} + +func mapToAttrs(data map[string]any) []slog.Attr { + attrs := make([]slog.Attr, 0, len(data)) + for k, v := range data { + attrs = append(attrs, slog.Any(k, v)) + } + return attrs +} From c7aae03bfb5063858f6f4fe2eab36fd22ed0fe1d Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Mon, 16 Feb 2026 07:24:33 +0300 Subject: [PATCH 09/13] Update logger even more --- log3/logger.go | 21 +++++++++--------- log3/sampler.go | 57 +++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 68 insertions(+), 10 deletions(-) create mode 100644 log3/sampler.go diff --git a/log3/logger.go b/log3/logger.go index 89ff943..00b5404 100644 --- a/log3/logger.go +++ b/log3/logger.go @@ -4,26 +4,27 @@ import ( "context" "io" "log/slog" + + "github.com/platforma-dev/platforma/log" ) type Logger struct { w io.Writer - sampler func(*Event) bool + sampler Sampler logger *slog.Logger } +func NewWideEventLogger(w io.Writer, s Sampler, loggerType string, contextKeys map[string]any) *Logger { + return &Logger{ + sampler: s, + logger: log.New(w, loggerType, slog.LevelDebug, contextKeys), + } +} + func (l *Logger) WriteEvent(ctx context.Context, e *Event) { e.Finish() - if l.sampler(e) { + if l.sampler.ShouldSample(ctx, e) { l.logger.LogAttrs(ctx, e.level, "", e.ToAttrs()...) } } - -func mapToAttrs(data map[string]any) []slog.Attr { - attrs := make([]slog.Attr, 0, len(data)) - for k, v := range data { - attrs = append(attrs, slog.Any(k, v)) - } - return attrs -} diff --git a/log3/sampler.go b/log3/sampler.go new file mode 100644 index 0000000..9779e42 --- /dev/null +++ b/log3/sampler.go @@ -0,0 +1,57 @@ +package log3 + +import ( + "context" + "math/rand/v2" + "time" +) + +type Sampler interface { + ShouldSample(ctx context.Context, e *Event) bool +} + +type SamplerFunc func(ctx context.Context, e *Event) bool + +func (f SamplerFunc) ShouldSample(ctx context.Context, e *Event) bool { + return f(ctx, e) +} + +type DefaultSampler struct { + slowThreshold time.Duration + keepHttpStatusAtLeast int + randomKeepRate float64 +} + +func NewDefaultSampler() *DefaultSampler { + return &DefaultSampler{} +} + +func (s *DefaultSampler) ShouldSample(ctx context.Context, e *Event) bool { + if len(e.errors) > 0 { + return true + } + + if e.duration >= s.slowThreshold { + return true + } + + httpStatus := 0 + statusFromMap, exists := e.attrs["request.status"] + if exists { + success := false + httpStatus, success = statusFromMap.(int) + if !success { + httpStatus = 0 + } + } + + if httpStatus >= s.keepHttpStatusAtLeast { + return true + } + + if s.randomKeepRate <= rand.Float64() { + return true + } + + return false +} From aae72ee6838093cf737dade5a7e53f50165bbbc2 Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Mon, 16 Feb 2026 07:25:17 +0300 Subject: [PATCH 10/13] Delete log2.mdx --- docs/src/content/docs/packages/log2.mdx | 195 ------------------------ 1 file changed, 195 deletions(-) delete mode 100644 docs/src/content/docs/packages/log2.mdx diff --git a/docs/src/content/docs/packages/log2.mdx b/docs/src/content/docs/packages/log2.mdx deleted file mode 100644 index 37cc730..0000000 --- a/docs/src/content/docs/packages/log2.mdx +++ /dev/null @@ -1,195 +0,0 @@ ---- -title: log2 ---- -import { Steps } from '@astrojs/starlight/components'; - -The `log2` package provides wide-event logging with tail sampling, so each operation emits one structured event enriched with timeline steps, errors, and request context. - -Core Components: - -- `Config`: Logger configuration (`Writer`, `Format`, `Level`, `ContextKeys`, `Sampler`, `MaxSteps`). -- `DefaultConfig`: Returns defaults for output format, level, max steps, and sampler settings. -- `Logger`: Wide-event logger instance. -- `New`: Creates a logger from `Config`. -- `SetDefault`: Replaces package-level default logger. -- `Start`: Starts an event (`log2.Start` and `(*Logger).Start`). -- `Event`: Mutable event object. -- `Event.Add`, `Event.Step`, `Event.Error`, `Event.Finish`: Event lifecycle methods. -- `TailSampler`: Sampling interface. -- `SamplingDecision`: Keep/drop decision with reason. -- `EventView`: Immutable event view for sampling. -- `DefaultTailSamplerConfig`: Config for default sampler. -- `KeepRule`: Rule definition for forced-keep sampling. -- `NewDefaultTailSampler`: Builds default rule-based sampler. -- `HTTPMiddlewareConfig`, `NewHTTPMiddleware`: HTTP middleware that creates one event per request. -- `WithEvent`, `EventFromContext`, `LogEventContextKey`: Context helpers. -- `ErrEventAlreadyFinished`: Returned when `Finish` is called more than once. - -[Full package docs at pkg.go.dev](https://pkg.go.dev/github.com/platforma-dev/platforma/log2) - -## Step-by-step guide - - - -1. Create a logger - - ```go - cfg := log2.DefaultConfig() - cfg.Level = slog.LevelInfo - logger := log2.New(cfg) - log2.SetDefault(logger) - ``` - - `DefaultConfig` includes: - - - `Format: "json"` - - Default tail sampler (keep errors, 5xx, slow events, and a random sample) - - `MaxSteps: 100` - -2. Start and enrich an event - - ```go - ev := logger.Start(ctx, "auth_request", "component", "handler") - ev.Add("userId", "u-123") - ev.Step(slog.LevelInfo, "credentials_validated", "provider", "password") - ``` - - `Add` merges persistent attributes. `Step` appends timeline entries. - -3. Record errors and finish - - ```go - if err != nil { - ev.Error(err, "stage", "db_lookup") - } - - if finishErr := ev.Finish("status", 200); finishErr != nil { - if errors.Is(finishErr, log2.ErrEventAlreadyFinished) { - // finish was called twice - } - } - ``` - - `Finish` evaluates sampling using event status, duration, errors, and attributes. - -4. Configure custom tail sampling rules - - ```go - cfg := log2.DefaultConfig() - cfg.Sampler = log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ - KeepRules: []log2.KeepRule{ - {Field: "attrs.feature", Op: "eq", Value: "change_password"}, - {Field: "queue", Op: "in", Value: []string{"billing", "emails"}}, - {Field: "vip", Op: "exists"}, - {Field: "security.risk", Op: "true"}, - }, - RandomKeepRate: 0.01, - }) - logger := log2.New(cfg) - ``` - - Supported rule operators are `eq`, `in`, `exists`, and `true`. - -5. Add HTTP middleware and use event from request context - - ```go - logger := log2.New(log2.DefaultConfig()) - middleware := log2.NewHTTPMiddleware(logger, log2.HTTPMiddlewareConfig{ - EventName: "http_request", - RouteAttr: "route", - }) - - mux := http.NewServeMux() - mux.HandleFunc("/ping", func(w http.ResponseWriter, r *http.Request) { - if ev, ok := log2.EventFromContext(r.Context()); ok { - ev.Step(slog.LevelInfo, "handler_started", "path", r.URL.Path) - } - - w.WriteHeader(http.StatusOK) - _, _ = w.Write([]byte("pong")) - }) - - handler := middleware(mux) - _ = handler - ``` - - Middleware stores the event in context using `WithEvent`, collects request/response metadata, and calls `Finish` automatically. - - - -## Behavior notes - -- `Finish` called twice returns `ErrEventAlreadyFinished`. -- Event log level is inferred: - - `ERROR` for event errors or 5xx status. - - `WARN` for 4xx status. - - `INFO` otherwise. -- Status is inferred from `status`, `statusCode`, `response.status`, or `response.status` inside a `response` map. -- If steps exceed `MaxSteps`, extra steps are dropped and counted in `stepsDropped`. - -## Integration with `log` context keys - -`log2.Start` extracts known context values from the `log` package and includes them in event attributes when present: - -- `traceId` -- `serviceName` -- `domainName` -- `startupTask` -- `userId` -- `workerId` - -This allows `log2` events to align with existing `log` and `httpserver` context propagation. - -## Complete example - -```go -package main - -import ( - "context" - "errors" - "log/slog" - "net/http" - "os" - "time" - - "github.com/platforma-dev/platforma/log2" -) - -func main() { - cfg := log2.DefaultConfig() - cfg.Writer = os.Stdout - cfg.Level = slog.LevelInfo - cfg.Sampler = log2.NewDefaultTailSampler(log2.DefaultTailSamplerConfig{ - SlowThreshold: 500 * time.Millisecond, - RandomKeepRate: 0.02, - }) - - logger := log2.New(cfg) - middleware := log2.NewHTTPMiddleware(logger, log2.HTTPMiddlewareConfig{}) - - mux := http.NewServeMux() - mux.HandleFunc("/users", func(w http.ResponseWriter, r *http.Request) { - ev, ok := log2.EventFromContext(r.Context()) - if ok { - ev.Step(slog.LevelInfo, "fetch_users_started") - defer func() { - if err := ev.Finish("status", http.StatusOK); err != nil && !errors.Is(err, log2.ErrEventAlreadyFinished) { - // Handle finish error. - } - }() - } - - w.WriteHeader(http.StatusOK) - _, _ = w.Write([]byte(`{"users":[]}`)) - }) - - server := &http.Server{ - Addr: ":8080", - Handler: middleware(mux), - } - - _ = server.ListenAndServe() - _ = server.Shutdown(context.Background()) -} -``` From 0192a5f46353d584fddd32e127deb99573300300 Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Mon, 16 Feb 2026 08:24:35 +0300 Subject: [PATCH 11/13] demo --- demo-app/cmd/wide-events/main.go | 31 +++++++++++++++++++++++++ log3/event.go | 40 +++++++++++++++++++++----------- log3/sampler.go | 8 +++++-- 3 files changed, 63 insertions(+), 16 deletions(-) create mode 100644 demo-app/cmd/wide-events/main.go diff --git a/demo-app/cmd/wide-events/main.go b/demo-app/cmd/wide-events/main.go new file mode 100644 index 0000000..932a7ee --- /dev/null +++ b/demo-app/cmd/wide-events/main.go @@ -0,0 +1,31 @@ +package main + +import ( + "context" + "errors" + "log/slog" + "os" + "time" + + "github.com/platforma-dev/platforma/log3" +) + +func main() { + logger := log3.NewWideEventLogger( + os.Stdout, + log3.NewDefaultSampler(3*time.Second, 200, 0.1), + "text", + nil, + ) + + ev := log3.NewEvent("test_event") + + ev.AddStep(slog.LevelInfo, "some step") + ev.AddError(errors.New("some error")) + ev.AddAttrs(map[string]any{ + "attr1": 1, + "attr2": true, + }) + + logger.WriteEvent(context.Background(), ev) +} diff --git a/log3/event.go b/log3/event.go index 8e31e87..1519218 100644 --- a/log3/event.go +++ b/log3/event.go @@ -19,8 +19,9 @@ type Event struct { errors []errorRecord } -func NewEvent() *Event { +func NewEvent(name string) *Event { return &Event{ + name: name, timestamp: time.Now(), level: slog.LevelDebug, attrs: map[string]any{}, @@ -31,6 +32,10 @@ func (e *Event) SetLevel(level slog.Level) { e.mu.Lock() defer e.mu.Unlock() + e.setLevelNoLock(level) +} + +func (e *Event) setLevelNoLock(level slog.Level) { if level > e.level { e.level = level } @@ -47,12 +52,12 @@ func (e *Event) AddStep(level slog.Level, name string) { e.mu.Lock() defer e.mu.Unlock() - e.SetLevel(level) + e.setLevelNoLock(level) e.steps = append(e.steps, stepRecord{ - timestamp: time.Now(), - level: level, - name: name, + Timestamp: time.Now(), + Level: level, + Name: name, }) } @@ -60,11 +65,11 @@ func (e *Event) AddError(err error) { e.mu.Lock() defer e.mu.Unlock() - e.SetLevel(slog.LevelError) + e.setLevelNoLock(slog.LevelError) e.errors = append(e.errors, errorRecord{ - timestamp: time.Now(), - err: err, + Timestamp: time.Now(), + Error: err.Error(), }) } @@ -84,7 +89,6 @@ func (e *Event) ToAttrs() []slog.Attr { return []slog.Attr{ slog.String("name", e.name), slog.Time("timestamp", e.timestamp), - slog.Int("level", int(e.level)), slog.Duration("duration", e.duration), slog.Any("attrs", e.attrs), slog.Any("steps", e.steps), @@ -93,12 +97,20 @@ func (e *Event) ToAttrs() []slog.Attr { } type stepRecord struct { - timestamp time.Time - level slog.Level - name string + Timestamp time.Time `json:"timestamp"` + Level slog.Level `json:"level"` + Name string `json:"name"` +} + +func (r stepRecord) LogValue() slog.Value { + return slog.GroupValue( + slog.Time("timestamp", r.Timestamp), + slog.String("name", r.Name), + slog.String("level", r.Level.String()), + ) } type errorRecord struct { - timestamp time.Time - err error + Timestamp time.Time `json:"timestamp"` + Error string `json:"error"` } diff --git a/log3/sampler.go b/log3/sampler.go index 9779e42..61518c7 100644 --- a/log3/sampler.go +++ b/log3/sampler.go @@ -22,8 +22,12 @@ type DefaultSampler struct { randomKeepRate float64 } -func NewDefaultSampler() *DefaultSampler { - return &DefaultSampler{} +func NewDefaultSampler(slowThreshold time.Duration, keepHttpStatusAtLeast int, randomKeepRate float64) *DefaultSampler { + return &DefaultSampler{ + slowThreshold: slowThreshold, + keepHttpStatusAtLeast: keepHttpStatusAtLeast, + randomKeepRate: randomKeepRate, + } } func (s *DefaultSampler) ShouldSample(ctx context.Context, e *Event) bool { From 8bb29621ad0b70d0716ca29de99c393d0b13a599 Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Mon, 16 Feb 2026 08:30:45 +0300 Subject: [PATCH 12/13] Update astro.config.mjs --- docs/astro.config.mjs | 1 - 1 file changed, 1 deletion(-) diff --git a/docs/astro.config.mjs b/docs/astro.config.mjs index 6d34fe8..811882f 100644 --- a/docs/astro.config.mjs +++ b/docs/astro.config.mjs @@ -28,7 +28,6 @@ export default defineConfig({ "packages/database", "packages/httpserver", "packages/log", - "packages/log2", "packages/queue", "packages/scheduler", "packages/auth", From 233777170c8b2328bd068b08142c6f5f4f2fced8 Mon Sep 17 00:00:00 2001 From: Denis Mishankov Date: Mon, 16 Feb 2026 08:31:11 +0300 Subject: [PATCH 13/13] better case from log attrs --- demo-app/cmd/wide-events/main.go | 2 +- log3/event.go | 19 +++++++++++++++++-- 2 files changed, 18 insertions(+), 3 deletions(-) diff --git a/demo-app/cmd/wide-events/main.go b/demo-app/cmd/wide-events/main.go index 932a7ee..5d802bd 100644 --- a/demo-app/cmd/wide-events/main.go +++ b/demo-app/cmd/wide-events/main.go @@ -14,7 +14,7 @@ func main() { logger := log3.NewWideEventLogger( os.Stdout, log3.NewDefaultSampler(3*time.Second, 200, 0.1), - "text", + "json", nil, ) diff --git a/log3/event.go b/log3/event.go index 1519218..e2da8ba 100644 --- a/log3/event.go +++ b/log3/event.go @@ -85,14 +85,29 @@ func (e *Event) ToAttrs() []slog.Attr { defer e.mu.Unlock() e.duration = time.Since(e.timestamp) + steps := make([]map[string]any, 0, len(e.steps)) + for _, step := range e.steps { + steps = append(steps, map[string]any{ + "timestamp": step.Timestamp, + "level": step.Level.String(), + "name": step.Name, + }) + } + eventErrors := make([]map[string]any, 0, len(e.errors)) + for _, eventError := range e.errors { + eventErrors = append(eventErrors, map[string]any{ + "timestamp": eventError.Timestamp, + "error": eventError.Error, + }) + } return []slog.Attr{ slog.String("name", e.name), slog.Time("timestamp", e.timestamp), slog.Duration("duration", e.duration), slog.Any("attrs", e.attrs), - slog.Any("steps", e.steps), - slog.Any("errors", e.errors), + slog.Any("steps", steps), + slog.Any("errors", eventErrors), } }