Big changes

2026-07-29 15:26:55 +12:00
parent 70914400b4
commit a265636139
73 changed files with 9593 additions and 0 deletions
@@ -0,0 +1,204 @@
+// Package logging configures the server's human-readable, structured log output.
+package logging
+
+import (
+	"context"
+	"io"
+	"log/slog"
+	"strconv"
+	"strings"
+	"sync"
+	"sync/atomic"
+	"time"
+)
+
+// ParseLevel returns a supported slog level, defaulting to INFO for empty or invalid
+// values. Keeping this forgiving prevents a typo in Docker configuration from stopping
+// the gateway.
+func ParseLevel(value string) slog.Level {
+	switch strings.ToUpper(strings.TrimSpace(value)) {
+	case "DEBUG":
+		return slog.LevelDebug
+	case "WARN", "WARNING":
+		return slog.LevelWarn
+	case "ERROR":
+		return slog.LevelError
+	default:
+		return slog.LevelInfo
+	}
+}
+
+// New returns a text logger suited to `docker compose logs`. Fields remain structured
+// key=value pairs, but each event is one compact line rather than a JSON object.
+func New(w io.Writer, level slog.Leveler) *slog.Logger {
+	logger, _ := NewBuffered(w, level, 0)
+	return logger
+}
+
+// Event is the browser-safe representation of one structured server log record.
+type Event struct {
+	Sequence   int64             `json:"sequence"`
+	OccurredAt time.Time         `json:"occurredAt"`
+	Level      string            `json:"level"`
+	Message    string            `json:"message"`
+	Attributes map[string]string `json:"attributes,omitempty"`
+}
+
+// EventPage is cursor based so an admin browser can drain bursts without repeatedly
+// downloading records it has already rendered.
+type EventPage struct {
+	Events  []Event `json:"events"`
+	Next    int64   `json:"next"`
+	Oldest  int64   `json:"oldest"`
+	Latest  int64   `json:"latest"`
+	Dropped int64   `json:"dropped"`
+	HasMore bool    `json:"hasMore"`
+}
+
+// Buffer is a bounded, concurrency-safe ring of recent structured log records.
+// Bounding is important: a broken TV can generate traffic indefinitely, while 20,000
+// records is still enough context for an operator to inspect a sustained incident.
+type Buffer struct {
+	mu       sync.RWMutex
+	capacity int
+	events   []Event
+	next     atomic.Int64
+}
+
+// NewBuffered writes normal text logs and mirrors accepted records into a ring buffer.
+func NewBuffered(w io.Writer, level slog.Leveler, capacity int) (*slog.Logger, *Buffer) {
+	options := &slog.HandlerOptions{
+		Level: level,
+		ReplaceAttr: func(_ []string, attr slog.Attr) slog.Attr {
+			if attr.Key == slog.TimeKey {
+				return slog.String(slog.TimeKey, attr.Value.Time().UTC().Format(time.RFC3339))
+			}
+			return attr
+		},
+	}
+	buffer := &Buffer{capacity: capacity}
+	text := slog.NewTextHandler(w, options)
+	if capacity <= 0 {
+		return slog.New(text), buffer
+	}
+	return slog.New(&captureHandler{next: text, buffer: buffer, level: level}), buffer
+}
+
+type captureHandler struct {
+	next   slog.Handler
+	buffer *Buffer
+	level  slog.Leveler
+	attrs  []slog.Attr
+	groups []string
+}
+
+func (h *captureHandler) Enabled(ctx context.Context, level slog.Level) bool {
+	return level >= h.level.Level() && h.next.Enabled(ctx, level)
+}
+
+func (h *captureHandler) Handle(ctx context.Context, record slog.Record) error {
+	attributes := make(map[string]string, record.NumAttrs()+len(h.attrs))
+	for _, attr := range h.attrs {
+		addAttribute(attributes, h.groups, attr)
+	}
+	record.Attrs(func(attr slog.Attr) bool {
+		addAttribute(attributes, h.groups, attr)
+		return true
+	})
+	h.buffer.append(Event{
+		OccurredAt: record.Time.UTC(),
+		Level:      record.Level.String(),
+		Message:    record.Message,
+		Attributes: attributes,
+	})
+	return h.next.Handle(ctx, record)
+}
+
+func (h *captureHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	clone := *h
+	clone.next = h.next.WithAttrs(attrs)
+	clone.attrs = append(append([]slog.Attr{}, h.attrs...), attrs...)
+	return &clone
+}
+
+func (h *captureHandler) WithGroup(name string) slog.Handler {
+	clone := *h
+	clone.next = h.next.WithGroup(name)
+	clone.groups = append(append([]string{}, h.groups...), name)
+	return &clone
+}
+
+func addAttribute(target map[string]string, groups []string, attr slog.Attr) {
+	attr.Value = attr.Value.Resolve()
+	if attr.Equal(slog.Attr{}) {
+		return
+	}
+	key := strings.Join(append(append([]string{}, groups...), attr.Key), ".")
+	if attr.Value.Kind() == slog.KindGroup {
+		for _, child := range attr.Value.Group() {
+			addAttribute(target, append(groups, attr.Key), child)
+		}
+		return
+	}
+	switch attr.Value.Kind() {
+	case slog.KindDuration:
+		target[key] = attr.Value.Duration().String()
+	case slog.KindTime:
+		target[key] = attr.Value.Time().UTC().Format(time.RFC3339Nano)
+	default:
+		target[key] = attr.Value.String()
+		if attr.Value.Kind() == slog.KindInt64 {
+			target[key] = strconv.FormatInt(attr.Value.Int64(), 10)
+		}
+	}
+}
+
+func (b *Buffer) append(event Event) {
+	event.Sequence = b.next.Add(1)
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	if len(b.events) == b.capacity {
+		copy(b.events, b.events[1:])
+		b.events[len(b.events)-1] = event
+		return
+	}
+	b.events = append(b.events, event)
+}
+
+// Events returns records strictly newer than after, up to limit. If the caller fell
+// behind the ring, Dropped reports the gap and delivery resumes at the oldest record.
+func (b *Buffer) Events(after int64, limit int) EventPage {
+	if limit < 1 {
+		limit = 250
+	}
+	if limit > 1000 {
+		limit = 1000
+	}
+	b.mu.RLock()
+	defer b.mu.RUnlock()
+
+	latest := b.next.Load()
+	page := EventPage{Next: after, Latest: latest, Events: []Event{}}
+	if len(b.events) == 0 {
+		return page
+	}
+	page.Oldest = b.events[0].Sequence
+	if after < page.Oldest-1 {
+		page.Dropped = page.Oldest - after - 1
+		after = page.Oldest - 1
+	}
+	start := len(b.events)
+	for i := range b.events {
+		if b.events[i].Sequence > after {
+			start = i
+			break
+		}
+	}
+	end := min(start+limit, len(b.events))
+	page.Events = append(page.Events, b.events[start:end]...)
+	if len(page.Events) > 0 {
+		page.Next = page.Events[len(page.Events)-1].Sequence
+	}
+	page.HasMore = page.Next < latest
+	return page
+}
@@ -0,0 +1,58 @@
+package logging
+
+import (
+	"bytes"
+	"log/slog"
+	"strings"
+	"testing"
+)
+
+func TestNewWritesReadableStructuredText(t *testing.T) {
+	var output bytes.Buffer
+	New(&output, slog.LevelInfo).Info("server ready", "listen", ":8080")
+
+	line := output.String()
+	if strings.HasPrefix(strings.TrimSpace(line), "{") {
+		t.Fatalf("expected text output, got JSON: %s", line)
+	}
+	for _, want := range []string{`level=INFO`, `msg="server ready"`, `listen=:8080`} {
+		if !strings.Contains(line, want) {
+			t.Errorf("output %q does not contain %q", line, want)
+		}
+	}
+}
+
+func TestBufferedLoggerRetainsStructuredEventsWithCursorPagination(t *testing.T) {
+	var output bytes.Buffer
+	logger, buffer := NewBuffered(&output, slog.LevelDebug, 3)
+	for i := 1; i <= 5; i++ {
+		logger.Info("request complete", "number", i)
+	}
+
+	first := buffer.Events(0, 2)
+	if first.Dropped != 2 || len(first.Events) != 2 || !first.HasMore {
+		t.Fatalf("unexpected first page: %+v", first)
+	}
+	if first.Events[0].Sequence != 3 || first.Events[0].Attributes["number"] != "3" {
+		t.Fatalf("oldest retained event was not delivered: %+v", first.Events[0])
+	}
+	second := buffer.Events(first.Next, 2)
+	if len(second.Events) != 1 || second.Events[0].Sequence != 5 || second.HasMore {
+		t.Fatalf("unexpected second page: %+v", second)
+	}
+}
+
+func TestParseLevel(t *testing.T) {
+	tests := map[string]slog.Level{
+		"":        slog.LevelInfo,
+		"debug":   slog.LevelDebug,
+		"WARNING": slog.LevelWarn,
+		"error":   slog.LevelError,
+		"unknown": slog.LevelInfo,
+	}
+	for input, want := range tests {
+		if got := ParseLevel(input); got != want {
+			t.Errorf("ParseLevel(%q) = %v, want %v", input, got, want)
+		}
+	}
+}