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 diff --git a/.golangci.yml b/.golangci.yml index c5e8103..06f083b 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -63,6 +63,7 @@ linters: case: rules: json: camel + exclusions: paths: - demo-app @@ -72,6 +73,11 @@ linters: linters: - revive + - path: log/.*\.go + text: "var-naming: avoid package names that conflict with Go standard library package names" + linters: + - revive + - path: _test\.go linters: - dupl 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/demo-app/cmd/api/main.go b/demo-app/cmd/api/main.go index 7fc3432..c17208f 100644 --- a/demo-app/cmd/api/main.go +++ b/demo-app/cmd/api/main.go @@ -31,7 +31,7 @@ func main() { }) // Add middleware to HTTP server. It will add trace ID to logs and responce headers - api.Use(httpserver.NewTraceIDMiddleware(nil, "")) + api.Use(log.NewTraceIDMiddleware(nil, "")) // Create handler group subApiGroup := httpserver.NewHandlerGroup() diff --git a/demo-app/cmd/auth/main.go b/demo-app/cmd/auth/main.go index a2d8c25..9215b10 100644 --- a/demo-app/cmd/auth/main.go +++ b/demo-app/cmd/auth/main.go @@ -31,7 +31,7 @@ func main() { app.RegisterDomain("auth", "main", authDomain) api := httpserver.New("8080", 3*time.Second) - api.Use(httpserver.NewTraceIDMiddleware(nil, "")) + api.Use(log.NewTraceIDMiddleware(nil, "")) api.Use(httpserver.NewRecoverMiddleware()) api.HandleGroup("/auth", authDomain.HandleGroup) diff --git a/demo-app/cmd/wide-events/main.go b/demo-app/cmd/wide-events/main.go new file mode 100644 index 0000000..b3701d9 --- /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/log" +) + +func main() { + logger := log.NewWideEventLogger( + os.Stdout, + log.NewDefaultSampler(3*time.Second, 200, 0.1), + "json", + nil, + ) + + ev := log.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/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", diff --git a/docs/src/content/docs/packages/log.mdx b/docs/src/content/docs/packages/log.mdx index 1b8df71..1547a6f 100644 --- a/docs/src/content/docs/packages/log.mdx +++ b/docs/src/content/docs/packages/log.mdx @@ -2,17 +2,21 @@ title: log --- import { LinkButton, Steps } from '@astrojs/starlight/components'; +import { Code } from '@astrojs/starlight/components'; +import importedCode from '../../../../../demo-app/cmd/wide-events/main.go?raw'; -The `log` package provides structured logging with automatic context value extraction for tracing and debugging. +The `log` package provides structured application logs, HTTP trace propagation, and request-wide event logging with tail sampling. Core Components: -- `Logger`: Default logger instance used by package-level logging functions. -- `New`: Creates a new `slog.Logger` with text or JSON output and custom context keys. -- `SetDefault`: Replaces the default logger used by package-level functions. -- `TraceIDKey`, `ServiceNameKey`, `WorkerIDKey`, etc.: Context keys automatically extracted into log output. -- `Debug`, `Info`, `Warn`, `Error`: Package-level logging functions. -- `DebugContext`, `InfoContext`, `WarnContext`, `ErrorContext`: Context-aware logging functions that extract trace IDs and other values. +- `Logger`, `SetDefault`, `Debug`/`Info`/`Warn`/`Error`: Package-level logging API built on top of `slog`. +- `New`: Builds a text or JSON logger that automatically extracts values like `traceId` and `serviceName` from `context.Context`. +- `TraceIDMiddleware`: Adds a per-request trace ID to context and response headers. +- `Event`: Mutable wide-event model with attrs, steps, errors, severity, and duration. +- `WideEventLogger`: Writes finalized `Event` values through a `Sampler`. +- `WideEventMiddleware`: Creates request-wide events, stores them in context, and emits them after handlers finish. +- `Sampler`, `SamplerFunc`, `DefaultSampler`: Tail-sampling rules for keeping errors, slow requests, selected status codes, and random samples. +- `EventFromContext`: Fetches the current request-wide event from context using `WideEventKey`. [Full package docs at pkg.go.dev](https://pkg.go.dev/github.com/platforma-dev/platforma/log) @@ -20,168 +24,93 @@ Core Components: -1. Use package-level logging functions +1. Configure default structured logging ```go - log.Info("server started", "port", 8080) - log.Error("failed to connect", "error", err) + logger := log.New(os.Stdout, "json", slog.LevelInfo, nil) + log.SetDefault(logger) ``` - These use the default logger which outputs text format at Info level. - - Expected output: - - ``` - time=2025-01-01T12:00:00.000+00:00 level=INFO msg="server started" port=8080 - ``` + This switches package-level logging to JSON and keeps context extraction enabled. -2. Use context-aware logging +2. Add trace IDs to each request ```go - ctx := context.WithValue(ctx, log.TraceIDKey, "abc-123") - log.InfoContext(ctx, "processing request", "path", "/users") + server := httpserver.New("8080", 3*time.Second) + server.Use(log.NewTraceIDMiddleware(nil, "")) ``` - Context values from known keys are automatically added to log output. - - Expected output: + With default arguments, the middleware stores IDs under `log.TraceIDKey` and writes `Platforma-Trace-Id` response headers. - ``` - time=2025-01-01T12:00:00.000+00:00 level=INFO msg="processing request" path=/users traceId=abc-123 - ``` - -3. Create a custom logger +3. Configure wide-event logging with sampling ```go - logger := log.New(os.Stdout, "json", slog.LevelDebug, nil) - logger.Info("message", "key", "value") + wideLogger := log.NewWideEventLogger( + os.Stdout, + log.NewDefaultSampler(2*time.Second, 500, 0.05), + "json", + nil, + ) + server.Use(log.NewWideEventMiddleware(wideLogger, "", nil)) ``` - The second argument is the format: `"text"` or `"json"`. The third is the minimum log level. + This keeps all error events, slow requests (>=2s), `5xx` responses, and 5% of the remaining traffic. - Expected JSON output: - - ```json - {"time":"2025-01-01T12:00:00.000+00:00","level":"INFO","msg":"message","key":"value"} - ``` - -4. Set a custom default logger +4. Enrich events and logs inside handlers ```go - logger := log.New(os.Stdout, "json", slog.LevelDebug, nil) - log.SetDefault(logger) + server.HandleFunc("/users", func(w http.ResponseWriter, r *http.Request) { + log.InfoContext(r.Context(), "users request started") - log.Info("now using JSON format") - ``` + if ev := log.EventFromContext(r.Context()); ev != nil { + ev.AddStep(slog.LevelInfo, "query users table") + ev.AddAttrs(map[string]any{"users.limit": 50}) + } - After calling `SetDefault`, all package-level functions use the new logger. + w.WriteHeader(http.StatusOK) + }) + ``` -5. Add custom context keys + `InfoContext` includes request metadata (for example `traceId`), and `EventFromContext` lets handlers attach detailed wide-event data. - ```go - type myKey string - const RequestIDKey myKey = "requestId" +5. Verify runtime output - customKeys := map[string]any{ - "requestId": RequestIDKey, - } - logger := log.New(os.Stdout, "text", slog.LevelInfo, customKeys) - log.SetDefault(logger) - - ctx := context.WithValue(ctx, RequestIDKey, "req-456") - log.InfoContext(ctx, "custom key extracted") + ```json + {"level":"INFO","msg":"users request started","traceId":"14b3..."} + {"level":"INFO","name":"http.request","duration":"12ms","request.status":200} ``` - Expected output: - - ``` - time=2025-01-01T12:00:00.000+00:00 level=INFO msg="custom key extracted" requestId=req-456 - ``` + The first line is an immediate log entry. The second line is the finalized request-wide event emitted after the response is completed. -## Built-in context keys - -The logger automatically extracts these context keys when using `*Context` functions: - -| Key | Description | -|-----|-------------| -| `TraceIDKey` | Request trace ID for distributed tracing | -| `ServiceNameKey` | Service identifier | -| `DomainNameKey` | Domain name for domain-based architectures | -| `StartupTaskKey` | Startup task name during application initialization | -| `UserIDKey` | Authenticated user ID | -| `WorkerIDKey` | Queue processor worker ID | - ## Using with Application -The `application` package and other Platforma components automatically set context keys like `ServiceNameKey` and `StartupTaskKey`. Use context-aware logging to include this information: +Integrate logging by registering an HTTP service and attaching `log` middlewares before `app.Run`: ```go app := application.New() -app.OnStart(application.StartupTask{ - Name: "init-cache", - Task: func(ctx context.Context, config any) error { - log.InfoContext(ctx, "initializing cache") - // startupTask=init-cache automatically added to output - return nil - }, -}, nil) - -app.Run(ctx) -``` - -With `httpserver.TraceIDMiddleware`, the trace ID is automatically available in request handlers: - -```go server := httpserver.New("8080", 3*time.Second) -server.Use(httpserver.NewTraceIDMiddleware(nil, "")) - -server.HandleFunc("/users", func(w http.ResponseWriter, r *http.Request) { - log.InfoContext(r.Context(), "handling request") - // traceId= automatically added to output -}) -``` +server.Use(log.NewTraceIDMiddleware(nil, "")) -## Complete example - -```go -package main - -import ( - "context" - "log/slog" - "net/http" - "os" - "time" - - "github.com/platforma-dev/platforma/application" - "github.com/platforma-dev/platforma/httpserver" - "github.com/platforma-dev/platforma/log" +wideLogger := log.NewWideEventLogger( + os.Stdout, + log.NewDefaultSampler(2*time.Second, 500, 0.05), + "json", + nil, ) +server.Use(log.NewWideEventMiddleware(wideLogger, "", nil)) -func main() { - ctx := context.Background() - - // Configure JSON logging at Debug level - logger := log.New(os.Stdout, "json", slog.LevelDebug, nil) - log.SetDefault(logger) - - app := application.New() - - server := httpserver.New("8080", 3*time.Second) - server.Use(httpserver.NewTraceIDMiddleware(nil, "")) +server.HandleFunc("/health", func(w http.ResponseWriter, r *http.Request) { + log.InfoContext(r.Context(), "health check") + w.WriteHeader(http.StatusOK) +}) - server.HandleFunc("/ping", func(w http.ResponseWriter, r *http.Request) { - log.InfoContext(r.Context(), "ping received") - w.Write([]byte("pong")) - }) +app.RegisterService("api", server) +app.Run(ctx) +``` - app.RegisterService("api", server) +## Complete example - if err := app.Run(ctx); err != nil { - log.ErrorContext(ctx, "app finished with error", "error", err) - } -} -``` + diff --git a/log/event.go b/log/event.go new file mode 100644 index 0000000..ac823ba --- /dev/null +++ b/log/event.go @@ -0,0 +1,219 @@ +package log + +import ( + "log/slog" + "maps" + "slices" + "sort" + "sync" + "time" +) + +// Event is a mutable wide event. +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 +} + +// NewEvent creates a new wide event. +func NewEvent(name string) *Event { + return &Event{ + name: name, + timestamp: time.Now(), + level: slog.LevelDebug, + attrs: map[string]any{}, + } +} + +// SetLevel sets event level if it is higher than the current one. +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 + } +} + +// AddAttrs adds attributes to event data. +func (e *Event) AddAttrs(attrs map[string]any) { + e.mu.Lock() + defer e.mu.Unlock() + + maps.Copy(e.attrs, attrs) +} + +// AddStep appends an event step and potentially escalates level. +func (e *Event) AddStep(level slog.Level, name string) { + e.mu.Lock() + defer e.mu.Unlock() + + e.setLevelNoLock(level) + + e.steps = append(e.steps, stepRecord{ + Timestamp: time.Now(), + Level: level, + Name: name, + }) +} + +// AddError appends an error and escalates event level to error. +func (e *Event) AddError(err error) { + if err == nil { + return + } + + e.mu.Lock() + defer e.mu.Unlock() + + e.setLevelNoLock(slog.LevelError) + + e.errors = append(e.errors, errorRecord{ + Timestamp: time.Now(), + Error: err.Error(), + }) +} + +// Finish stores current event duration. +func (e *Event) Finish() { + e.mu.Lock() + defer e.mu.Unlock() + + e.duration = time.Since(e.timestamp) +} + +// HasErrors returns true if the event has errors. +func (e *Event) HasErrors() bool { + e.mu.Lock() + defer e.mu.Unlock() + + return len(e.errors) > 0 +} + +// Duration returns the event duration. +func (e *Event) Duration() time.Duration { + e.mu.Lock() + defer e.mu.Unlock() + + return e.duration +} + +// Level returns the event level. +func (e *Event) Level() slog.Level { + e.mu.Lock() + defer e.mu.Unlock() + + return e.level +} + +// Name returns the event name. +func (e *Event) Name() string { + e.mu.Lock() + defer e.mu.Unlock() + + return e.name +} + +// Attr returns an event attribute by key. +func (e *Event) Attr(key string) (any, bool) { + e.mu.Lock() + defer e.mu.Unlock() + + value, ok := e.attrs[key] + + return value, ok +} + +// ToAttrs converts event to slog attributes. +func (e *Event) ToAttrs() []slog.Attr { + return e.toAttrs(nil) +} + +func (e *Event) toAttrs(additionalReservedAttrKeys []string) []slog.Attr { + e.mu.Lock() + defer e.mu.Unlock() + + 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, + }) + } + + builtinAttrKeys := wideEventBuiltinAttrKeys() + reservedAttrKeys := make([]string, 0, len(builtinAttrKeys)+len(additionalReservedAttrKeys)) + reservedAttrKeys = append(reservedAttrKeys, builtinAttrKeys...) + for _, key := range additionalReservedAttrKeys { + if slices.Contains(reservedAttrKeys, key) { + continue + } + reservedAttrKeys = append(reservedAttrKeys, key) + } + + attrs := make([]slog.Attr, 0, len(e.attrs)+len(builtinAttrKeys)) + attrs = append(attrs, + slog.String("name", e.name), + slog.Time("timestamp", e.timestamp), + slog.Duration("duration", e.duration), + slog.Any("steps", steps), + slog.Any("errors", eventErrors), + ) + + customAttrKeys := make([]string, 0, len(e.attrs)) + for key := range e.attrs { + if slices.Contains(reservedAttrKeys, key) { + continue + } + + customAttrKeys = append(customAttrKeys, key) + } + sort.Strings(customAttrKeys) + + for _, key := range customAttrKeys { + attrs = append(attrs, slog.Any(key, e.attrs[key])) + } + + return attrs +} + +type stepRecord struct { + Timestamp time.Time `json:"timestamp"` + Level slog.Level `json:"level"` + Name string `json:"name"` +} + +type errorRecord struct { + Timestamp time.Time `json:"timestamp"` + Error string `json:"error"` +} + +func wideEventBuiltinAttrKeys() []string { + return []string{ + "name", + "timestamp", + "duration", + "steps", + "errors", + } +} diff --git a/log/event_context.go b/log/event_context.go new file mode 100644 index 0000000..ebe0b6d --- /dev/null +++ b/log/event_context.go @@ -0,0 +1,18 @@ +package log + +import "context" + +const ( + // WideEventKey is the default context key for request-wide events. + WideEventKey contextKey = "wideEvent" +) + +// EventFromContext returns a wide event from context when present. +func EventFromContext(ctx context.Context) *Event { + event, ok := ctx.Value(WideEventKey).(*Event) + if !ok { + return nil + } + + return event +} diff --git a/log/sampler.go b/log/sampler.go new file mode 100644 index 0000000..2b1d03c --- /dev/null +++ b/log/sampler.go @@ -0,0 +1,67 @@ +package log + +import ( + "context" + "math/rand/v2" + "time" +) + +// Sampler decides whether a wide event should be emitted. +type Sampler interface { + ShouldSample(ctx context.Context, e *Event) bool +} + +// SamplerFunc is a function adapter for Sampler. +type SamplerFunc func(ctx context.Context, e *Event) bool + +// ShouldSample implements Sampler. +func (f SamplerFunc) ShouldSample(ctx context.Context, e *Event) bool { + return f(ctx, e) +} + +// DefaultSampler samples by error, duration, status code, and random keep rate. +type DefaultSampler struct { + slowThreshold time.Duration + keepHTTPStatusAtLeast int + randomKeepRate float64 +} + +// NewDefaultSampler creates a rule-based sampler. +func NewDefaultSampler(slowThreshold time.Duration, keepHTTPStatusAtLeast int, randomKeepRate float64) *DefaultSampler { + return &DefaultSampler{ + slowThreshold: slowThreshold, + keepHTTPStatusAtLeast: keepHTTPStatusAtLeast, + randomKeepRate: randomKeepRate, + } +} + +// ShouldSample decides if event should be logged. +func (s *DefaultSampler) ShouldSample(_ context.Context, e *Event) bool { + if e.HasErrors() { + return true + } + + if e.Duration() >= s.slowThreshold { + return true + } + + if e.Name() == "http.request" { + httpStatus := 0 + if statusFromMap, exists := e.Attr("request.status"); exists { + if status, ok := statusFromMap.(int); ok { + httpStatus = status + } + } + + if httpStatus >= s.keepHTTPStatusAtLeast { + return true + } + } + + //nolint:gosec // Non-cryptographic sampling is sufficient for log event retention. + if rand.Float64() < s.randomKeepRate { + return true + } + + return false +} diff --git a/httpserver/traceid.go b/log/traceid.go similarity index 71% rename from httpserver/traceid.go rename to log/traceid.go index ad1f744..24f08a6 100644 --- a/httpserver/traceid.go +++ b/log/traceid.go @@ -1,26 +1,24 @@ -package httpserver +package log import ( "context" "net/http" - "github.com/platforma-dev/platforma/log" - "github.com/google/uuid" ) -// TraceIDMiddleware is a middleware that adds a trace ID to the request context and response headers. +// TraceIDMiddleware adds a trace ID to request context and response headers. type TraceIDMiddleware struct { contextKey any header string } // NewTraceIDMiddleware returns a new TraceID middleware. -// If key is nil, log.TraceIdKey is used. +// If key is nil, TraceIDKey is used. // If header is empty, "Platforma-Trace-Id" is used. func NewTraceIDMiddleware(contextKey any, header string) *TraceIDMiddleware { if contextKey == nil { - contextKey = log.TraceIDKey + contextKey = TraceIDKey } if header == "" { @@ -30,7 +28,7 @@ func NewTraceIDMiddleware(contextKey any, header string) *TraceIDMiddleware { return &TraceIDMiddleware{contextKey: contextKey, header: header} } -// Wrap implements the Middleware interface by adding trace ID to requests. +// Wrap adds trace ID to requests. func (m *TraceIDMiddleware) Wrap(h http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { traceID := uuid.NewString() diff --git a/httpserver/traceid_test.go b/log/traceid_test.go similarity index 55% rename from httpserver/traceid_test.go rename to log/traceid_test.go index ed65bd6..29263ff 100644 --- a/httpserver/traceid_test.go +++ b/log/traceid_test.go @@ -1,27 +1,26 @@ -package httpserver_test +package log_test import ( "net/http" "net/http/httptest" "testing" - "github.com/platforma-dev/platforma/httpserver" - "github.com/platforma-dev/platforma/log" + platformalog "github.com/platforma-dev/platforma/log" ) -func TestTraceIdMiddleware(t *testing.T) { +func TestTraceIDMiddleware(t *testing.T) { t.Parallel() t.Run("default params", func(t *testing.T) { t.Parallel() - m := httpserver.NewTraceIDMiddleware(nil, "") - wrappedHandler := m.Wrap(&handler{serveHTTP: func(w http.ResponseWriter, r *http.Request) { - i, ok := r.Context().Value(log.TraceIDKey).(string) + m := platformalog.NewTraceIDMiddleware(nil, "") + wrappedHandler := m.Wrap(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + i, ok := r.Context().Value(platformalog.TraceIDKey).(string) if ok { w.Header().Add("TraceIdFromContext", i) } - }}) + })) r := httptest.NewRequest(http.MethodGet, "/", nil) w := httptest.NewRecorder() @@ -34,8 +33,7 @@ func TestTraceIdMiddleware(t *testing.T) { } if len(resp.Header.Get("TraceIdFromContext")) == 0 { - t.Fatalf("trsce id from cotext expected, got: %s", resp.Header) + t.Fatalf("trace id from context expected, got: %s", resp.Header) } - }) } diff --git a/log/wideevent_logger.go b/log/wideevent_logger.go new file mode 100644 index 0000000..476b667 --- /dev/null +++ b/log/wideevent_logger.go @@ -0,0 +1,74 @@ +package log + +import ( + "context" + "io" + "log/slog" + "slices" +) + +// WideEventLogger writes wide events with tail sampling. +type WideEventLogger struct { + sampler Sampler + logger *slog.Logger + reservedAttrKeys []string +} + +// NewWideEventLogger creates a wide-event logger. +func NewWideEventLogger(w io.Writer, s Sampler, loggerType string, contextKeys map[string]any) *WideEventLogger { + opts := &slog.HandlerOptions{ + Level: slog.LevelDebug, + ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { + if a.Key == slog.TimeKey || a.Key == slog.MessageKey { + return slog.Attr{} + } + return a + }, + } + + var handler slog.Handler + if loggerType == "json" { + handler = slog.NewJSONHandler(w, opts) + } else { + handler = slog.NewTextHandler(w, opts) + } + + return &WideEventLogger{ + sampler: s, + logger: slog.New(&contextHandler{handler, contextKeys}), + reservedAttrKeys: wideEventReservedAttrKeys(contextKeys), + } +} + +// WriteEvent finalizes event duration and conditionally writes it. +func (l *WideEventLogger) WriteEvent(ctx context.Context, e *Event) { + e.Finish() + + if l.sampler.ShouldSample(ctx, e) { + l.logger.LogAttrs(ctx, e.Level(), "", e.toAttrs(l.reservedAttrKeys)...) + } +} + +func wideEventReservedAttrKeys(contextKeys map[string]any) []string { + reservedAttrKeys := append([]string{}, wideEventBuiltinAttrKeys()...) + reservedAttrKeys = appendUnique(reservedAttrKeys, slog.LevelKey) + reservedAttrKeys = appendUnique(reservedAttrKeys, string(DomainNameKey)) + reservedAttrKeys = appendUnique(reservedAttrKeys, string(TraceIDKey)) + reservedAttrKeys = appendUnique(reservedAttrKeys, string(ServiceNameKey)) + reservedAttrKeys = appendUnique(reservedAttrKeys, string(StartupTaskKey)) + reservedAttrKeys = appendUnique(reservedAttrKeys, string(UserIDKey)) + reservedAttrKeys = appendUnique(reservedAttrKeys, string(WorkerIDKey)) + for key := range contextKeys { + reservedAttrKeys = appendUnique(reservedAttrKeys, key) + } + + return reservedAttrKeys +} + +func appendUnique(keys []string, key string) []string { + if slices.Contains(keys, key) { + return keys + } + + return append(keys, key) +} diff --git a/log/wideevent_middleware.go b/log/wideevent_middleware.go new file mode 100644 index 0000000..a45217d --- /dev/null +++ b/log/wideevent_middleware.go @@ -0,0 +1,103 @@ +package log + +import ( + "context" + "errors" + "fmt" + "net/http" +) + +const defaultWideEventName = "http.request" + +var errPanicRecovered = errors.New("panic recovered") + +// WideEventMiddleware creates and writes a request-wide event. +type WideEventMiddleware struct { + logger *WideEventLogger + eventName string + contextKey any +} + +// NewWideEventMiddleware creates middleware that stores a wide event in request context +// and writes it after request processing. +func NewWideEventMiddleware(logger *WideEventLogger, eventName string, contextKey any) *WideEventMiddleware { + if eventName == "" { + eventName = defaultWideEventName + } + + if contextKey == nil { + contextKey = WideEventKey + } + + return &WideEventMiddleware{ + logger: logger, + eventName: eventName, + contextKey: contextKey, + } +} + +// Wrap creates request-wide event, stores it in context and writes event after handling. +func (m *WideEventMiddleware) Wrap(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + event := NewEvent(m.eventName) + event.AddAttrs(map[string]any{ + "request.method": r.Method, + "request.path": r.URL.Path, + "request.remoteAddr": r.RemoteAddr, + }) + + ctx := context.WithValue(r.Context(), m.contextKey, event) + r = r.WithContext(ctx) + + recorder := &statusResponseWriter{ + ResponseWriter: w, + statusCode: http.StatusOK, + } + + defer func() { + recovered := recover() + if recovered != nil { + event.AddError(fmt.Errorf("%w: %v", errPanicRecovered, recovered)) + if !recorder.wroteHeader { + recorder.statusCode = http.StatusInternalServerError + } + } + + event.AddAttrs(map[string]any{ + "request.status": recorder.statusCode, + }) + m.logger.WriteEvent(ctx, event) + + if recovered != nil { + panic(recovered) + } + }() + + next.ServeHTTP(recorder, r) + }) +} + +type statusResponseWriter struct { + http.ResponseWriter + statusCode int + wroteHeader bool +} + +func (w *statusResponseWriter) WriteHeader(statusCode int) { + w.statusCode = statusCode + w.wroteHeader = true + w.ResponseWriter.WriteHeader(statusCode) +} + +func (w *statusResponseWriter) Write(p []byte) (int, error) { + if !w.wroteHeader { + w.WriteHeader(http.StatusOK) + } + + n, err := w.ResponseWriter.Write(p) + if err != nil { + return n, fmt.Errorf("write response body: %w", err) + } + + return n, nil +}