diff options
Diffstat (limited to 'logging')
-rw-r--r-- | logging/http/http.go | 134 | ||||
-rw-r--r-- | logging/http/http_test.go | 113 | ||||
-rw-r--r-- | logging/log.go | 136 | ||||
-rw-r--r-- | logging/log_test.go | 141 | ||||
-rw-r--r-- | logging/test/handler.go | 112 |
5 files changed, 636 insertions, 0 deletions
diff --git a/logging/http/http.go b/logging/http/http.go new file mode 100644 index 0000000..b88ae3a --- /dev/null +++ b/logging/http/http.go @@ -0,0 +1,134 @@ +// Package http provides HTTP middleware and utilities, including request logging using slog. +// +// The LoggingHandler middleware logs HTTP request details, response status, bytes written, +// and handles panics gracefully with stack trace logging. + +package http + +import ( + "bufio" + "log/slog" + "net" + "net/http" + "time" + + "go.sudomsg.com/kit/logging" +) + +type tracingWriter struct { + http.ResponseWriter + StatusCode int + BytesWritten int + Hijacked bool +} + +var ( + _ http.ResponseWriter = &tracingWriter{} + _ http.Flusher = &tracingWriter{} + _ http.Hijacker = &tracingWriter{} + _ interface{ Unwrap() http.ResponseWriter } = &tracingWriter{} +) + +func (tw *tracingWriter) WriteHeader(code int) { + tw.ResponseWriter.WriteHeader(code) + tw.StatusCode = code +} + +func (tw *tracingWriter) Write(b []byte) (int, error) { + if tw.StatusCode == 0 { + tw.WriteHeader(http.StatusOK) + } + n, err := tw.ResponseWriter.Write(b) + tw.BytesWritten += n + return n, err +} + +func (tw *tracingWriter) Flush() { + rc := http.NewResponseController(tw.ResponseWriter) + _ = rc.Flush() +} + +func (tw *tracingWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) { + rc := http.NewResponseController(tw.ResponseWriter) + conn, rw, err := rc.Hijack() + if err == nil { + tw.Hijacked = true + } + return conn, rw, err +} + +func (tw *tracingWriter) Unwrap() http.ResponseWriter { + return tw.ResponseWriter +} + +// LoggingHandler is an HTTP middleware that logs requests and responses using slog. +// +// It recovers panics during request processing, logs them with stack traces, +// and returns a 500 Internal Server Error if the connection is not hijacked. +type LoggingHandler struct { + next http.Handler + logger *slog.Logger +} + +var _ http.Handler = &LoggingHandler{} + +// New creates a new LoggingHandler wrapping the next http.Handler, using the provided slog.Logger. +// +// If logger is nil, it attempts to obtain one from the request context. +func New(next http.Handler, logger *slog.Logger) *LoggingHandler { + return &LoggingHandler{ + next: next, + logger: logger, + } +} + +// ServeHTTP implements the http.Handler interface. +// +// It logs the HTTP method, path, client IP, protocol, host, user-agent, referer, +// request latency, response status, and bytes written. +// It also recovers panics, logs them, and returns HTTP 500 if appropriate. +func (h *LoggingHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { + ctx := r.Context() + + logger := h.logger + if logger == nil { + logger = logging.FromContext(ctx) + } + + logger = logger.With( + slog.String("method", r.Method), + slog.String("path", r.URL.RequestURI()), + slog.String("ip", r.RemoteAddr), + ) + ctx = logging.WithLogger(ctx, logger) + r = r.WithContext(ctx) + + tw := &tracingWriter{ResponseWriter: w} + + defer func() { + if err := recover(); err != nil { + logging.RecoverAndLog(ctx, "http panic", err) + if !tw.Hijacked && tw.StatusCode == 0 { + http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) + } + } + }() + + start := time.Now() + + h.next.ServeHTTP(tw, r) + + if !tw.Hijacked { + latency := time.Since(start) + + logger.LogAttrs(r.Context(), slog.LevelInfo, "HTTP request Handled", + slog.String("proto", r.Proto), + slog.String("host", r.Host), + slog.String("user-agent", r.UserAgent()), + slog.String("referer", r.Referer()), + slog.Duration("latency", latency), + slog.Int("status", tw.StatusCode), + slog.Int("bytes", tw.BytesWritten), + ) + } +} diff --git a/logging/http/http_test.go b/logging/http/http_test.go new file mode 100644 index 0000000..26e5974 --- /dev/null +++ b/logging/http/http_test.go @@ -0,0 +1,113 @@ +package http_test + +import ( + "log/slog" + "net/http" + "net/http/httptest" + "net/url" + "testing" + + httpHandler "go.sudomsg.com/kit/logging/http" + "go.sudomsg.com/kit/logging/test" +) + +func TestNew(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + method string + url string + status int + handler http.HandlerFunc + }{ + { + name: "No Status", + method: http.MethodGet, + url: "http://example.com/", + status: http.StatusOK, + handler: func(w http.ResponseWriter, r *http.Request) { + w.Write([]byte{}) + }, + }, + { + name: "NotFound", + method: http.MethodGet, + url: "http://example.com/", + status: http.StatusNotFound, + handler: http.NotFound, + }, + { + name: "Query", + method: http.MethodGet, + url: "http://example.com/a?b", + status: http.StatusNotFound, + handler: http.NotFound, + }, + { + name: "Flush", + method: http.MethodGet, + url: "http://example.com/", + status: http.StatusOK, + handler: func(w http.ResponseWriter, r *http.Request) { + rc := http.NewResponseController(w) + w.Write([]byte{}) + rc.Flush() + }, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + log := test.NewMockLogHandler(t) + + logger := slog.New(log) + + handler := httpHandler.New(tt.handler, logger) + + r := httptest.NewRequest(tt.method, tt.url, nil) + w := httptest.NewRecorder() + + handler.ServeHTTP(w, r) + + records := log.Records() + + if len(records) != 1 { + t.Fatalf("expected 1 log record, got %d", len(records)) + } + + record := records[0] + + attrs := map[string]slog.Value{} + record.Attrs(func(a slog.Attr) bool { + attrs[a.Key] = a.Value + return true + }) + + method := attrs["method"] + if got := method.String(); got != tt.method { + t.Fatalf("expected %v log record, got %v", tt.method, got) + } + status := attrs["status"] + if got := int(status.Int64()); got != tt.status { + t.Fatalf("expected %v log record, got %v", tt.status, got) + } + + url, err := url.Parse(tt.url) + if err != nil { + t.Fatalf("Unexpected error: %v", err) + } + + host := attrs["host"] + if got := host.String(); got != url.Host { + t.Fatalf("expected %v log record, got %v", url.Host, got) + } + path := attrs["path"] + if got := path.String(); got != url.RequestURI() { + t.Fatalf("expected %v log record, got %v", url.RequestURI(), got) + } + }) + } +} diff --git a/logging/log.go b/logging/log.go new file mode 100644 index 0000000..8dc8017 --- /dev/null +++ b/logging/log.go @@ -0,0 +1,136 @@ +// Package logging provides helpers for context-aware logging using Go's slog package. +// +// It allows attaching loggers to context.Context for structured logging, +// recovering and logging panics with stack traces, +// and provides a simple package-level logger setup function. +package logging + +import ( + "context" + "fmt" + "io" + "log/slog" + "os" + "runtime" + "strings" +) + +type ctxLoggerKeyType struct{} + +var ctxLoggerKey = ctxLoggerKeyType{} + +// WithLogger returns a new context derived from ctx that carries the provided slog.Logger. +// +// Typical usage: +// +// ctx = logging.WithLogger(ctx, logger) +func WithLogger(ctx context.Context, logger *slog.Logger) context.Context { + return context.WithValue(ctx, ctxLoggerKey, logger) +} + +// FromContext retrieves the slog.Logger stored in ctx if any. +// If no logger is attached to the context, returns slog.Default(). +func FromContext(ctx context.Context) *slog.Logger { + if logger, ok := ctx.Value(ctxLoggerKey).(*slog.Logger); ok { + return logger + } + return slog.Default() +} + +// With returns a new slog.Logger augmented with the passed key-value pairs, +// and a new context holding this logger. +// +// Typical usage: +// +// logger, ctx := logging.With(ctx, "user_id", userID) +func With(ctx context.Context, args ...any) (*slog.Logger, context.Context) { + logger := FromContext(ctx) + logger = logger.With(args...) + ctx = WithLogger(ctx, logger) + return logger, ctx +} + +// WithGroup returns a new slog.Logger grouped under name, +// and a new context holding this logger. +// +// Typical usage: +// +// logger, ctx := logging.WithGroup(ctx, "http") +func WithGroup(ctx context.Context, name string) (*slog.Logger, context.Context) { + logger := FromContext(ctx) + logger = logger.WithGroup(name) + ctx = WithLogger(ctx, logger) + return logger, ctx +} + +// RecoverAndLog logs a recovered panic or error with a stack trace using the logger from ctx. +// +// Typically used in a deferred recover block: +// +// defer func() { +// if err := recover(); err != nil { +// logging.RecoverAndLog(ctx, "Panic recovered", err) +// os.Exit(1) +// } +// }() +func RecoverAndLog(ctx context.Context, msg string, err any) { + const size = 64 << 10 // 64 KB stack trace buffer + buf := make([]byte, size) + buf = buf[:runtime.Stack(buf, false)] + logger := FromContext(ctx) + logger.ErrorContext(ctx, msg, "Error", err, "stack", string(buf)) +} + +type LogSink string + +const ( + SinkStdout LogSink = "stdout" + SinkStderr LogSink = "stderr" + SinkFile LogSink = "file" +) + +type LogConfig struct { + Level slog.Level `toml:"level"` + Sink LogSink `toml:"sink"` + Format string `toml:"format"` + File string `toml:"file"` +} + +func Setup(cfg LogConfig) error { + var w io.Writer + + switch cfg.Sink { + case SinkStdout, "": + w = os.Stdout + case SinkStderr: + w = os.Stderr + case SinkFile: + if cfg.File == "" { + return fmt.Errorf("log sink set to 'file' but no file path provided") + } + f, err := os.OpenFile(cfg.File, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) + if err != nil { + return fmt.Errorf("failed to open log file: %w", err) + } + w = f + default: + return fmt.Errorf("unsupported log sink: %s", cfg.Sink) + } + + var handler slog.Handler + opts := &slog.HandlerOptions{ + Level: cfg.Level, + } + + switch strings.ToLower(cfg.Format) { + case "text": + handler = slog.NewTextHandler(w, opts) + case "json", "": + handler = slog.NewJSONHandler(w, opts) + default: + return fmt.Errorf("unsupported log format: %s", cfg.Format) + } + + slog.SetDefault(slog.New(handler)) + return nil +} diff --git a/logging/log_test.go b/logging/log_test.go new file mode 100644 index 0000000..93ceaf6 --- /dev/null +++ b/logging/log_test.go @@ -0,0 +1,141 @@ +package logging_test + +import ( + "errors" + "log/slog" + "testing" + + "go.sudomsg.com/kit/logging" + "go.sudomsg.com/kit/logging/test" +) + +func TestWithLogger_And_FromContext(t *testing.T) { + ctx := t.Context() + mock := test.NewMockLogHandler(t) + logger := slog.New(mock) + + ctx = logging.WithLogger(ctx, logger) + + got := logging.FromContext(ctx) + if got != logger { + t.Errorf("expected logger from context to match original logger") + } +} + +func TestFromContext_DefaultFallback(t *testing.T) { + ctx := t.Context() + got := logging.FromContext(ctx) + + if got != slog.Default() { + t.Errorf("expected default logger when no logger is in context") + } +} + +func TestRecoverAndLog(t *testing.T) { + ctx := t.Context() + mock := test.NewMockLogHandler(t) + + logger := slog.New(mock) + ctx = logging.WithLogger(ctx, logger) + + err := errors.New("something broke") + logging.RecoverAndLog(ctx, "panic recovered", err) + + records := mock.Records() + if len(records) != 1 { + t.Fatalf("expected 1 log record, got %d", len(records)) + } + + record := records[0] + if record.Message != "panic recovered" { + t.Errorf("expected message 'panic recAvered', got %q", record.Message) + } + + foundStack := false + record.Attrs(func(a slog.Attr) bool { + if a.Key == "stack" { + foundStack = true + } + return true + }) + + if !foundStack { + t.Errorf("expected 'stack' attribute in log") + } +} + +func TestWith(t *testing.T) { + ctx := t.Context() + + mock := test.NewMockLogHandler(t) + + logger := slog.New(mock) + ctx = logging.WithLogger(ctx, logger) + + user := "user" + id := "1234" + + logger2, newCtx := logging.With(ctx, "user", user, "id", id) + logger2.InfoContext(ctx, "test message") + + records := mock.Records() + if len(records) != 1 { + t.Fatalf("expected 1 record, got %d", len(records)) + } + + record := records[0] + foundUser := false + foundID := false + + record.Attrs(func(attr slog.Attr) bool { + switch attr.Key { + case "user": + foundUser = attr.Value.String() == user + case "id": + foundID = attr.Value.String() == id + } + return true + }) + + if !foundUser || !foundID { + t.Errorf("expected 'user' and 'id' attributes in log record, %v", records) + } + + // Test context carries logger with same attributes + logFromCtx := logging.FromContext(newCtx) + logFromCtx.InfoContext(ctx, "second message") + + if len(mock.Records()) != 2 { + t.Errorf("expected 2 log records, got %d", len(mock.Records())) + } +} + +func TestWithGroup(t *testing.T) { + ctx := t.Context() + + mock := test.NewMockLogHandler(t) + + logger := slog.New(mock) + ctx = logging.WithLogger(ctx, logger) + + logger2, _ := logging.WithGroup(ctx, "foo") + logger2.InfoContext(ctx, "test message", "key", "value") + + records := mock.Records() + if len(records) != 1 { + t.Fatalf("expected 1 record, got %d", len(records)) + } + + record := records[0] + var foundGroup bool + + record.Attrs(func(attr slog.Attr) bool { + foundGroup = attr.Value.Kind() == slog.KindGroup + + return false + }) + + if !foundGroup { + t.Errorf("expected 'user' and 'id' attributes in log record, %v", records) + } +} diff --git a/logging/test/handler.go b/logging/test/handler.go new file mode 100644 index 0000000..d1f5d40 --- /dev/null +++ b/logging/test/handler.go @@ -0,0 +1,112 @@ +package test + +// Package test provides mocks and helpers for testing code that uses slog logging. +// +// It includes MockHandler, a thread-safe slog.Handler implementation for capturing log records in tests. + +import ( + "context" + "log/slog" + "slices" + "sync" + "testing" +) + +type logRecorder struct { + mu sync.Mutex + records []slog.Record +} + +func (h *logRecorder) Append(r slog.Record) { + h.mu.Lock() + defer h.mu.Unlock() + + h.records = append(h.records, r.Clone()) +} + +func (h *logRecorder) Records() []slog.Record { + h.mu.Lock() + defer h.mu.Unlock() + return slices.Clone(h.records) +} + +// MockHandler is a slog.Handler that records log records for testing. +// +// It supports attribute and group chaining like slog's built-in handlers. +// Use NewMockLogHandler to construct one, then pass it to slog.New in your tests. +// +// All recorded logs can be retrieved with the Records method. +type MockHandler struct { + recorder *logRecorder + parent *MockHandler + group string + attrs []slog.Attr +} + +var _ slog.Handler = &MockHandler{} + +// NewMockLogHandler creates a new MockHandler for use in tests. +func NewMockLogHandler(tb testing.TB) *MockHandler { + tb.Helper() + + return &MockHandler{ + recorder: &logRecorder{}, + } +} + +func (h *MockHandler) Enabled(ctx context.Context, level slog.Level) bool { + return true // Capture all logs +} + +func (h *MockHandler) Handle(ctx context.Context, r slog.Record) error { + if h.parent == nil { + r.Clone() + h.recorder.Append(r) + return nil + } + + newRecord := slog.NewRecord(r.Time, r.Level, r.Message, r.PC) + + attrs := slices.Clone(h.attrs) + r.Attrs(func(attr slog.Attr) bool { + attrs = append(attrs, attr) + return true + }) + + if h.group != "" { + newRecord.AddAttrs(slog.Attr{ + Key: h.group, + Value: slog.GroupValue(attrs...), + }) + } else { + newRecord.AddAttrs(attrs...) + } + + return h.parent.Handle(ctx, newRecord) +} + +func (h *MockHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &MockHandler{ + recorder: h.recorder, + parent: h, + attrs: attrs, + } +} + +func (h *MockHandler) WithGroup(name string) slog.Handler { + if name == "" { + return h + } + return &MockHandler{ + recorder: h.recorder, + parent: h, + group: name, + } +} + +// Records returns a copy of all slog.Records captured by this handler so far. +// +// It is safe to call from multiple goroutines. +func (h *MockHandler) Records() []slog.Record { + return h.recorder.Records() +} |