From 840fbb103eb1845d94203f275d623ca3b77ddbc3 Mon Sep 17 00:00:00 2001 From: trefeon Date: Tue, 18 Aug 2026 14:54:55 +0700 Subject: [PATCH 1/6] logging: correlation IDs, wire transparency, rate-limit ledger Wave 1 of the observability plan (docs/delivery/logging-observability-plan.md). Why: the acerblue log watch (docs/research/log-observations-2026-08-18.md) proved logs were uncorrelatable (no request id), upstream 4xx/5xx were logged as 'upstream ok', rate-limit codes collapsed into a 200-char truncated 'rate_limited', and 184 identical WARNs flooded a burst. Future session and rate-limit work needs these signals debuggable from logs alone. - telemetry: LevelTrace(-8), ParseLevel('trace'), LOG_FORMAT=json|text, real WithAttrs/WithGroup, RedactHeaders covers x-freebuff-*, new RedactSecrets scrubs cb_/Bearer from logged bodies - req_id minted per request (access wrapper), threaded via ChatOptions into upstream do()/retry logs; client_request_id from X-Request-Id; chat routing/done/trace carry both; trace_session_id now logged on run start/finish and chat trace - chat trace enriched: attempts, statuses_seen, retried, backoff_ms; 'transient chat error, retrying once' structured (reason/backoff_ms/ attempt/req_id) + 'chat retry succeeded'; retry skipped on canceled ctx - do(): >=400 logs 'upstream response' (class, redacted body <=500 runes, body re-wrapped); 'upstream rate limit classified' logs full body with code/window/retry_after/reset_at - 'request failed' WARN structured: req_id, retry_after, reset_at, token, model; rate_limited WARNs deduped per (token|code|window) 1st+50th - freebuff_proxy_rate_limit_events_total{token,code} counter in /metrics - config: LOG_FORMAT validated; LOG_LEVEL accepts trace --- cmd/freebuff-proxy/main.go | 14 +- cmd/freebuff-proxy/main_test.go | 23 ++ internal/config/config.go | 27 +- internal/config/config_test.go | 66 ++- internal/pool/pool.go | 6 + internal/runs/runs.go | 9 +- internal/runs/runs_test.go | 75 ++++ internal/server/auth_internal_test.go | 50 ++- internal/server/server.go | 319 +++++++++++++- internal/server/server_api_test.go | 339 +++++++++++++++ internal/server/wire_metrics_internal_test.go | 150 +++++++ internal/server/wire_metrics_test.go | 63 +++ internal/telemetry/telemetry.go | 389 +++++++++++++++++- internal/telemetry/telemetry_test.go | 305 ++++++++++++-- internal/testutil/env.go | 2 +- internal/upstream/client.go | 279 ++++++++++++- internal/upstream/client_test.go | 18 + internal/upstream/wire_metrics_test.go | 241 +++++++++++ 18 files changed, 2288 insertions(+), 87 deletions(-) create mode 100644 internal/server/wire_metrics_internal_test.go create mode 100644 internal/server/wire_metrics_test.go create mode 100644 internal/upstream/wire_metrics_test.go diff --git a/cmd/freebuff-proxy/main.go b/cmd/freebuff-proxy/main.go index a3ebfc0..c18cc56 100644 --- a/cmd/freebuff-proxy/main.go +++ b/cmd/freebuff-proxy/main.go @@ -99,7 +99,7 @@ func main() { // Effective log level: LOG_LEVEL config wins, else -v → debug, else info. level := resolveLogLevel(cfg.LogLevel, *verbose) - logger := telemetry.New(level, cfg.LogFile) + logger := telemetry.New(level, cfg.LogFile, cfg.LogFormat) // The dashboard log viewer reads from an in-memory ring that mirrors // every record the process logger emits (no log file or docker needed). logringHandler := logring.NewHandler(logger.Handler(), 500) @@ -281,7 +281,7 @@ func main() { "registry_refresh", cfg.RegistryRefresh.String(), "registry_agents", len(reg.AgentIDs()), "registry_models", reg.ModelCount(), - "log_level", level.String(), + "log_level", logLevelDisplay(level), "verbose", *verbose, ) if cfg.ActingUserID != "" { @@ -432,6 +432,16 @@ func resolveLogLevel(cfgLogLevel string, verbose bool) slog.Level { return slog.LevelInfo } +// logLevelDisplay renders the configured level for the startup summary. +// LevelTrace prints as TRACE instead of slog's "DEBUG-4" (the level sits +// below DEBUG, so slog's String() appends the negative offset). +func logLevelDisplay(level slog.Level) string { + if level == telemetry.LevelTrace { + return "TRACE" + } + return level.String() +} + // ignoredExeAdjacentEnv returns the path of a .env that sits next to the // executable while the process reads ./.env from the working directory — // the usual reason config "seems to vanish" under a non-interactive diff --git a/cmd/freebuff-proxy/main_test.go b/cmd/freebuff-proxy/main_test.go index c03b6a4..c2c85e9 100644 --- a/cmd/freebuff-proxy/main_test.go +++ b/cmd/freebuff-proxy/main_test.go @@ -12,6 +12,7 @@ import ( "time" "freebuff-proxy/internal/egress" + "freebuff-proxy/internal/telemetry" ) // TestHoldForExitIfConsolePipedStderrNoHang guards the console hold: with @@ -234,6 +235,8 @@ func TestResolveLogLevel(t *testing.T) { {"config wins", "warn", false, slog.LevelWarn}, {"config beats verbose", "error", true, slog.LevelError}, {"config case-insensitive", "DEBUG", false, slog.LevelDebug}, + {"trace level", "trace", false, telemetry.LevelTrace}, + {"trace case-insensitive", "TRACE", true, telemetry.LevelTrace}, {"unparseable falls back to info", "bogus", true, slog.LevelInfo}, } for _, tc := range cases { @@ -245,6 +248,26 @@ func TestResolveLogLevel(t *testing.T) { } } +// TestLogLevelDisplay pins the startup-summary level rendering: trace shows +// as TRACE (not slog's "DEBUG-4"), every other level keeps slog's name. +func TestLogLevelDisplay(t *testing.T) { + cases := []struct { + level slog.Level + want string + }{ + {telemetry.LevelTrace, "TRACE"}, + {slog.LevelDebug, "DEBUG"}, + {slog.LevelInfo, "INFO"}, + {slog.LevelWarn, "WARN"}, + {slog.LevelError, "ERROR"}, + } + for _, tc := range cases { + if got := logLevelDisplay(tc.level); got != tc.want { + t.Errorf("logLevelDisplay(%v) = %q, want %q", tc.level, got, tc.want) + } + } +} + // TestIgnoredExeAdjacentEnv pins the exe-adjacent .env warning branch: a // .env next to the executable is flagged ONLY when the working directory // differs from the executable's directory — the usual reason config "seems diff --git a/internal/config/config.go b/internal/config/config.go index 906b62a..41ac114 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -20,6 +20,8 @@ import ( "strconv" "strings" "time" + + "freebuff-proxy/internal/telemetry" ) // Config is the fully-resolved, validated runtime configuration. @@ -49,7 +51,8 @@ type Config struct { RegistryRefresh time.Duration DebugDump bool LogFile string - LogLevel string // "" (use -v/default) or debug|info|warn|error + LogLevel string // "" (use -v/default) or debug|info|warn|error|trace + LogFormat string // "text" (default) or "json" MaxMessagesPerDay int // 0 = unlimited: per-token cap on successful chats per 24h MaxSpendPerDay int64 // 0 = unlimited: ADVISORY per-token Pacific-day spend ceiling in ledger units (tokens from upstream usage blocks; issue #122). Never blocks — the upstream $ ceilings ($15 full / $5 limited / $0.50 restricted, compose by minimum, server-enforced) are the real gate. Surfaced as SpendLimit/SpendPct on /healthz so operator comparisons align with the Pacific-midnight reset. IdleRotationTimeout time.Duration // 0 = disabled: pause rotation/refresh after this idle period @@ -184,6 +187,7 @@ type rawConfig struct { DebugDump bool `json:"DEBUG_DUMP"` LogFile string `json:"LOG_FILE"` LogLevel string `json:"LOG_LEVEL"` + LogFormat string `json:"LOG_FORMAT"` MaxMessagesPerDay *int `json:"MAX_MESSAGES_PER_DAY"` MaxSpendPerDay *int `json:"MAX_SPEND_PER_DAY"` IdleRotationTimeout string `json:"IDLE_ROTATION_TIMEOUT"` @@ -377,6 +381,7 @@ func Load(configPath string) (Config, error) { overrideBool(&raw.DebugDump, "DEBUG_DUMP") overrideString(&raw.LogFile, "LOG_FILE") overrideString(&raw.LogLevel, "LOG_LEVEL") + overrideString(&raw.LogFormat, "LOG_FORMAT") overrideInt(&raw.MaxMessagesPerDay, "MAX_MESSAGES_PER_DAY") overrideInt(&raw.MaxSpendPerDay, "MAX_SPEND_PER_DAY") overrideString(&raw.IdleRotationTimeout, "IDLE_ROTATION_TIMEOUT") @@ -585,6 +590,12 @@ func Load(configPath string) (Config, error) { raw.ActingUserID = raw.LegacyActingUserID } + // LOG_FORMAT default: empty means the text format (the historic output). + logFormat := strings.TrimSpace(raw.LogFormat) + if logFormat == "" { + logFormat = "text" + } + cfg := Config{ ListenAddr: strings.TrimSpace(raw.ListenAddr), UpstreamBaseURL: upstreamBaseURL, @@ -602,6 +613,7 @@ func Load(configPath string) (Config, error) { DebugDump: raw.DebugDump, LogFile: strings.TrimSpace(raw.LogFile), LogLevel: strings.TrimSpace(raw.LogLevel), + LogFormat: logFormat, MaxMessagesPerDay: maxMessagesPerDay, MaxSpendPerDay: maxSpendPerDay, IdleRotationTimeout: idleRotationTimeout, @@ -804,11 +816,17 @@ func (c Config) Validate() error { } if c.LogLevel != "" { - var level slog.Level - if err := level.UnmarshalText([]byte(c.LogLevel)); err != nil { - return fmt.Errorf("LOG_LEVEL %q must be one of: debug, info, warn, error", c.LogLevel) + if _, ok := telemetry.ParseLevel(c.LogLevel); !ok { + return fmt.Errorf("LOG_LEVEL %q must be one of: debug, info, warn, error, trace", c.LogLevel) } } + switch c.LogFormat { + case "", "text", "json": + // "" never survives From (it defaults to "text"), accepted for + // direct Config construction. + default: + return fmt.Errorf("LOG_FORMAT %q must be one of: text, json", c.LogFormat) + } u, err := url.Parse(c.UpstreamBaseURL) if err != nil { @@ -918,6 +936,7 @@ func applyDotenv(raw *rawConfig, path string) error { overrideBoolFrom(&raw.DebugDump, get, "DEBUG_DUMP") overrideStringFrom(&raw.LogFile, get, "LOG_FILE") overrideStringFrom(&raw.LogLevel, get, "LOG_LEVEL") + overrideStringFrom(&raw.LogFormat, get, "LOG_FORMAT") overrideIntFrom(&raw.MaxMessagesPerDay, get, "MAX_MESSAGES_PER_DAY") overrideIntFrom(&raw.MaxSpendPerDay, get, "MAX_SPEND_PER_DAY") overrideStringFrom(&raw.IdleRotationTimeout, get, "IDLE_ROTATION_TIMEOUT") diff --git a/internal/config/config_test.go b/internal/config/config_test.go index 0d2d82e..886c5d6 100644 --- a/internal/config/config_test.go +++ b/internal/config/config_test.go @@ -17,7 +17,7 @@ import ( var envKeys = []string{ "LISTEN_ADDR", "UPSTREAM_BASE_URL", "AUTH_TOKENS", "ROTATION_INTERVAL", "REQUEST_TIMEOUT", "SESSION_CALL_TIMEOUT", "API_KEYS", "COST_MODE", "ACTING_USER_ID", "USER_ID", - "TLS_FINGERPRINT", "REGISTRY_REFRESH", "DEBUG_DUMP", "LOG_FILE", "LOG_LEVEL", + "TLS_FINGERPRINT", "REGISTRY_REFRESH", "DEBUG_DUMP", "LOG_FILE", "LOG_LEVEL", "LOG_FORMAT", "MAX_MESSAGES_PER_DAY", "IDLE_ROTATION_TIMEOUT", "SAFE_MODE", "HYBRID_MODE", "MODELS_HIDE_UNAVAILABLE", "CORS_ALLOWED_ORIGIN", "REQUEST_JITTER", "CLI_VERSION", "MODEL_ALIASES", "AUTO_DISCOVER_TOKEN", "TRANSIENT_RETRIES", "ADMIN_TOKEN", @@ -1011,11 +1011,22 @@ func TestLogLevel(t *testing.T) { t.Errorf("LogLevel = %q, want debug", cfg.LogLevel) } + // trace is accepted (case-insensitive), matching telemetry.ParseLevel + t.Setenv("LOG_LEVEL", "trace") + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (env trace): %v", err) + } else if cfg.LogLevel != "trace" { + t.Errorf("LogLevel = %q, want trace", cfg.LogLevel) + } + // invalid level fails validation t.Setenv("LOG_LEVEL", "bogus") if _, err := Load(""); err == nil || !strings.Contains(err.Error(), "LOG_LEVEL") { t.Fatalf("Load (invalid level): err = %v, want error mentioning LOG_LEVEL", err) } + if _, err := Load(""); err == nil || !strings.Contains(err.Error(), "debug, info, warn, error, trace") { + t.Fatalf("Load (invalid level): err = %v, want error listing trace", err) + } // .env source t.Setenv("LOG_LEVEL", "") @@ -1029,6 +1040,59 @@ func TestLogLevel(t *testing.T) { } } +func TestLogFormat(t *testing.T) { + clearEnv(t) + t.Setenv("AUTH_TOKENS", "tok") + + // default: "text" when unset (the historic output shape) + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (default): %v", err) + } else if cfg.LogFormat != "text" { + t.Errorf("LogFormat = %q, want text by default", cfg.LogFormat) + } + + // env source + t.Setenv("LOG_FORMAT", "json") + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (env json): %v", err) + } else if cfg.LogFormat != "json" { + t.Errorf("LogFormat = %q, want json", cfg.LogFormat) + } + + // explicit empty resets to the default + t.Setenv("LOG_FORMAT", "") + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (empty format): %v", err) + } else if cfg.LogFormat != "text" { + t.Errorf("LogFormat = %q, want text for empty value", cfg.LogFormat) + } + + // invalid format fails validation + t.Setenv("LOG_FORMAT", "xml") + if _, err := Load(""); err == nil || !strings.Contains(err.Error(), "LOG_FORMAT") { + t.Fatalf("Load (invalid format): err = %v, want error mentioning LOG_FORMAT", err) + } + + // JSON file source (weakest): env wins over it + t.Setenv("LOG_FORMAT", "text") + json := `{"AUTH_TOKENS":["tok"],"LOG_FORMAT":"json"}` + path := filepath.Join(t.TempDir(), "config.json") + if err := os.WriteFile(path, []byte(json), 0o644); err != nil { + t.Fatal(err) + } + if cfg, err := Load(path); err != nil { + t.Fatalf("Load (json file): %v", err) + } else if cfg.LogFormat != "text" { + t.Errorf("LogFormat = %q, want text (env beats JSON file)", cfg.LogFormat) + } + t.Setenv("LOG_FORMAT", "") + if cfg, err := Load(path); err != nil { + t.Fatalf("Load (json file, no env): %v", err) + } else if cfg.LogFormat != "json" { + t.Errorf("LogFormat = %q, want json from JSON file", cfg.LogFormat) + } +} + func TestTLSFingerprint(t *testing.T) { clearEnv(t) t.Setenv("AUTH_TOKENS", "tok") diff --git a/internal/pool/pool.go b/internal/pool/pool.go index 2180875..af57485 100644 --- a/internal/pool/pool.go +++ b/internal/pool/pool.go @@ -200,6 +200,11 @@ type TokenSnapshot struct { // pinned TLS fingerprint swaps. Surfaced per-token in /metrics. TransientRetries int64 FingerprintRotations int64 + // RateLimitEvents is this token's upstream rate-limit classification + // ledger (T7), keyed by upstream body code (rate_limited, ip_capped, + // spend_limited, insufficient_quota, limit_burst_rate, + // free_mode_rate_limited, ...). Surfaced per-token in /metrics. + RateLimitEvents map[string]int64 } // Pool balances requests across the configured tokens. @@ -1709,6 +1714,7 @@ func (p *Pool) Snapshot() []TokenSnapshot { Standing: ss.Standing, TransientRetries: tok.client.TransientRetries(), FingerprintRotations: tok.client.FingerprintRotations(), + RateLimitEvents: tok.client.RateLimitEvents(), Spend24h: spend.Rolling24h, SpendDay: spend.Day, SpendWeek: spend.Week, diff --git a/internal/runs/runs.go b/internal/runs/runs.go index b383ab9..ce25f9f 100644 --- a/internal/runs/runs.go +++ b/internal/runs/runs.go @@ -1011,9 +1011,12 @@ func (m *RunManager) rotate(ctx context.Context, agentID string) error { m.mu.Unlock() return err } - slog.Debug("runs: run started", "agent_id", agentID, "run_id", runID) + // Mint the trace session id before logging so the run-started line + // and every chat trace of this run share it (T3, D2). + traceSessionID := newTraceSessionID() + slog.Debug("runs: run started", "agent_id", agentID, "run_id", runID, "trace_session_id", traceSessionID) - newRun := &Run{AgentID: agentID, RunID: runID, StartedAt: time.Now(), TraceSessionID: newTraceSessionID()} + newRun := &Run{AgentID: agentID, RunID: runID, StartedAt: time.Now(), TraceSessionID: traceSessionID} oldRun := m.runs[agentID] m.runs[agentID] = newRun if oldRun != nil { @@ -1356,7 +1359,7 @@ func (m *RunManager) finishIfReadyCtx(ctx context.Context, run *Run) { m.draining = filtered m.mu.Unlock() m.removeRun(run) - slog.Debug("runs: run finished", "run_id", run.RunID, "requests", run.Requests) + slog.Debug("runs: run finished", "run_id", run.RunID, "requests", run.Requests, "trace_session_id", run.TraceSessionID) } // ReleaseAbandoned releases run after the downstream client's context was diff --git a/internal/runs/runs_test.go b/internal/runs/runs_test.go index 9e9bfe5..7fe610f 100644 --- a/internal/runs/runs_test.go +++ b/internal/runs/runs_test.go @@ -6,6 +6,7 @@ import ( "errors" "fmt" "log/slog" + "regexp" "strings" "sync" "testing" @@ -917,3 +918,77 @@ func TestTraceSessionIDMintedPerRun(t *testing.T) { } mgr.Release(run3) } + +// lockedBuffer is a mutex-guarded bytes.Buffer for captureSlogLocked: the +// deferred finish worker logs asynchronously while the test reads, so the +// underlying buffer must not be written concurrently with a read. +type lockedBuffer struct { + mu sync.Mutex + b bytes.Buffer +} + +func (w *lockedBuffer) Write(p []byte) (int, error) { + w.mu.Lock() + defer w.mu.Unlock() + return w.b.Write(p) +} + +func (w *lockedBuffer) String() string { + w.mu.Lock() + defer w.mu.Unlock() + return w.b.String() +} + +// captureSlogLocked swaps the default slog handler for a locked Debug-level +// recorder and returns a restore func plus a snapshot of everything logged +// since capture. +func captureSlogLocked() (restore func(), logged func() string) { + buf := &lockedBuffer{} + prev := slog.Default() + slog.SetDefault(slog.New(slog.NewTextHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug}))) + return func() { slog.SetDefault(prev) }, buf.String +} + +// TestRunStartedFinishedLogTraceSessionID verifies T3: the run's +// trace_session_id (the value threaded into codebuff_metadata) appears on +// BOTH "runs: run started" and "runs: run finished" with the same value. +func TestRunStartedFinishedLogTraceSessionID(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + mgr, _ := newTestManager(t, mock, 40*time.Millisecond) + + restore, logged := captureSlogLocked() + defer restore() + + first, err := mgr.Acquire(context.Background(), agentA) + if err != nil { + t.Fatal(err) + } + mgr.Release(first) + // Let the run age past the rotation interval: the next acquire rotates + // it away and FINISHes it asynchronously through the deferred queue. + time.Sleep(60 * time.Millisecond) + second, err := mgr.Acquire(context.Background(), agentA) + if err != nil { + t.Fatal(err) + } + mgr.Release(second) + + startedRe := regexp.MustCompile(`runs: run started[^\n]*trace_session_id=([0-9a-f-]+)`) + started := startedRe.FindStringSubmatch(logged()) + if started == nil { + t.Fatalf("no run started line with trace_session_id:\n%s", logged()) + } + + eventually(t, "run finished line", func() bool { + return strings.Contains(logged(), "runs: run finished") + }) + finishedRe := regexp.MustCompile(`runs: run finished[^\n]*trace_session_id=([0-9a-f-]+)`) + finished := finishedRe.FindStringSubmatch(logged()) + if finished == nil { + t.Fatalf("run finished line missing trace_session_id:\n%s", logged()) + } + if finished[1] != started[1] { + t.Errorf("run finished trace_session_id = %q, want the run started value %q", finished[1], started[1]) + } +} diff --git a/internal/server/auth_internal_test.go b/internal/server/auth_internal_test.go index 2be8b15..ab5bafe 100644 --- a/internal/server/auth_internal_test.go +++ b/internal/server/auth_internal_test.go @@ -11,6 +11,7 @@ import ( "net/http/httptest" "os" "path/filepath" + "regexp" "runtime" "strings" "testing" @@ -168,7 +169,7 @@ func errorResponse(t *testing.T, err error) (status int, hdr http.Header, body s s := &Server{logger: slog.New(slog.NewTextHandler(io.Discard, nil))} w := httptest.NewRecorder() r := httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil) - s.writeError(w, r, err) + s.writeError(w, r, err, "", nil) if err := json.Unmarshal(w.Body.Bytes(), &body); err != nil { t.Fatalf("writeError response is not JSON: %v: %s", err, w.Body.Bytes()) } @@ -493,7 +494,7 @@ func TestWriteErrorModelIPLimited(t *testing.T) { s := &Server{logger: slog.New(slog.NewTextHandler(io.Discard, nil))} w := httptest.NewRecorder() r := httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil) - s.writeError(w, r, err) + s.writeError(w, r, err, "", nil) if got := w.Header().Get("Retry-After"); got != "300" { t.Errorf("Retry-After = %q, want 300", got) } @@ -501,7 +502,7 @@ func TestWriteErrorModelIPLimited(t *testing.T) { // A zero RetryAfter must not emit the header. w2 := httptest.NewRecorder() r2 := httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil) - s.writeError(w2, r2, &upstream.LimitedIpError{Body: "no window"}) + s.writeError(w2, r2, &upstream.LimitedIpError{Body: "no window"}, "", nil) if got := w2.Header().Get("Retry-After"); got != "" { t.Errorf("Retry-After with zero RetryAfter = %q, want empty", got) } @@ -521,8 +522,49 @@ func TestWriteErrorBareModelIPLimitedSentinel(t *testing.T) { s := &Server{logger: slog.New(slog.NewTextHandler(io.Discard, nil))} w := httptest.NewRecorder() r := httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil) - s.writeError(w, r, upstream.ErrModelIPLimited) + s.writeError(w, r, upstream.ErrModelIPLimited, "", nil) if got := w.Header().Get("Retry-After"); got != "" { t.Errorf("Retry-After = %q, want none for bare sentinel", got) } } + +// TestNewReqIDUUIDv4 pins the correlation-id mint (D1): RFC 4122 §4.4 +// shape — version nibble 4, variant bits 10 — and a fresh value per mint. +func TestNewReqIDUUIDv4(t *testing.T) { + id := newReqID() + re := regexp.MustCompile(`^[0-9a-f]{8}-[0-9a-f]{4}-4[0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$`) + if !re.MatchString(id) { + t.Errorf("newReqID() = %q, want UUIDv4 shape", id) + } + if id2 := newReqID(); id2 == id { + t.Error("two mints produced the same id") + } +} + +// TestClientRequestIDSanitize pins the X-Request-Id sanitizer (D1): trimmed, +// printable ASCII only, max 64 runes, else dropped (""). +func TestClientRequestIDSanitize(t *testing.T) { + cases := []struct { + hdr string + want string + }{ + {"", ""}, + {"abc", "abc"}, + {" abc ", "abc"}, // trimmed + {"a b", "a b"}, // inner spaces kept + {strings.Repeat("x", 64), strings.Repeat("x", 64)}, + {strings.Repeat("x", 65), ""}, // >64 runes dropped + {"héllo", ""}, // non-ASCII dropped + {"line\nbreak", ""}, // control character dropped + {"tab\there", ""}, // control character dropped + } + for _, c := range cases { + r := httptest.NewRequest(http.MethodGet, "/", nil) + if c.hdr != "" { + r.Header.Set("X-Request-Id", c.hdr) + } + if got := clientRequestID(r); got != c.want { + t.Errorf("clientRequestID(%q) = %q, want %q", c.hdr, got, c.want) + } + } +} diff --git a/internal/server/server.go b/internal/server/server.go index 1a9258e..dee1676 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -40,6 +40,7 @@ import ( "sync" "sync/atomic" "time" + "unicode/utf8" "freebuff-proxy/internal/config" "freebuff-proxy/internal/convert" @@ -232,15 +233,29 @@ func (s *Server) Handler() http.Handler { cors := s.corsMiddleware(mux) return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() + // D1: mint the request's correlation id exactly once here, then + // carry it in the request context so every downstream log line + // (chat routing/done/trace, request failed, upstream do/retry) + // shares it. Handlers reached without this wrapper (direct calls + // in tests) mint a fallback id in chatCore. + reqID := newReqID() + r = r.WithContext(context.WithValue(r.Context(), reqIDKey{}, reqID)) sw := &statusWriter{ResponseWriter: w, status: http.StatusOK} cors.ServeHTTP(sw, r) - s.logger.Info("access", + attrs := []any{ + "req_id", reqID, "method", r.Method, "path", r.URL.Path, "status", sw.status, "ms", time.Since(start).Milliseconds(), "remote", remoteHost(r), - ) + } + // The client's X-Request-Id is preserved as a separate + // client_request_id field (never trusted as the correlation key). + if crid := clientRequestID(r); crid != "" { + attrs = append(attrs, "client_request_id", crid) + } + s.logger.Info("access", attrs...) }) } @@ -1788,6 +1803,53 @@ func bearerToken(r *http.Request) string { return "" } +// --- correlation ids --- + +// reqIDKey carries the per-request correlation id (req_id) through the +// request context. The key type is unexported so only this package can +// read/write it; the upstream client threads the same id a second way (via +// ChatOptions.RequestID) for its do()/retry log lines. +type reqIDKey struct{} + +// reqIDFrom returns the request's correlation id, or "" when the request +// did not pass through the access wrapper (direct handler calls in tests). +func reqIDFrom(ctx context.Context) string { + id, _ := ctx.Value(reqIDKey{}).(string) + return id +} + +// newReqID mints a UUIDv4 correlation id from crypto/rand (RFC 4122 §4.4: +// 122 random bits, version 4, variant 1). A rand failure is unrecoverable +// in practice; fall back to a time-seeded hex id rather than failing the +// request. +func newReqID() string { + var b [16]byte + if _, err := rand.Read(b[:]); err != nil { + return fmt.Sprintf("%x", time.Now().UnixNano()) + } + b[6] = (b[6] & 0x0f) | 0x40 // version 4 + b[8] = (b[8] & 0x3f) | 0x80 // variant 10 + return fmt.Sprintf("%x-%x-%x-%x-%x", b[0:4], b[4:6], b[6:8], b[8:10], b[10:16]) +} + +// clientRequestID sanitizes the client's X-Request-Id header for logging: +// trimmed, printable ASCII only (0x20-0x7e), max 64 runes. Returns "" when +// the header is absent or fails the checks — the field is then omitted from +// log lines (the proxy never trusts a client-supplied id as its correlation +// key, D1). +func clientRequestID(r *http.Request) string { + v := strings.TrimSpace(r.Header.Get("X-Request-Id")) + if v == "" || utf8.RuneCountInString(v) > 64 { + return "" + } + for _, b := range []byte(v) { + if b < 0x20 || b > 0x7e { + return "" + } + } + return v +} + // --- chat --- // --- chat --- @@ -1856,7 +1918,16 @@ func (s *Server) handleChat(w http.ResponseWriter, r *http.Request) { // retry-once recovery, then relay the forced stream to the client through // relay. kind names the endpoint in request/done log lines. func (s *Server) chatCore(w http.ResponseWriter, r *http.Request, model string, stream bool, normalized []byte, reasoningEffort, kind string, relay relayFunc) { - ctx, phases := phasetiming.WithContext(r.Context()) + // D1: the access wrapper minted the request's correlation id; direct + // handler calls (tests) mint here so it is never empty. The value is + // threaded into the request context AND into ChatOptions.RequestID so + // the upstream client's do()/retry lines share it. + reqID := reqIDFrom(r.Context()) + if reqID == "" { + reqID = newReqID() + } + st := &chatTraceState{reqID: reqID, clientRequestID: clientRequestID(r)} + ctx, phases := phasetiming.WithContext(context.WithValue(r.Context(), reqIDKey{}, reqID)) start := time.Now() agentID, _ := s.reg.AgentForModel(model) @@ -1912,8 +1983,8 @@ func (s *Server) chatCore(w http.ResponseWriter, r *http.Request, model string, if lie != nil { refuseErr = &upstream.LimitedIpError{Model: lie.Model, Body: lie.Body, RetryAfter: time.Until(until)} } - s.traceChat(nil, model, time.Since(start).Milliseconds(), "error", "model_ip_limited", phases.All()) - s.writeError(w, r, refuseErr) + s.traceChat(nil, model, time.Since(start).Milliseconds(), "error", "model_ip_limited", phases.All(), st) + s.writeError(w, r, refuseErr, model, nil) return } } @@ -1936,7 +2007,7 @@ func (s *Server) chatCore(w http.ResponseWriter, r *http.Request, model string, "invalid_request_error", "missing_bearer_token", 0) return } - up, lease, err = s.chatAttempt(ctx, model, normalized, + up, lease, err = s.chatAttempt(ctx, model, normalized, st, acquireTimed(func(ctx context.Context, model string) (*pool.Lease, error) { return s.pool.AcquireBridge(ctx, tok, model) }), @@ -1986,7 +2057,7 @@ func (s *Server) chatCore(w http.ResponseWriter, r *http.Request, model string, return l, err } } - up, lease, err = s.chatAttempt(ctx, model, normalized, + up, lease, err = s.chatAttempt(ctx, model, normalized, st, acquire, s.pool.Chat, func(l *pool.Lease) { s.pool.InvalidateSession(l.Token) }, @@ -2002,12 +2073,12 @@ func (s *Server) chatCore(w http.ResponseWriter, r *http.Request, model string, } if err != nil { phases.Since(phasetiming.TotalMS, start) - s.traceChat(lease, model, time.Since(start).Milliseconds(), "error", chatErrClass(err), phases.All()) + s.traceChat(lease, model, time.Since(start).Milliseconds(), "error", chatErrClass(err), phases.All(), st) // Issue #114: a chat that died on a terminal upstream error must // not leave its run FINISHing as completed — report it honestly // (nil-safe: an acquire failure leaves no lease). s.pool.MarkRunFailed(lease) - s.writeError(w, r, err) + s.writeError(w, r, err, model, lease) return } defer func() { _ = up.Close() }() @@ -2031,6 +2102,7 @@ func (s *Server) chatCore(w http.ResponseWriter, r *http.Request, model string, defer release() routingAttrs := []any{ + "req_id", reqID, "token", tokenLabel(lease), "model", model, "agent", lease.AgentID, @@ -2064,18 +2136,41 @@ func (s *Server) chatCore(w http.ResponseWriter, r *http.Request, model string, s.pool.RecordSpend(lease, stats.usageTokens) phases.Since(phasetiming.TotalMS, start) ms := time.Since(start).Milliseconds() - s.logger.Info(kind+" done", chatDoneAttrs(model, lease.AgentID, stream, ms, stats.chunks, stats.bytes, reasoningEffort)...) - s.traceChat(lease, model, ms, "ok", "", phases.All()) + s.logger.Info(kind+" done", chatDoneAttrs(reqID, model, lease.AgentID, stream, ms, stats.chunks, stats.bytes, reasoningEffort)...) + s.traceChat(lease, model, ms, "ok", "", phases.All(), st) } // traceChat records a structured "chat trace" entry for the dashboard // traces page (the page filters the shared log ring by msg == "chat trace"). // phases carries the per-request latency phases (#89); the map is ordered -// deterministically for stable log output. -func (s *Server) traceChat(lease *pool.Lease, model string, ms int64, status, errClass string, phases map[string]int64) { +// deterministically for stable log output. st carries the retry-once +// attempt history (nil-safe: a refusal before any chat attempt passes a +// zero state). +func (s *Server) traceChat(lease *pool.Lease, model string, ms int64, status, errClass string, phases map[string]int64, st *chatTraceState) { attrs := []any{"model", model, "status", status, "ms", ms} + if st != nil { + if st.reqID != "" { + attrs = append(attrs, "req_id", st.reqID) + } + if st.clientRequestID != "" { + attrs = append(attrs, "client_request_id", st.clientRequestID) + } + if st.attempts > 0 { + attrs = append(attrs, "attempts", st.attempts) + } + if seen := st.statusesSeen(); seen != "" { + attrs = append(attrs, "statuses_seen", seen) + } + if st.retried { + attrs = append(attrs, "retried", true, "backoff_ms", st.backoffMs) + } + } if lease != nil { - attrs = append(attrs, "token", tokenLabel(lease), "agent", lease.AgentID) + attrs = append(attrs, + "token", tokenLabel(lease), + "agent", lease.AgentID, + "trace_session_id", lease.Run.TraceSessionID, + ) } if errClass != "" { attrs = append(attrs, "error", errClass) @@ -2120,8 +2215,9 @@ func chatErrClass(err error) string { // chatDoneAttrs builds the structured log attributes for a completed chat, // including reasoning effort when the client requested it. -func chatDoneAttrs(model, agent string, stream bool, ms int64, chunks, bytes int, reasoningEffort string) []any { +func chatDoneAttrs(reqID, model, agent string, stream bool, ms int64, chunks, bytes int, reasoningEffort string) []any { attrs := []any{ + "req_id", reqID, "model", model, "agent", agent, "stream", stream, @@ -2137,6 +2233,66 @@ func chatDoneAttrs(model, agent string, stream bool, ms int64, chunks, bytes int return attrs } +// chatTraceState accumulates the per-request attempt history for the chat +// trace line: how many upstream chat attempts fired, the HTTP statuses +// observed per attempt (success = 200), whether the retry-once recovery +// re-acquired a lease, and the measured re-acquire wait before the retry. +// Created in chatCore (which owns the req_id), filled by chatAttempt's +// retry loop. +type chatTraceState struct { + reqID string + clientRequestID string + attempts int + statuses []int + retried bool + backoffMs int64 +} + +// statusesSeen renders the observed attempt statuses comma-joined +// ("409,200"), or "" when no attempt status was observed. +func (st *chatTraceState) statusesSeen() string { + if len(st.statuses) == 0 { + return "" + } + parts := make([]string, len(st.statuses)) + for i, s := range st.statuses { + parts[i] = strconv.Itoa(s) + } + return strings.Join(parts, ",") +} + +// attemptStatus extracts the upstream HTTP status carried by a chat error, +// or 0 when the error carries none (wrapped sentinels such as +// ErrSessionInvalid/ErrRunInvalid, and transport-level failures). A 0 is +// skipped in statuses_seen — only observed statuses are listed. +func attemptStatus(err error) int { + switch e := err.(type) { + case *upstream.UpstreamError: + return e.Status + case *upstream.CreditsError: + return e.Status + case *upstream.CapacityDeferredError: + return e.Status + case *upstream.SessionSupersededError: + return e.Status + case *upstream.SessionLimitError: + return e.Status + case *upstream.WaitingRoomRequiredError: + // The canonical 428 waiting_room_required (#94); the marker can + // ride 428/429 alike, 428 is the documented gate. No named + // net/http constant exists for 428, so spell it out. + return 428 + case *upstream.RateLimitError: + // RateLimitError.Status is the upstream "429" string; parse when + // numeric, else the 429 bucket is implicit. + if n, perr := strconv.Atoi(e.Status); perr == nil { + return n + } + return http.StatusTooManyRequests + } + return 0 +} + // chatAttempt runs the retry-once recovery loop for one chat request: chat // through the leased token; on session-invalid / run-invalid the lease is // released, the cached session/run invalidated, and a fresh lease acquired @@ -2151,6 +2307,7 @@ func (s *Server) chatAttempt( ctx context.Context, model string, normalized []byte, + st *chatTraceState, acquire func(context.Context, string) (*pool.Lease, error), chat func(context.Context, *pool.Lease, upstream.ChatOptions, []byte) (io.ReadCloser, error), invalidateSession func(*pool.Lease), @@ -2187,6 +2344,9 @@ func (s *Server) chatAttempt( RunID: lease.Run.RunID, SessionInstanceID: lease.SessionInstanceID, TraceSessionID: lease.Run.TraceSessionID, + // D1: the request's correlation id, threaded to the upstream + // client so its do()/retry log lines share the server's req_id. + RequestID: st.reqID, // Issue #113: stamp the run's 1-based per-chat step counter so // codebuff_metadata["llm_step_number"] matches the CLI (each chat // call is one agent step; run-agent-step.ts increments per step). @@ -2206,9 +2366,19 @@ func (s *Server) chatAttempt( var up io.ReadCloser attempts := 0 + // failTime pins when the failed chat attempt returned; the measured + // re-acquire wait below becomes the trace's backoff_ms. + var failTime time.Time + // transientErr remembers the default-branch chat error so the retry + // announcement can log it AFTER the re-acquire (with a real backoff_ms). + var transientErr error for { + chatStart := time.Now() up, err = chat(ctx, lease, opts, normalized) + attempts++ + st.attempts = attempts if err == nil { + st.statuses = append(st.statuses, http.StatusOK) // Issue #74 P2: a successful chat is egress-level proof the // model is servable again — drop any (egress, model) unfit mark. // Only marks created before THIS lease's acquisition (a retry @@ -2219,10 +2389,21 @@ func (s *Server) chatAttempt( if !lease.AcquiredAt.IsZero() { s.pool.ClearModelUnfitBefore(effectiveModel, lease.AcquiredAt) } + if attempts > 1 { + // T13: the retry-once recovery landed — one Debug line that + // greps the whole retry chain by req_id (ms = the retry + // chat call's duration). + s.logger.Debug("chat retry succeeded", + "attempts", attempts, "req_id", st.reqID, + "ms", time.Since(chatStart).Milliseconds()) + } released = true // Disarm deferred release: ownership transferred to caller return up, lease, nil } - attempts++ + if s := attemptStatus(err); s != 0 { + st.statuses = append(st.statuses, s) + } + failTime = time.Now() switch { case errors.Is(err, upstream.ErrModelIPLimited): // Issue #74 P2: the egress IP is limited for the requested @@ -2338,16 +2519,35 @@ func (s *Server) chatAttempt( if errors.As(err, &ue) && ue.Retryable { return nil, nil, err } - if attempts > 1 { + // T8: a retry cannot succeed on a canceled context (the log + // watch showed `transient chat error, retrying once + // err="context canceled"`) — surface the original error instead + // of re-acquiring into a dead ctx. + if attempts > 1 || ctx.Err() != nil { return nil, nil, err } - s.logger.Debug("transient chat error, retrying once", "err", err) + transientErr = err } lease, err = acquire(ctx, effectiveModel) if err != nil { return nil, nil, err } released = false + st.retried = true + // The effective backoff before the retry: the re-acquire wait after + // the failed attempt (a waiting-room/session gate can stall it). + st.backoffMs = time.Since(failTime).Milliseconds() + if transientErr != nil { + // T13: logged here (not at the failure) so backoff_ms reflects + // the real re-acquire wait before the retry attempt. + s.logger.Debug("transient chat error, retrying once", + "err", transientErr, + "reason", chatErrClass(transientErr), + "backoff_ms", st.backoffMs, + "attempt", attempts, + "req_id", st.reqID) + transientErr = nil + } // A fresh lease may bind a different model (fallback path): refresh // the effective model + body so opts.Model, the body and the // lease's session/run stay consistent. @@ -2860,6 +3060,18 @@ func (s *Server) handleMetrics(w http.ResponseWriter, r *http.Request) { } sb.WriteString("\n") + sb.WriteString("# HELP freebuff_proxy_rate_limit_events_total Upstream rate-limit classifications per token and code\n") + sb.WriteString("# TYPE freebuff_proxy_rate_limit_events_total counter\n") + for _, snap := range snaps { + for code, n := range snap.RateLimitEvents { + if n > 0 { + fmt.Fprintf(&sb, "freebuff_proxy_rate_limit_events_total{token=\"%d\",code=\"%s\"} %d\n", + snap.Token+1, escapeLabelValue(code), n) + } + } + } + sb.WriteString("\n") + _, _ = w.Write([]byte(sb.String())) } @@ -2941,10 +3153,42 @@ func defaultHintForCode(code, message string) string { } } +// rateLimitWarnDedupe gates identical (token, code, window) `request failed` +// WARNs (D6): the first + every 50th occurrence fire; the per-key counter +// always increments so a silent burst stays countable, and the client +// response is always written. Package-level = per-process, shared by every +// server instance. +var rateLimitWarnDedupe = struct { + mu sync.Mutex + m map[string]int64 +}{} + +// resetRateLimitWarnDedupe clears the dedupe ledger (test hook). +func resetRateLimitWarnDedupe() { + rateLimitWarnDedupe.mu.Lock() + defer rateLimitWarnDedupe.mu.Unlock() + rateLimitWarnDedupe.m = make(map[string]int64) +} + +// rateLimitWarnShouldLog reports whether the (token, code, window) WARN +// should fire for this occurrence, always incrementing the occurrence count. +func rateLimitWarnShouldLog(key string) bool { + rateLimitWarnDedupe.mu.Lock() + defer rateLimitWarnDedupe.mu.Unlock() + if rateLimitWarnDedupe.m == nil { + rateLimitWarnDedupe.m = make(map[string]int64) + } + rateLimitWarnDedupe.m[key]++ + n := rateLimitWarnDedupe.m[key] + return n == 1 || n%50 == 0 +} + // writeError maps any error from the pool/upstream to the PRD §6 matrix and // logs it once. Canceled client contexts are logged at debug and dropped (no -// response written). -func (s *Server) writeError(w http.ResponseWriter, r *http.Request, err error) { +// response written). model and lease come from the call site: model is the +// request's effective model, lease the acquired token lease (nil when the +// error fired before acquisition — e.g. an unfit-egress refusal). +func (s *Server) writeError(w http.ResponseWriter, r *http.Request, err error, model string, lease *pool.Lease) { if errors.Is(err, context.Canceled) { s.logger.Debug("request canceled by client", "err", err) return @@ -2958,6 +3202,8 @@ func (s *Server) writeError(w http.ResponseWriter, r *http.Request, err error) { code := "upstream_unavailable" message := err.Error() var retryAfter time.Duration + var resetAt time.Time + window := "" // T7 ledger window; set for rate-limit errors (dedupe key) var wr *session.WaitingRoomError var uwr *upstream.WaitingRoomError @@ -2976,12 +3222,14 @@ func (s *Server) writeError(w http.ResponseWriter, r *http.Request, err error) { case errors.As(err, &be): status, code = http.StatusForbidden, "account_banned" message, retryAfter = be.Error(), time.Until(be.ResumesAt) + resetAt = be.ResumesAt if retryAfter < 0 { retryAfter = 0 } case errors.As(err, &rle): status, code = http.StatusTooManyRequests, "rate_limited" message, retryAfter = rle.Error(), rle.RetryAfter + resetAt, window = rle.ResetAt, rle.Window if !rle.ResetAt.IsZero() && rle.ResetAt.After(time.Now()) { retryAfter = time.Until(rle.ResetAt) } @@ -3108,6 +3356,35 @@ func (s *Server) writeError(w http.ResponseWriter, r *http.Request, err error) { message = "upstream request timed out: " + err.Error() } - s.logger.Warn("request failed", "status", status, "code", code, "err", err) + attrs := []any{"status", status, "code", code, "err", err} + if r != nil { + if reqID := reqIDFrom(r.Context()); reqID != "" { + attrs = append(attrs, "req_id", reqID) + } + } + if retryAfter > 0 { + attrs = append(attrs, "retry_after", int(retryAfter.Seconds())) + } + if !resetAt.IsZero() { + attrs = append(attrs, "reset_at", resetAt.UTC().Format(time.RFC3339)) + } + if lease != nil { + attrs = append(attrs, "token", tokenLabel(lease)) + } + if model != "" { + attrs = append(attrs, "model", model) + } + + if code == "rate_limited" { + // D6 dedupe: identical (token, code, window) WARNs fire on the 1st + + // every 50th; the counter always increments and the response is + // always written. + key := tokenLabel(lease) + "|" + code + "|" + window + if !rateLimitWarnShouldLog(key) { + s.writeJSONError(w, status, message, "upstream_error", code, retryAfter) + return + } + } + s.logger.Warn("request failed", attrs...) s.writeJSONError(w, status, message, "upstream_error", code, retryAfter) } diff --git a/internal/server/server_api_test.go b/internal/server/server_api_test.go index 48c86f4..e850dd8 100644 --- a/internal/server/server_api_test.go +++ b/internal/server/server_api_test.go @@ -7,13 +7,16 @@ package server_test import ( "bytes" + "context" "encoding/json" "fmt" + "io" "log/slog" "net/http" "net/http/httptest" "regexp" "strings" + "sync/atomic" "testing" "time" @@ -970,3 +973,339 @@ func TestTracePhasesRecorded(t *testing.T) { t.Errorf("trace missing status=ok: %s", joined) } } + +// --- D1 correlation ids + T2/T3/T8/T12/T13 --- + +// entryField extracts a "key=value" field from a logring entry, or "". +func entryField(e logring.Entry, key string) string { + for _, f := range e.Fields { + if v, ok := strings.CutPrefix(f, key+"="); ok { + return v + } + } + return "" +} + +// debugRing builds a logring-wrapped Debug-level logger so tests can assert +// on Debug lines (upstream do/retry, runs lifecycle, transient retry). +func debugRing(t *testing.T) (*bytes.Buffer, *logring.Handler, *slog.Logger) { + t.Helper() + var sink bytes.Buffer + ring := logring.NewHandler(slog.NewTextHandler(&sink, &slog.HandlerOptions{Level: slog.LevelDebug}), 400) + logger := slog.New(ring) + // runs.go and upstream/client.go log via the package-level default + // logger (slog.Debug), mirroring production where main.go calls + // slog.SetDefault. Route the default at the ring so those lines are + // assertable, and restore on test end. + oldDefault := slog.Default() + slog.SetDefault(logger) + t.Cleanup(func() { slog.SetDefault(oldDefault) }) + return &sink, ring, logger +} + +// TestRequestCorrelationIDs verifies D1 (T2): one request with +// X-Request-Id: abc produces the SAME req_id on access → chat routing → +// chat done → chat trace, a client_request_id=abc passthrough on access + +// trace, and a header-less request carries no client_request_id and a +// fresh req_id. +func TestRequestCorrelationIDs(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + mock.ChatBody = responsesChunks() + _, ring, logger := debugRing(t) + ts, _ := newTestServerWithLogger(t, nil, logger, ring, mock) + + _, data := doJSON(t, http.MethodPost, ts.URL+"/v1/chat/completions", chatBody(modelA), + map[string]string{"X-Request-Id": "abc"}) + if !strings.Contains(string(data), "Hello") { + t.Fatalf("chat stream unexpected: %s", truncate(string(data), 200)) + } + entries := ring.Recent(100) + byMsg := map[string]*logring.Entry{} + for i := range entries { + e := &entries[i] + switch e.Message { + case "access", "chat routing", "chat done", "chat trace": + byMsg[e.Message] = e + } + } + for _, want := range []string{"access", "chat routing", "chat done", "chat trace"} { + if byMsg[want] == nil { + t.Fatalf("missing %q entry in the log ring", want) + } + } + reqID := entryField(*byMsg["access"], "req_id") + if reqID == "" { + t.Fatal("access entry missing req_id") + } + uuidRe := regexp.MustCompile(`^[0-9a-f]{8}-[0-9a-f]{4}-4[0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$`) + if !uuidRe.MatchString(reqID) { + t.Errorf("access req_id = %q, want UUIDv4 shape", reqID) + } + for _, m := range []string{"chat routing", "chat done", "chat trace"} { + if got := entryField(*byMsg[m], "req_id"); got != reqID { + t.Errorf("%s req_id = %q, want the access req_id %q", m, got, reqID) + } + } + for _, m := range []string{"access", "chat trace"} { + if got := entryField(*byMsg[m], "client_request_id"); got != "abc" { + t.Errorf("%s client_request_id = %q, want abc", m, got) + } + } + + // A second request without X-Request-Id: no client_request_id anywhere + // and a fresh req_id (not the previous request's). + _, data2 := doJSON(t, http.MethodPost, ts.URL+"/v1/chat/completions", chatBody(modelA), nil) + if !strings.Contains(string(data2), "Hello") { + t.Fatalf("second chat stream unexpected: %s", truncate(string(data2), 200)) + } + entries2 := ring.Recent(200) + var access2, trace2 *logring.Entry + for i := range entries2 { + e := &entries2[i] + if e.Message == "access" && entryField(*e, "req_id") != reqID && access2 == nil { + access2 = e + } + if e.Message == "chat trace" && entryField(*e, "req_id") != reqID && trace2 == nil { + trace2 = e + } + } + if access2 == nil { + t.Fatal("no access entry for the second request") + } + if got := entryField(*access2, "client_request_id"); got != "" { + t.Errorf("header-less request access client_request_id = %q, want absent", got) + } + if trace2 == nil { + t.Fatal("no chat trace entry for the second request") + } + if got := entryField(*trace2, "client_request_id"); got != "" { + t.Errorf("header-less request trace client_request_id = %q, want absent", got) + } +} + +// TestTransientRetrySkippedOnCanceledContext verifies T8: a chat that fails +// because the request context was canceled must NOT fire the retry-once +// recovery (a retry cannot succeed on a canceled context) — no +// "transient chat error, retrying once", no "chat retry succeeded". +func TestTransientRetrySkippedOnCanceledContext(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + chatSeen := make(chan struct{}) + mock.ChatHandler = func(w http.ResponseWriter, r *http.Request) { + select { + case <-chatSeen: + default: + close(chatSeen) + } + // Hold the chat POST open until the request context dies, so the + // upstream call fails with a context error at the retry decision + // point (the exact log-watch scenario: retry on "context canceled"). + select { + case <-r.Context().Done(): + mock.AbortDetected.Store(true) + case <-time.After(30 * time.Second): + } + } + _, ring, logger := debugRing(t) + ts, _ := newTestServerWithLogger(t, nil, logger, ring, mock) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + req, err := http.NewRequestWithContext(ctx, http.MethodPost, ts.URL+"/v1/chat/completions", bytes.NewReader(chatBody(modelA))) + if err != nil { + t.Fatal(err) + } + errCh := make(chan error, 1) + go func() { + resp, err := testClient.Do(req) + if resp != nil { + _ = resp.Body.Close() + } + errCh <- err + }() + + select { + case <-chatSeen: + case <-time.After(5 * time.Second): + t.Fatal("upstream never saw the chat request") + } + cancel() + + // Wait for the handler to finish logging the canceled request. + eventually(t, "request canceled by client entry", func() bool { + for _, e := range ring.Recent(400) { + if e.Message == "request canceled by client" { + return true + } + } + return false + }) + for _, e := range ring.Recent(400) { + if strings.Contains(e.Message, "transient chat error") { + t.Errorf("canceled request logged a retry announcement: %s", e.Message) + } + if e.Message == "chat retry succeeded" { + t.Error("canceled request logged chat retry succeeded") + } + } + <-errCh +} + +// TestChatRetryTelemetry verifies T12/T13: a retried request logs the +// structured "transient chat error, retrying once" (reason/backoff_ms/ +// attempt/req_id), "chat retry succeeded" (attempts=2), a chat trace with +// attempts=2/retried=true/statuses_seen=500,200, and the SAME req_id on +// both upstream attempt lines (D1 threading to the client do() logs). +func TestChatRetryTelemetry(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + var calls atomic.Int32 + mock.ChatHandler = func(w http.ResponseWriter, r *http.Request) { + if calls.Add(1) == 1 { + // Generic 5xx: not a classified error and not Retryable, so the + // server's retry-once recovery fires (the UpstreamError carries + // status 500 into statuses_seen). + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(http.StatusInternalServerError) + _, _ = io.WriteString(w, `{"error":"internal boom"}`) + return + } + w.Header().Set("Content-Type", "text/event-stream") + w.WriteHeader(http.StatusOK) + _, _ = io.WriteString(w, responsesChunks()) + } + _, ring, logger := debugRing(t) + ts, _ := newTestServerWithLogger(t, nil, logger, ring, mock) + + _, data := doJSON(t, http.MethodPost, ts.URL+"/v1/chat/completions", chatBody(modelA), + map[string]string{"X-Request-Id": "req-1"}) + if !strings.Contains(string(data), "Hello") { + t.Fatalf("retried chat stream unexpected: %s", truncate(string(data), 200)) + } + if got := calls.Load(); got != 2 { + t.Fatalf("upstream chat attempts = %d, want 2", got) + } + + var transient, retriedOK, trace, ok1, ok2 *logring.Entry + recent := ring.Recent(400) + for i := range recent { + e := &recent[i] + switch e.Message { + case "transient chat error, retrying once": + transient = e + case "chat retry succeeded": + retriedOK = e + case "chat trace": + trace = e + case "upstream ok", "upstream response": + // Session/run management calls also log these; only the + // two /api/v1/chat/completions attempts carry the chat req_id. + // T5: the failed attempt logs "upstream response", the + // successful retry logs "upstream ok". + if entryField(*e, "path") != "/api/v1/chat/completions" { + continue + } + if ok1 == nil { + ok1 = e + } else if ok2 == nil { + ok2 = e + } + } + } + if transient == nil { + t.Fatal("no 'transient chat error, retrying once' entry") + } + if got := entryField(*transient, "attempt"); got != "1" { + t.Errorf("transient entry attempt = %q, want 1", got) + } + if entryField(*transient, "reason") == "" { + t.Error("transient entry missing reason") + } + if entryField(*transient, "backoff_ms") == "" { + t.Error("transient entry missing backoff_ms") + } + if retriedOK == nil { + t.Fatal("no 'chat retry succeeded' entry") + } + if got := entryField(*retriedOK, "attempts"); got != "2" { + t.Errorf("retry succeeded attempts = %q, want 2", got) + } + if entryField(*retriedOK, "ms") == "" { + t.Error("retry succeeded missing ms") + } + if trace == nil { + t.Fatal("no chat trace entry") + } + reqID := entryField(*trace, "req_id") + if reqID == "" { + t.Fatal("chat trace missing req_id") + } + for _, f := range []struct{ key, want string }{ + {"attempts", "2"}, + {"retried", "true"}, + {"statuses_seen", "500,200"}, + {"client_request_id", "req-1"}, + } { + if got := entryField(*trace, f.key); got != f.want { + t.Errorf("chat trace %s = %q, want %q", f.key, got, f.want) + } + } + if got := entryField(*trace, "backoff_ms"); got == "" { + t.Error("chat trace missing backoff_ms") + } + // D1: the same req_id must appear on both upstream attempt lines, and + // on the server-side retry lines. + if ok1 == nil || ok2 == nil { + t.Fatal("expected two upstream attempt entries (one per chat attempt)") + } + if got := entryField(*ok1, "req_id"); got != reqID { + t.Errorf("first upstream attempt req_id = %q, want %q", got, reqID) + } + if got := entryField(*ok2, "req_id"); got != reqID { + t.Errorf("second upstream attempt req_id = %q, want %q", got, reqID) + } + if got := entryField(*transient, "req_id"); got != reqID { + t.Errorf("transient entry req_id = %q, want %q", got, reqID) + } + if got := entryField(*retriedOK, "req_id"); got != reqID { + t.Errorf("retry succeeded req_id = %q, want %q", got, reqID) + } +} + +// TestTraceSessionIDThreaded verifies T3: the run's trace_session_id (the +// value threaded into codebuff_metadata) appears on "runs: run started" +// and on the chat trace of the request that acquired the run, with the +// same value. +func TestTraceSessionIDThreaded(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + mock.ChatBody = responsesChunks() + _, ring, logger := debugRing(t) + ts, _ := newTestServerWithLogger(t, nil, logger, ring, mock) + + _, data := doJSON(t, http.MethodPost, ts.URL+"/v1/chat/completions", chatBody(modelA), nil) + if !strings.Contains(string(data), "Hello") { + t.Fatalf("chat stream unexpected: %s", truncate(string(data), 200)) + } + var startedTS, traceTS string + recent := ring.Recent(400) + for i := range recent { + e := &recent[i] + switch e.Message { + case "runs: run started": + startedTS = entryField(*e, "trace_session_id") + case "chat trace": + traceTS = entryField(*e, "trace_session_id") + } + } + if startedTS == "" { + t.Fatal("runs: run started entry missing trace_session_id") + } + if traceTS == "" { + t.Fatal("chat trace entry missing trace_session_id") + } + if traceTS != startedTS { + t.Errorf("chat trace trace_session_id = %q, want the run started value %q", traceTS, startedTS) + } +} diff --git a/internal/server/wire_metrics_internal_test.go b/internal/server/wire_metrics_internal_test.go new file mode 100644 index 0000000..a2a5799 --- /dev/null +++ b/internal/server/wire_metrics_internal_test.go @@ -0,0 +1,150 @@ +package server + +import ( + "context" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" + "time" + + "freebuff-proxy/internal/logring" + "freebuff-proxy/internal/pool" + "freebuff-proxy/internal/upstream" +) + +// requestFailedFields returns the Fields of the newest `request failed` +// record, or nil when absent. +func requestFailedFields(entries []logring.Entry) []string { + for _, e := range entries { + if e.Message == "request failed" { + return e.Fields + } + } + return nil +} + +// countRequestFailedCode counts `request failed` records carrying the exact +// code= field (e.g. "code=rate_limited"). +func countRequestFailedCode(entries []logring.Entry, codeField string) int { + n := 0 + for _, e := range entries { + if e.Message != "request failed" { + continue + } + for _, f := range e.Fields { + if f == codeField { + n++ + break + } + } + } + return n +} + +// TestRequestFailedWarnDedupe pins D6: 100 identical rate_limited errors +// produce <=4 `request failed` WARNs (1st + every 50th) while the per-key +// ledger always counts every occurrence; non-rate-limit codes log every +// time. The client response is written on every call regardless. +func TestRequestFailedWarnDedupe(t *testing.T) { + resetRateLimitWarnDedupe() + t.Cleanup(resetRateLimitWarnDedupe) + + t.Run("rate_limited burst fires <=4 WARNs", func(t *testing.T) { + ring := logring.NewHandler(slog.NewTextHandler(io.Discard, nil), 500) + s := &Server{logger: slog.New(ring)} + rle := &upstream.RateLimitError{Status: "", RetryAfter: time.Minute, Window: "reset", Body: "daily quota exhausted"} + var gotStatus int + for i := 0; i < 100; i++ { + w := httptest.NewRecorder() + r := httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil) + s.writeError(w, r, rle, "deepseek/deepseek-v4-flash", nil) + gotStatus = w.Code + } + if gotStatus != http.StatusTooManyRequests { + t.Errorf("response status = %d, want 429 even on suppressed WARNs", gotStatus) + } + if n := countRequestFailedCode(ring.Recent(500), "code=rate_limited"); n > 4 { + t.Errorf("`request failed` WARNs = %d, want <= 4 for 100 identical rate_limited errors", n) + } + rateLimitWarnDedupe.mu.Lock() + n := rateLimitWarnDedupe.m["bridge|rate_limited|reset"] + rateLimitWarnDedupe.mu.Unlock() + if n != 100 { + t.Errorf("dedupe ledger count = %d, want 100 (counter always increments)", n) + } + }) + + t.Run("non-rate-limit codes log every time", func(t *testing.T) { + ring := logring.NewHandler(slog.NewTextHandler(io.Discard, nil), 500) + s := &Server{logger: slog.New(ring)} + be := &upstream.BanError{ResumesAt: time.Now().Add(time.Hour), Body: `{"status":"banned"}`} + for i := 0; i < 25; i++ { + w := httptest.NewRecorder() + s.writeError(w, httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil), be, "", nil) + } + if n := countRequestFailedCode(ring.Recent(500), "code=account_banned"); n != 25 { + t.Errorf("`request failed` WARNs for banned = %d, want 25 (every time)", n) + } + }) +} + +// TestRequestFailedStructuredFields pins T6: the `request failed` WARN +// carries req_id, retry_after, reset_at, token and model when the caller and +// the error provide them. +func TestRequestFailedStructuredFields(t *testing.T) { + resetRateLimitWarnDedupe() + t.Cleanup(resetRateLimitWarnDedupe) + future := time.Now().Add(2 * time.Hour).UTC().Truncate(time.Second) + + t.Run("req_id token model retry_after", func(t *testing.T) { + ring := logring.NewHandler(slog.NewTextHandler(io.Discard, nil), 100) + s := &Server{logger: slog.New(ring)} + rle := &upstream.RateLimitError{RetryAfter: 90 * time.Second, Window: "retry-after", Body: "quota"} + ctx := context.WithValue(context.Background(), reqIDKey{}, "req-test-123") + r := httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil).WithContext(ctx) + w := httptest.NewRecorder() + s.writeError(w, r, rle, "deepseek/deepseek-v4-flash", &pool.Lease{Token: 0}) + fields := requestFailedFields(ring.Recent(100)) + if fields == nil { + t.Fatal("no `request failed` WARN captured") + } + joined := strings.Join(fields, " ") + for _, want := range []string{ + "req_id=req-test-123", + "retry_after=90", + "token=1", + "model=deepseek/deepseek-v4-flash", + "code=rate_limited", + "status=429", + } { + if !strings.Contains(joined, want) { + t.Errorf("`request failed` missing %q in %s", want, joined) + } + } + if strings.Contains(joined, "reset_at=") { + t.Errorf("unexpected reset_at when the error carries none: %s", joined) + } + }) + + t.Run("reset_at when the error carries it", func(t *testing.T) { + ring := logring.NewHandler(slog.NewTextHandler(io.Discard, nil), 100) + s := &Server{logger: slog.New(ring)} + rle := &upstream.RateLimitError{ResetAt: future, Window: "reset", Body: "quota"} + w := httptest.NewRecorder() + s.writeError(w, httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil), rle, "", &pool.Lease{Token: 0}) + fields := requestFailedFields(ring.Recent(100)) + if fields == nil { + t.Fatal("no `request failed` WARN captured") + } + joined := strings.Join(fields, " ") + if want := "reset_at=" + future.Format(time.RFC3339); !strings.Contains(joined, want) { + t.Errorf("`request failed` missing %q in %s", want, joined) + } + if !strings.Contains(joined, "retry_after=") { + t.Errorf("`request failed` missing derived retry_after in %s", joined) + } + }) +} diff --git a/internal/server/wire_metrics_test.go b/internal/server/wire_metrics_test.go new file mode 100644 index 0000000..a5f6c10 --- /dev/null +++ b/internal/server/wire_metrics_test.go @@ -0,0 +1,63 @@ +package server_test + +import ( + "net/http" + "strings" + "testing" + + "freebuff-proxy/internal/testutil" +) + +// TestMetricsRateLimitEvents pins T7's metrics surface: a classified 429 +// chat renders freebuff_proxy_rate_limit_events_total with the token label. +func TestMetricsRateLimitEvents(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + mock.ChatStatus = http.StatusTooManyRequests + mock.ChatErrorBody = `{"error":"free_mode_rate_limited","message":"wait 30 minutes","retryAfterMs":1800000}` + ts, _ := newTestServer(t, nil, mock) + + resp, data := doJSON(t, http.MethodPost, ts.URL+"/v1/chat/completions", chatBody(modelA), nil) + if resp.StatusCode != http.StatusTooManyRequests { + t.Fatalf("chat status = %d, want 429: %s", resp.StatusCode, data) + } + + resp, data = doJSON(t, http.MethodGet, ts.URL+"/metrics", nil, nil) + if resp.StatusCode != http.StatusOK { + t.Fatalf("metrics status = %d, want 200: %s", resp.StatusCode, data) + } + body := string(data) + for _, want := range []string{ + "# HELP freebuff_proxy_rate_limit_events_total", + `freebuff_proxy_rate_limit_events_total{token="1",code="free_mode_rate_limited"} 1`, + } { + if !strings.Contains(body, want) { + t.Errorf("metrics missing %s in:\n%s", want, body) + } + } +} + +// TestMetricsRateLimitEventsLabelEscaping mirrors TestMetricsLabelEscaping +// for the code label: quotes in upstream-derived codes are escaped so the +// Prometheus text format stays parseable. +func TestMetricsRateLimitEventsLabelEscaping(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + mock.ChatStatus = http.StatusTooManyRequests + mock.ChatErrorBody = `{"error":"weird\"code","message":"x"}` + ts, _ := newTestServer(t, nil, mock) + + resp, data := doJSON(t, http.MethodPost, ts.URL+"/v1/chat/completions", chatBody(modelA), nil) + if resp.StatusCode != http.StatusTooManyRequests { + t.Fatalf("chat status = %d, want 429: %s", resp.StatusCode, data) + } + resp, data = doJSON(t, http.MethodGet, ts.URL+"/metrics", nil, nil) + if resp.StatusCode != http.StatusOK { + t.Fatalf("metrics status = %d, want 200: %s", resp.StatusCode, data) + } + body := string(data) + want := `freebuff_proxy_rate_limit_events_total{token="1",code="weird\"code"} 1` + if !strings.Contains(body, want) { + t.Errorf("metrics missing escaped label %s in:\n%s", want, body) + } +} diff --git a/internal/telemetry/telemetry.go b/internal/telemetry/telemetry.go index f41c143..64e062a 100644 --- a/internal/telemetry/telemetry.go +++ b/internal/telemetry/telemetry.go @@ -4,13 +4,17 @@ package telemetry import ( + "bytes" "context" + "encoding/json" "fmt" "io" "log/slog" + "math" "net/http" "os" "path/filepath" + "regexp" "strconv" "strings" "sync" @@ -29,22 +33,33 @@ const ( // timeFormat mirrors slog's text handler timestamp. const timeFormat = "2006-01-02T15:04:05.000Z07:00" +// LevelTrace is the most verbose log level, one step below debug. slog has +// no built-in trace level; -8 sits below LevelDebug (-4). slog's String() +// renders it "DEBUG-4", so the handlers and the startup banner print TRACE +// explicitly (see levelName). +const LevelTrace = slog.Level(-8) + // NewLogger builds the process logger at Info level, or Debug when verbose. -// It is a convenience wrapper over New keeping the original API. +// It is a convenience wrapper over New keeping the original API (text format). func NewLogger(verbose bool, logFile string) *slog.Logger { level := slog.LevelInfo if verbose { level = slog.LevelDebug } - return New(level, logFile) + return New(level, logFile, "text") } // ParseLevel parses a LOG_LEVEL-style string into a slog level. The empty -// string returns ok=false (caller falls back to its default). +// string returns ok=false (caller falls back to its default). "trace" +// (case-insensitive) maps to LevelTrace; the four slog names are accepted +// as before. func ParseLevel(s string) (slog.Level, bool) { if s == "" { return 0, false } + if strings.EqualFold(s, "trace") { + return LevelTrace, true + } var level slog.Level if err := level.UnmarshalText([]byte(s)); err != nil { return 0, false @@ -58,7 +73,10 @@ func ParseLevel(s string) (slog.Level, bool) { // actually opened — a single handler writes to both sinks and ANSI escapes // in a file are noise. A log file that cannot be opened is reported on // stderr and stderr-only logging continues, keeping its colors. -func New(level slog.Level, logFile string) *slog.Logger { +// +// format selects the handler: "json" writes one JSON object per record +// (real group nesting); anything else — including "" — is the text format. +func New(level slog.Level, logFile string, format string) *slog.Logger { w := io.Writer(os.Stderr) var file *os.File if logFile != "" { @@ -78,20 +96,51 @@ func New(level slog.Level, logFile string) *slog.Logger { } } - h := &textHandler{w: w, level: level, colorize: file == nil, file: file} - return slog.New(h) + switch format { + case "json": + return slog.New(&jsonHandler{w: w, level: level, file: file}) + default: + h := &textHandler{w: w, level: level, colorize: file == nil, file: file} + return slog.New(h) + } +} + +// levelName renders a level token. LevelTrace prints as TRACE instead of +// slog's "DEBUG-4" (the level is below DEBUG, so slog's String() appends the +// negative offset); every other level keeps slog's exact rendering. +func levelName(level slog.Level) string { + if level == LevelTrace { + return "TRACE" + } + return level.String() } // textHandler is a minimal slog text handler that colorizes the level token -// (time=... level=INFO msg=... key=value...). WithAttrs/WithGroup are no-ops: -// the process logger never carries bound attrs. file is the appended log -// file (nil for stderr-only), kept for tests and a future shutdown close. +// (time=... level=INFO msg=... key=value...). WithAttrs/WithGroup are +// copy-on-write: each returns a new handler with the base attrs/groups +// extended, so a handler never mutates the attrs it was built from. Bound +// attrs are rendered at the group depth active when they were bound — +// record attrs sit under all handler groups — mirroring slog's text +// handler (e.g. WithAttrs(pre).WithGroup("s") logs "pre=3 s.a=one"). file +// is the appended log file (nil for stderr-only), kept for tests and a +// future shutdown close. type textHandler struct { mu sync.Mutex level slog.Leveler w io.Writer colorize bool file *os.File + // attrs holds handler attrs bound via WithAttrs, each under the group + // depth active at bind time (len(h.groups) is the current depth). + attrs []boundAttrs + groups []string +} + +// boundAttrs is one WithAttrs batch together with the group depth it was +// bound under. +type boundAttrs struct { + depth int + attrs []slog.Attr } func (h *textHandler) Enabled(_ context.Context, level slog.Level) bool { @@ -104,24 +153,89 @@ func (h *textHandler) Handle(_ context.Context, r slog.Record) error { line := fmt.Sprintf("time=%s level=%s msg=%s", r.Time.Format(timeFormat), h.levelToken(r.Level), quoteMessage(r.Message)) + if len(h.attrs) == 0 && len(h.groups) == 0 { + // Fast path (the process logger never binds attrs): no allocation, + // byte-identical to the pre-WithAttrs handler. + r.Attrs(func(a slog.Attr) bool { + line += " " + a.Key + "=" + quoteMessage(a.Value.String()) + return true + }) + } else { + for _, ba := range h.attrs { + line = appendTextAttrs(line, strings.Join(h.groups[:ba.depth], "."), ba.attrs) + } + line = appendTextAttrs(line, strings.Join(h.groups, "."), collectAttrs(r)) + } + _, err := io.WriteString(h.w, line+"\n") + return err +} + +func (h *textHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return h + } + clone := *h + clone.attrs = append(append([]boundAttrs{}, h.attrs...), boundAttrs{depth: len(h.groups), attrs: attrs}) + return &clone +} + +func (h *textHandler) WithGroup(name string) slog.Handler { + if name == "" { + return h + } + clone := *h + clone.groups = append(append([]string{}, h.groups...), name) + return &clone +} + +// collectAttrs returns the record's attrs as a slice. +func collectAttrs(r slog.Record) []slog.Attr { + attrs := make([]slog.Attr, 0, r.NumAttrs()) r.Attrs(func(a slog.Attr) bool { - line += " " + a.Key + "=" + quoteMessage(a.Value.String()) + attrs = append(attrs, a) return true }) - _, err := io.WriteString(h.w, line+"\n") - return err + return attrs } -func (h *textHandler) WithAttrs(_ []slog.Attr) slog.Handler { return h } -func (h *textHandler) WithGroup(_ string) slog.Handler { return h } +// appendTextAttrs appends " key=value" pairs for attrs to line. When prefix +// is non-empty every key is rendered prefix.key; record group attrs extend +// the prefix (g.k=v), mirroring slog's text handler. Empty attrs and empty +// groups are skipped. +func appendTextAttrs(line, prefix string, attrs []slog.Attr) string { + for _, a := range attrs { + if a.Equal(slog.Attr{}) { + continue + } + if a.Value.Kind() == slog.KindGroup { + group := a.Value.Group() + if len(group) == 0 { + continue + } + line = appendTextAttrs(line, joinKey(prefix, a.Key), group) + continue + } + line += " " + joinKey(prefix, a.Key) + "=" + quoteMessage(a.Value.String()) + } + return line +} + +// joinKey prefixes key with prefix using slog's dotted group notation +// ("group.key"); prefix "" returns the key unchanged. +func joinKey(prefix, key string) string { + if prefix == "" { + return key + } + return prefix + "." + key +} // levelToken renders the level marker, colorized unless the sink includes a // file (ANSI escapes in a log file are noise). func (h *textHandler) levelToken(level slog.Level) string { if !h.colorize { - return level.String() + return levelName(level) } - return levelColor(level) + level.String() + ansiReset + return levelColor(level) + levelName(level) + ansiReset } func levelColor(level slog.Level) string { @@ -137,6 +251,214 @@ func levelColor(level slog.Level) string { } } +// jsonHandler is a minimal slog JSON handler: one valid JSON object per +// record with real nesting for WithGroup and group attrs. Never colorized +// (ANSI escapes would corrupt the JSON). WithAttrs/WithGroup are +// copy-on-write like the text handler's; bound attrs are written at the +// group depth active when they were bound, record attrs under all handler +// groups, mirroring slog's JSON handler. +type jsonHandler struct { + mu sync.Mutex + level slog.Leveler + w io.Writer + file *os.File + attrs []boundAttrs + groups []string +} + +func (h *jsonHandler) Enabled(_ context.Context, level slog.Level) bool { + return level >= h.level.Level() +} + +func (h *jsonHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return h + } + clone := *h + clone.attrs = append(append([]boundAttrs{}, h.attrs...), boundAttrs{depth: len(h.groups), attrs: attrs}) + return &clone +} + +func (h *jsonHandler) WithGroup(name string) slog.Handler { + if name == "" { + return h + } + clone := *h + clone.groups = append(append([]string{}, h.groups...), name) + return &clone +} + +func (h *jsonHandler) Handle(_ context.Context, r slog.Record) error { + h.mu.Lock() + defer h.mu.Unlock() + + var w jsonWriter + w.sep = []bool{false} + w.buf.WriteByte('{') + w.writePair("time", slog.StringValue(r.Time.Format(timeFormat))) + w.writePair("level", slog.StringValue(levelName(r.Level))) + w.writePair("msg", slog.StringValue(r.Message)) + + // Handler attrs (bound at their group depth), then record attrs under + // all handler groups. Group depths only grow, so groups opened for one + // batch stay open for the next. + openDepth := 0 + var opened []groupFrame + writeBatch := func(depth int, attrs []slog.Attr) { + for openDepth < depth { + r0, rs, pp := w.openObject(h.groups[openDepth]) + opened = append(opened, groupFrame{restore: r0, restoreSep: rs, parentPrior: pp}) + openDepth++ + } + w.writeAttrs(attrs) + } + for _, ba := range h.attrs { + writeBatch(ba.depth, ba.attrs) + } + writeBatch(len(h.groups), collectAttrs(r)) + for len(opened) > 0 { + f := opened[len(opened)-1] + opened = opened[:len(opened)-1] + w.closeObject(f.restore, f.restoreSep, f.parentPrior) + } + w.buf.WriteByte('}') + w.buf.WriteByte('\n') + _, err := io.WriteString(h.w, w.buf.String()) + return err +} + +// groupFrame records where a handler group was opened so it can be closed +// — or rewound entirely — when the batch ends. +type groupFrame struct { + restore int + restoreSep int + parentPrior bool +} + +// jsonWriter emits a JSON object incrementally. sep tracks, per nesting +// depth, whether an element has already been written at that depth (a comma +// is then required before the next one). +type jsonWriter struct { + buf bytes.Buffer + sep []bool +} + +// beforeValue writes the separator for the next element at the current +// depth and marks the depth non-empty. +func (w *jsonWriter) beforeValue() { + if w.sep[len(w.sep)-1] { + w.buf.WriteByte(',') + } + w.sep[len(w.sep)-1] = true +} + +func (w *jsonWriter) writePair(key string, v slog.Value) { + w.beforeValue() + writeJSONString(&w.buf, key) + w.buf.WriteByte(':') + writeJSONValue(&w.buf, v) +} + +// openObject writes "key":{ at the current depth and descends. It returns +// buffer and sep-stack positions — plus the parent's pre-open separator +// state — so closeObject can rewind the object if it turns out empty (slog +// suppresses empty groups). +func (w *jsonWriter) openObject(key string) (restore, restoreSep int, parentPrior bool) { + restore = w.buf.Len() + restoreSep = len(w.sep) + parentPrior = restoreSep > 0 && w.sep[restoreSep-1] + w.beforeValue() + writeJSONString(&w.buf, key) + w.buf.WriteByte(':') + w.buf.WriteByte('{') + w.sep = append(w.sep, false) + return restore, restoreSep, parentPrior +} + +// closeObject finishes an object opened by openObject: when the object +// received at least one element it is closed with '}'; an empty object is +// removed entirely (buffer and sep stack rewound, including the parent's +// separator state, since the comma before it was rewound too) so no empty +// groups leak into the output. +func (w *jsonWriter) closeObject(restore, restoreSep int, parentPrior bool) { + if w.sep[len(w.sep)-1] { + w.buf.WriteByte('}') + w.sep = w.sep[:len(w.sep)-1] + return + } + w.buf.Truncate(restore) + w.sep = w.sep[:restoreSep] + w.sep[restoreSep-1] = parentPrior +} + +// writeAttrs writes attrs into the object at the current depth. Group +// attrs open nested objects (rewound when empty), giving JSON handlers +// their real nesting. +func (w *jsonWriter) writeAttrs(attrs []slog.Attr) { + for _, a := range attrs { + if a.Equal(slog.Attr{}) { + continue + } + if a.Value.Kind() == slog.KindGroup { + group := a.Value.Group() + if len(group) == 0 { + continue + } + restore, restoreSep, parentPrior := w.openObject(a.Key) + w.writeAttrs(group) + w.closeObject(restore, restoreSep, parentPrior) + continue + } + w.writePair(a.Key, a.Value.Resolve()) + } +} + +// writeJSONValue writes v as its JSON representation. Strings are quoted +// and escaped; numbers and booleans are raw; durations and times render as +// strings (RFC3339-ms for times, matching the record time); Any values go +// through json.Marshal with a string fallback when they cannot marshal. +func writeJSONValue(buf *bytes.Buffer, v slog.Value) { + switch v.Kind() { + case slog.KindString: + writeJSONString(buf, v.String()) + case slog.KindInt64: + buf.WriteString(strconv.FormatInt(v.Int64(), 10)) + case slog.KindUint64: + buf.WriteString(strconv.FormatUint(v.Uint64(), 10)) + case slog.KindFloat64: + if f := v.Float64(); math.IsNaN(f) || math.IsInf(f, 0) { + buf.WriteString("null") + } else { + buf.WriteString(strconv.FormatFloat(f, 'g', -1, 64)) + } + case slog.KindBool: + if v.Bool() { + buf.WriteString("true") + } else { + buf.WriteString("false") + } + case slog.KindDuration: + writeJSONString(buf, v.Duration().String()) + case slog.KindTime: + writeJSONString(buf, v.Time().Format(timeFormat)) + case slog.KindAny: + data, err := json.Marshal(v.Any()) + if err != nil { + writeJSONString(buf, fmt.Sprint(v.Any())) + return + } + buf.Write(data) + } +} + +// writeJSONString writes s as a quoted, escaped JSON string. json.Marshal +// of a string cannot fail; invalid UTF-8 is replaced with U+FFFD, so the +// output is always valid JSON. +func writeJSONString(buf *bytes.Buffer, s string) { + data, _ := json.Marshal(s) + buf.Write(data) +} + // quoteMessage quotes multi-word messages so one line stays one record. // Values containing quotes, newlines, tabs, carriage returns or other // control characters are quoted too: an attr value (model name, URL path) @@ -172,14 +494,15 @@ var sensitiveHeaders = map[string]struct{}{ } // RedactHeaders returns a copy of h with the values of sensitive headers -// (Authorization, x-api-key, x-codebuff-api-key, Cookie, Set-Cookie) replaced -// by "[redacted]". The input header is not modified. +// (Authorization, x-api-key, x-codebuff-api-key, Cookie, Set-Cookie, and +// every x-freebuff-* header) replaced by "[redacted]". The input header is +// not modified. func RedactHeaders(h http.Header) map[string][]string { out := make(map[string][]string, len(h)) for k, vs := range h { copied := make([]string, len(vs)) copy(copied, vs) - if _, sensitive := sensitiveHeaders[strings.ToLower(k)]; sensitive { + if isSensitiveHeader(k) { for i := range copied { copied[i] = "[redacted]" } @@ -189,6 +512,34 @@ func RedactHeaders(h http.Header) map[string][]string { return out } +// isSensitiveHeader reports whether a header key must be redacted: the +// fixed secret set plus every x-freebuff-* header (session tokens, instance +// ids, model and acting-user metadata are all sensitive request context). +func isSensitiveHeader(k string) bool { + lower := strings.ToLower(k) + if _, ok := sensitiveHeaders[lower]; ok { + return true + } + return strings.HasPrefix(lower, "x-freebuff-") +} + +// cbTokenRE matches FreeBuff token values (the cb_ prefix the CLI mints). +var cbTokenRE = regexp.MustCompile(`cb_[A-Za-z0-9]+`) + +// bearerTokenRE matches Authorization-style "Bearer " sequences +// (tokens are base64url + . _ ~ + / = characters). +var bearerTokenRE = regexp.MustCompile(`Bearer [A-Za-z0-9._~+/=-]+`) + +// RedactSecrets replaces FreeBuff token values embedded in s with +// "[redacted]": cb_-prefixed tokens and "Bearer " sequences, both +// anywhere in the string. Apply it to every logged upstream body so raw +// token material can never reach the log sink. +func RedactSecrets(s string) string { + s = cbTokenRE.ReplaceAllString(s, "[redacted]") + s = bearerTokenRE.ReplaceAllString(s, "[redacted]") + return s +} + // sanitizeName makes a request path safe to embed in a dump file name on // every platform: separators, dots and each character that is invalid in // Windows file names are replaced with underscores. The 60-rune cap is diff --git a/internal/telemetry/telemetry_test.go b/internal/telemetry/telemetry_test.go index 2d43bb7..bdf018d 100644 --- a/internal/telemetry/telemetry_test.go +++ b/internal/telemetry/telemetry_test.go @@ -2,6 +2,8 @@ package telemetry import ( "bytes" + "context" + "encoding/json" "io" "log/slog" "net/http" @@ -9,22 +11,31 @@ import ( "path/filepath" "strings" "testing" + "time" "unicode/utf8" ) -// closeLogFile closes the log file held by a NewLogger result so TempDir -// cleanup can delete it (Windows refuses to delete open files). +// closeLogFile closes the log file held by a New/NewLogger result so +// TempDir cleanup can delete it (Windows refuses to delete open files). func closeLogFile(t *testing.T, logger *slog.Logger) { t.Helper() - th, ok := logger.Handler().(*textHandler) - if !ok { - t.Fatalf("logger handler is %T, want *textHandler", logger.Handler()) - } - th.mu.Lock() - defer th.mu.Unlock() - if th.file != nil { - _ = th.file.Close() - th.file = nil + switch th := logger.Handler().(type) { + case *textHandler: + th.mu.Lock() + defer th.mu.Unlock() + if th.file != nil { + _ = th.file.Close() + th.file = nil + } + case *jsonHandler: + th.mu.Lock() + defer th.mu.Unlock() + if th.file != nil { + _ = th.file.Close() + th.file = nil + } + default: + t.Fatalf("logger handler is %T, want *textHandler or *jsonHandler", logger.Handler()) } } @@ -166,6 +177,66 @@ func TestRedactHeadersNonCanonicalKey(t *testing.T) { } } +// TestRedactHeadersFreebuffPrefix verifies every x-freebuff-* header is +// redacted (session tokens, instance ids and account metadata are sensitive +// request context) while unrelated headers pass through untouched. +func TestRedactHeadersFreebuffPrefix(t *testing.T) { + h := http.Header{} + h.Set("X-Freebuff-Session-Id", "sess-abc") + h.Set("x-freebuff-model", "deepseek-v4-pro") + h.Set("X-Freebuff-Instance-Id", "inst-1") + h.Set("X-Freebuff-Heartbeat", "1") + h.Set("X-Request-Id", "req-123") + h.Set("Content-Type", "application/json") + + got := RedactHeaders(h) + for _, k := range []string{"X-Freebuff-Session-Id", "X-Freebuff-Model", "X-Freebuff-Instance-Id", "X-Freebuff-Heartbeat"} { + if v := got[k][0]; v != "[redacted]" { + t.Errorf("RedactHeaders[%q] = %q, want [redacted]", k, v) + } + } + if v := got["X-Request-Id"][0]; v != "req-123" { + t.Errorf("X-Request-Id = %q, want req-123 (not sensitive)", v) + } + if v := got["Content-Type"][0]; v != "application/json" { + t.Errorf("Content-Type = %q, want application/json", v) + } +} + +// TestRedactSecrets pins the token scrubber: cb_-prefixed tokens and +// Bearer sequences (base64url alphabet) are replaced everywhere, +// and strings without secrets pass through unchanged. +func TestRedactSecrets(t *testing.T) { + cases := []struct { + name string + in string + want string + }{ + {"cb token alone", "cb_AbC123", "[redacted]"}, + {"cb token in body", `{"error":"free_mode_limited","token":"cb_xyz789"}`, `{"error":"free_mode_limited","token":"[redacted]"}`}, + {"bearer header", "Authorization: Bearer abcDEF012._~+/=-9", "Authorization: [redacted]"}, + {"bearer in json", `{"auth":"Bearer xYz","ok":1}`, `{"auth":"[redacted]","ok":1}`}, + {"both forms", "token=cb_a1B2 auth=Bearer q.r-s", "token=[redacted] auth=[redacted]"}, + {"no secret", "plain text with no tokens", "plain text with no tokens"}, + {"empty", "", ""}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + if got := RedactSecrets(tc.in); got != tc.want { + t.Errorf("RedactSecrets(%q) = %q, want %q", tc.in, got, tc.want) + } + }) + } + // The input string is not mutated. + in := "cb_keep" + if got := RedactSecrets(in); got != "[redacted]" { + t.Errorf("RedactSecrets returned %q", got) + } + if in != "cb_keep" { + t.Errorf("RedactSecrets mutated its input: %q", in) + } +} + func TestParseLevel(t *testing.T) { if _, ok := ParseLevel(""); ok { t.Error(`ParseLevel("") ok=true, want false`) @@ -179,6 +250,18 @@ func TestParseLevel(t *testing.T) { if _, ok := ParseLevel("bogus"); ok { t.Error("ParseLevel(bogus) ok=true, want false") } + // trace is a first-class level, one step below debug, case-insensitive. + for _, s := range []string{"trace", "TRACE", "Trace"} { + if lv, ok := ParseLevel(s); !ok || lv != LevelTrace { + t.Errorf("ParseLevel(%q) = %v, ok=%v; want LevelTrace, true", s, lv, ok) + } + } + if LevelTrace >= slog.LevelDebug { + t.Errorf("LevelTrace = %v, want strictly below LevelDebug (%v)", LevelTrace, slog.LevelDebug) + } + if got := LevelTrace.String(); got != "DEBUG-4" { + t.Errorf("LevelTrace.String() = %q, want slog's DEBUG-4 (banner must special-case TRACE)", got) + } } func TestSanitizeName(t *testing.T) { @@ -279,30 +362,198 @@ func TestAttrValueEscaping(t *testing.T) { } } -// TestWithAttrsWithGroupNoOp pins the text handler's no-op -// WithAttrs/WithGroup contract: both return the SAME handler, and bound -// attrs/groups are silently dropped from the output (the process logger -// never carries them — a regression would double-print fields). -func TestWithAttrsWithGroupNoOp(t *testing.T) { +// TestTextHandlerWithAttrsWithGroup pins the text handler's copy-on-write +// WithAttrs/WithGroup contract: bound attrs are appended to every record, +// group keys get the dotted group.key prefix, and the handler a With* +// call was made on is never mutated (immutable base attrs). +func TestTextHandlerWithAttrsWithGroup(t *testing.T) { var buf bytes.Buffer h := &textHandler{w: &buf, level: slog.LevelInfo} - if got := h.WithAttrs([]slog.Attr{slog.String("k", "v")}); got != slog.Handler(h) { - t.Errorf("WithAttrs returned a different handler: %T", got) + + base := slog.New(h) + if got := h.WithAttrs([]slog.Attr{slog.String("k", "v")}); got == slog.Handler(h) { + t.Error("WithAttrs returned the same handler, want a copy") + } + if got := h.WithGroup("grp"); got == slog.Handler(h) { + t.Error("WithGroup returned the same handler, want a copy") } - if got := h.WithGroup("grp"); got != slog.Handler(h) { - t.Errorf("WithGroup returned a different handler: %T", got) + + // Without bound state the base handler output is untouched. + base.Info("plain") + if !strings.Contains(buf.String(), "msg=plain\n") { + t.Errorf("base handler output changed by With* calls: %q", buf.String()) } + + // Bound attrs first (at their bind-time depth, no group prefix yet), + // record attrs under the group — slog's text-handler order. + buf.Reset() logger := slog.New(h).With("bound", "attr").WithGroup("grp") - logger.Info("msg") + logger.Info("msg", "k", "v") out := buf.String() - if strings.Contains(out, "bound=attr") { - t.Errorf("bound attr leaked into output despite no-op WithAttrs: %q", out) + for _, want := range []string{"msg=msg", "bound=attr", "grp.k=v"} { + if !strings.Contains(out, want) { + t.Errorf("output %q missing %q", out, want) + } + } + if strings.Contains(out, "grp.bound=") { + t.Errorf("bound attr wrongly prefixed by a later group: %q", out) + } + if n := strings.Count(out, "\n"); n != 1 { + t.Errorf("record split across %d lines, want 1: %q", n, out) + } + + // A second WithGroup nests: grp.a.k=v. Record group attrs prefix too. + buf.Reset() + logger = slog.New(h).WithGroup("grp").WithGroup("a").With("b", "1") + logger.Info("nested", slog.Group("g", slog.Int("n", 2))) + out = buf.String() + for _, want := range []string{"grp.a.b=1", "grp.a.g.n=2"} { + if !strings.Contains(out, want) { + t.Errorf("nested output %q missing %q", out, want) + } + } + + // The original handler still has no bound state after all the With* + // calls above (copy-on-write left it immutable). + buf.Reset() + base.Info("still plain") + if strings.Contains(buf.String(), "bound=attr") || strings.Contains(buf.String(), "grp.") { + t.Errorf("base handler leaked bound state: %q", buf.String()) + } +} + +// TestTextHandlerShape pins the byte-for-byte output shape at info/debug +// for attr-less records (the process-logger contract) and the trace token. +func TestTextHandlerShape(t *testing.T) { + fixed := time.Date(2026, 8, 18, 12, 0, 0, 123000000, time.UTC) + var buf bytes.Buffer + h := &textHandler{w: &buf, level: LevelTrace} + + rec := slog.NewRecord(fixed, slog.LevelInfo, "hello", 0) + rec.AddAttrs(slog.String("k", "v")) + if err := h.Handle(context.Background(), rec); err != nil { + t.Fatal(err) + } + want := "time=2026-08-18T12:00:00.123Z level=INFO msg=hello k=v\n" + if got := buf.String(); got != want { + t.Errorf("text record = %q, want %q", got, want) + } + + buf.Reset() + rec = slog.NewRecord(fixed, LevelTrace, "trace line", 0) + if err := h.Handle(context.Background(), rec); err != nil { + t.Fatal(err) + } + if !strings.Contains(buf.String(), "level=TRACE ") { + t.Errorf("trace record level token not TRACE: %q", buf.String()) + } +} + +// TestJSONHandlerShape writes records through New with format "json" and +// verifies each line parses as JSON with the RFC3339-ms time, the level and +// msg fields, and real group nesting. +func TestJSONHandlerShape(t *testing.T) { + out := captureStderr(t, func() { + logger := New(LevelTrace, "", "json").With("node", "n1").WithGroup("svc") + logger.Info("hello", "k", "v", slog.Int("status", 200), slog.Group("http", slog.Int("latency_ms", 12))) + logger.Warn("warn line") + }) + lines := strings.Split(strings.TrimRight(out, "\n"), "\n") + if len(lines) != 2 { + t.Fatalf("expected 2 JSON lines, got %d: %q", len(lines), out) + } + var rec map[string]any + if err := json.Unmarshal([]byte(lines[0]), &rec); err != nil { + t.Fatalf("line 1 is not valid JSON: %v\n%q", err, lines[0]) + } + // RFC3339 with milliseconds (the record time is local, so no zone + // assertion). + tm, err := time.Parse("2006-01-02T15:04:05.000Z07:00", rec["time"].(string)) + if err != nil { + t.Errorf("time field %q not RFC3339-ms: %v", rec["time"], err) + } else if tm.IsZero() { + t.Errorf("time field parsed to zero time: %v", rec["time"]) + } + if rec["level"] != "INFO" { + t.Errorf("level = %v, want INFO", rec["level"]) + } + if rec["msg"] != "hello" { + t.Errorf("msg = %v, want hello", rec["msg"]) + } + // The bound "node" attr predates WithGroup("svc"), so it sits at the top + // level; record attrs nest inside svc — slog's semantics. + if rec["node"] != "n1" { + t.Errorf("node = %v, want n1 (bound before the group)", rec["node"]) + } + svc, ok := rec["svc"].(map[string]any) + if !ok { + t.Fatalf("svc field not nested object: %v", rec["svc"]) + } + if svc["k"] != "v" { + t.Errorf("svc.k = %v, want v", svc["k"]) + } + if svc["status"] != float64(200) { + t.Errorf("svc.status = %v, want 200", svc["status"]) + } + httpGroup, ok := svc["http"].(map[string]any) + if !ok { + t.Fatalf("svc.http not nested object: %v", svc["http"]) + } + if httpGroup["latency_ms"] != float64(12) { + t.Errorf("svc.http.latency_ms = %v, want 12", httpGroup["latency_ms"]) + } + // Color-free: JSON must not contain ANSI escapes. + if strings.Contains(out, "\x1b[") { + t.Errorf("json output contains ANSI escapes: %q", out) + } + // The warn line parses too and levels map to their slog names. + var w map[string]any + if err := json.Unmarshal([]byte(lines[1]), &w); err != nil { + t.Fatalf("line 2 is not valid JSON: %v\n%q", err, lines[1]) + } + if w["level"] != "WARN" || w["msg"] != "warn line" { + t.Errorf("warn record = %v, want level WARN msg warn line", w) + } +} + +// TestJSONHandlerEmptyGroups verifies that groups that end up empty are +// suppressed (slog's contract), so no "key":{} shells pollute the JSON. +func TestJSONHandlerEmptyGroups(t *testing.T) { + var buf bytes.Buffer + h := &jsonHandler{w: &buf, level: slog.LevelInfo} + logger := slog.New(h).WithGroup("x").WithGroup("y") + logger.Info("no groups") + var rec map[string]any + if err := json.Unmarshal(buf.Bytes(), &rec); err != nil { + t.Fatalf("output not valid JSON: %v\n%q", err, buf.String()) + } + if _, ok := rec["x"]; ok { + t.Errorf("empty group x leaked into output: %v", rec) + } + if rec["msg"] != "no groups" { + t.Errorf("msg = %v, want no groups", rec["msg"]) + } + + // A group with content is kept; an inner empty group is dropped. + buf.Reset() + logger = slog.New(&jsonHandler{w: &buf, level: slog.LevelInfo}). + WithGroup("x").With("a", 1).WithGroup("y") + logger.Info("kept", slog.Group("g")) + if err := json.Unmarshal(buf.Bytes(), &rec); err != nil { + t.Fatalf("output not valid JSON: %v\n%q", err, buf.String()) + } + x, ok := rec["x"].(map[string]any) + if !ok { + t.Fatalf("x not nested object: %v", rec) + } + if x["a"] != float64(1) { + t.Errorf("x.a = %v, want 1", x["a"]) } - if strings.Contains(out, "grp.") { - t.Errorf("group prefix leaked into output despite no-op WithGroup: %q", out) + if _, ok := x["y"]; ok { + t.Errorf("empty group y leaked: %v", x) } - if !strings.Contains(out, "msg=msg") { - t.Errorf("plain record missing: %q", out) + if _, ok := x["g"]; ok { + t.Errorf("empty group attr g leaked: %v", x) } } diff --git a/internal/testutil/env.go b/internal/testutil/env.go index b63d358..f60823e 100644 --- a/internal/testutil/env.go +++ b/internal/testutil/env.go @@ -14,7 +14,7 @@ var configEnvKeys = []string{ "LISTEN_ADDR", "UPSTREAM_BASE_URL", "AUTH_TOKENS", "ROTATION_INTERVAL", "REQUEST_TIMEOUT", "SESSION_CALL_TIMEOUT", "API_KEYS", "ADMIN_TOKEN", "COST_MODE", "TLS_FINGERPRINT", "REGISTRY_REFRESH", "DEBUG_DUMP", - "LOG_FILE", "LOG_LEVEL", "MAX_MESSAGES_PER_DAY", "IDLE_ROTATION_TIMEOUT", + "LOG_FILE", "LOG_LEVEL", "LOG_FORMAT", "MAX_MESSAGES_PER_DAY", "IDLE_ROTATION_TIMEOUT", "SAFE_MODE", "HYBRID_MODE", "MODELS_HIDE_UNAVAILABLE", "REQUEST_JITTER", "CLI_VERSION", "MODEL_ALIASES", "TRANSIENT_RETRIES", "SESSION_PERSIST", "SESSION_STATE_FILE", "AUTO_DISCOVER_TOKEN", "HTTP2_UPSTREAM", diff --git a/internal/upstream/client.go b/internal/upstream/client.go index 5b4648f..0329502 100644 --- a/internal/upstream/client.go +++ b/internal/upstream/client.go @@ -41,6 +41,7 @@ import ( "freebuff-proxy/internal/config" "freebuff-proxy/internal/stealth" + "freebuff-proxy/internal/telemetry" ) // Typed error sentinels. Callers use errors.Is against these; the concrete @@ -216,7 +217,12 @@ type RateLimitError struct { Limit float64 RecentCount float64 ResetAt time.Time - Body string // truncated upstream body + // Window is the T7 ledger window for this refusal (body "1 minute"/ + // "30 minutes" text, else "reset" when ResetAt is set, else + // "retry-after" when RetryAfter is set, else "none") — reused by the + // server's `request failed` WARN dedupe. + Window string + Body string // truncated upstream body } func (e *RateLimitError) Error() string { @@ -511,6 +517,11 @@ type ChatOptions struct { Model string RunID string SessionInstanceID string // "" when the session is disabled + // RequestID is the server's per-request correlation id (D1): the + // access wrapper mints it once and threads it here so the client's + // do()/retry log lines (upstream ok/error/transient/retry) share the + // server's req_id. Never sent upstream. + RequestID string // TraceSessionID is the per-run trace id minted once by the run manager // (crypto/rand UUID) and reused across the run's requests, mirroring the // CLI (run.ts: previousRun?.traceSessionId ?? randomUUID). Injected as @@ -572,6 +583,14 @@ type Client struct { transientRetries atomic.Int64 // transient transport failures retried fingerprintRotations atomic.Int64 // pinned fingerprint swaps ahead of a retry + // rateLimitEvents is the T7 rate-limit ledger: upstream rate-limit + // classifications counted by body code (rate_limited, spend_limited, + // ip_capped, insufficient_quota, limit_burst_rate, + // free_mode_rate_limited, ...). rateLimitMu guards the map; values are + // atomics so snapshot reads never race a concurrent classification. + rateLimitMu sync.Mutex + rateLimitEvents map[string]*atomic.Int64 + // waitingRoomRequired records that the last upstream refusal was a 428 // waiting_room_required (issue #94): the pre-session ad-chain + streak // flow must fire before the next session create (WAITING_ROOM_CHAIN @@ -668,6 +687,7 @@ func NewWithIndex(token string, tokenIndex int, cfg *config.Config) (*Client, er transientRetriesLimit: cfg.TransientRetries, http2Upstream: cfg.HTTP2Upstream, risk: stealth.DefaultRiskEngine, + rateLimitEvents: make(map[string]*atomic.Int64), } transport := http.DefaultTransport.(*http.Transport).Clone() @@ -779,12 +799,36 @@ func NewWithIndex(token string, tokenIndex int, cfg *config.Config) (*Client, er return c, nil } +// reqIDKey carries the request correlation id (opts.RequestID) through the +// request context for the do()/retry log lines. The key type is unexported; +// the server threads the same id via ChatOptions.RequestID (its own +// unexported server-side key is separate). +type reqIDKey struct{} + +// withReqID returns a context carrying the request correlation id. +func withReqID(ctx context.Context, id string) context.Context { + return context.WithValue(ctx, reqIDKey{}, id) +} + +// ReqID returns the request correlation id carried in ctx, or "" when the +// call was not made through ChatCompletions with opts.RequestID set (e.g. +// session/run management calls). +func ReqID(ctx context.Context) string { + id, _ := ctx.Value(reqIDKey{}).(string) + return id +} + // ChatCompletions POSTs an OpenAI-shaped request to the upstream chat // endpoint, injecting the CLI envelope, and returns the raw SSE body reader // on 2xx. On error status it drains (up to 500 chars), classifies, and // returns a typed error. The returned reader must be closed; closing it // releases the connection. func (c *Client) ChatCompletions(ctx context.Context, opts ChatOptions, body []byte) (io.ReadCloser, error) { + // D1: thread the server's correlation id into the request context so + // every do()/retry log line for this chat shares the server's req_id. + if opts.RequestID != "" { + ctx = withReqID(ctx, opts.RequestID) + } if c.requestJitter > 0 { var b [8]byte _, _ = cryptoRand.Read(b[:]) @@ -1432,8 +1476,32 @@ func (c *Client) do(req *http.Request, timeout time.Duration) (*http.Response, c } return nil, nil, fmt.Errorf("upstream: %s %s: %w", req.Method, req.URL.Path, werr) } + if resp.StatusCode >= 400 { + // T5 wire transparency: error responses are read (2KB cap), + // logged as `upstream response` (redacted, ≤500 runes), and + // re-wrapped so the caller's classification parses the same + // body. Never logged as `upstream ok` — a transport-level + // 200 and an upstream 429 are different classes of event. + bodyBytes, _ := io.ReadAll(io.LimitReader(resp.Body, 2048)) + _ = resp.Body.Close() + bodyText := telemetry.RedactSecrets(string(bodyBytes)) + class := errClassName(classifyError(resp.StatusCode, bodyText, resp.Header)) + attrs := []any{ + "method", req.Method, "path", req.URL.Path, + "status", resp.StatusCode, "ms", time.Since(start).Milliseconds(), + "class", class, + "body", truncateRunes(bodyText, 500), + } + if reqID := ReqID(ctx); reqID != "" { + attrs = append(attrs, "req_id", reqID) + } + slog.Debug("upstream response", attrs...) + resp.Body = io.NopCloser(strings.NewReader(bodyText)) + return resp, cancel, nil + } slog.Debug("upstream ok", "method", req.Method, "path", req.URL.Path, - "status", resp.StatusCode, "ms", time.Since(start).Milliseconds()) + "status", resp.StatusCode, "ms", time.Since(start).Milliseconds(), + "req_id", ReqID(ctx)) return resp, cancel, nil } @@ -1446,7 +1514,8 @@ func (c *Client) do(req *http.Request, timeout time.Duration) (*http.Response, c body, bodyErr := replayBody() if bodyErr != nil { slog.Debug("upstream retry aborted: body replay failed", - "token", c.tokenIndex+1, "attempt", attempt, "err", bodyErr) + "token", c.tokenIndex+1, "attempt", attempt, "err", bodyErr, + "req_id", ReqID(ctx)) } else { // Count the retry only once the replay succeeded: the counter // reflects retries that actually fired, not aborted ones. @@ -1455,7 +1524,7 @@ func (c *Client) do(req *http.Request, timeout time.Duration) (*http.Response, c req.Close = true // fresh connection for the retry slog.Debug("upstream transient failure, retrying", "token", c.tokenIndex+1, "attempt", attempt, "reason", err.Error(), - "path", req.URL.Path) + "path", req.URL.Path, "req_id", ReqID(ctx)) timer := time.NewTimer(c.retryDelay()) select { case <-timer.C: @@ -1472,7 +1541,7 @@ func (c *Client) do(req *http.Request, timeout time.Duration) (*http.Response, c } slog.Debug("upstream error", "method", req.Method, "path", req.URL.Path, - "ms", time.Since(start).Milliseconds(), "err", err) + "ms", time.Since(start).Milliseconds(), "err", err, "req_id", ReqID(ctx)) if cancel != nil { cancel() } @@ -1525,6 +1594,35 @@ func (c *Client) TransientRetries() int64 { return c.transientRetries.Load() } // TRANSIENT_RETRIES budget, issue #75). func (c *Client) CapacityDeferredRetries() int64 { return c.capacityDeferredRetries.Load() } +// countRateLimitEvent increments the per-code rate-limit ledger (T7). The +// map entry is created lazily so clients built without the constructor +// (tests, bridge entries) still record safely. +func (c *Client) countRateLimitEvent(code string) { + c.rateLimitMu.Lock() + ctr := c.rateLimitEvents[code] + if ctr == nil { + ctr = &atomic.Int64{} + if c.rateLimitEvents == nil { + c.rateLimitEvents = make(map[string]*atomic.Int64) + } + c.rateLimitEvents[code] = ctr + } + c.rateLimitMu.Unlock() + ctr.Add(1) +} + +// RateLimitEvents returns a copy of this client's per-code rate-limit +// classification counters (pool snapshot /metrics aggregation). +func (c *Client) RateLimitEvents() map[string]int64 { + c.rateLimitMu.Lock() + defer c.rateLimitMu.Unlock() + out := make(map[string]int64, len(c.rateLimitEvents)) + for code, ctr := range c.rateLimitEvents { + out[code] = ctr.Load() + } + return out +} + // PendingWaitingRoomChain reports whether the client last classified a 428 // waiting_room_required (issue #94) and the pre-session chain has not been // fired/cleared yet. The pool consults it before a session create when @@ -2050,6 +2148,16 @@ func (c *Client) classify(status int, body string, hdr http.Header) error { if errors.Is(err, ErrWaitingRoomRequired) { c.waitingRoomRequired.Store(true) } + // T7 ledger: count every rate-limit-family classification by its + // upstream body code and surface one Debug line carrying the FULL + // (redacted) body, so the distinct refusal codes (free_mode_rate_limited, + // insufficient_quota, limit_burst_rate, ip_capped, spend_limited, + // rate_limited, ...) are distinguishable in logs before the #133 + // behavior fix lands. + if code, window := rateLimitInfo(body, err); code != "" { + c.countRateLimitEvent(code) + logRateLimitClassified(status, body, code, window, err) + } return err } @@ -2157,6 +2265,163 @@ func classifyError(status int, body string, hdr http.Header) error { } } +// rateLimitInfo derives the T7 ledger code and window for a rate-limit +// classification. The classification must be in the rate-limit error family +// (RateLimitError/IpCappedError/CapacityDeferredError) — 403 bans, 401 auth +// refusals, waiting rooms and other gates never count; code is empty then +// and nothing is logged. +func rateLimitInfo(body string, err error) (code, window string) { + switch err.(type) { + case *RateLimitError, *IpCappedError, *CapacityDeferredError: + default: + return "", "" + } + code = rateLimitCode(body, err) + if code == "" { + return "", "" + } + return code, rateLimitWindow(body, err) +} + +// rateLimitCode extracts the upstream refusal code from the body's +// "error"/"type" field (free_mode_rate_limited, insufficient_quota, +// limit_burst_rate, ip_capped, spend_limited, rate_limited, ...), falling +// back to the classified error type when the body carries no code key. +func rateLimitCode(body string, err error) string { + if code := bodyCode(body); code != "" { + return code + } + switch e := err.(type) { + case *CapacityDeferredError: + return "free_mode_capacity_deferred" + case *IpCappedError: + return "ip_capped" + case *RateLimitError: + if e.Status != "" { + return e.Status // load_shedding | peak_hours + } + return "rate_limited" + } + return "" +} + +// bodyCode reads the first non-empty "error":"X" or "type":"X" string from a +// JSON error body (the ledger's code source). +func bodyCode(body string) string { + var raw struct { + Error string `json:"error"` + Type string `json:"type"` + } + if json.Unmarshal([]byte(body), &raw) != nil { + return "" + } + if raw.Error != "" { + return raw.Error + } + return raw.Type +} + +// rateLimitWindow maps a rate-limit classification to the shared window +// table: the body's own "1 minute"/"30 minutes" text when present, else +// "reset" when the error carries a reset timestamp, else "retry-after" when +// it carries a retry delay, else "none". +func rateLimitWindow(body string, err error) string { + lower := strings.ToLower(body) + if strings.Contains(lower, "1 minute") { + return "1 minute" + } + if strings.Contains(lower, "30 minutes") { + return "30 minutes" + } + switch e := err.(type) { + case *RateLimitError: + if !e.ResetAt.IsZero() { + return "reset" + } + if e.RetryAfter > 0 { + return "retry-after" + } + case *IpCappedError: + if e.RetryAfter > 0 { + return "retry-after" + } + case *CapacityDeferredError: + if e.RetryAfter > 0 { + return "retry-after" + } + } + return "none" +} + +// rateLimitFields extracts the retry-after delay and reset timestamp a +// rate-limit-family error carries, for the classification Debug line. +func rateLimitFields(err error) (time.Duration, time.Time) { + switch e := err.(type) { + case *RateLimitError: + return e.RetryAfter, e.ResetAt + case *IpCappedError: + return e.RetryAfter, time.Time{} + case *CapacityDeferredError: + return e.RetryAfter, time.Time{} + } + return 0, time.Time{} +} + +// logRateLimitClassified emits the T7 ledger Debug line. The body is logged +// in FULL (the 200-rune truncation applies to the HTTP error response only) +// and must already be redacted by the caller. +func logRateLimitClassified(status int, body, code, window string, err error) { + attrs := []any{ + "status", status, + "code", code, + "window", window, + "body", body, + } + if retryAfter, resetAt := rateLimitFields(err); retryAfter > 0 { + attrs = append(attrs, "retry_after", int(retryAfter.Seconds())) + if !resetAt.IsZero() { + attrs = append(attrs, "reset_at", resetAt.UTC().Format(time.RFC3339)) + } + } + slog.Debug("upstream rate limit classified", attrs...) +} + +// errClassName names the classified error type for the `upstream response` +// debug line (T5). Wrapped sentinel errors (auth/session/run refusals built +// with fmt.Errorf) fall back to the generic upstream error class. +func errClassName(err error) string { + switch err.(type) { + case *RateLimitError: + return "RateLimitError" + case *IpCappedError: + return "IpCappedError" + case *BanError: + return "BanError" + case *CountryBlockedError: + return "CountryBlockedError" + case *CreditsError: + return "CreditsError" + case *SessionLimitError: + return "SessionLimitError" + case *SessionSupersededError: + return "SessionSupersededError" + case *LimitedIpError: + return "LimitedIpError" + case *CapacityDeferredError: + return "CapacityDeferredError" + case *WaitingRoomError: + return "WaitingRoomError" + case *WaitingRoomRequiredError: + return "WaitingRoomRequiredError" + case *UpstreamError: + return "UpstreamError" + } + if err == nil { + return "" + } + return "UpstreamError" +} + // parseCountryBlock builds a CountryBlockedError from a 403 country_blocked // body, extracting countryCode/countryBlockReason/ipPrivacySignals // best-effort (absent fields are tolerated). @@ -2343,6 +2608,10 @@ func parseRateLimit(body string, headerRetryAfter time.Duration) error { if rle.RetryAfter <= 0 { rle.RetryAfter = 60 * time.Second } + // T7 ledger window, computed after ResetAt/RetryAfter are finalized + // (the Pacific-midnight fallback above sets ResetAt, so the window is + // "reset" for timestamp-less 429s). + rle.Window = rateLimitWindow(body, rle) return rle } diff --git a/internal/upstream/client_test.go b/internal/upstream/client_test.go index 29738a0..9f51feb 100644 --- a/internal/upstream/client_test.go +++ b/internal/upstream/client_test.go @@ -3564,3 +3564,21 @@ func TestDeviceOSWireContract(t *testing.T) { } } } + +// TestReqIDContextHelpers pins the D1 ctx plumbing: withReqID stores the id +// and ReqID reads it through descendant contexts (the timeout wraps in +// ChatCompletions/do derive from the wrapped ctx). +func TestReqIDContextHelpers(t *testing.T) { + if got := ReqID(context.Background()); got != "" { + t.Errorf("ReqID(background) = %q, want empty", got) + } + ctx := withReqID(context.Background(), "req-123") + if got := ReqID(ctx); got != "req-123" { + t.Errorf("ReqID = %q, want req-123", got) + } + child, cancel := context.WithTimeout(ctx, time.Second) + defer cancel() + if got := ReqID(child); got != "req-123" { + t.Errorf("ReqID(child) = %q, want req-123 (value must survive descendant wraps)", got) + } +} diff --git a/internal/upstream/wire_metrics_test.go b/internal/upstream/wire_metrics_test.go new file mode 100644 index 0000000..74b702c --- /dev/null +++ b/internal/upstream/wire_metrics_test.go @@ -0,0 +1,241 @@ +package upstream + +import ( + "errors" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" + "time" + + "freebuff-proxy/internal/config" + "freebuff-proxy/internal/logring" + "freebuff-proxy/internal/testutil" +) + +// entryFields returns the Fields of the newest entry whose message matches, +// or nil when absent. +func entryFields(entries []logring.Entry, msg string) []string { + for _, e := range entries { + if e.Message == msg { + return e.Fields + } + } + return nil +} + +// TestDoUpstreamResponseLogsAndPreservesBody pins T5: a >=400 upstream +// response is logged as `upstream response` (redacted body, error class, +// req_id when present) and the body is re-wrapped so the caller's +// classification still parses it (retryAfterMs survives the round-trip). +func TestDoUpstreamResponseLogsAndPreservesBody(t *testing.T) { + testutil.UnsetConfigEnv(t) + const upstreamBody = `{"error":"free_mode_rate_limited","message":"wait 30 minutes before retrying cb_token_abc","retryAfterMs":1800000}` + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(http.StatusTooManyRequests) + _, _ = w.Write([]byte(upstreamBody)) + })) + defer srv.Close() + + client, err := New("tok-0", &config.Config{UpstreamBaseURL: srv.URL, CostMode: "free"}) + if err != nil { + t.Fatal(err) + } + + ring := logring.NewHandler(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug}), 200) + orig := slog.Default() + slog.SetDefault(slog.New(ring)) + t.Cleanup(func() { slog.SetDefault(orig) }) + + req, err := http.NewRequest(http.MethodPost, srv.URL+"/api/v1/chat/completions", nil) + if err != nil { + t.Fatal(err) + } + resp, cancel, err := client.do(req, 5*time.Second) + if err != nil { + t.Fatal(err) + } + defer cancel() + bodyText := drainBody(resp.Body) + _ = resp.Body.Close() + cerr := client.classify(resp.StatusCode, bodyText, resp.Header) + + // The caller still parses the re-wrapped body: retryAfterMs survived, + // and the redacted body never leaks the token downstream. + var rle *RateLimitError + if !errors.As(cerr, &rle) { + t.Fatalf("classify = %T, want *RateLimitError", cerr) + } + if rle.RetryAfter != 30*time.Minute { + t.Errorf("RetryAfter = %v, want 30m (body must survive the re-wrap)", rle.RetryAfter) + } + if strings.Contains(rle.Body, "cb_token_abc") { + t.Errorf("rle.Body leaked the redacted token: %q", rle.Body) + } + + entries := ring.Recent(200) + fields := entryFields(entries, "upstream response") + if fields == nil { + t.Fatalf("no `upstream response` line captured") + } + joined := strings.Join(fields, " ") + for _, want := range []string{ + "method=POST", + "path=/api/v1/chat/completions", + "status=429", + "class=RateLimitError", + "wait 30 minutes before retrying", + "[redacted]", + } { + if !strings.Contains(joined, want) { + t.Errorf("`upstream response` missing %q in %s", want, joined) + } + } + if strings.Contains(joined, "cb_token_abc") { + t.Errorf("`upstream response` body not redacted: %s", joined) + } + + // T7 classification line: FULL redacted body, correct code + window. + fields = entryFields(entries, "upstream rate limit classified") + if fields == nil { + t.Fatalf("no `upstream rate limit classified` line captured") + } + joined = strings.Join(fields, " ") + for _, want := range []string{ + "status=429", + "code=free_mode_rate_limited", + "window=30 minutes", + "retry_after=1800", + "wait 30 minutes before retrying", // full body, not 200-rune truncated + } { + if !strings.Contains(joined, want) { + t.Errorf("`upstream rate limit classified` missing %q in %s", want, joined) + } + } + if strings.Contains(joined, "cb_token_abc") { + t.Errorf("classification body not redacted: %s", joined) + } + + // Ledger counter incremented exactly once. + events := client.RateLimitEvents() + if events["free_mode_rate_limited"] != 1 { + t.Errorf("RateLimitEvents[free_mode_rate_limited] = %d, want 1 (all: %v)", events["free_mode_rate_limited"], events) + } +} + +// TestDoKeepsUpstreamOkForSuccess pins T5's split: a <400 response still logs +// `upstream ok` and is returned untouched (no re-wrap, no class/body). +func TestDoKeepsUpstreamOkForSuccess(t *testing.T) { + testutil.UnsetConfigEnv(t) + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte("data: ok\n\n")) + })) + defer srv.Close() + + client, err := New("tok-0", &config.Config{UpstreamBaseURL: srv.URL, CostMode: "free"}) + if err != nil { + t.Fatal(err) + } + ring := logring.NewHandler(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug}), 100) + orig := slog.Default() + slog.SetDefault(slog.New(ring)) + t.Cleanup(func() { slog.SetDefault(orig) }) + + req, err := http.NewRequest(http.MethodPost, srv.URL+"/api/v1/chat/completions", nil) + if err != nil { + t.Fatal(err) + } + resp, cancel, err := client.do(req, 5*time.Second) + if err != nil { + t.Fatal(err) + } + defer cancel() + got := drainBody(resp.Body) + if got != "data: ok\n\n" { + t.Errorf("body = %q, want untouched 200 body", got) + } + entries := ring.Recent(100) + if entryFields(entries, "upstream ok") == nil { + t.Errorf("missing `upstream ok` for 200 response") + } + if entryFields(entries, "upstream response") != nil { + t.Errorf("`upstream response` must not fire for 200 responses") + } +} + +// TestRateLimitClassificationLedger pins the T7 counters: distinct upstream +// body codes are counted independently, and non-rate-limit classifications +// (403 bans) never touch the ledger. +func TestRateLimitClassificationLedger(t *testing.T) { + testutil.UnsetConfigEnv(t) + client, err := New("tok-0", &config.Config{UpstreamBaseURL: "http://127.0.0.1:1", CostMode: "free"}) + if err != nil { + t.Fatal(err) + } + for i := 0; i < 3; i++ { + client.classify(http.StatusTooManyRequests, `{"error":"free_mode_rate_limited","message":"wait 1 minute"}`, http.Header{}) + } + client.classify(http.StatusTooManyRequests, `{"error":"insufficient_quota","message":"load is saturated"}`, http.Header{}) + client.classify(http.StatusTooManyRequests, `{"error":"limit_burst_rate","message":"slow down"}`, http.Header{}) + client.classify(http.StatusTooManyRequests, `{"status":"rate_limited","retryAfterMs":48549499}`, http.Header{}) + client.classify(http.StatusForbidden, `{"status":"banned"}`, http.Header{}) // NOT a rate-limit event + + events := client.RateLimitEvents() + want := map[string]int64{ + "free_mode_rate_limited": 3, + "insufficient_quota": 1, + "limit_burst_rate": 1, + "rate_limited": 1, + } + for code, n := range want { + if events[code] != n { + t.Errorf("events[%q] = %d, want %d (all: %v)", code, events[code], n, events) + } + } + for code, n := range events { + if want[code] != n { + t.Errorf("unexpected ledger entry %q=%d", code, n) + } + } +} + +// TestRateLimitWindowTable pins the shared window derivation table. +func TestRateLimitWindowTable(t *testing.T) { + future := time.Now().Add(time.Hour) + cases := []struct { + name string + body string + err error + want string + }{ + {"body 1 minute text", `{"error":"free_mode_rate_limited","message":"wait 1 minute"}`, &RateLimitError{RetryAfter: time.Minute}, "1 minute"}, + {"body 30 minutes text", `{"error":"free_mode_rate_limited","message":"wait 30 minutes"}`, &RateLimitError{RetryAfter: 30 * time.Minute}, "30 minutes"}, + {"reset wins over retry-after", `{}`, &RateLimitError{RetryAfter: time.Minute, ResetAt: future}, "reset"}, + {"retry-after", `{}`, &RateLimitError{RetryAfter: time.Minute}, "retry-after"}, + {"none", `{}`, &RateLimitError{}, "none"}, + } + for _, tc := range cases { + if got := rateLimitWindow(tc.body, tc.err); got != tc.want { + t.Errorf("%s: rateLimitWindow = %q, want %q", tc.name, got, tc.want) + } + } +} + +// TestRateLimitInfoExcludesNonRateLimit pins that the ledger code is empty +// for classifications outside the rate-limit family (no counter, no log). +func TestRateLimitInfoExcludesNonRateLimit(t *testing.T) { + for _, err := range []error{ + &BanError{ResumesAt: time.Now().Add(time.Hour)}, + &WaitingRoomError{RetryAfter: time.Minute}, + &SessionSupersededError{Status: http.StatusConflict}, + &UpstreamError{Status: http.StatusBadGateway}, + } { + if code, _ := rateLimitInfo(`{"error":"x"}`, err); code != "" { + t.Errorf("rateLimitInfo(%T) = %q, want empty", err, code) + } + } +} From 7e84a10ecc6e557c18ec3ab05738556a559a6711 Mon Sep 17 00:00:00 2001 From: trefeon Date: Tue, 18 Aug 2026 15:22:05 +0700 Subject: [PATCH 2/6] logging: session lifecycle reasons, re-admit storm detector, coverage Wave 2 of the observability plan. Why: session end reasons were inconsistent and invisible at WARN; the re-admit 409 storm (issue #132) produced 60+ uncorrelated DEBUG lines with no summary; admin actions, silent endpoints, and four silent packages left the log blind to reloads, failed logins, config saves, registry success, updatecheck decisions, webhook failures, stealth picks, spend updates, and DEBUG_DUMP write errors. - session: terminal events carry table reasons (ended/superseded/shutdown/ model_lock/expired/409/poll/store); new InvalidateWithReason; re-admit storm detector fires ONE Info summary (count/duration_ms/superseded/ burned_slots) per 60s burst; heartbeat poll Debug (instance/ms/status) + heartbeat-end WARN with reason - admin audit: reload success/failure, login failure (no credential), config save changed key NAMES only, token add/remove + remote - silent endpoints: unsupported_endpoint WARN, count_tokens WARN (was Error), /v1/models empty-registry WARN - LOG_ACCESS config (default true); access quiet paths (/healthz, /metrics, OPTIONS) rate-limited to 1/min - packages: registry refresh success INFO (+ms, deduped the main.go copy), updatecheck decision, webhook send failure WARN, stealth profile pick, spend bucket updates, DEBUG_DUMP write failure WARN --- cmd/freebuff-proxy/main.go | 4 +- internal/config/config.go | 6 + internal/config/config_test.go | 55 +++- internal/notify/notify.go | 31 ++- internal/notify/notify_test.go | 56 +++++ internal/pool/spend.go | 13 + internal/pool/spend_test.go | 27 ++ internal/registry/registry.go | 18 +- internal/registry/registry_test.go | 28 +++ internal/server/logging_wave2_test.go | 305 ++++++++++++++++++++++ internal/server/server.go | 181 ++++++++++++- internal/server/server_api_test.go | 1 + internal/server/server_test.go | 1 + internal/server/server_wave6_test.go | 1 + internal/session/session.go | 195 +++++++++++++- internal/session/session_test.go | 308 +++++++++++++++++++++++ internal/stealth/profiles.go | 33 ++- internal/stealth/stealth_test.go | 34 +++ internal/testutil/env.go | 2 +- internal/updatecheck/updatecheck.go | 26 +- internal/updatecheck/updatecheck_test.go | 49 ++++ internal/upstream/client.go | 6 +- internal/upstream/client_test.go | 35 +++ 23 files changed, 1383 insertions(+), 32 deletions(-) create mode 100644 internal/server/logging_wave2_test.go diff --git a/cmd/freebuff-proxy/main.go b/cmd/freebuff-proxy/main.go index c18cc56..e46bda5 100644 --- a/cmd/freebuff-proxy/main.go +++ b/cmd/freebuff-proxy/main.go @@ -481,9 +481,9 @@ func refreshLoop(ctx context.Context, logger *slog.Logger, reg *registry.Registr } func logRegistryRefresh(ctx context.Context, logger *slog.Logger, reg *registry.Registry) { + // Success is logged inside Registry.Refresh (agents/models/ms); only the + // failure path lives here so refresh failures stay visible at the caller. if err := reg.Refresh(ctx); err != nil { logger.Warn("registry refresh failed; keeping previous state", "err", err) - return } - logger.Info("registry refreshed", "agents", len(reg.AgentIDs()), "models", reg.ModelCount()) } diff --git a/internal/config/config.go b/internal/config/config.go index 41ac114..e6f0529 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -53,6 +53,7 @@ type Config struct { LogFile string LogLevel string // "" (use -v/default) or debug|info|warn|error|trace LogFormat string // "text" (default) or "json" + LogAccess bool // true = per-request access log lines (LOG_ACCESS; default true, an empty .env line keeps it enabled) MaxMessagesPerDay int // 0 = unlimited: per-token cap on successful chats per 24h MaxSpendPerDay int64 // 0 = unlimited: ADVISORY per-token Pacific-day spend ceiling in ledger units (tokens from upstream usage blocks; issue #122). Never blocks — the upstream $ ceilings ($15 full / $5 limited / $0.50 restricted, compose by minimum, server-enforced) are the real gate. Surfaced as SpendLimit/SpendPct on /healthz so operator comparisons align with the Pacific-midnight reset. IdleRotationTimeout time.Duration // 0 = disabled: pause rotation/refresh after this idle period @@ -188,6 +189,7 @@ type rawConfig struct { LogFile string `json:"LOG_FILE"` LogLevel string `json:"LOG_LEVEL"` LogFormat string `json:"LOG_FORMAT"` + LogAccess bool `json:"LOG_ACCESS"` MaxMessagesPerDay *int `json:"MAX_MESSAGES_PER_DAY"` MaxSpendPerDay *int `json:"MAX_SPEND_PER_DAY"` IdleRotationTimeout string `json:"IDLE_ROTATION_TIMEOUT"` @@ -230,6 +232,7 @@ func defaultRawConfig() rawConfig { MaxSpendPerDay: nil, // 0 = unlimited advisory spend ceiling (never enforced) IdleRotationTimeout: "", // "" = disabled (unset → SAFE_MODE preset may fill) SafeMode: true, // anti-ban presets on by default; set SAFE_MODE=false to disable + LogAccess: true, // per-request access lines on by default; LOG_ACCESS=false disables them HybridMode: false, // relay client tokens AND serve the pool (off by default) CORSAllowedOrigin: "*", // browser clients reach /v1/* cross-origin by default RequestJitter: "", // "" = disabled (unset → SAFE_MODE preset may fill) @@ -382,6 +385,7 @@ func Load(configPath string) (Config, error) { overrideString(&raw.LogFile, "LOG_FILE") overrideString(&raw.LogLevel, "LOG_LEVEL") overrideString(&raw.LogFormat, "LOG_FORMAT") + overrideBool(&raw.LogAccess, "LOG_ACCESS") overrideInt(&raw.MaxMessagesPerDay, "MAX_MESSAGES_PER_DAY") overrideInt(&raw.MaxSpendPerDay, "MAX_SPEND_PER_DAY") overrideString(&raw.IdleRotationTimeout, "IDLE_ROTATION_TIMEOUT") @@ -614,6 +618,7 @@ func Load(configPath string) (Config, error) { LogFile: strings.TrimSpace(raw.LogFile), LogLevel: strings.TrimSpace(raw.LogLevel), LogFormat: logFormat, + LogAccess: raw.LogAccess, MaxMessagesPerDay: maxMessagesPerDay, MaxSpendPerDay: maxSpendPerDay, IdleRotationTimeout: idleRotationTimeout, @@ -937,6 +942,7 @@ func applyDotenv(raw *rawConfig, path string) error { overrideStringFrom(&raw.LogFile, get, "LOG_FILE") overrideStringFrom(&raw.LogLevel, get, "LOG_LEVEL") overrideStringFrom(&raw.LogFormat, get, "LOG_FORMAT") + overrideBoolFrom(&raw.LogAccess, get, "LOG_ACCESS") overrideIntFrom(&raw.MaxMessagesPerDay, get, "MAX_MESSAGES_PER_DAY") overrideIntFrom(&raw.MaxSpendPerDay, get, "MAX_SPEND_PER_DAY") overrideStringFrom(&raw.IdleRotationTimeout, get, "IDLE_ROTATION_TIMEOUT") diff --git a/internal/config/config_test.go b/internal/config/config_test.go index 886c5d6..cbadb2c 100644 --- a/internal/config/config_test.go +++ b/internal/config/config_test.go @@ -17,7 +17,7 @@ import ( var envKeys = []string{ "LISTEN_ADDR", "UPSTREAM_BASE_URL", "AUTH_TOKENS", "ROTATION_INTERVAL", "REQUEST_TIMEOUT", "SESSION_CALL_TIMEOUT", "API_KEYS", "COST_MODE", "ACTING_USER_ID", "USER_ID", - "TLS_FINGERPRINT", "REGISTRY_REFRESH", "DEBUG_DUMP", "LOG_FILE", "LOG_LEVEL", "LOG_FORMAT", + "TLS_FINGERPRINT", "REGISTRY_REFRESH", "DEBUG_DUMP", "LOG_FILE", "LOG_LEVEL", "LOG_FORMAT", "LOG_ACCESS", "MAX_MESSAGES_PER_DAY", "IDLE_ROTATION_TIMEOUT", "SAFE_MODE", "HYBRID_MODE", "MODELS_HIDE_UNAVAILABLE", "CORS_ALLOWED_ORIGIN", "REQUEST_JITTER", "CLI_VERSION", "MODEL_ALIASES", "AUTO_DISCOVER_TOKEN", "TRANSIENT_RETRIES", "ADMIN_TOKEN", @@ -1093,6 +1093,59 @@ func TestLogFormat(t *testing.T) { } } +// TestLogAccess pins T17: LOG_ACCESS defaults to true, an empty .env line +// keeps it enabled (the access gate must never flip off from an unset or +// blank value), and only an explicit false disables the access lines. +func TestLogAccess(t *testing.T) { + clearEnv(t) + t.Setenv("AUTH_TOKENS", "tok") + + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (default): %v", err) + } else if !cfg.LogAccess { + t.Error("LogAccess = false by default, want true") + } + + // env source: explicit false disables. + t.Setenv("LOG_ACCESS", "false") + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (env false): %v", err) + } else if cfg.LogAccess { + t.Error("LogAccess = true for LOG_ACCESS=false, want false") + } + + // Explicit true re-enables. + t.Setenv("LOG_ACCESS", "true") + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (env true): %v", err) + } else if !cfg.LogAccess { + t.Error("LogAccess = false for LOG_ACCESS=true, want true") + } + + // An empty .env line must not disable access logging: the empty value + // leaves the default (true) untouched. + t.Setenv("LOG_ACCESS", "") + if err := os.WriteFile(".env", []byte("AUTH_TOKENS=tok\nLOG_ACCESS=\n"), 0o644); err != nil { + t.Fatal(err) + } + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (empty .env line): %v", err) + } else if !cfg.LogAccess { + t.Error("LogAccess = false for an empty LOG_ACCESS=.env line, want true") + } + + // The .env source: LOG_ACCESS=false in .env disables (env wins). + t.Setenv("LOG_ACCESS", "") + if err := os.WriteFile(".env", []byte("AUTH_TOKENS=tok\nLOG_ACCESS=false\n"), 0o644); err != nil { + t.Fatal(err) + } + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (.env false): %v", err) + } else if cfg.LogAccess { + t.Error("LogAccess = true for .env LOG_ACCESS=false, want false") + } +} + func TestTLSFingerprint(t *testing.T) { clearEnv(t) t.Setenv("AUTH_TOKENS", "tok") diff --git a/internal/notify/notify.go b/internal/notify/notify.go index d0c8ad5..bf3dd8d 100644 --- a/internal/notify/notify.go +++ b/internal/notify/notify.go @@ -11,6 +11,7 @@ import ( "context" "encoding/json" "fmt" + "log/slog" "net/http" "sync" "time" @@ -31,6 +32,7 @@ const throttleWindow = 5 * time.Minute type Sender struct { url string client *http.Client + logger *slog.Logger // send-failure WARN sink (nil = slog.Default()) mu sync.Mutex lastSent map[string]time.Time // event type → last accepted POST time @@ -43,7 +45,17 @@ func New(url string, client *http.Client) *Sender { if client == nil { client = &http.Client{Timeout: defaultTimeout} } - return &Sender{url: url, client: client, lastSent: make(map[string]time.Time), startedAt: time.Now()} + return &Sender{url: url, client: client, logger: slog.Default(), lastSent: make(map[string]time.Time), startedAt: time.Now()} +} + +// SetLogger replaces the sender's log sink (nil restores slog.Default). +// Used by tests and by hosts that want the send-failure WARN on a custom +// logger. +func (s *Sender) SetLogger(l *slog.Logger) { + if l == nil { + l = slog.Default() + } + s.logger = l } // Event is one webhook payload (issue #48). Fields mirror the alert @@ -61,8 +73,9 @@ type Event struct { // Send fires a best-effort webhook POST for the event, throttled per event // type (at most one per throttleWindow). It never blocks: the POST runs on // a background goroutine with its own timeout. A nil receiver or an empty -// configured URL is a no-op. Failures are silent — the alert is best-effort -// by design (issue #48: "fire-and-forget goroutine with its own timeout"). +// configured URL is a no-op. Delivery failures are logged as a WARN (T18) — +// the alert itself stays best-effort by design (issue #48: +// "fire-and-forget goroutine with its own timeout"). func (s *Sender) Send(event Event) { if s == nil || s.url == "" { return @@ -91,25 +104,35 @@ func (s *Sender) throttle(eventType string) bool { // post performs one webhook POST with the sender's client timeout. The // payload is the JSON event; the response is drained and closed, and a -// non-2xx status is treated as a failed delivery (still silent). +// non-2xx status is treated as a failed delivery. Delivery failures are +// logged as a WARN with the err and the target URL (T18) — the alert +// itself stays best-effort and never blocks the request path. func (s *Sender) post(event Event) { payload, err := json.Marshal(event) if err != nil { + s.logger.Warn("webhook send failed", "err", err, "target", s.url) return } ctx, cancel := context.WithTimeout(context.Background(), defaultTimeout) defer cancel() req, err := http.NewRequestWithContext(ctx, http.MethodPost, s.url, bytes.NewReader(payload)) if err != nil { + s.logger.Warn("webhook send failed", "err", err, "target", s.url) return } req.Header.Set("Content-Type", "application/json") req.Header.Set("User-Agent", "freebuff-proxy-webhook/1.0") resp, err := s.client.Do(req) if err != nil { + s.logger.Warn("webhook send failed", "err", err, "target", s.url) return } defer func() { _ = resp.Body.Close() }() + if resp.StatusCode < 200 || resp.StatusCode > 299 { + _, _ = drain(resp) + s.logger.Warn("webhook send failed", "err", fmt.Errorf("webhook returned status %d", resp.StatusCode), "target", s.url) + return + } _, _ = drain(resp) } diff --git a/internal/notify/notify_test.go b/internal/notify/notify_test.go index 148d4e6..aa4081e 100644 --- a/internal/notify/notify_test.go +++ b/internal/notify/notify_test.go @@ -1,9 +1,13 @@ package notify import ( + "bytes" "encoding/json" + "errors" + "log/slog" "net/http" "net/http/httptest" + "strings" "sync" "sync/atomic" "testing" @@ -115,3 +119,55 @@ func TestSendDisabledNoOps(t *testing.T) { t.Fatalf("POSTs = %d, want 0 for disabled sender", count.Load()) } } + +// failRT is a RoundTripper that always fails, for the transport-error path. +type failRT struct{} + +func (failRT) RoundTrip(*http.Request) (*http.Response, error) { + return nil, errors.New("webhook unreachable") +} + +// TestSendFailureLogsWarn verifies T18: a failed webhook delivery logs a +// WARN with the err and the target URL — a non-2xx status and a transport +// error both fire it. +func TestSendFailureLogsWarn(t *testing.T) { + t.Run("non-2xx status", func(t *testing.T) { + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusServiceUnavailable) + })) + defer srv.Close() + var sink bytes.Buffer + s := New(srv.URL, nil) + s.SetLogger(slog.New(slog.NewTextHandler(&sink, &slog.HandlerOptions{Level: slog.LevelWarn}))) + s.Send(Event{Event: "token_banned"}) + + deadline := time.Now().Add(3 * time.Second) + for !strings.Contains(sink.String(), "webhook send failed") && time.Now().Before(deadline) { + time.Sleep(10 * time.Millisecond) + } + logs := sink.String() + for _, want := range []string{"webhook send failed", "webhook returned status 503", "target=" + srv.URL} { + if !strings.Contains(logs, want) { + t.Errorf("status-failure WARN missing %q: %s", want, logs) + } + } + }) + + t.Run("transport error", func(t *testing.T) { + var sink bytes.Buffer + s := New("https://webhook.invalid/hook", &http.Client{Transport: failRT{}}) + s.SetLogger(slog.New(slog.NewTextHandler(&sink, &slog.HandlerOptions{Level: slog.LevelWarn}))) + s.Send(Event{Event: "pool_exhausted"}) + + deadline := time.Now().Add(3 * time.Second) + for !strings.Contains(sink.String(), "webhook send failed") && time.Now().Before(deadline) { + time.Sleep(10 * time.Millisecond) + } + logs := sink.String() + for _, want := range []string{"webhook send failed", "webhook unreachable", "target=https://webhook.invalid/hook"} { + if !strings.Contains(logs, want) { + t.Errorf("transport-failure WARN missing %q: %s", want, logs) + } + } + }) +} diff --git a/internal/pool/spend.go b/internal/pool/spend.go index 517a6e9..4865d70 100644 --- a/internal/pool/spend.go +++ b/internal/pool/spend.go @@ -333,6 +333,17 @@ func (p *Pool) recordSpend(token int, tokens int64) { return } p.spendPerToken[token].add(tokens, time.Now()) + p.logSpendBuckets(tokens) +} + +// logSpendBuckets emits one Debug line per period bucket a spend record +// updated (T18): bucket names the ledger bucket, spend_delta the tokens +// added, period the wire-style period name. Debug level so the per-chat +// ledger noise only appears when operators opt in. +func (p *Pool) logSpendBuckets(tokens int64) { + p.logger.Debug("pool: spend bucket updated", "bucket", "day", "spend_delta", tokens, "period", "pacific_day") + p.logger.Debug("pool: spend bucket updated", "bucket", "week", "spend_delta", tokens, "period", "pacific_week") + p.logger.Debug("pool: spend bucket updated", "bucket", "month", "spend_delta", tokens, "period", "pacific_month") } // recordSpendEntry adds tokens to the lease's backing entry's ledger by @@ -352,6 +363,7 @@ func (p *Pool) recordSpendEntry(entry *tokenEntry, tokens int64) { return } p.spendPerToken[idx].add(tokens, time.Now()) + p.logSpendBuckets(tokens) return } } @@ -364,6 +376,7 @@ func (p *Pool) bridgeRecordSpend(entry *bridgeEntry, tokens int64) { p.bridgeMu.Lock() defer p.bridgeMu.Unlock() entry.spend.add(tokens, time.Now()) + p.logSpendBuckets(tokens) } // spendView is one ledger's snapshot for healthz (issue #87). diff --git a/internal/pool/spend_test.go b/internal/pool/spend_test.go index 7989bab..a8f4f54 100644 --- a/internal/pool/spend_test.go +++ b/internal/pool/spend_test.go @@ -10,7 +10,10 @@ package pool // dates exercise PST. import ( + "bytes" "context" + "log/slog" + "strings" "testing" "time" @@ -286,3 +289,27 @@ func TestSpendPct(t *testing.T) { t.Errorf("SpendDay = %d, want 300", snaps[0].SpendDay) } } + +// TestSpendBucketUpdateLogs verifies T18: a spend record emits one Debug +// line per period bucket with bucket, spend_delta, and the wire-style +// period name. +func TestSpendBucketUpdateLogs(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + p := newTestPool(t, mock) + var sink bytes.Buffer + p.logger = slog.New(slog.NewTextHandler(&sink, &slog.HandlerOptions{Level: slog.LevelDebug})) + p.recordSpend(0, 100) + + logs := sink.String() + for _, want := range []string{ + "pool: spend bucket updated", + "bucket=day", "spend_delta=100", "period=pacific_day", + "bucket=week", "period=pacific_week", + "bucket=month", "period=pacific_month", + } { + if !strings.Contains(logs, want) { + t.Errorf("spend bucket Debug missing %q: %s", want, logs) + } + } +} diff --git a/internal/registry/registry.go b/internal/registry/registry.go index 6ed4980..8cdbd7b 100644 --- a/internal/registry/registry.go +++ b/internal/registry/registry.go @@ -13,6 +13,7 @@ import ( "errors" "fmt" "io" + "log/slog" "net/http" "net/url" "os" @@ -149,6 +150,7 @@ type Registry struct { mu sync.RWMutex cfg atomic.Pointer[config.Config] // swapped atomically on reload (SetConfig) client *http.Client // fetch client; redirects followed, fetchTimeout applied + logger *slog.Logger // success-refresh INFO sink (nil = slog.Default()) sources []string // override of the default 5 source URLs (tests) lastAttempted []string // URLs tried during the most recent Refresh, in order @@ -166,13 +168,22 @@ func New(cfg *config.Config, client *http.Client) *Registry { if client == nil { client = &http.Client{Timeout: fetchTimeout} } - r := &Registry{client: client} + r := &Registry{client: client, logger: slog.Default()} if cfg != nil { r.cfg.Store(cfg) } return r } +// SetLogger replaces the registry's log sink (nil restores slog.Default). +// Used by tests and by hosts that want the refresh INFO on a custom logger. +func (r *Registry) SetLogger(l *slog.Logger) { + if l == nil { + l = slog.Default() + } + r.logger = l +} + // SetConfig atomically replaces the config the registry reads, so alias // resolution (ResolveModel) reflects a dashboard .env save or /admin/reload // without a restart. A nil cfg clears the stored config. @@ -199,6 +210,7 @@ func (r *Registry) SetSources(urls []string) { // kept and the error returned. Every URL actually attempted is recorded for // LastAttemptedSources (-doctor output). func (r *Registry) Refresh(ctx context.Context) error { + start := time.Now() candidates := r.sourceCandidates() texts := make([]string, len(candidates)) @@ -244,7 +256,11 @@ func (r *Registry) Refresh(ctx context.Context) error { r.agentModels = agentModels r.modelToAgent = modelToAgent r.allModels = allModels + agents, models := len(agentModels), len(allModels) r.mu.Unlock() + // T18: the success path was silent (the failure path logs in main.go) — + // surface the refresh outcome with agents/models counts and duration. + r.logger.Info("registry refreshed", "agents", agents, "models", models, "ms", time.Since(start).Milliseconds()) return nil } diff --git a/internal/registry/registry_test.go b/internal/registry/registry_test.go index b310bd2..0c804f2 100644 --- a/internal/registry/registry_test.go +++ b/internal/registry/registry_test.go @@ -1,15 +1,18 @@ package registry import ( + "bytes" "context" "errors" "io" + "log/slog" "net/http" "net/http/httptest" "os" "path/filepath" "reflect" "sort" + "strconv" "strings" "sync" "testing" @@ -806,3 +809,28 @@ func TestLastAttemptedSources(t *testing.T) { t.Errorf("LastAttemptedSources after successful refresh = %v, want [%s]", got, fixture) } } + +// TestRefreshLogsSuccess verifies T18: a successful refresh logs an INFO +// with agents/models counts and the duration (the success path was silent; +// only main.go's failure path logged). +func TestRefreshLogsSuccess(t *testing.T) { + var sink bytes.Buffer + r := New(nil, nil) + r.SetLogger(slog.New(slog.NewTextHandler(&sink, &slog.HandlerOptions{Level: slog.LevelInfo}))) + r.SetSources([]string{fileSource(t, filepath.Join("testdata", "registry-fixture.ts"))}) + if err := r.Refresh(context.Background()); err != nil { + t.Fatalf("Refresh: %v", err) + } + logs := sink.String() + if !strings.Contains(logs, "registry refreshed") { + t.Fatalf("refresh success log missing msg: %s", logs) + } + for _, want := range []string{"agents=", "models=", "ms="} { + if !strings.Contains(logs, want) { + t.Errorf("refresh success log missing %q: %s", want, logs) + } + } + if !strings.Contains(logs, "models="+strconv.Itoa(r.ModelCount())) { + t.Errorf("refresh log models = %s, want %d", logs, r.ModelCount()) + } +} diff --git a/internal/server/logging_wave2_test.go b/internal/server/logging_wave2_test.go new file mode 100644 index 0000000..0678c60 --- /dev/null +++ b/internal/server/logging_wave2_test.go @@ -0,0 +1,305 @@ +package server + +// Wave-2 observability tests (T15-T17): admin audit trail, silent-endpoint +// coverage, and access-log hygiene. Internal package so the tests can reach +// the unexported access gate, adminAuth snapshots, and config-diff helpers. + +import ( + "bytes" + "log/slog" + "net/http" + "net/http/httptest" + "net/url" + "os" + "strings" + "testing" + "time" + + "freebuff-proxy/internal/config" + "freebuff-proxy/internal/registry" + "freebuff-proxy/internal/testutil" +) + +// newLoggingServer builds a full test server (one mock token, fallback +// registry) whose logger writes to a capture buffer at Debug level, so the +// T15-T17 log lines are assertable. +func newLoggingServer(t *testing.T, mock *testutil.MockUpstream, mut func(*config.Config)) (*Server, *bytes.Buffer) { + t.Helper() + srv := newServerOpts(t, mock, mut) + var sink bytes.Buffer + srv.logger = slog.New(slog.NewTextHandler(&sink, &slog.HandlerOptions{Level: slog.LevelDebug})) + return srv, &sink +} + +// TestAccessLogGate pins the quiet-path gate (T17): the first request for a +// path logs, requests within the window are suppressed, a different path is +// its own gate, and a request after the window logs again. +func TestAccessLogGate(t *testing.T) { + resetAccessLogGate() + t.Cleanup(resetAccessLogGate) + orig := accessQuietWindow + accessQuietWindow = 60 * time.Second + t.Cleanup(func() { accessQuietWindow = orig }) + + t0 := time.Now() + if !accessLogDue("/healthz", t0) { + t.Fatal("first /healthz request must log") + } + if accessLogDue("/healthz", t0.Add(time.Second)) { + t.Error("second /healthz within the window must be suppressed") + } + if !accessLogDue("/metrics", t0.Add(time.Second)) { + t.Error("a different quiet path has its own gate") + } + if !accessLogDue("/healthz", t0.Add(61*time.Second)) { + t.Error("/healthz after the window must log again (a new minute)") + } +} + +// TestAccessQuietEndpointsRateLimited verifies end-to-end that two /healthz +// requests in the same window produce one access line, and a request after +// the window produces a second (T17). +func TestAccessQuietEndpointsRateLimited(t *testing.T) { + testutil.UnsetConfigEnv(t) + resetAccessLogGate() + t.Cleanup(resetAccessLogGate) + mock := testutil.NewMock() + defer mock.Close() + srv, sink := newLoggingServer(t, mock, nil) + h := srv.Handler() + + for i := 0; i < 2; i++ { + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/healthz", nil)) + } + if got := strings.Count(sink.String(), "msg=access"); got != 1 { + t.Fatalf("access lines for two same-window /healthz = %d, want 1", got) + } + + // Shrink the window to zero: the next request logs again (deterministic + // stand-in for "two requests in different minutes"). + orig := accessQuietWindow + accessQuietWindow = 0 + t.Cleanup(func() { accessQuietWindow = orig }) + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/healthz", nil)) + if got := strings.Count(sink.String(), "msg=access"); got != 2 { + t.Fatalf("access lines after window expiry = %d, want 2", got) + } +} + +// TestAccessLogDisabledSuppressesLines verifies LOG_ACCESS=false turns the +// access lines off entirely (normal paths included), and flipping the +// effective config back on restores them (T17). +func TestAccessLogDisabledSuppressesLines(t *testing.T) { + testutil.UnsetConfigEnv(t) + mock := testutil.NewMock() + defer mock.Close() + srv, sink := newLoggingServer(t, mock, func(c *config.Config) { c.LogAccess = false }) + h := srv.Handler() + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/v1/models", nil)) + if rec.Code != http.StatusOK { + t.Fatalf("models status = %d, want 200", rec.Code) + } + if strings.Contains(sink.String(), "msg=access") { + t.Fatal("access line logged with LOG_ACCESS=false") + } + + // Runtime toggle back on (config reload semantics). + cfg := *srv.cfg.Load() + cfg.LogAccess = true + srv.cfg.Store(&cfg) + rec = httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/v1/models", nil)) + if !strings.Contains(sink.String(), "msg=access") { + t.Fatal("no access line after LOG_ACCESS re-enabled") + } +} + +// TestAdminReloadLogsAudit verifies T15: /admin/reload success logs INFO and +// failure logs WARN, both with remote and path. +func TestAdminReloadLogsAudit(t *testing.T) { + testutil.UnsetConfigEnv(t) + t.Chdir(t.TempDir()) + mock := testutil.NewMock() + defer mock.Close() + srv, sink := newLoggingServer(t, mock, nil) + h := srv.Handler() + + req := httptest.NewRequest(http.MethodPost, "/admin/reload", nil) + req.RemoteAddr = "198.51.100.7:1234" + rec := httptest.NewRecorder() + h.ServeHTTP(rec, req) + if rec.Code != http.StatusOK { + t.Fatalf("reload status = %d, want 200: %s", rec.Code, rec.Body.String()) + } + logs := sink.String() + for _, want := range []string{"admin reload requested", "config reloaded successfully", "remote=198.51.100.7", "path=/admin/reload"} { + if !strings.Contains(logs, want) { + t.Errorf("reload success logs missing %q", want) + } + } + + // Failure path: an invalid .env makes config.Load reject the reload. + if err := os.WriteFile(".env", []byte("ROTATION_INTERVAL=not-a-duration\n"), 0o644); err != nil { + t.Fatal(err) + } + reqFail := httptest.NewRequest(http.MethodPost, "/admin/reload", nil) + reqFail.RemoteAddr = "198.51.100.7:1234" + rec = httptest.NewRecorder() + h.ServeHTTP(rec, reqFail) + if rec.Code != http.StatusInternalServerError { + t.Fatalf("reload failure status = %d, want 500", rec.Code) + } + logs = sink.String() + for _, want := range []string{"admin reload failed", "remote=198.51.100.7", "path=/admin/reload"} { + if !strings.Contains(logs, want) { + t.Errorf("reload failure logs missing %q", want) + } + } +} + +// TestAdminLoginFailureLogsNoCredential verifies T15: a failed /admin/login +// logs a WARN with remote, running attempt count, and reason — never the +// submitted credential or the configured token. +func TestAdminLoginFailureLogsNoCredential(t *testing.T) { + testutil.UnsetConfigEnv(t) + mock := testutil.NewMock() + defer mock.Close() + srv, sink := newLoggingServer(t, mock, func(c *config.Config) { c.AdminToken = "secret-admin-token" }) + h := srv.Handler() + + post := func(cred string) { + t.Helper() + form := url.Values{"token": {cred}} + req := httptest.NewRequest(http.MethodPost, "/admin/login", strings.NewReader(form.Encode())) + req.Header.Set("Content-Type", "application/x-www-form-urlencoded") + req.RemoteAddr = "198.51.100.9:1234" + rec := httptest.NewRecorder() + h.ServeHTTP(rec, req) + } + + post("wrong-credential-value") + logs := sink.String() + if !strings.Contains(logs, "admin login failed") { + t.Fatal("missing admin login failure WARN") + } + for _, want := range []string{"remote=198.51.100.9", "attempts=1", "reason=invalid_token"} { + if !strings.Contains(logs, want) { + t.Errorf("login WARN missing %q", want) + } + } + if strings.Contains(logs, "wrong-credential-value") || strings.Contains(logs, "secret-admin-token") { + t.Fatal("login failure log leaked the credential") + } + + post("another-wrong-value") + if !strings.Contains(sink.String(), "attempts=2") { + t.Errorf("second failure did not log attempts=2: %s", sink.String()) + } + if strings.Contains(sink.String(), "another-wrong-value") { + t.Fatal("second login failure log leaked the credential") + } +} + +// TestConfigSaveLogsChangedKeys verifies T15: a config save logs the sorted +// changed effective key NAMES (never values — including secret values). +func TestConfigSaveLogsChangedKeys(t *testing.T) { + testutil.UnsetConfigEnv(t) + t.Chdir(t.TempDir()) + if err := os.WriteFile(".env", []byte("SAFE_MODE=true\nAUTH_TOKENS=tok-a\n"), 0o644); err != nil { + t.Fatal(err) + } + mock := testutil.NewMock() + defer mock.Close() + // The helper cfg must mirror the initial .env effective state + // (SAFE_MODE=true, one token) so the save diff is old-vs-new effective. + srv, sink := newLoggingServer(t, mock, func(c *config.Config) { + c.SafeMode = true + c.AuthTokens = []string{"tok-a"} + }) + h := srv.Handler() + + // Loopback remote + Host: the open-mode adminSensitive gate requires it. + req := httptest.NewRequest(http.MethodPost, "/admin/config", + strings.NewReader("SAFE_MODE=false\nAUTH_TOKENS=tok-a\nADMIN_TOKEN=new-secret-xyz\nMAX_MESSAGES_PER_DAY=10\n")) + req.Header.Set("Content-Type", "text/plain") + req.RemoteAddr = "127.0.0.1:1234" + req.Host = "127.0.0.1:3457" + rec := httptest.NewRecorder() + h.ServeHTTP(rec, req) + if rec.Code != http.StatusOK { + t.Fatalf("config save status = %d: %s", rec.Code, rec.Body.String()) + } + + logs := sink.String() + if !strings.Contains(logs, "dashboard config saved and reloaded") { + t.Fatal("missing config save INFO") + } + if !strings.Contains(logs, "changed_keys=") { + t.Fatalf("save INFO missing changed_keys: %s", logs) + } + for _, key := range []string{"ADMIN_TOKEN", "MAX_MESSAGES_PER_DAY", "SAFE_MODE"} { + if !strings.Contains(logs, key) { + t.Errorf("changed_keys missing %q: %s", key, logs) + } + } + // AUTH_TOKENS kept the same count → not changed. + if strings.Contains(logs, "AUTH_TOKENS") { + t.Errorf("AUTH_TOKENS listed as changed despite the same count: %s", logs) + } + // Values — including the new ADMIN_TOKEN secret — must never appear. + for _, leaked := range []string{"new-secret-xyz", "SAFE_MODE=false", "MAX_MESSAGES_PER_DAY=10"} { + if strings.Contains(logs, leaked) { + t.Errorf("config save log leaked %q: %s", leaked, logs) + } + } +} + +// TestEmbeddingsUnsupportedWarn verifies T16: the unsupported_endpoint 400 +// logs a WARN with path, remote, and status. +func TestEmbeddingsUnsupportedWarn(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + srv, sink := newLoggingServer(t, mock, nil) + h := srv.Handler() + + req := httptest.NewRequest(http.MethodPost, "/v1/embeddings", strings.NewReader(`{"model":"x"}`)) + req.RemoteAddr = "198.51.100.11:1234" + rec := httptest.NewRecorder() + h.ServeHTTP(rec, req) + if rec.Code != http.StatusBadRequest { + t.Fatalf("embeddings status = %d, want 400", rec.Code) + } + logs := sink.String() + for _, want := range []string{"unsupported endpoint requested", "path=/v1/embeddings", "remote=198.51.100.11", "status=400"} { + if !strings.Contains(logs, want) { + t.Errorf("embeddings WARN missing %q", want) + } + } +} + +// TestModelsEmptyRegistryWarn verifies T16: /v1/models with an empty +// registry logs a WARN (model_count 0) when requested — not at startup. +func TestModelsEmptyRegistryWarn(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + srv, sink := newLoggingServer(t, mock, nil) + // Replace the fallback-populated registry with an empty one. + srv.reg = registry.New(srv.cfg.Load(), nil) + h := srv.Handler() + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/v1/models", nil)) + if rec.Code != http.StatusOK { + t.Fatalf("models status = %d, want 200", rec.Code) + } + logs := sink.String() + for _, want := range []string{"model list requested with empty registry", "model_count=0"} { + if !strings.Contains(logs, want) { + t.Errorf("empty-registry WARN missing %q", want) + } + } +} diff --git a/internal/server/server.go b/internal/server/server.go index dee1676..5ed0557 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -158,7 +158,7 @@ func New(cfg *config.Config, p *pool.Pool, reg *registry.Registry, logger *slog. // count_tokens requests never rebuild the vocabulary. est, err := tokenestimate.New() if err != nil { - logger.Error("token estimator unavailable; /v1/messages/count_tokens will fail", "err", err) + logger.Warn("token estimator unavailable; /v1/messages/count_tokens will fail", "err", err) } s.tokenEstimator = est for _, opt := range opts { @@ -255,10 +255,63 @@ func (s *Server) Handler() http.Handler { if crid := clientRequestID(r); crid != "" { attrs = append(attrs, "client_request_id", crid) } + // T17: LOG_ACCESS=false disables access lines entirely. Quiet + // endpoints (/healthz, /metrics, OPTIONS preflights) are + // rate-limited to one access line per path per accessQuietWindow so + // a poller or browser preflight does not flood the log; every other + // path keeps one line per request. req_id/client_request_id survive + // in both cases. + if !s.cfg.Load().LogAccess { + return + } + if quietAccessPath(r.Method, r.URL.Path) && !accessLogDue(r.URL.Path, start) { + return + } s.logger.Info("access", attrs...) }) } +// quietAccessPath reports whether path is a poll/fire-and-forget endpoint +// whose access lines are rate-limited (T17): /healthz, /metrics, and CORS +// OPTIONS preflights. Every other path logs one access line per request. +func quietAccessPath(method, path string) bool { + return path == "/healthz" || path == "/metrics" || method == http.MethodOptions +} + +// accessQuietWindow is the quiet-endpoint access gate window: at most one +// access line per path per window (T17). A var so tests can shrink it. +var accessQuietWindow = 60 * time.Second + +// accessLogGate is the per-process quiet-path access gate: map[path]lastLog +// plus a mutex (T17). The path set is bounded by the route table, so no +// cleanup is needed. +var accessLogGate = struct { + mu sync.Mutex + lastSeen map[string]time.Time +}{lastSeen: make(map[string]time.Time)} + +// accessLogDue reports whether an access line may fire for path now, +// recording the current attempt. The first request for a path and any +// request at least accessQuietWindow after the last line fire; requests +// inside the window are suppressed. +func accessLogDue(path string, now time.Time) bool { + accessLogGate.mu.Lock() + defer accessLogGate.mu.Unlock() + last, ok := accessLogGate.lastSeen[path] + if !ok || now.Sub(last) >= accessQuietWindow { + accessLogGate.lastSeen[path] = now + return true + } + return false +} + +// resetAccessLogGate clears the quiet-path access gate (test hook). +func resetAccessLogGate() { + accessLogGate.mu.Lock() + defer accessLogGate.mu.Unlock() + clear(accessLogGate.lastSeen) +} + // corsOrigin returns the configured Access-Control-Allow-Origin, treating an // empty value as the "*" default (an empty .env line must not disable CORS). func (s *Server) corsOrigin() string { @@ -590,6 +643,18 @@ func (a *adminAuth) clearFails(ip string) { delete(a.fails, ip) } +// loginFailState snapshots the failure entry for ip: the current attempt +// count and whether ip is locked out (T15 audit trail). +func (a *adminAuth) loginFailState(ip string) (attempts int, locked bool) { + a.mu.Lock() + defer a.mu.Unlock() + e, ok := a.fails[ip] + if !ok { + return 0, false + } + return e.count, !e.until.IsZero() && time.Now().Before(e.until) +} + // dashboardAuth guards the browser UI. With ADMIN_TOKEN unset the dashboard // is open (legacy behavior, matching /admin/reload; main.go warns at startup). // Otherwise the request must carry a valid fb_admin cookie; missing/invalid @@ -706,6 +771,10 @@ func (s *Server) handleAdminLogin(w http.ResponseWriter, r *http.Request) { ip := remoteHost(r) if r.Method == http.MethodPost { if !s.adminAuth.allow(ip) { + // T15: audit the lockout rejection — attempts is the lockout + // bound that was crossed; the submitted credential is never + // logged. + s.logger.Warn("admin login failed", "remote", ip, "attempts", maxLoginFails, "reason", "locked_out") s.dash.RenderLogin(w, r, "Too many failed attempts — try again in a minute.") return } @@ -721,6 +790,13 @@ func (s *Server) handleAdminLogin(w http.ResponseWriter, r *http.Request) { return } s.adminAuth.recordFail(ip) + attempts, locked := s.adminAuth.loginFailState(ip) + if locked { + attempts = maxLoginFails + } + // T15: audit a failed login — remote, running attempt count, and + // reason only; the credential itself is never logged. + s.logger.Warn("admin login failed", "remote", ip, "attempts", attempts, "reason", "invalid_token") s.dash.RenderLogin(w, r, "Invalid admin token.") return } @@ -890,6 +966,7 @@ func (s *Server) handleTokenTestAll(w http.ResponseWriter, r *http.Request) { // documented "unsupported_endpoint" code (distinct from the mux's bare 404, // which gives an embeddings client no actionable signal). func (s *Server) handleEmbeddings(w http.ResponseWriter, r *http.Request) { + s.logger.Warn("unsupported endpoint requested", "path", r.URL.Path, "remote", remoteHost(r), "status", http.StatusBadRequest) s.writeJSONError(w, http.StatusBadRequest, "this proxy serves chat completions only; embeddings are not supported. Use POST /v1/chat/completions with one of: "+strings.Join(s.reg.Models(), ", "), "unsupported_endpoint", "unsupported_endpoint", 0) @@ -1364,11 +1441,11 @@ func (s *Server) handleTokenAdd(w http.ResponseWriter, r *http.Request) { tokens := append(append([]string{}, cfg.AuthTokens...), req.Token) if err := s.syncTokensAfterMutation(tokens); err != nil { _ = s.pool.RemoveLastToken() - s.logger.Warn("dashboard token add rolled back", "err", err) + s.logger.Warn("dashboard token add rolled back", "remote", remoteHost(r), "err", err) s.dash.RenderConfigResult(w, r, false, err.Error()) return } - s.logger.Info("dashboard token added", "index", idx) + s.logger.Info("dashboard token added", "remote", remoteHost(r), "index", idx) s.dash.RenderConfigResult(w, r, true, "Token added at index "+strconv.Itoa(idx)+" and persisted to .env.") } @@ -1406,14 +1483,14 @@ func (s *Server) handleTokenRemove(w http.ResponseWriter, r *http.Request) { // handleTokenAdd's rollback). if removed != "" { if _, addErr := s.pool.AddToken(removed); addErr != nil { - s.logger.Warn("dashboard token remove rollback re-add failed", "err", addErr) + s.logger.Warn("dashboard token remove rollback re-add failed", "remote", remoteHost(r), "err", addErr) } } - s.logger.Warn("dashboard token remove rolled back", "err", err) + s.logger.Warn("dashboard token remove rolled back", "remote", remoteHost(r), "err", err) s.dash.RenderConfigResult(w, r, false, err.Error()) return } - s.logger.Info("dashboard token removed") + s.logger.Info("dashboard token removed", "remote", remoteHost(r)) s.dash.RenderConfigResult(w, r, true, "Last token removed and persisted to .env.") } @@ -1732,14 +1809,94 @@ func (s *Server) handleConfigSave(w http.ResponseWriter, r *http.Request) { s.dash.RenderConfigResult(w, r, false, "Configuration rejected: "+err.Error()) return } + oldCfg := s.cfg.Load() s.cfg.Store(&newCfg) s.reg.SetConfig(&newCfg) s.pool.SetConfig(&newCfg) s.logger.Info("dashboard config saved and reloaded", + "remote", remoteHost(r), "changed_keys", changedConfigKeys(oldCfg, &newCfg), "auth_tokens", len(newCfg.AuthTokens), "safe_mode", newCfg.SafeMode) s.dash.RenderConfigResult(w, r, true, "Saved and reloaded — effective configuration updated.") } +// effectiveConfigKV renders cfg as a key→normalized-value map of the +// effective config surface (mirrors the dashboard config editor's effective +// table, T15). Secret-bearing values are reduced to counts or set/unset +// markers, so the map is safe to diff for the changed_keys audit log: only +// key NAMES are ever logged, never values. +func effectiveConfigKV(cfg *config.Config) map[string]string { + return map[string]string{ + "LISTEN_ADDR": cfg.ListenAddr, + "UPSTREAM_BASE_URL": cfg.UpstreamBaseURL, + "AUTH_TOKENS": strconv.Itoa(len(cfg.AuthTokens)), + "API_KEYS": strconv.Itoa(len(cfg.APIKeys)), + "ADMIN_TOKEN": boolWord(cfg.AdminToken != ""), + "ROTATION_INTERVAL": cfg.RotationInterval.String(), + "REQUEST_TIMEOUT": cfg.RequestTimeout.String(), + "SESSION_CALL_TIMEOUT": cfg.SessionCallTimeout.String(), + "COST_MODE": cfg.CostMode, + "TLS_FINGERPRINT": cfg.TLSFingerprint, + "REGISTRY_REFRESH": cfg.RegistryRefresh.String(), + "DEBUG_DUMP": strconv.FormatBool(cfg.DebugDump), + "LOG_FILE": cfg.LogFile, + "LOG_LEVEL": cfg.LogLevel, + "LOG_FORMAT": cfg.LogFormat, + "LOG_ACCESS": strconv.FormatBool(cfg.LogAccess), + "MAX_MESSAGES_PER_DAY": strconv.Itoa(cfg.MaxMessagesPerDay), + "MAX_SPEND_PER_DAY": strconv.FormatInt(cfg.MaxSpendPerDay, 10), + "IDLE_ROTATION_TIMEOUT": cfg.IdleRotationTimeout.String(), + "SAFE_MODE": strconv.FormatBool(cfg.SafeMode), + "HYBRID_MODE": strconv.FormatBool(cfg.HybridMode), + "MODELS_HIDE_UNAVAILABLE": strconv.FormatBool(cfg.ModelsHideUnavailable), + "CORS_ALLOWED_ORIGIN": cfg.CORSAllowedOrigin, + "REQUEST_JITTER": cfg.RequestJitter.String(), + "CLI_VERSION": cfg.CLIVersion, + "MODEL_ALIASES": strconv.Itoa(len(cfg.ModelAliases)), + "TRANSIENT_RETRIES": strconv.Itoa(cfg.TransientRetries), + "SESSION_PERSIST": strconv.FormatBool(cfg.SessionPersist), + "SESSION_STATE_FILE": cfg.SessionStateFile, + "HTTP2_UPSTREAM": strconv.FormatBool(cfg.HTTP2Upstream), + "SESSION_CREATE_MAX_PARALLEL_GLOBAL": strconv.Itoa(cfg.SessionCreateMaxParallelGlobal), + "SESSION_CREATE_MAX_PARALLEL_PER_MODEL": strconv.Itoa(cfg.SessionCreateMaxParallelPerModel), + "RUN_FINISH_QUEUE_SIZE": strconv.Itoa(cfg.RunFinishQueueSize), + "RUN_FINISH_INLINE_TIMEOUT": cfg.RunFinishInlineTimeout.String(), + "RUNS_DRAIN_QUEUE_CAP": strconv.Itoa(cfg.RunsDrainQueueCap), + "RUNS_DRAIN_TTL": cfg.RunsDrainTTL.String(), + "SESSION_RE_ADMIT_LEAD": cfg.SessionReAdmitLead.String(), + "SESSION_PROBE_CACHE_TTL": cfg.SessionProbeCacheTTL.String(), + "WEBHOOK_URL": boolWord(cfg.WebhookURL != ""), + "FALLBACK_AFTER_MS": cfg.FallbackAfter.String(), + "FALLBACK_MODEL": strconv.Itoa(len(cfg.FallbackModels)), + "ADOPT_CLI_SESSION": strconv.FormatBool(cfg.AdoptCLISession), + "WAITING_ROOM_CHAIN": strconv.FormatBool(cfg.WaitingRoomChain), + } +} + +// boolWord renders a boolean flag as "set"/"unset" for the redacted +// effective-config table (never the raw value). +func boolWord(v bool) string { + if v { + return "set" + } + return "unset" +} + +// changedConfigKeys returns the sorted names of effective config keys whose +// normalized value differs between oldCfg and newCfg (T15 audit trail). The +// values are compared only; never logged. +func changedConfigKeys(oldCfg, newCfg *config.Config) []string { + oldKV := effectiveConfigKV(oldCfg) + newKV := effectiveConfigKV(newCfg) + var changed []string + for k, v := range newKV { + if oldKV[k] != v { + changed = append(changed, k) + } + } + sort.Strings(changed) + return changed +} + // writeFileAtomic writes data to path via a temp file + rename: readers never // observe a truncated file, and a crash mid-write leaves the previous content // intact. os.Rename replaces an existing target atomically on every supported @@ -2804,6 +2961,12 @@ func (s *Server) handleModels(w http.ResponseWriter, r *http.Request) { created := s.started.Unix() snaps := s.pool.Snapshot() models := s.reg.Models() + if len(models) == 0 { + // T16: an empty registry is an operational anomaly (the fallback + // table should always populate at boot) — surface it when a client + // actually asks, not at startup. + s.logger.Warn("model list requested with empty registry", "path", r.URL.Path, "remote", remoteHost(r), "model_count", 0) + } hideUnavailable := s.cfg.Load().ModelsHideUnavailable data := make([]map[string]any, 0, len(models)) for _, id := range models { @@ -3077,16 +3240,18 @@ func (s *Server) handleMetrics(w http.ResponseWriter, r *http.Request) { // handleReload handles POST /admin/reload for hot configuration reloads (#26). func (s *Server) handleReload(w http.ResponseWriter, r *http.Request) { - s.logger.Info("admin reload requested") + s.logger.Info("admin reload requested", "remote", remoteHost(r), "path", r.URL.Path) newCfg, err := config.Load(s.configPath) if err != nil { + s.logger.Warn("admin reload failed", "remote", remoteHost(r), "path", r.URL.Path, "err", err) s.writeJSONError(w, http.StatusInternalServerError, "failed to reload config: "+err.Error(), "internal_error", "reload_failed", 0) return } s.cfg.Store(&newCfg) s.reg.SetConfig(&newCfg) s.pool.SetConfig(&newCfg) - s.logger.Info("config reloaded successfully", "auth_tokens", len(newCfg.AuthTokens), "safe_mode", newCfg.SafeMode) + s.logger.Info("config reloaded successfully", "remote", remoteHost(r), "path", r.URL.Path, + "auth_tokens", len(newCfg.AuthTokens), "safe_mode", newCfg.SafeMode) w.Header().Set("Content-Type", "application/json") _ = json.NewEncoder(w).Encode(map[string]any{ "status": "ok", diff --git a/internal/server/server_api_test.go b/internal/server/server_api_test.go index e850dd8..c6ae60f 100644 --- a/internal/server/server_api_test.go +++ b/internal/server/server_api_test.go @@ -42,6 +42,7 @@ func newTestServerWithLogger(t *testing.T, apiKeys []string, logger *slog.Logger RegistryRefresh: 6 * time.Hour, UpstreamBaseURL: "https://www.codebuff.com", APIKeys: apiKeys, + LogAccess: true, } clients := make([]*upstream.Client, 0, len(mocks)) sessions := make([]*session.Manager, 0, len(mocks)) diff --git a/internal/server/server_test.go b/internal/server/server_test.go index 6ec3ba2..dfa6600 100644 --- a/internal/server/server_test.go +++ b/internal/server/server_test.go @@ -47,6 +47,7 @@ func newTestServerCfg(t *testing.T, apiKeys []string, mut func(*config.Config), RegistryRefresh: 6 * time.Hour, UpstreamBaseURL: "https://www.codebuff.com", APIKeys: apiKeys, + LogAccess: true, } if mut != nil { mut(cfg) diff --git a/internal/server/server_wave6_test.go b/internal/server/server_wave6_test.go index 9ca7709..ad4f435 100644 --- a/internal/server/server_wave6_test.go +++ b/internal/server/server_wave6_test.go @@ -301,6 +301,7 @@ func newServerOpts(t *testing.T, mock *testutil.MockUpstream, mut func(*config.C SessionCallTimeout: 5 * time.Second, RegistryRefresh: 6 * time.Hour, UpstreamBaseURL: "https://www.codebuff.com", + LogAccess: true, } if mut != nil { mut(cfg) diff --git a/internal/session/session.go b/internal/session/session.go index 6caafd4..616291b 100644 --- a/internal/session/session.go +++ b/internal/session/session.go @@ -46,6 +46,27 @@ const ( // asyncReAdmitTimeout bounds the background pre-emptive re-admit // (issue #99) so a hung upstream never leaks a goroutine. asyncReAdmitTimeout = time.Minute + + // Terminal-event reasons (T9): the standardized session/invalidation + // cause vocabulary shared by every terminal session log line. The + // poll/refresh drop paths map upstream statuses through tableReason; + // InvalidateWithReason accepts these so callers can name the cause. + reasonEnded = "ended" + reasonSuperseded = "superseded" + reasonShutdown = "shutdown" + reasonModelLock = "model_lock" + reasonExpired = "expired" + reason409 = "409" + reasonPoll = "poll" + reasonStore = "store" + + // Re-admit storm detector (T10): more than stormThreshold terminal + // session events within stormWindow is a session re-admit storm — each + // invalidation is followed by a fresh admission that burns a daily + // session slot, so the burst is surfaced once (one Info summary) and + // re-armed only after a full quiet window passes. + stormWindow = 60 * time.Second + stormThreshold = 3 ) // WaitingRoomError is returned when the session is queued and pollAt has not @@ -97,6 +118,26 @@ type Manager struct { // the CLI's active instance and refuses to create a competing session // while the CLI process is alive. adopt *CLIAdoption + + // now returns the current time; injectable in tests to drive the + // re-admit storm detector deterministically. Defaults to time.Now. + now func() time.Time + + // invalidationEvents is the rolling stormWindow of terminal session + // events (timestamps + reason) feeding the re-admit storm detector + // (T10); reAdmitTriggers records pre-emptive re-admit trigger times so + // a storm summary can report how many daily slots the burst burned; + // lastStormAt suppresses repeat summaries until a quiet window passes. + invalidationEvents []invalidationEvent + reAdmitTriggers []time.Time + lastStormAt time.Time +} + +// invalidationEvent is one terminal session event in the re-admit storm +// window (T10): when the cached session was dropped and why. +type invalidationEvent struct { + at time.Time + reason string } type cachedState struct { @@ -135,7 +176,7 @@ func NewManager(client *upstream.Client) *Manager { // NewManagerWithStore builds a session manager that also persists its cached // state through store (nil disables persistence). func NewManagerWithStore(client *upstream.Client, store *Store) *Manager { - m := &Manager{client: client, store: store} + m := &Manager{client: client, store: store, now: time.Now} if client != nil { m.key = client.TokenKey() } @@ -385,6 +426,7 @@ func (m *Manager) EnsureSessionForModel(ctx context.Context, model string) (stri m.refreshCh = refreshCh m.mu.Unlock() go m.asyncReAdmit(model) + m.recordReAdmitTrigger() slog.Debug("session: pre-emptive re-admit triggered", "instance_id", instance, "model", s.model) return instance, nil } @@ -529,6 +571,92 @@ func (m *Manager) asyncReAdmit(model string) { slog.Debug("session: pre-emptive re-admit done") } +// recordReAdmitTrigger remembers a pre-emptive re-admit trigger (issue #99) +// for the re-admit storm summary's burned_slots count (T10): a trigger whose +// session is later invalidated burned a daily session slot. Caller must NOT +// hold m.mu. +func (m *Manager) recordReAdmitTrigger() { + m.mu.Lock() + now := m.now() + cutoff := now.Add(-stormWindow) + m.reAdmitTriggers = append(m.reAdmitTriggers, now) + triggers := m.reAdmitTriggers[:0] + for _, t := range m.reAdmitTriggers { + if t.After(cutoff) { + triggers = append(triggers, t) + } + } + m.reAdmitTriggers = triggers + m.mu.Unlock() +} + +// recordInvalidation appends a terminal session event to the rolling +// re-admit storm window (T10) and, when more than stormThreshold +// invalidations land within stormWindow and the suppression window has +// passed, emits ONE Info summary (count, duration_ms, superseded, +// burned_slots). Caller must NOT hold m.mu; the summary is logged outside +// the lock. +func (m *Manager) recordInvalidation(reason string) { + m.mu.Lock() + now := m.now() + m.invalidationEvents = append(m.invalidationEvents, invalidationEvent{at: now, reason: reason}) + cutoff := now.Add(-stormWindow) + events := m.invalidationEvents[:0] + for _, ev := range m.invalidationEvents { + if ev.at.After(cutoff) { + events = append(events, ev) + } + } + m.invalidationEvents = events + triggers := m.reAdmitTriggers[:0] + for _, t := range m.reAdmitTriggers { + if t.After(cutoff) { + triggers = append(triggers, t) + } + } + m.reAdmitTriggers = triggers + + // Storm only when strictly more than the threshold invalidations sit in + // the window, and only once per suppression window (60s of quiet re-arms + // the detector). + if len(m.invalidationEvents) <= stormThreshold || (!m.lastStormAt.IsZero() && now.Sub(m.lastStormAt) < stormWindow) { + m.mu.Unlock() + return + } + m.lastStormAt = now + count := len(m.invalidationEvents) + duration := m.invalidationEvents[len(m.invalidationEvents)-1].at.Sub(m.invalidationEvents[0].at).Milliseconds() + superseded := 0 + for _, ev := range m.invalidationEvents { + if ev.reason == reasonSuperseded { + superseded++ + } + } + // burned_slots: pre-emptive re-admit triggers within the same window — + // each one whose session the storm then invalidated burned a daily slot. + // The trigger list is pruned to the window above, so its length is the + // count. + burned := len(m.reAdmitTriggers) + m.mu.Unlock() + + slog.Info("session re-admit storm", + "count", count, + "duration_ms", duration, + "superseded", superseded, + "burned_slots", burned) +} + +// tableReason maps an upstream session status to the terminal-event reason +// vocabulary (T9). Used by the poll/refresh drop paths so the logged reason +// is always one of the table values; the raw upstream status rides in the +// log's status field. +func tableReason(status string) string { + if status == "superseded" { + return reasonSuperseded + } + return reasonEnded +} + // statusError maps an upstream session status to the typed error callers // use for recovery (token cooldown, region surfacing). st supplies the // fields carried by the error; non-error statuses return nil. Shared by @@ -696,7 +824,8 @@ func (m *Manager) refresh(ctx context.Context, requestedModel string) error { m.mu.Lock() m.commit(nil) m.mu.Unlock() - slog.Debug("session recreated", "reason", status, "instance_id", st.InstanceID) + m.recordInvalidation(tableReason(status)) + slog.Debug("session recreated", "reason", tableReason(status), "status", status, "instance_id", st.InstanceID) case "banned", "country_blocked", "rate_limited", "ip_capped", "spend_limited", "session_model_mismatch", "limited_ip": return statusError(status, st) case "model_locked": @@ -705,8 +834,9 @@ func (m *Manager) refresh(ctx context.Context, requestedModel string) error { m.mu.Lock() m.commit(nil) m.mu.Unlock() + m.recordInvalidation(reasonModelLock) _ = m.client.EndSession(ctx) - slog.Debug("session released on model lock, retrying", "current", st.CurrentModel, "target", targetModel) + slog.Debug("session released on model lock, retrying", "reason", reasonModelLock, "current", st.CurrentModel, "target", targetModel) case "model_unavailable": // Requested model is not available; fall back to default model. slog.Warn("session: model unavailable upstream, falling back to default", "requested", targetModel, "fallback", DefaultFallbackModel) @@ -808,8 +938,20 @@ func (m *Manager) Snapshot() SessionSnapshot { } // Invalidate drops the cached session so the next EnsureSession re-creates -// it. Used when a chat request reports a session-level error. +// it. Used when a chat request reports a session-level error. The +// invalidation is recorded with the canonical 409 reason (the session-invalid +// chat family); callers that can name a more specific cause use +// InvalidateWithReason. func (m *Manager) Invalidate() { + m.InvalidateWithReason(reason409, 0) +} + +// InvalidateWithReason drops the cached session, recording WHY (T9/T10) and +// feeding the re-admit storm detector. reason is a terminal-event cause from +// the vocabulary (ended|superseded|shutdown|model_lock|expired|409|poll| +// store); status is the triggering HTTP status when known (e.g. 409 from the +// chat/poll error), 0 when unknown — a 0 status is omitted from the log. +func (m *Manager) InvalidateWithReason(reason string, status int) { m.mu.Lock() instanceID := "" if m.state != nil { @@ -817,7 +959,12 @@ func (m *Manager) Invalidate() { } m.commit(nil) m.mu.Unlock() - slog.Debug("session invalidated", "instance_id", instanceID) + m.recordInvalidation(reason) + if status > 0 { + slog.Debug("session invalidated", "instance_id", instanceID, "reason", reason, "status", status) + return + } + slog.Debug("session invalidated", "instance_id", instanceID, "reason", reason) } // ClearQueued drops the cached session only when it is in the queued @@ -848,7 +995,7 @@ func (m *Manager) EndSession(ctx context.Context) error { if instanceID == "" { return nil } - slog.Debug("session ended", "instance_id", instanceID) + slog.Debug("session ended", "instance_id", instanceID, "reason", reasonEnded) // A superseded DELETE is the same "slot already gone" case as // session-invalid (#119): swallow both so teardown never errors on a // slot another instance took over. @@ -897,7 +1044,7 @@ func (m *Manager) Shutdown(ctx context.Context) error { // session wire: DELETE = Bearer only, #120 — EndSession never sends the // instance header). The cached state is kept in-memory so the store // entry stays; the process is exiting. - slog.Debug("session ended on shutdown", "instance_id", shortInstance(instanceID)) + slog.Debug("session ended on shutdown", "instance_id", shortInstance(instanceID), "reason", reasonShutdown) if err := m.client.EndSession(ctx); err != nil && !errors.Is(err, upstream.ErrSessionInvalid) && !errors.Is(err, upstream.ErrSessionSuperseded) { return err } @@ -998,7 +1145,9 @@ func (m *Manager) Poll(ctx context.Context) error { instanceID := m.state.instanceID m.mu.Unlock() + start := time.Now() st, err := m.client.GetSessionWithOpts(ctx, instanceID, true) + ms := time.Since(start).Milliseconds() if err != nil { // #116: 428 waiting_room_required is session-ENDING // (endsTheSession:true per FREEBUFF_GATE_CODES — the seat is gone; @@ -1007,12 +1156,17 @@ func (m *Manager) Poll(ctx context.Context) error { // WAITING_ROOM_CHAIN fires before the create). Any other poll error // is left for the pool's failure backoff. if errors.Is(err, upstream.ErrWaitingRoomRequired) { + dropped := false m.mu.Lock() if m.state != nil && m.state.instanceID == instanceID { m.commit(nil) - slog.Debug("session dropped during poll", "reason", "waiting_room_required", "instance_id", instanceID) + dropped = true } m.mu.Unlock() + if dropped { + m.recordInvalidation(reasonPoll) + slog.Warn("session dropped during poll", "reason", reasonPoll, "status", "waiting_room_required", "instance_id", instanceID) + } } return err } @@ -1025,22 +1179,32 @@ func (m *Manager) Poll(ctx context.Context) error { // admission (cooldown) so the token re-admits only after the pool's // ban window, instead of polling a stale slot. if st.Status == "banned" { + dropped := false m.mu.Lock() if m.state != nil && m.state.instanceID == instanceID { m.commit(nil) - slog.Debug("session dropped during poll", "reason", st.Status, "instance_id", instanceID) + dropped = true } m.mu.Unlock() + if dropped { + m.recordInvalidation(reasonPoll) + slog.Warn("session dropped during poll", "reason", reasonPoll, "status", st.Status, "instance_id", instanceID) + } } return serr } if st.Status == "superseded" || st.Status == "none" { + dropped := false m.mu.Lock() if m.state != nil && m.state.instanceID == instanceID { m.commit(nil) - slog.Debug("session ended during poll", "reason", st.Status, "instance_id", instanceID) + dropped = true } m.mu.Unlock() + if dropped { + m.recordInvalidation(tableReason(st.Status)) + slog.Warn("session ended during poll", "reason", tableReason(st.Status), "status", st.Status, "instance_id", instanceID) + } return nil } if st.Status == "ended" { @@ -1070,13 +1234,22 @@ func (m *Manager) Poll(ctx context.Context) error { } // The row is gone (no instance id) or past grace: drop it so the // next EnsureSession re-creates a fresh session. + dropped := false m.mu.Lock() if m.state != nil && m.state.instanceID == instanceID { m.commit(nil) - slog.Debug("session ended during poll", "reason", st.Status, "instance_id", instanceID) + dropped = true } m.mu.Unlock() + if dropped { + m.recordInvalidation(tableReason(st.Status)) + slog.Warn("session ended during poll", "reason", tableReason(st.Status), "status", st.Status, "instance_id", instanceID) + } return nil } + // Heartbeat liveness confirmed: the compact poll returned a usable + // status (active). instance/ms/status standardize the heartbeat poll + // line (T11) so ops can see each liveness beat and its latency. + slog.Debug("session: heartbeat poll", "instance_id", shortInstance(instanceID), "ms", ms, "status", st.Status) return nil } diff --git a/internal/session/session_test.go b/internal/session/session_test.go index fb2dae2..411704d 100644 --- a/internal/session/session_test.go +++ b/internal/session/session_test.go @@ -1,11 +1,14 @@ package session import ( + "bytes" "context" "errors" "fmt" "io" + "log/slog" "net/http" + "path/filepath" "strings" "sync" "sync/atomic" @@ -1478,3 +1481,308 @@ func TestSnapshotActiveUsersForIP(t *testing.T) { t.Errorf("Status = %q, want active", snap.Status) } } + +// — T9/T10/T11: session lifecycle telemetry (wave 2). — + +// captureLogs swaps slog's default handler for a buffer-backed text handler +// at Debug level and returns the restore function. Session tests run +// sequentially (no t.Parallel), so swapping the process default is safe. +func captureLogs(buf *bytes.Buffer) func() { + prev := slog.Default() + slog.SetDefault(slog.New(slog.NewTextHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug}))) + return func() { slog.SetDefault(prev) } +} + +// TestTerminalEventReasons pins T9: every terminal session event carries a +// reason from the vocabulary (ended|superseded|shutdown|model_lock|expired| +// 409|poll|store), and session invalidated gains the triggering HTTP status +// when known. +func TestTerminalEventReasons(t *testing.T) { + t.Run("invalidated carries caller reason and status", func(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + mgr := newTestManager(t, mock) + if _, err := mgr.EnsureSession(context.Background()); err != nil { + t.Fatal(err) + } + var buf bytes.Buffer + restore := captureLogs(&buf) + defer restore() + mgr.InvalidateWithReason("expired", 400) + got := buf.String() + if !strings.Contains(got, `msg="session invalidated"`) || + !strings.Contains(got, "reason=expired") || + !strings.Contains(got, "status=400") { + t.Errorf("invalidated log missing reason/status:\n%s", got) + } + }) + + t.Run("bare invalidate defaults to 409 reason", func(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + mgr := newTestManager(t, mock) + if _, err := mgr.EnsureSession(context.Background()); err != nil { + t.Fatal(err) + } + var buf bytes.Buffer + restore := captureLogs(&buf) + defer restore() + mgr.Invalidate() + got := buf.String() + if !strings.Contains(got, `msg="session invalidated"`) || !strings.Contains(got, "reason=409") { + t.Errorf("bare Invalidate log missing default reason=409:\n%s", got) + } + }) + + t.Run("ended carries reason ended", func(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + mgr := newTestManager(t, mock) + if _, err := mgr.EnsureSession(context.Background()); err != nil { + t.Fatal(err) + } + var buf bytes.Buffer + restore := captureLogs(&buf) + defer restore() + if err := mgr.EndSession(context.Background()); err != nil { + t.Fatal(err) + } + got := buf.String() + if !strings.Contains(got, `msg="session ended"`) || !strings.Contains(got, "reason=ended") { + t.Errorf("ended log missing reason=ended:\n%s", got) + } + }) + + t.Run("shutdown carries reason shutdown", func(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + store := NewStore(filepath.Join(t.TempDir(), "state.json")) + mgr := newTestManagerWithStore(t, mock, store) + if _, err := mgr.EnsureSession(context.Background()); err != nil { + t.Fatal(err) + } + var buf bytes.Buffer + restore := captureLogs(&buf) + defer restore() + if err := mgr.Shutdown(context.Background()); err != nil { + t.Fatal(err) + } + got := buf.String() + if !strings.Contains(got, `msg="session ended on shutdown"`) || !strings.Contains(got, "reason=shutdown") { + t.Errorf("shutdown log missing reason=shutdown:\n%s", got) + } + }) + + t.Run("dropped during poll carries poll reason and status", func(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + mgr := newTestManager(t, mock) + if _, err := mgr.EnsureSession(context.Background()); err != nil { + t.Fatal(err) + } + mock.SessionHandler = func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusTooEarly) // 428 waiting_room_required + _, _ = io.WriteString(w, `{"error":"waiting_room_required"}`) + } + var buf bytes.Buffer + restore := captureLogs(&buf) + defer restore() + _ = mgr.Poll(context.Background()) + got := buf.String() + if !strings.Contains(got, `msg="session dropped during poll"`) || + !strings.Contains(got, "reason=poll") || + !strings.Contains(got, "status=waiting_room_required") { + t.Errorf("poll drop log missing reason=poll/status:\n%s", got) + } + }) + + t.Run("ended during poll maps superseded reason", func(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + mgr := newTestManager(t, mock) + if _, err := mgr.EnsureSession(context.Background()); err != nil { + t.Fatal(err) + } + mock.SessionHandler = func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "application/json") + _, _ = io.WriteString(w, `{"status":"superseded","instanceId":"inst-abc-123"}`) + } + var buf bytes.Buffer + restore := captureLogs(&buf) + defer restore() + if err := mgr.Poll(context.Background()); err != nil { + t.Fatalf("Poll: %v", err) + } + got := buf.String() + if !strings.Contains(got, `msg="session ended during poll"`) || + !strings.Contains(got, "reason=superseded") || + !strings.Contains(got, "status=superseded") { + t.Errorf("poll end log missing reason=superseded/status:\n%s", got) + } + }) + + t.Run("recreated maps upstream status to table reason", func(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + mock.SessionSequence = []string{"none", "active"} + mgr := newTestManager(t, mock) + var buf bytes.Buffer + restore := captureLogs(&buf) + defer restore() + if _, err := mgr.EnsureSession(context.Background()); err != nil { + t.Fatal(err) + } + got := buf.String() + if !strings.Contains(got, `msg="session recreated"`) || + !strings.Contains(got, "reason=ended") || + !strings.Contains(got, "status=none") { + t.Errorf("recreated log missing table reason/status:\n%s", got) + } + }) +} + +// TestReAdmitStormDetector pins T10: more than 3 invalidations within 60s +// emit exactly ONE "session re-admit storm" summary with the count, +// duration_ms, superseded, and burned_slots fields; isolated invalidations +// stay quiet; the detector re-arms only after a full quiet window. +func TestReAdmitStormDetector(t *testing.T) { + base := time.Date(2026, 8, 18, 12, 0, 0, 0, time.UTC) + + t.Run("isolated and three-in-window stay quiet", func(t *testing.T) { + now := base + m := &Manager{now: func() time.Time { return now }} + var buf bytes.Buffer + restore := captureLogs(&buf) + defer restore() + + m.InvalidateWithReason("expired", 400) + now = now.Add(30 * time.Second) + m.InvalidateWithReason("expired", 400) + now = now.Add(29 * time.Second) + m.InvalidateWithReason("expired", 400) // 3 within 59s: not >3 + if got := buf.String(); strings.Contains(got, "session re-admit storm") { + t.Fatalf("isolated/3-in-window invalidations emitted a storm summary:\n%s", got) + } + }) + + t.Run("burst fires one summary then suppresses until quiet", func(t *testing.T) { + now := base + m := &Manager{now: func() time.Time { return now }} + var buf bytes.Buffer + restore := captureLogs(&buf) + defer restore() + + m.InvalidateWithReason("superseded", 409) // t+0s + now = now.Add(time.Second) + m.InvalidateWithReason("superseded", 409) // t+1s + now = now.Add(time.Second) + m.InvalidateWithReason("expired", 400) // t+2s + now = now.Add(time.Second) + m.recordReAdmitTrigger() // pre-emptive re-admit in the window + m.InvalidateWithReason("expired", 400) // t+3s: 4th in window → storm + + got := buf.String() + if n := strings.Count(got, "session re-admit storm"); n != 1 { + t.Fatalf("storm summaries = %d, want 1:\n%s", n, got) + } + for _, want := range []string{"count=4", "duration_ms=3000", "superseded=2", "burned_slots=1"} { + if !strings.Contains(got, want) { + t.Errorf("storm summary missing %s:\n%s", want, got) + } + } + + // A 5th invalidation right after the burst is suppressed. + now = now.Add(time.Second) + m.InvalidateWithReason("expired", 400) + if n := strings.Count(buf.String(), "session re-admit storm"); n != 1 { + t.Fatalf("storm summaries after 5th invalidation = %d, want still 1 (suppressed):\n%s", n, buf.String()) + } + + // After a full quiet window the detector re-arms: a new burst of 4 + // fires a second summary. + now = now.Add(70 * time.Second) // 70s past the last summary + m.InvalidateWithReason("expired", 400) + now = now.Add(time.Second) + m.InvalidateWithReason("expired", 400) + now = now.Add(time.Second) + m.InvalidateWithReason("expired", 400) + now = now.Add(time.Second) + m.InvalidateWithReason("expired", 400) // 4th in window, quiet passed + if n := strings.Count(buf.String(), "session re-admit storm"); n != 2 { + t.Fatalf("storm summaries after re-arm burst = %d, want 2:\n%s", n, buf.String()) + } + }) +} + +// TestReAdmitStormTracksPreemptiveTriggers wires the burned_slots count to +// the real pre-emptive re-admit path (issue #99): a triggered re-admit +// whose session is then invalidated in a storm counts as a burned slot. +func TestReAdmitStormTracksPreemptiveTriggers(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + var creates atomic.Int32 + mock.SessionHandler = func(w http.ResponseWriter, r *http.Request) { + if r.Method != http.MethodPost { + writeJSON(w, http.StatusOK, map[string]any{"status": "active", "instanceId": "inst-1", "expiresAt": time.Now().Add(30 * time.Minute).Format(time.RFC3339)}) + return + } + n := creates.Add(1) + id := "inst-1" + if n >= 2 { + id = "inst-2" + } + writeJSON(w, http.StatusOK, map[string]any{"status": "active", "instanceId": id, "expiresAt": time.Now().Add(10 * time.Second).Format(time.RFC3339)}) + } + m := newTestSession(t, mock) + now := time.Date(2026, 8, 18, 12, 0, 0, 0, time.UTC) + m.now = func() time.Time { return now } + m.SetReAdmitLead(time.Minute) + + if _, err := m.EnsureSession(context.Background()); err != nil { + t.Fatal(err) + } + // Second call: cached active with ~5s left (10s expiry, 60s lead) — + // triggers the pre-emptive re-admit and rides the old session. + if _, err := m.EnsureSession(context.Background()); err != nil { + t.Fatal(err) + } + + var buf bytes.Buffer + restore := captureLogs(&buf) + defer restore() + for i := 0; i < 4; i++ { + now = now.Add(time.Second) + m.InvalidateWithReason("expired", 400) + } + got := buf.String() + if n := strings.Count(got, "session re-admit storm"); n != 1 { + t.Fatalf("storm summaries = %d, want 1:\n%s", n, got) + } + if !strings.Contains(got, "burned_slots=1") { + t.Errorf("burned_slots missing/inaccurate, want 1 pre-emptive trigger in window:\n%s", got) + } +} + +// TestHeartbeatPollFields pins T11: the liveness poll's Debug line carries +// instance/ms/status so ops can see each heartbeat beat and its latency. +func TestHeartbeatPollFields(t *testing.T) { + mock := testutil.NewMock() + defer mock.Close() + mgr := newTestManager(t, mock) + if _, err := mgr.EnsureSession(context.Background()); err != nil { + t.Fatal(err) + } + var buf bytes.Buffer + restore := captureLogs(&buf) + defer restore() + if err := mgr.Poll(context.Background()); err != nil { + t.Fatal(err) + } + got := buf.String() + if !strings.Contains(got, `msg="session: heartbeat poll"`) || + !strings.Contains(got, "instance_id=") || + !strings.Contains(got, "ms=") || + !strings.Contains(got, "status=active") { + t.Errorf("heartbeat poll log missing instance/ms/status:\n%s", got) + } +} diff --git a/internal/stealth/profiles.go b/internal/stealth/profiles.go index c199b67..d218b4b 100644 --- a/internal/stealth/profiles.go +++ b/internal/stealth/profiles.go @@ -6,7 +6,9 @@ package stealth import ( cryptoRand "crypto/rand" "encoding/binary" + "log/slog" "strings" + "sync/atomic" utls "github.com/refraction-networking/utls" ) @@ -129,6 +131,29 @@ var ( // DefaultProfile returns Chrome 126 as the default modern profile. func DefaultProfile() *Profile { return ProfileChrome126 } +// logger is the package's Debug sink for profile-selection lines (T18), +// settable via SetLogger so tests can capture them. atomic so a test +// SetLogger can never race with a concurrent dial reading it; the zero +// value falls back to the process logger. +var logger atomic.Pointer[slog.Logger] + +// SetLogger replaces the package's log sink (nil restores slog.Default). +// Used by tests to capture the profile-selection Debug line. +func SetLogger(l *slog.Logger) { + if l == nil { + l = slog.Default() + } + logger.Store(l) +} + +// log returns the package log sink, defaulting to the process logger. +func log() *slog.Logger { + if l := logger.Load(); l != nil { + return l + } + return slog.Default() +} + // Lookup returns the profile matching the given name (case-insensitive) // and true, or nil, false for unknown names. func Lookup(name string) (*Profile, bool) { @@ -159,6 +184,8 @@ func Lookup(name string) (*Profile, bool) { // GetProfileForConnection returns a concrete profile for one connection. // For static profiles it returns p unchanged. For ProfileRandom or ProfileAuto, // it resolves a fresh profile and User-Agent using crypto/rand (#3, #21). +// Every resolution logs a Debug line naming the selected profile (T18), so +// an operator can correlate each connection to its TLS fingerprint. func GetProfileForConnection(p *Profile) *Profile { if p == nil { p = DefaultProfile() @@ -171,14 +198,18 @@ func GetProfileForConnection(p *Profile) *Profile { ProfileEdge126, } idx := cryptoRandInt(len(presets)) - return presets[idx] + selected := presets[idx] + log().Debug("stealth profile selected", "profile", string(selected.ID)) + return selected } if p.ID == ProfileIDRandom { prof := *p prof.UserAgent = RandomUserAgent() prof.SecChUA, prof.SecChUAPlatform = clientHintsForUA(prof.UserAgent) + log().Debug("stealth profile selected", "profile", string(prof.ID)) return &prof } + log().Debug("stealth profile selected", "profile", string(p.ID)) return p } diff --git a/internal/stealth/stealth_test.go b/internal/stealth/stealth_test.go index 3063e60..006ad8b 100644 --- a/internal/stealth/stealth_test.go +++ b/internal/stealth/stealth_test.go @@ -11,6 +11,7 @@ import ( "crypto/x509/pkix" "encoding/pem" "io" + "log/slog" "math/big" "net" "net/http" @@ -728,3 +729,36 @@ func TestDialerALPNNegotiation(t *testing.T) { t.Errorf("nil ALPN negotiated %q, want http/1.1 (default)", got) } } + +// TestProfileSelectionLogs verifies T18: every GetProfileForConnection +// resolution logs a Debug line naming the selected profile — static, +// auto-resolved, and random alike. +func TestProfileSelectionLogs(t *testing.T) { + var sink bytes.Buffer + SetLogger(slog.New(slog.NewTextHandler(&sink, &slog.HandlerOptions{Level: slog.LevelDebug}))) + t.Cleanup(func() { SetLogger(nil) }) + + if p := GetProfileForConnection(ProfileChrome120); p != ProfileChrome120 { + t.Fatalf("static selection = %v, want ProfileChrome120", p) + } + if !strings.Contains(sink.String(), "stealth profile selected") || !strings.Contains(sink.String(), "profile=chrome120") { + t.Errorf("static profile selection not logged: %s", sink.String()) + } + + before := sink.Len() + sel := GetProfileForConnection(ProfileAuto) + if sel == nil || sel.ID == ProfileIDAuto { + t.Fatal("auto profile not resolved to a concrete profile") + } + after := sink.String()[before:] + if !strings.Contains(after, "stealth profile selected") || !strings.Contains(after, "profile=") { + t.Errorf("auto profile selection not logged: %s", after) + } + + before = sink.Len() + GetProfileForConnection(ProfileRandom) + after = sink.String()[before:] + if !strings.Contains(after, "stealth profile selected") || !strings.Contains(after, "profile=random") { + t.Errorf("random profile selection not logged: %s", after) + } +} diff --git a/internal/testutil/env.go b/internal/testutil/env.go index f60823e..558d50b 100644 --- a/internal/testutil/env.go +++ b/internal/testutil/env.go @@ -14,7 +14,7 @@ var configEnvKeys = []string{ "LISTEN_ADDR", "UPSTREAM_BASE_URL", "AUTH_TOKENS", "ROTATION_INTERVAL", "REQUEST_TIMEOUT", "SESSION_CALL_TIMEOUT", "API_KEYS", "ADMIN_TOKEN", "COST_MODE", "TLS_FINGERPRINT", "REGISTRY_REFRESH", "DEBUG_DUMP", - "LOG_FILE", "LOG_LEVEL", "LOG_FORMAT", "MAX_MESSAGES_PER_DAY", "IDLE_ROTATION_TIMEOUT", + "LOG_FILE", "LOG_LEVEL", "LOG_FORMAT", "LOG_ACCESS", "MAX_MESSAGES_PER_DAY", "IDLE_ROTATION_TIMEOUT", "SAFE_MODE", "HYBRID_MODE", "MODELS_HIDE_UNAVAILABLE", "REQUEST_JITTER", "CLI_VERSION", "MODEL_ALIASES", "TRANSIENT_RETRIES", "SESSION_PERSIST", "SESSION_STATE_FILE", "AUTO_DISCOVER_TOKEN", "HTTP2_UPSTREAM", diff --git a/internal/updatecheck/updatecheck.go b/internal/updatecheck/updatecheck.go index 62fe3a2..dc62017 100644 --- a/internal/updatecheck/updatecheck.go +++ b/internal/updatecheck/updatecheck.go @@ -13,6 +13,7 @@ import ( "encoding/json" "fmt" "io" + "log/slog" "net/http" "strconv" "strings" @@ -36,6 +37,7 @@ const fetchTimeout = 3 * time.Second type Checker struct { repo string client *http.Client + logger *slog.Logger // decision Debug sink (nil = slog.Default()) mu sync.Mutex latest string @@ -49,7 +51,16 @@ func New(repo string, client *http.Client) *Checker { if client == nil { client = &http.Client{Timeout: fetchTimeout} } - return &Checker{repo: repo, client: client} + return &Checker{repo: repo, client: client, logger: slog.Default()} +} + +// SetLogger replaces the checker's log sink (nil restores slog.Default). +// Used by tests and by hosts that want the decision Debug on a custom logger. +func (c *Checker) SetLogger(l *slog.Logger) { + if l == nil { + l = slog.Default() + } + c.logger = l } // Latest returns the latest release tag (e.g. "v0.9.3") from the in-memory @@ -57,12 +68,16 @@ func New(repo string, client *http.Client) *Checker { // older than CacheTTL. A fetch failure returns the previously cached tag // (or "") with the error and still records the attempt, so subsequent // calls back off for CacheTTL instead of re-fetching. The cache is -// refreshed single-flight so concurrent renders share one GET. +// refreshed single-flight so concurrent renders share one GET. Each lookup +// emits a Debug line with the decision (cached|fetched|failed) and the +// lookup duration (T18). func (c *Checker) Latest(ctx context.Context) (string, error) { + start := time.Now() c.mu.Lock() if time.Since(c.fetched) < CacheTTL { tag := c.latest c.mu.Unlock() + c.logger.Debug("update check decision", "decision", "cached", "ms", time.Since(start).Milliseconds()) return tag, nil } if c.fetching { @@ -76,6 +91,7 @@ func (c *Checker) Latest(ctx context.Context) (string, error) { c.mu.Lock() tag := c.latest c.mu.Unlock() + c.logger.Debug("update check decision", "decision", "cached", "ms", time.Since(start).Milliseconds()) return tag, ctx.Err() case <-time.After(50 * time.Millisecond): } @@ -83,6 +99,7 @@ func (c *Checker) Latest(ctx context.Context) (string, error) { } tag := c.latest c.mu.Unlock() + c.logger.Debug("update check decision", "decision", "cached", "ms", time.Since(start).Milliseconds()) return tag, nil } c.fetching = true @@ -104,6 +121,11 @@ func (c *Checker) Latest(ctx context.Context) (string, error) { } got := c.latest c.mu.Unlock() + decision := "fetched" + if err != nil || tag == "" { + decision = "failed" + } + c.logger.Debug("update check decision", "decision", decision, "ms", time.Since(start).Milliseconds()) return got, err } diff --git a/internal/updatecheck/updatecheck_test.go b/internal/updatecheck/updatecheck_test.go index f27d5a5..09f246b 100644 --- a/internal/updatecheck/updatecheck_test.go +++ b/internal/updatecheck/updatecheck_test.go @@ -1,7 +1,9 @@ package updatecheck import ( + "bytes" "context" + "log/slog" "net/http" "net/http/httptest" "strings" @@ -151,3 +153,50 @@ func (t *rewriteTransport) RoundTrip(req *http.Request) (*http.Response, error) } var _ = time.Second // keep the time import for future cache-age assertions + +// TestLatestLogsDecision verifies T18: each Latest() lookup logs a Debug +// line with the decision (fetched|cached|failed) and the lookup duration. +func TestLatestLogsDecision(t *testing.T) { + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + _, _ = w.Write([]byte(`{"tag_name":"v9.9.9"}`)) + })) + defer srv.Close() + + var sink bytes.Buffer + c := New(DefaultRepo, &http.Client{Transport: &rewriteTransport{target: srv.URL}, Timeout: fetchTimeout}) + c.SetLogger(slog.New(slog.NewTextHandler(&sink, &slog.HandlerOptions{Level: slog.LevelDebug}))) + + // First lookup fetches → decision=fetched with ms. + if _, err := c.Latest(context.Background()); err != nil { + t.Fatal(err) + } + logs := sink.String() + for _, want := range []string{"update check decision", "decision=fetched", "ms="} { + if !strings.Contains(logs, want) { + t.Errorf("fetched lookup log missing %q: %s", want, logs) + } + } + + // Second lookup within CacheTTL → decision=cached, no new fetch. + if _, err := c.Latest(context.Background()); err != nil { + t.Fatal(err) + } + if got := strings.Count(sink.String(), "decision=cached"); got != 1 { + t.Errorf("cached decision lines = %d, want 1", got) + } + + // A failing source → decision=failed. + srvFail := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusInternalServerError) + })) + defer srvFail.Close() + var sinkFail bytes.Buffer + c2 := New(DefaultRepo, &http.Client{Transport: &rewriteTransport{target: srvFail.URL}, Timeout: fetchTimeout}) + c2.SetLogger(slog.New(slog.NewTextHandler(&sinkFail, &slog.HandlerOptions{Level: slog.LevelDebug}))) + if _, err := c2.Latest(context.Background()); err == nil { + t.Fatal("Latest against a 500 source succeeded, want error") + } + if !strings.Contains(sinkFail.String(), "decision=failed") { + t.Errorf("failed lookup log missing decision=failed: %s", sinkFail.String()) + } +} diff --git a/internal/upstream/client.go b/internal/upstream/client.go index 0329502..72c54c4 100644 --- a/internal/upstream/client.go +++ b/internal/upstream/client.go @@ -2770,7 +2770,11 @@ func (c *Client) dump(kind string, req *http.Request, status int, body string) { } } fmt.Fprintf(&buf, "\n[status %d]\n%s\n", status, truncate(body, 20000)) - _ = os.WriteFile(path, buf.Bytes(), 0o600) + if err := os.WriteFile(path, buf.Bytes(), 0o600); err != nil { + // T18: the write was previously swallowed (`_ = os.WriteFile`) — + // surface the failure so a broken dump dir is not silent. + slog.Warn("debug dump write failed", "path", path, "err", err) + } } func sanitizeName(p string) string { diff --git a/internal/upstream/client_test.go b/internal/upstream/client_test.go index 9f51feb..07fe286 100644 --- a/internal/upstream/client_test.go +++ b/internal/upstream/client_test.go @@ -11,6 +11,7 @@ import ( "errors" "fmt" "io" + "log/slog" "net" "net/http" "net/http/httptest" @@ -3582,3 +3583,37 @@ func TestReqIDContextHelpers(t *testing.T) { t.Errorf("ReqID(child) = %q, want req-123 (value must survive descendant wraps)", got) } } + +// TestDumpWriteFailureLogsWarn verifies T18: when DEBUG_DUMP is enabled but +// the dump write fails (a regular file occupies the dump/ path), the failure +// is logged as a WARN with path and err instead of being swallowed. +func TestDumpWriteFailureLogsWarn(t *testing.T) { + orig := slog.Default() + var sink bytes.Buffer + slog.SetDefault(slog.New(slog.NewTextHandler(&sink, &slog.HandlerOptions{Level: slog.LevelWarn}))) + t.Cleanup(func() { slog.SetDefault(orig) }) + + t.Chdir(t.TempDir()) + // A regular FILE named "dump": MkdirAll fails and WriteFile hits + // ENOTDIR/EEXIST — deterministic failure injection. + if err := os.WriteFile("dump", []byte("occupied"), 0o644); err != nil { + t.Fatal(err) + } + client, err := New("tok", testConfig("", func(c *config.Config) { c.DebugDump = true })) + if err != nil { + t.Fatal(err) + } + req, err := http.NewRequest(http.MethodPost, "https://www.codebuff.com/v1/chat/completions", nil) + if err != nil { + t.Fatal(err) + } + client.dump("chat", req, http.StatusOK, "response body") + + logs := sink.String() + if !strings.Contains(logs, "debug dump write failed") { + t.Fatalf("dump WARN missing: %s", logs) + } + if !strings.Contains(logs, "path=") || !strings.Contains(logs, "err=") { + t.Errorf("dump WARN missing path/err attrs: %s", logs) + } +} From 81ef8d02fd3e69b1a5b40bdf7b24b000e946d6d7 Mon Sep 17 00:00:00 2001 From: trefeon Date: Tue, 18 Aug 2026 15:37:10 +0700 Subject: [PATCH 3/6] logging: runs lifecycle closure, logring filters, log-event metrics Wave 3 of the observability plan. Why: runs ended without a visible lifecycle record (11 started vs 3 finished in the log watch), the shutdown abandon WARN dumped the whole *RunManager struct, the log ring was a fixed 500 with no admin filtering, and log volume had no machine-readable counter. - runs: run finished gains duration_ms/steps/termination (finish|drop); drop paths keep their TTL/queue-cap WARNs; shutdown-abandon WARN now logs pending_jobs/runs/key instead of the manager struct - LOG_RING_SIZE config (50..5000, default 500); /admin/logs level+msg filters with hx-get filter row (poll preserves filters via hx-include) - logring counts records per (level,msg); Counts() snapshot; Server retains the ring; /metrics renders freebuff_proxy_log_events_total{level,msg} with escaped labels --- cmd/freebuff-proxy/main.go | 2 +- internal/config/config.go | 47 ++++-- internal/config/config_test.go | 80 +++++++++- internal/dashboard/assets/app.css | 20 +++ internal/dashboard/dashboard.go | 37 ++++- internal/dashboard/dashboard_test.go | 68 ++++++++ internal/dashboard/templates/layout.tmpl | 2 +- internal/dashboard/templates/logs.tmpl | 20 +++ internal/logring/logring.go | 45 +++++- internal/logring/logring_test.go | 70 +++++++++ internal/runs/runs.go | 33 +++- internal/runs/runs_test.go | 188 +++++++++++++++++++++++ internal/server/server.go | 25 ++- internal/server/wire_metrics_test.go | 56 +++++++ internal/testutil/env.go | 2 +- 15 files changed, 666 insertions(+), 29 deletions(-) diff --git a/cmd/freebuff-proxy/main.go b/cmd/freebuff-proxy/main.go index e46bda5..3707eb0 100644 --- a/cmd/freebuff-proxy/main.go +++ b/cmd/freebuff-proxy/main.go @@ -102,7 +102,7 @@ func main() { logger := telemetry.New(level, cfg.LogFile, cfg.LogFormat) // The dashboard log viewer reads from an in-memory ring that mirrors // every record the process logger emits (no log file or docker needed). - logringHandler := logring.NewHandler(logger.Handler(), 500) + logringHandler := logring.NewHandler(logger.Handler(), cfg.LogRingSize) logger = slog.New(logringHandler) // The pool/upstream/session/runs log through slog.Default(); route it // through our logger so the configured level and log file cover them too. diff --git a/internal/config/config.go b/internal/config/config.go index e6f0529..f5a7b52 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -46,14 +46,17 @@ type Config struct { // The only safe value is the token's own account id. (True CLI parity — // auto-deriving each token's own id once via GET /api/v1/me — is // deferred; see the gap analysis item 24.) - ActingUserID string - TLSFingerprint string // "" (plain Go transport) | chrome120 | chrome126 | safari17 | safari18 | firefox120 | firefox128 | edge126 | random | auto - RegistryRefresh time.Duration - DebugDump bool - LogFile string - LogLevel string // "" (use -v/default) or debug|info|warn|error|trace - LogFormat string // "text" (default) or "json" - LogAccess bool // true = per-request access log lines (LOG_ACCESS; default true, an empty .env line keeps it enabled) + ActingUserID string + TLSFingerprint string // "" (plain Go transport) | chrome120 | chrome126 | safari17 | safari18 | firefox120 | firefox128 | edge126 | random | auto + RegistryRefresh time.Duration + DebugDump bool + LogFile string + LogLevel string // "" (use -v/default) or debug|info|warn|error|trace + LogFormat string // "text" (default) or "json" + LogAccess bool // true = per-request access log lines (LOG_ACCESS; default true, an empty .env line keeps it enabled) + // LogRingSize is the bounded in-memory log ring capacity behind the + // dashboard log viewer (LOG_RING_SIZE; default 500, validated 50..5000). + LogRingSize int MaxMessagesPerDay int // 0 = unlimited: per-token cap on successful chats per 24h MaxSpendPerDay int64 // 0 = unlimited: ADVISORY per-token Pacific-day spend ceiling in ledger units (tokens from upstream usage blocks; issue #122). Never blocks — the upstream $ ceilings ($15 full / $5 limited / $0.50 restricted, compose by minimum, server-enforced) are the real gate. Surfaced as SpendLimit/SpendPct on /healthz so operator comparisons align with the Pacific-midnight reset. IdleRotationTimeout time.Duration // 0 = disabled: pause rotation/refresh after this idle period @@ -190,6 +193,7 @@ type rawConfig struct { LogLevel string `json:"LOG_LEVEL"` LogFormat string `json:"LOG_FORMAT"` LogAccess bool `json:"LOG_ACCESS"` + LogRingSize *int `json:"LOG_RING_SIZE"` MaxMessagesPerDay *int `json:"MAX_MESSAGES_PER_DAY"` MaxSpendPerDay *int `json:"MAX_SPEND_PER_DAY"` IdleRotationTimeout string `json:"IDLE_ROTATION_TIMEOUT"` @@ -229,13 +233,14 @@ func defaultRawConfig() rawConfig { RegistryRefresh: "6h", CostMode: "free", // free-tier mode; omission routes requests as PAID and fresh free accounts get 402 "Out of credits" (upstream check: cost_mode !== 'free' → billing) MaxMessagesPerDay: nil, - MaxSpendPerDay: nil, // 0 = unlimited advisory spend ceiling (never enforced) - IdleRotationTimeout: "", // "" = disabled (unset → SAFE_MODE preset may fill) - SafeMode: true, // anti-ban presets on by default; set SAFE_MODE=false to disable - LogAccess: true, // per-request access lines on by default; LOG_ACCESS=false disables them - HybridMode: false, // relay client tokens AND serve the pool (off by default) - CORSAllowedOrigin: "*", // browser clients reach /v1/* cross-origin by default - RequestJitter: "", // "" = disabled (unset → SAFE_MODE preset may fill) + MaxSpendPerDay: nil, // 0 = unlimited advisory spend ceiling (never enforced) + IdleRotationTimeout: "", // "" = disabled (unset → SAFE_MODE preset may fill) + SafeMode: true, // anti-ban presets on by default; set SAFE_MODE=false to disable + LogAccess: true, // per-request access lines on by default; LOG_ACCESS=false disables them + LogRingSize: ptrInt(500), // dashboard log viewer ring capacity (T19) + HybridMode: false, // relay client tokens AND serve the pool (off by default) + CORSAllowedOrigin: "*", // browser clients reach /v1/* cross-origin by default + RequestJitter: "", // "" = disabled (unset → SAFE_MODE preset may fill) CLIVersion: "0.10.7", TransientRetries: nil, // nil = 1 (one retry after a transient transport failure; 0 disables) SessionPersist: false, // opt-in: persist session state across restarts @@ -386,6 +391,7 @@ func Load(configPath string) (Config, error) { overrideString(&raw.LogLevel, "LOG_LEVEL") overrideString(&raw.LogFormat, "LOG_FORMAT") overrideBool(&raw.LogAccess, "LOG_ACCESS") + overrideInt(&raw.LogRingSize, "LOG_RING_SIZE") overrideInt(&raw.MaxMessagesPerDay, "MAX_MESSAGES_PER_DAY") overrideInt(&raw.MaxSpendPerDay, "MAX_SPEND_PER_DAY") overrideString(&raw.IdleRotationTimeout, "IDLE_ROTATION_TIMEOUT") @@ -549,6 +555,13 @@ func Load(configPath string) (Config, error) { transientRetries = *raw.TransientRetries } + // LOG_RING_SIZE: nil (unset/empty) defaults to 500; an explicit value + // must stay within 50..5000 (validated in Validate). + logRingSize := 500 + if raw.LogRingSize != nil { + logRingSize = *raw.LogRingSize + } + // FALLBACK_AFTER_MS (issue #100): milliseconds, ""/0 = disabled. Any // parse failure fails the load — a typo silently disabling model // fallback would be worse than surfacing it. @@ -619,6 +632,7 @@ func Load(configPath string) (Config, error) { LogLevel: strings.TrimSpace(raw.LogLevel), LogFormat: logFormat, LogAccess: raw.LogAccess, + LogRingSize: logRingSize, MaxMessagesPerDay: maxMessagesPerDay, MaxSpendPerDay: maxSpendPerDay, IdleRotationTimeout: idleRotationTimeout, @@ -773,6 +787,8 @@ func (c Config) Validate() error { return errors.New("MAX_MESSAGES_PER_DAY cannot be negative") case c.MaxSpendPerDay < 0: return errors.New("MAX_SPEND_PER_DAY cannot be negative") + case c.LogRingSize != 0 && (c.LogRingSize < 50 || c.LogRingSize > 5000): + return errors.New("LOG_RING_SIZE must be between 50 and 5000 (default 500)") } if c.WebhookURL != "" { @@ -943,6 +959,7 @@ func applyDotenv(raw *rawConfig, path string) error { overrideStringFrom(&raw.LogLevel, get, "LOG_LEVEL") overrideStringFrom(&raw.LogFormat, get, "LOG_FORMAT") overrideBoolFrom(&raw.LogAccess, get, "LOG_ACCESS") + overrideIntFrom(&raw.LogRingSize, get, "LOG_RING_SIZE") overrideIntFrom(&raw.MaxMessagesPerDay, get, "MAX_MESSAGES_PER_DAY") overrideIntFrom(&raw.MaxSpendPerDay, get, "MAX_SPEND_PER_DAY") overrideStringFrom(&raw.IdleRotationTimeout, get, "IDLE_ROTATION_TIMEOUT") diff --git a/internal/config/config_test.go b/internal/config/config_test.go index cbadb2c..1cb8cf6 100644 --- a/internal/config/config_test.go +++ b/internal/config/config_test.go @@ -5,6 +5,7 @@ import ( "log/slog" "os" "path/filepath" + "strconv" "strings" "testing" "time" @@ -17,7 +18,7 @@ import ( var envKeys = []string{ "LISTEN_ADDR", "UPSTREAM_BASE_URL", "AUTH_TOKENS", "ROTATION_INTERVAL", "REQUEST_TIMEOUT", "SESSION_CALL_TIMEOUT", "API_KEYS", "COST_MODE", "ACTING_USER_ID", "USER_ID", - "TLS_FINGERPRINT", "REGISTRY_REFRESH", "DEBUG_DUMP", "LOG_FILE", "LOG_LEVEL", "LOG_FORMAT", "LOG_ACCESS", + "TLS_FINGERPRINT", "REGISTRY_REFRESH", "DEBUG_DUMP", "LOG_FILE", "LOG_LEVEL", "LOG_FORMAT", "LOG_ACCESS", "LOG_RING_SIZE", "MAX_MESSAGES_PER_DAY", "IDLE_ROTATION_TIMEOUT", "SAFE_MODE", "HYBRID_MODE", "MODELS_HIDE_UNAVAILABLE", "CORS_ALLOWED_ORIGIN", "REQUEST_JITTER", "CLI_VERSION", "MODEL_ALIASES", "AUTO_DISCOVER_TOKEN", "TRANSIENT_RETRIES", "ADMIN_TOKEN", @@ -221,6 +222,83 @@ func TestTransientRetries(t *testing.T) { t.Setenv("TRANSIENT_RETRIES", "") } +// TestLogRingSize pins the T19 LOG_RING_SIZE knob: default 500 when unset, +// an empty value keeps the default, explicit values must stay within +// 50..5000 (below the floor / above the cap fail validation), and the JSON +// and .env sources both apply. +func TestLogRingSize(t *testing.T) { + clearEnv(t) + t.Setenv("AUTH_TOKENS", "tok") + + // default: 500 when unset + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (default): %v", err) + } else if cfg.LogRingSize != 500 { + t.Errorf("LogRingSize default = %d, want 500", cfg.LogRingSize) + } + + // explicit empty value keeps the default + t.Setenv("LOG_RING_SIZE", "") + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (empty): %v", err) + } else if cfg.LogRingSize != 500 { + t.Errorf("LogRingSize (empty) = %d, want 500", cfg.LogRingSize) + } + + // env source: a valid value loads + t.Setenv("LOG_RING_SIZE", "2000") + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (env 2000): %v", err) + } else if cfg.LogRingSize != 2000 { + t.Errorf("LogRingSize (env) = %d, want 2000", cfg.LogRingSize) + } + + // boundary values are accepted + for _, v := range []string{"50", "5000"} { + t.Setenv("LOG_RING_SIZE", v) + n, _ := strconv.Atoi(v) + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (LOG_RING_SIZE=%s): %v", v, err) + } else if cfg.LogRingSize != n { + t.Errorf("LogRingSize (LOG_RING_SIZE=%s) = %d, want %d", v, cfg.LogRingSize, n) + } + } + + // below the floor fails validation + t.Setenv("LOG_RING_SIZE", "49") + if _, err := Load(""); err == nil || !strings.Contains(err.Error(), "LOG_RING_SIZE") { + t.Fatalf("Load (49): err = %v, want validation error mentioning LOG_RING_SIZE", err) + } + + // above the cap fails validation + t.Setenv("LOG_RING_SIZE", "5001") + if _, err := Load(""); err == nil || !strings.Contains(err.Error(), "LOG_RING_SIZE") { + t.Fatalf("Load (5001): err = %v, want validation error mentioning LOG_RING_SIZE", err) + } + t.Setenv("LOG_RING_SIZE", "") + + // JSON file source + path := filepath.Join(t.TempDir(), "config.json") + if err := os.WriteFile(path, []byte(`{"LOG_RING_SIZE": 750}`), 0o644); err != nil { + t.Fatal(err) + } + if cfg, err := Load(path); err != nil { + t.Fatalf("Load (file): %v", err) + } else if cfg.LogRingSize != 750 { + t.Errorf("LogRingSize (file) = %d, want 750", cfg.LogRingSize) + } + + // .env source (applyDotenv) + if err := os.WriteFile(".env", []byte("AUTH_TOKENS=tok\nLOG_RING_SIZE=900\n"), 0o644); err != nil { + t.Fatal(err) + } + if cfg, err := Load(""); err != nil { + t.Fatalf("Load (.env): %v", err) + } else if cfg.LogRingSize != 900 { + t.Errorf("LogRingSize (.env) = %d, want 900", cfg.LogRingSize) + } +} + func TestSafeMode(t *testing.T) { t.Run("default SafeMode values", func(t *testing.T) { clearEnv(t) diff --git a/internal/dashboard/assets/app.css b/internal/dashboard/assets/app.css index c4edfcb..508c25c 100644 --- a/internal/dashboard/assets/app.css +++ b/internal/dashboard/assets/app.css @@ -515,6 +515,26 @@ textarea[name="content"] { margin-bottom: 0.6rem; } +.logs-filter { + display: flex; + gap: 0.5rem; + align-items: center; + flex-wrap: wrap; + margin: 0 0 0.8rem; +} + +.logs-filter select, +.logs-filter input { + margin: 0; + width: auto; + flex: 0 1 auto; +} + +.logs-filter input[type="search"] { + flex: 1 1 18rem; + min-width: 10rem; +} + .step-card { margin-bottom: 1rem; } diff --git a/internal/dashboard/dashboard.go b/internal/dashboard/dashboard.go index 717d064..6763f16 100644 --- a/internal/dashboard/dashboard.go +++ b/internal/dashboard/dashboard.go @@ -185,7 +185,7 @@ func (d *Dashboard) render(w http.ResponseWriter, r *http.Request, content strin // Page returns a handler for the named content template, wired to its data. func (d *Dashboard) Page(name string) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { - d.render(w, r, name, d.dataFor(name)) + d.render(w, r, name, d.dataFor(name, r)) } } @@ -215,8 +215,9 @@ func (d *Dashboard) RenderRestricted(w http.ResponseWriter, r *http.Request, msg } } -// dataFor resolves the page data for a named content template. -func (d *Dashboard) dataFor(name string) any { +// dataFor resolves the page data for a named content template. r carries the +// query params consumed by the filtered pages (logs). +func (d *Dashboard) dataFor(name string, r *http.Request) any { switch name { case "overview": return d.overviewData() @@ -227,7 +228,7 @@ func (d *Dashboard) dataFor(name string) any { case "models": return d.modelsData() case "logs": - return d.logsData() + return d.logsData(r) case "traces": return d.tracesData() case "setup": @@ -266,7 +267,15 @@ func (d *Dashboard) playgroundData() playgroundData { type logsData struct { Enabled bool - Entries []logEntry + // Level/Msg echo the active filters so the template keeps the controls + // in sync when a filtered fragment re-renders (hx-get targets the same + // #logs-root region). + Level string + Msg string + // HasFilter reports whether a filter is active (drives the empty-state + // copy: "no matching records" vs "no records yet"). + HasFilter bool + Entries []logEntry } type logEntry struct { @@ -276,12 +285,28 @@ type logEntry struct { Fields string } -func (d *Dashboard) logsData() logsData { +func (d *Dashboard) logsData(r *http.Request) logsData { ld := logsData{Enabled: d.logs != nil} if d.logs == nil { return ld } + level := strings.TrimSpace(r.URL.Query().Get("level")) + msg := strings.TrimSpace(r.URL.Query().Get("msg")) + // Echo the level lowercased so the select's option comparison (exact + // match) stays in sync even when the client passes "WARN" or "Info". + ld.Level = strings.ToLower(level) + ld.Msg = msg + ld.HasFilter = level != "" || msg != "" + msgLower := strings.ToLower(msg) for _, e := range d.logs.Recent(200) { + // level matches exactly (INFO/WARN/... case-insensitive); msg is a + // case-insensitive substring of the message. + if level != "" && !strings.EqualFold(e.Level, level) { + continue + } + if msg != "" && !strings.Contains(strings.ToLower(e.Message), msgLower) { + continue + } ld.Entries = append(ld.Entries, logEntry{ Time: e.Time, Level: e.Level, diff --git a/internal/dashboard/dashboard_test.go b/internal/dashboard/dashboard_test.go index e8be337..73cc31c 100644 --- a/internal/dashboard/dashboard_test.go +++ b/internal/dashboard/dashboard_test.go @@ -193,6 +193,74 @@ func TestLogsPageWithoutRing(t *testing.T) { } } +// TestLogsPageFilters pins the T19 filter row: ?level and ?msg (substring, +// case-insensitive) render only matching rows, the empty state switches to +// the filtered copy when a filter matches nothing, and the filter controls +// are present for the hx-get wiring. +func TestLogsPageFilters(t *testing.T) { + ts := newDashboardForPages(t, true) // seeds one INFO "hello ring" record + + get := func(path string) string { + t.Helper() + resp, err := http.Get(ts.URL + path) + if err != nil { + t.Fatal(err) + } + defer func() { _ = resp.Body.Close() }() + return string(mustReadAll(t, resp)) + } + + // The filter row renders: level select + msg input. + page := get("/logs") + for _, want := range []string{`name="level"`, `id="logs-msg"`, "all levels", "hx-get=\"/admin/logs\""} { + if !strings.Contains(page, want) { + t.Errorf("logs page missing filter control %q", want) + } + } + + // level=warn excludes the INFO record and shows the filtered empty state. + page = get("/logs?level=warn") + if strings.Contains(page, "hello ring") { + t.Error("level=warn filter rendered an info record") + } + if !strings.Contains(page, "No matching log records") { + t.Error("level=warn filter should show the filtered empty state") + } + + // level=info keeps the INFO record. + page = get("/logs?level=info") + if !strings.Contains(page, "hello ring") { + t.Error("level=info filter dropped the info record") + } + + // msg is a case-insensitive substring. + for _, q := range []string{"?msg=ring", "?msg=RING", "?msg=hello"} { + page = get("/logs" + q) + if !strings.Contains(page, "hello ring") { + t.Errorf("msg filter %q dropped the matching record", q) + } + } + + // A msg matching nothing flips to the filtered empty state. + page = get("/logs?msg=zzz-none") + if strings.Contains(page, "hello ring") { + t.Error("msg=zzz-none filter rendered a non-matching record") + } + if !strings.Contains(page, "No matching log records") { + t.Error("msg=zzz-none filter should show the filtered empty state") + } + + // Combined level+msg filter. + page = get("/logs?level=info&msg=ring") + if !strings.Contains(page, "hello ring") { + t.Error("combined info+ring filter dropped the matching record") + } + page = get("/logs?level=warn&msg=ring") + if strings.Contains(page, "hello ring") { + t.Error("combined warn+ring filter rendered a non-matching record") + } +} + func TestMetricsPageRendersSparklines(t *testing.T) { cfg := &config.Config{ UpstreamBaseURL: "https://www.codebuff.com", diff --git a/internal/dashboard/templates/layout.tmpl b/internal/dashboard/templates/layout.tmpl index 3fb91b8..d1432dc 100644 --- a/internal/dashboard/templates/layout.tmpl +++ b/internal/dashboard/templates/layout.tmpl @@ -43,7 +43,7 @@ {{if eq .Page "overview"}}{{end}} {{if eq .Page "tokens"}}{{end}} -{{if eq .Page "logs"}}{{end}} +{{if eq .Page "logs"}}{{end}} {{if eq .Page "traces"}}{{end}} {{if eq .Page "metrics"}}{{end}}