mirror of
https://github.com/tiennm99/ccs.git
synced 2026-07-16 04:18:05 +00:00
docs(logging): add structured contract reference and bump Node engines to 18+
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
This commit is contained in:
Tam Nhu Tran
@@ -417,7 +417,7 @@ Windows fallback: Copies if symlinks unavailable
|
||||
- Native JSON only, no external dependencies
|
||||
|
||||
### TypeScript (src/*.ts)
|
||||
- Node.js 14+, Bun 1.0+, TypeScript 5.3, strict mode
|
||||
- Node.js 18+, Bun 1.0+, TypeScript 5.3, strict mode
|
||||
- `child_process.spawn`, handle SIGINT/SIGTERM
|
||||
|
||||
### Terminal Output
|
||||
|
||||
@@ -0,0 +1,159 @@
|
||||
# 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 / fail` from `src/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
|
||||
|
||||
```jsonl
|
||||
{"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.
|
||||
|
||||
```ts
|
||||
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
|
||||
|
||||
1. Extend `SENSITIVE_KEY_PATTERN` in `src/services/logging/log-redaction.ts`.
|
||||
2. Add a unit test in `tests/unit/services/logging/log-redaction-extended.test.ts`.
|
||||
3. 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 `LogEntry` fields (`requestId`, `stage`, `latencyMs`, `error`) are optional. Old readers ignore them.
|
||||
- Existing `console.*` UX prints in `src/commands/`, `src/utils/ui.ts`, and similar user-facing paths are intentionally **not** converted to logger.
|
||||
- `/api/logs` reader unchanged in this PR; UI surfacing of new fields tracked under #1142.
|
||||
|
||||
## Future Work
|
||||
|
||||
- UI surfacing of `requestId` / `stage` / `latencyMs` in the dashboard (#1142).
|
||||
- `ccs logs` CLI improvements (filter by `requestId` / `stage`).
|
||||
- Per-stage performance budgets (see #1071).
|
||||
Reference in New Issue
Block a user