docs/logging-contract.md defines the canonical LogEntry shape, the 8 lifecycle stages, requestId propagation rules, redaction policy, and the backend ordering guarantee (per-requestId monotonic ts at emit time) that the dashboard logs UI consumes. CLAUDE.md updated: Node.js 14+ -> 18+ (AsyncLocalStorage is more stable on 18+ across timer / microtask / dynamic-import boundaries). Refs #1141, #1138
7.6 KiB
Logging Contract
Single source of truth for structured backend logging in CCS CLI. Companion to GitHub issues #1138 (umbrella) and #1141 (backend instrumentation).
Overview
CCS emits structured JSONL log entries for backend behavior (proxy daemons, OAuth flows, target spawn lifecycle, executor errors, etc.). This document defines the canonical schema, request-correlation pattern, lifecycle stages, and redaction policy.
CLI text output (
ok / info / warn / failfromsrc/utils/ui.ts) is NOT affected by this contract. Logs are a separate channel — never printed to stdout/stderr.
Schema (LogEntry)
Defined in src/services/logging/log-types.ts.
| Field | Type | Required | Notes |
|---|---|---|---|
id |
string |
yes | UUID per entry. |
timestamp |
string |
yes | ISO 8601. |
level |
'error'|'warn'|'info'|'debug' |
yes | |
source |
string |
yes | Module-scoped identifier (e.g. proxy:openai-compat:messages). |
event |
string |
yes | Dotted machine-readable event name (e.g. request.received). |
message |
string |
yes | Human-readable summary. |
processId |
number |
yes | process.pid. |
runId |
string |
yes | Stable per-process id. |
context |
object |
no | Free-form structured fields (redacted). |
requestId |
string |
no | Correlates entries belonging to one inbound request across stages. |
stage |
LogStage |
no | Lifecycle stage tag. |
latencyMs |
number |
no | Elapsed ms (typically on respond / cleanup). |
error |
{name, message, code?, stack?} |
no | Structured error metadata; never raw token strings. |
Old free-form entries (no requestId / stage) are still valid; new fields are additive.
Example
{"id":"...","timestamp":"2026-04-30T12:34:56.000Z","level":"info","source":"proxy:openai-compat:messages","event":"request.received","message":"Proxy /v1/messages request received","processId":42,"runId":"r1","requestId":"a1b2...","stage":"intake","context":{"method":"POST"}}
Lifecycle Stages
LogStage is one of:
| Stage | When to emit |
|---|---|
intake |
Inbound request received at an entry edge (HTTP handler, CLI dispatch). |
route |
Destination/profile/target resolution. |
auth |
Authentication / authorization (token exchange, profile auth). |
dispatch |
Outbound request prepared / child process spawned. |
upstream |
Upstream call in flight (provider HTTP / spawned child running). |
transform |
Payload translation (request/response shape conversion). |
respond |
Response written / dispatched (latencyMs typically populated). |
cleanup |
Error path, abort, teardown. |
Stages may be skipped or repeated. Streaming responses tag upstream only at start/end (NOT per chunk).
RequestId Propagation (AsyncLocalStorage)
requestId is propagated implicitly via Node AsyncLocalStorage. Entry edges wrap their handler in withRequestContext; every createLogger-emitted entry inside the context auto-merges requestId from the active store.
import { withRequestContext, createLogger } from './services/logging';
const logger = createLogger('proxy:my-edge');
http.createServer((req, res) => {
const requestId = req.headers['x-ccs-request-id'] ?? randomUUID();
res.setHeader('x-ccs-request-id', requestId);
withRequestContext({ requestId }, async () => {
logger.stage('intake', 'request.received', 'inbound');
// ... downstream work emits with the same requestId
});
});
Cross-daemon header
x-ccs-request-id round-trips across the proxy edge:
- Inbound: if the header is present and matches the UUID-ish guard (
/^[A-Za-z0-9._-]{8,128}$/), it is reused; otherwise a fresh UUID is minted. - Outbound (response): the resolved id is echoed back via
res.setHeader('x-ccs-request-id', ...). - When CCS calls another daemon (copilot, cursor, glmt), forward the active id in the same header so that daemon can correlate.
Ordering guarantee
Emit-time ordering of entries within a single requestId is monotonic — the active context is single-threaded relative to the request, so timestamp ordering reflects emit order. The UI layer (#1142) consumes this guarantee.
What NOT to put in the context
The ALS context object is mixed into every downstream entry. Never store:
- Raw tokens, API keys, refresh tokens, OAuth codes
- Raw request/response bodies
- User-supplied secrets
Only benign correlation metadata: requestId, method, path, command, profile.
Worker threads / spawned children
ALS context is not inherited by worker threads or child_process.spawn stdio pipes. At those boundaries, mint a fresh requestId at the child entry and pass the parent id explicitly via env var or header for correlation.
Redaction
src/services/logging/log-redaction.ts is the single source of truth.
Sensitive key matcher
SENSITIVE_KEY_PATTERN matches (case-insensitive, with _ / - / camelCase variants):
authorization, proxy-authorization, cookie, set-cookie, password, password_hash, secret, client_secret, token, auth_token, access_token, refresh_token, id_token, bearer, assertion, api_key, x-api-key, x-goog-api-key, management_key, copilot_token, cursor_session_key, oauth_code, auth_code.
String/object values for matching keys are replaced with [redacted]. Numeric/boolean values pass through (e.g., expires_at epoch numbers stay readable).
Auth-scheme value masking
Raw string values whose prefix matches ^(Bearer|Basic|Token)\s+\S+ are rewritten to <scheme> [redacted] even when nested under non-sensitive keys.
Argv redaction
redactArgv(argv) redacts the value following any sensitive flag (--token, --api-key, --auth, --bearer, --secret, --client-secret, --access-token, --refresh-token, --id-token, --password).
Adding new sensitive keys
- Extend
SENSITIVE_KEY_PATTERNinsrc/services/logging/log-redaction.ts. - Add a unit test in
tests/unit/services/logging/log-redaction-extended.test.ts. - Verify regex stays O(1) per key (no catastrophic backtracking).
Contributor Guide
When to use logger.stage() vs logger.info()
Use stage() whenever the entry corresponds to one of the canonical lifecycle stages — this is what observability tooling and the dashboard rely on. Use info() / warn() / error() for one-off events that don't fit a stage.
What NOT to log
- Token values (use metadata:
expires_at,scopes, account display name). - Request/response bodies (sample lengths only).
- Authorization headers (log header names present, not values).
Level guidance
| Level | Use for |
|---|---|
error |
Failures requiring action (cleanup stage). |
warn |
Recoverable issues (auth rejected, route fallback). |
info |
Lifecycle stage entries by default. |
debug |
High-volume detail (per-chunk stream metrics, lock acquire/release). |
Level config
Default level is info. Configure via logging.level in ~/.ccs/config.yaml. Streaming providers MUST gate per-chunk metrics behind debug.
Backward Compatibility
- All new
LogEntryfields (requestId,stage,latencyMs,error) are optional. Old readers ignore them. - Existing
console.*UX prints insrc/commands/,src/utils/ui.ts, and similar user-facing paths are intentionally not converted to logger. /api/logsreader unchanged in this PR; UI surfacing of new fields tracked under #1142.
Future Work
- UI surfacing of
requestId/stage/latencyMsin the dashboard (#1142). ccs logsCLI improvements (filter byrequestId/stage).- Per-stage performance budgets (see #1071).