logging: observability overhaul — correlation IDs, wire transparency, rate-limit ledger, lifecycle telemetry, coverage - #136
Merged
Conversation
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
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
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
- README + .env.example: LOG_LEVEL=trace, LOG_FORMAT, LOG_ACCESS, LOG_RING_SIZE rows - telemetry: explicit field-wise handler clones in WithAttrs/WithGroup (govet copylocks — copying the struct copied the mutex) - wire_metrics_test: check classify returns (errcheck)
…error classification - pool: in Acquire and AcquireBridge, synchronize effectiveModel and effectiveAgentID with ss.Model (session snapshot) after EnsureSessionForModel. When upstream coerces/downgrades the session (e.g. to mimo/mimo-v2.5 in limited regions like ID), the lease, agent run, and request body stay consistent with the session row instead of failing with session_model_mismatch. - upstream: broaden classifyError to match any session_model_mismatch containing 'limited' (including 'Limited free access is only available with...'), mapping to LimitedIpError instead of tripping a retry-loop 502.
… to fix data race
…uth_internal_test, session_test, client_test)
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What
Three waves of the logging observability plan (
docs/delivery/logging-observability-plan.md, derived from the acerblue log watchdocs/research/log-observations-2026-08-18.md). Observability only — no behavior change to session/rate-limit semantics.Wave 1 — foundations + wire transparency
req_idminted per HTTP request, threaded viaChatOptionsinto upstream do()/retry logs; clientX-Request-Idkept asclient_request_id;trace_session_idnow logged on run start/finish + chat traceLevelTrace(-8),LOG_LEVEL=trace,LOG_FORMAT=json|text, realWithAttrs/WithGroup,RedactHeaderscoversx-freebuff-*, newRedactSecretsscrubscb_/Bearerfrom logged bodiesdo(): status ≥400 logsupstream response(class, redacted body ≤500 runes, body re-wrapped) instead ofupstream ok;upstream rate limit classifiedlogs the FULL body with code/window/retry_after/reset_atrequest failedWARN 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}in /metricschat retry succeeded; retry skipped on canceled ctxWave 2 — session lifecycle + coverage
InvalidateWithReason; re-admit storm detector fires ONEsession re-admit stormsummary (count/duration_ms/superseded/burned_slots) per 60s burst (observability half of [P2] Pre-emptive re-admit storm: fresh instance churns 409s and 502s around every session expiry #132)LOG_ACCESS(default true); /healthz /metrics OPTIONS rate-limited 1/minWave 3 — telemetry surface
run finishedgains duration_ms/steps/termination (finish|drop); shutdown-abandon WARN logs pending_jobs/runs/key (was the whole *RunManager struct)LOG_RING_SIZE(50–5000, default 500); /admin/logs level+msg filters (hx-get, poll preserves filters)freebuff_proxy_log_events_total{level,msg}in /metricsdocs/research/LOG_EVENTS.md(local-only)Verification
Note for the merge
The main repo's working tree currently holds uncommitted #132/#133 WIP (load_shedding/peak_hours classification + re-admit changes) in
internal/upstream/client.go,internal/server/server.go,internal/session/session.go,internal/pool/*. Commit that WIP first or rebase this branch on it — the T7 classification-ledger code touches the sameclassifyErrorregion.No version bump in this PR (release step separate: v0.10.1 PATCH).