logging: observability overhaul — correlation IDs, wire transparency, rate-limit ledger, lifecycle telemetry, coverage

.env.example

@@ -129,8 +129,15 @@ ADMIN_TOKEN=
 #   export AUTO_DISCOVER_TOKEN=false
 
 # ── Observability ────────────────────────────────────────────────────────
-# Log level: debug | info | warn | error
+# Log level: debug | info | warn | error | trace (trace = wire-level bodies)
 LOG_LEVEL=info
+# Log format: text (key=value, colored) or json (one JSON object per line)
+#LOG_FORMAT=text
+# One `access` line per HTTP request; false disables (healthz/metrics/OPTIONS
+# are rate-limited to 1/min regardless)
+#LOG_ACCESS=true
+# In-memory log ring for /admin/logs (50-5000)
+#LOG_RING_SIZE=500
 
 # ── Optional extras (see .env.full-example for every key) ────────────────
 # Upstream base URL (default https://www.codebuff.com)

README.md

@@ -255,7 +255,10 @@ All keys can be set via environment variables or the JSON config file passed to
 | `TLS_FINGERPRINT` | `auto` | `auto`, `chrome120`, `chrome126`, `safari17`, `safari18`, `firefox120`, `firefox128`, `edge126`, `random` |
 | `DEBUG_DUMP` | `false` | Persist redacted traffic dumps to `./dump/` (mode 0600) |
 | `LOG_FILE` | `""` | Append log lines to a file (e.g. `./logs/proxy.log`) |
-| `LOG_LEVEL` | `info` | `debug`, `info`, `warn`, `error` |
+| `LOG_LEVEL` | `info` | `debug`, `info`, `warn`, `error`, `trace` (trace = wire-level bodies) |
+| `LOG_FORMAT` | `text` | `text` (key=value, colored) or `json` (one JSON object per line) |
+| `LOG_ACCESS` | `true` | Log one `access` line per HTTP request (`false` disables; `/healthz`, `/metrics`, OPTIONS are rate-limited to 1/min regardless) |
+| `LOG_RING_SIZE` | `500` | In-memory log ring for `/admin/logs` (50–5000) |
 | `MAX_MESSAGES_PER_DAY` | `0` | Per-token daily cap on successful chats (`0` = unlimited, default; the upstream `429` lock is the real enforcement) |
 | `IDLE_ROTATION_TIMEOUT` | `0` | Finish runs after this idle period (`0` = disabled; `SAFE_MODE` sets 30m when unset) |
 | `SAFE_MODE` | `true` | Apply anti-ban presets (see below; set `false` to disable) |

cmd/freebuff-proxy/main.go

@@ -99,10 +99,10 @@ 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)
+	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.
@@ -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
@@ -471,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())
 }

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

internal/config/config.go

@@ -20,6 +20,8 @@ import (
 	"strconv"
 	"strings"
 	"time"
+
+	"freebuff-proxy/internal/telemetry"
 )
 
 // Config is the fully-resolved, validated runtime configuration.
@@ -44,12 +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
+	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
@@ -184,6 +191,9 @@ type rawConfig struct {
 	DebugDump                        bool   `json:"DEBUG_DUMP"`
 	LogFile                          string `json:"LOG_FILE"`
 	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"`
@@ -223,12 +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
-		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
@@ -377,6 +389,9 @@ 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")
+	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")
@@ -540,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.
@@ -585,6 +607,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 +630,9 @@ func Load(configPath string) (Config, error) {
 		DebugDump:                        raw.DebugDump,
 		LogFile:                          strings.TrimSpace(raw.LogFile),
 		LogLevel:                         strings.TrimSpace(raw.LogLevel),
+		LogFormat:                        logFormat,
+		LogAccess:                        raw.LogAccess,
+		LogRingSize:                      logRingSize,
 		MaxMessagesPerDay:                maxMessagesPerDay,
 		MaxSpendPerDay:                   maxSpendPerDay,
 		IdleRotationTimeout:              idleRotationTimeout,
@@ -756,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 != "" {
@@ -804,11 +837,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 +957,9 @@ 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")
+	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")