// FDN-08 — Logging, Metriken & Fehler-Tracking. // // Dieses File enthält die drei Bausteine, die bisher gefehlt haben: // // 1. requestIDMiddleware: erzeugt (oder übernimmt aus X-Request-ID) eine // Korrelations-ID, hängt sie an den context.Context und gibt sie im // Response-Header zurück. Über loggerFromCtx(ctx) bekommt jede Log-Zeile // im Request-Lebenszyklus das Feld request_id, ohne dass jede Call-Site // umgeschrieben werden muss. // 2. metricsMiddleware: zählt Requests je (Methode, normalisierter Pfad, // Status) und summiert die Latenz in Histogramm-Buckets. Ausgabe über // GET /metrics im Prometheus-Textformat (kein prometheus/client_golang). // 3. recoverMiddleware: zentrales Panic-Recovery. net/http's ServeMux hat // keins; ohne das reißt ein Panic in einem Handler die Verbindung ab und // der Fehler taucht nirgends auf. // // Bewusst KEIN Logging von Query-Strings, Headern oder Request-Bodies: // dort stecken Tokens (Signed-URL-Signatur, Share-Token, Bearer-Keys) und // potenziell Passwörter. Geloggt werden ausschließlich Methode, normalisierter // Pfad (IDs/Tokens durch Platzhalter ersetzt), Status, Dauer und Client-IP. package api import ( "context" "crypto/rand" "encoding/hex" "log/slog" "net/http" "runtime/debug" "strconv" "strings" "sync" "time" ) // stackTrace liefert einen gekürzten Stacktrace für das Panic-Log. func stackTrace() string { const maxStack = 4096 buf := debug.Stack() if len(buf) > maxStack { buf = buf[:maxStack] } return string(buf) } const ( requestIDKey contextKey = "request_id" loggerKey contextKey = "logger" requestIDHeader = "X-Request-ID" maxRequestIDLen = 64 ) // newRequestID erzeugt eine zufällige 16-stellige Hex-ID. Fällt bei einem // (praktisch unmöglichen) Fehler der Entropiequelle auf einen Zeitstempel // zurück — eine Anfrage darf daran nie scheitern. func newRequestID() string { buf := make([]byte, 8) if _, err := rand.Read(buf); err != nil { return strconv.FormatInt(time.Now().UnixNano(), 36) } return hex.EncodeToString(buf) } // sanitizeRequestID übernimmt eine vom Client/Proxy gelieferte ID nur, wenn // sie kurz und druckbar-alphanumerisch ist. Verhindert Log-Injection über // Zeilenumbrüche im Header. func sanitizeRequestID(v string) string { v = strings.TrimSpace(v) if v == "" || len(v) > maxRequestIDLen { return "" } for _, r := range v { switch { case r >= 'a' && r <= 'z', r >= 'A' && r <= 'Z', r >= '0' && r <= '9': case r == '-' || r == '_' || r == '.': default: return "" } } return v } // requestIDFromCtx liefert die Korrelations-ID der laufenden Anfrage oder "". func requestIDFromCtx(ctx context.Context) string { if ctx == nil { return "" } v, _ := ctx.Value(requestIDKey).(string) return v } // loggerFromCtx liefert den Request-Logger (inkl. request_id-Feld). Außerhalb // eines HTTP-Requests — oder wenn kein Logger hinterlegt wurde — kommt ein // no-op-freier Fallback zurück, damit Aufrufer nie auf nil prüfen müssen. func loggerFromCtx(ctx context.Context) *slog.Logger { if ctx != nil { if l, ok := ctx.Value(loggerKey).(*slog.Logger); ok && l != nil { return l } } return slog.Default() } // reqLog ist der Einstieg für Handler: nutzt den Request-Logger aus dem // Context, fällt aber auf den Server-Logger zurück, wenn die Middleware nicht // durchlaufen wurde (z.B. in Tests, die Handler direkt aufrufen). func (s *Server) reqLog(ctx context.Context) *slog.Logger { if ctx != nil { if l, ok := ctx.Value(loggerKey).(*slog.Logger); ok && l != nil { return l } } if s.logger != nil { return s.logger } return slog.Default() } // requestIDMiddleware setzt die Korrelations-ID und den Request-Logger. func (s *Server) requestIDMiddleware(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { rid := sanitizeRequestID(r.Header.Get(requestIDHeader)) if rid == "" { rid = newRequestID() } base := s.logger if base == nil { base = slog.Default() } reqLogger := base.With("request_id", rid) ctx := context.WithValue(r.Context(), requestIDKey, rid) ctx = context.WithValue(ctx, loggerKey, reqLogger) w.Header().Set(requestIDHeader, rid) next.ServeHTTP(w, r.WithContext(ctx)) }) } // statusRecorder merkt sich Statuscode und geschriebene Bytes, damit die // Metrik-Middleware nach dem Handler auswerten kann. type statusRecorder struct { http.ResponseWriter status int written int64 wrote bool } func (rec *statusRecorder) WriteHeader(code int) { if !rec.wrote { rec.status = code rec.wrote = true } rec.ResponseWriter.WriteHeader(code) } func (rec *statusRecorder) Write(b []byte) (int, error) { if !rec.wrote { rec.status = http.StatusOK rec.wrote = true } n, err := rec.ResponseWriter.Write(b) rec.written += int64(n) return n, err } // Flush reicht http.Flusher durch (Downloads/Streaming-Endpunkte). func (rec *statusRecorder) Flush() { if f, ok := rec.ResponseWriter.(http.Flusher); ok { f.Flush() } } // recoverMiddleware fängt Panics zentral ab: Log mit Korrelations-ID + // Stacktrace, sauberer 500 an den Client. Ohne das stürzt zwar nicht der // Prozess (net/http fängt pro Verbindung ab), der Fehler bleibt aber // unsichtbar und der Client bekommt einen abgebrochenen Stream. func (s *Server) recoverMiddleware(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { defer func() { rec := recover() if rec == nil { return } if rec == http.ErrAbortHandler { panic(rec) } s.metrics.incPanic() loggerFromCtx(r.Context()).Error("panic in http handler", "method", r.Method, "path", normalizeRoute(r.URL.Path), "remote_ip", s.remoteIP(r), "panic", rec, "stack", stackTrace(), ) if sr, ok := w.(*statusRecorder); ok && sr.wrote { return // Header sind raus, mehr geht nicht } writeError(w, http.StatusInternalServerError, "interner Serverfehler") }() next.ServeHTTP(w, r) }) } // metricsMiddleware misst Dauer und Status jeder Anfrage. func (s *Server) metricsMiddleware(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { rec := &statusRecorder{ResponseWriter: w, status: http.StatusOK} start := time.Now() s.metrics.incInFlight() defer func() { s.metrics.decInFlight() d := time.Since(start) route := normalizeRoute(r.URL.Path) s.metrics.observe(r.Method, route, rec.status, d) // Zugriffs-Log: JEDE Anfrage erzeugt genau eine Zeile mit // request_id (AK1). Level nach Status gestaffelt, damit im // Normalbetrieb (Info) nur Auffälligkeiten sichtbar sind: // 5xx=Error, 4xx=Warn, Rest=Debug. lvl := slog.LevelDebug msg := "request completed" switch { case rec.status >= 500: lvl, msg = slog.LevelError, "request failed" case rec.status >= 400: lvl, msg = slog.LevelWarn, "request rejected" } loggerFromCtx(r.Context()).Log(r.Context(), lvl, msg, "method", r.Method, "route", route, "status", rec.status, "duration_ms", d.Milliseconds(), "bytes", rec.written, "remote_ip", s.remoteIP(r)) }() next.ServeHTTP(rec, r) }) } // --- Pfad-Normalisierung --- // tokenSegments sind Pfadabschnitte, deren FOLGENDES Segment ein Geheimnis // ist (Share-Token). Die dürfen niemals in Logs oder Metrik-Labels landen. var tokenSegments = map[string]bool{"share": true} // normalizeRoute ersetzt variable Pfadsegmente durch Platzhalter. Das hält // die Label-Kardinalität der Metriken klein UND verhindert, dass IDs oder // Share-Tokens in Logs/Metriken auftauchen. Query-Strings werden nie // betrachtet (dort stehen Signaturen und API-Keys). func normalizeRoute(path string) string { if path == "" { return "/" } parts := strings.Split(path, "/") prevSecret := false for i, p := range parts { if p == "" { continue } if prevSecret { parts[i] = "{token}" prevSecret = false continue } prevSecret = tokenSegments[p] if isVariableSegment(p) { parts[i] = "{id}" } } out := strings.Join(parts, "/") if len(out) > 120 { return "/other" } return out } // isVariableSegment erkennt IDs, Hashes und sonstige nicht-statische // Pfadbestandteile. Konservativ: im Zweifel maskieren. func isVariableSegment(seg string) bool { if _, err := strconv.ParseInt(seg, 10, 64); err == nil { return true } if len(seg) > 40 { return true } hasDigit := false for _, r := range seg { switch { case r >= '0' && r <= '9': hasDigit = true case r >= 'a' && r <= 'z', r >= 'A' && r <= 'Z', r == '-', r == '_', r == '.': default: // Alles Ungewöhnliche (Sonderzeichen, Umlaute, %-Encoding) ist mit // Sicherheit kein statisches Routensegment. return true } } // Statische Routensegmente sind reine Wörter ("delete-requests", // "classification-templates"). Längere Mischungen aus Buchstaben und // Ziffern sind Hashes/Tokens/Dateinamen -> maskieren. return hasDigit && len(seg) >= 8 } // --- Metrik-Registry --- // latencyBuckets sind die oberen Grenzen (Sekunden) des Latenz-Histogramms. var latencyBuckets = []float64{0.005, 0.025, 0.1, 0.5, 1, 2.5, 5, 10, 30} type routeKey struct { method string route string status int } type routeStat struct { count uint64 sumSeconds float64 bucketCount []uint64 // len(latencyBuckets), kumulativ erst beim Rendern } // metricsRegistry ist eine minimale, prozesslokale Metrik-Sammlung. Keine // globale Variable: hängt als Feld am Server (Dependency Injection). type metricsRegistry struct { mu sync.Mutex routes map[routeKey]*routeStat inFlight int64 panics uint64 started time.Time } func newMetricsRegistry() *metricsRegistry { return &metricsRegistry{ routes: make(map[routeKey]*routeStat), started: time.Now(), } } func (m *metricsRegistry) observe(method, route string, status int, d time.Duration) { if m == nil { return } k := routeKey{method: method, route: route, status: status} secs := d.Seconds() m.mu.Lock() defer m.mu.Unlock() // Kardinalitätsbremse: unbekannte Pfade nicht unbegrenzt sammeln. st := m.routes[k] if st == nil { if len(m.routes) >= 500 { k = routeKey{method: method, route: "/other", status: status} st = m.routes[k] } if st == nil { st = &routeStat{bucketCount: make([]uint64, len(latencyBuckets))} m.routes[k] = st } } st.count++ st.sumSeconds += secs for i, ub := range latencyBuckets { if secs <= ub { st.bucketCount[i]++ } } } func (m *metricsRegistry) incInFlight() { if m == nil { return } m.mu.Lock() m.inFlight++ m.mu.Unlock() } func (m *metricsRegistry) decInFlight() { if m == nil { return } m.mu.Lock() m.inFlight-- m.mu.Unlock() } func (m *metricsRegistry) incPanic() { if m == nil { return } m.mu.Lock() m.panics++ m.mu.Unlock() } // snapshot liefert eine Kopie der Zähler für das Rendern. func (m *metricsRegistry) snapshot() (map[routeKey]routeStat, int64, uint64) { m.mu.Lock() defer m.mu.Unlock() out := make(map[routeKey]routeStat, len(m.routes)) for k, v := range m.routes { cp := routeStat{count: v.count, sumSeconds: v.sumSeconds, bucketCount: make([]uint64, len(v.bucketCount))} copy(cp.bucketCount, v.bucketCount) out[k] = cp } return out, m.inFlight, m.panics }