feat(logging): add structured contract, ALS context, stage helpers, and redaction coverage

Establish the structured-log foundation that downstream modules consume:
- LogStage union (intake|route|auth|dispatch|upstream|transform|respond|cleanup)
- AsyncLocalStorage-backed log-context for end-to-end requestId propagation
- Logger.stage() emit helper with optional latencyMs and structured metadata
- Extended log-redaction patterns for proxy-authorization, x-goog-api-key,
  oauth-code, refresh-token classes; Bearer/Basic/Token value-shape masking
- Public exports: getRecentLogEntries, withRequestContext, runWithRequestId,
  getRequestId

Refs #1141, #1138
This commit is contained in:
Tam Nhu Tran
2026-04-30 12:59:42 -04:00
parent de6bdde66b
commit 7a22e89046
8 changed files with 542 additions and 8 deletions
+25 -1
View File
@@ -1,4 +1,5 @@
export { createLogger } from './logger';
export type { Logger, StageOptions } from './logger';
export { getResolvedLoggingConfig, invalidateLoggingConfigCache } from './log-config';
export { readLogEntries, readLogSourceSummaries, normalizeLogQueryLevel } from './log-reader';
export { pruneExpiredLogArchives } from './log-storage';
@@ -10,4 +11,27 @@ export {
getNativeLogsDir,
isPathInsideDirectory,
} from './log-paths';
export type { LogEntry, LogSourceSummary, LoggingLevel, ReadLogEntriesOptions } from './log-types';
export { getRecentLogEntries, clearRecentLogEntries } from './log-buffer';
export {
withRequestContext,
runWithRequestId,
getRequestContext,
getRequestId,
mergeRequestContext,
} from './log-context';
export type { RequestContext } from './log-context';
export {
LOG_LEVELS,
LOG_STAGES,
shouldWriteLogLevel,
isLoggingLevel,
isLogStage,
} from './log-types';
export type {
LogEntry,
LogErrorInfo,
LogSourceSummary,
LogStage,
LoggingLevel,
ReadLogEntriesOptions,
} from './log-types';
+61
View File
@@ -0,0 +1,61 @@
import { AsyncLocalStorage } from 'async_hooks';
import { randomUUID } from 'crypto';
/**
* Per-request context carried via Node.js {@link AsyncLocalStorage}.
*
* MUST contain only non-sensitive correlation metadata. NEVER store tokens,
* secrets, raw bodies, or other sensitive material in this object — values
* leak into every downstream log entry emitted within the context.
*/
export interface RequestContext {
/** UUID-shaped correlation id; round-trips via `x-ccs-request-id` header. */
requestId: string;
/** Optional benign request metadata (method, path, command name, etc.). */
[key: string]: unknown;
}
const storage = new AsyncLocalStorage<RequestContext>();
/**
* Run `fn` inside a fresh request context. Use ONLY at request entry edges
* (HTTP handlers, CLI command dispatch, daemon inbound boundaries).
*
* Never call from shared/reused infrastructure — that would leak the requestId
* to unrelated callers. Listeners that need to inherit context MUST be
* registered inside the `als.run()` callback.
*/
export function withRequestContext<T>(ctx: RequestContext, fn: () => T): T {
return storage.run(ctx, fn);
}
/**
* Convenience wrapper that mints a fresh UUID requestId and runs `fn` under it.
* Returns the requestId so callers can echo it back via response headers.
*/
export function runWithRequestId<T>(fn: () => T): { requestId: string; result: T } {
const requestId = randomUUID();
const result = withRequestContext({ requestId }, fn);
return { requestId, result };
}
/** Read the active request context, or `undefined` if not inside one. */
export function getRequestContext(): RequestContext | undefined {
return storage.getStore();
}
/** Read just the active requestId, or `undefined` if not inside a context. */
export function getRequestId(): string | undefined {
return storage.getStore()?.requestId;
}
/**
* Merge any active request context into the supplied context object,
* preferring explicit keys on the input. Existing `requestId` on `extra` wins
* (callers may explicitly override; e.g., for cross-daemon correlation).
*/
export function mergeRequestContext<T extends Record<string, unknown>>(extra: T): T {
const ctx = storage.getStore();
if (!ctx) return extra;
return { ...ctx, ...extra } as T;
}
+43 -2
View File
@@ -1,5 +1,20 @@
/**
* Sensitive log key matcher (single source of truth).
*
* Add new patterns conservatively. Numeric/boolean values are passed through
* even when their key matches (e.g., `expires_at` epoch numbers stay readable);
* only string and object values are redacted.
*/
const SENSITIVE_KEY_PATTERN =
/^(authorization|cookie|set-cookie|password|password_hash|secret|token|api[_-]?key|management[_-]?key)$/i;
/^(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)$/i;
/** CLI flags whose following argument should be redacted in argv arrays. */
const SENSITIVE_ARGV_FLAG_PATTERN =
/^--(token|api[_-]?key|auth|auth[_-]?token|secret|bearer|password|client[_-]?secret|refresh[_-]?token|access[_-]?token|id[_-]?token)$/i;
/** Bearer/Basic/Token auth-scheme prefix in raw string values. */
const AUTH_SCHEME_VALUE_PATTERN = /^(Bearer|Basic|Token)\s+\S+/;
const MAX_STRING_LENGTH = 2000;
const MAX_DEPTH = 5;
@@ -10,6 +25,12 @@ function truncateString(value: string): string {
return `${value.slice(0, MAX_STRING_LENGTH)}...[truncated]`;
}
function maskAuthSchemeValue(value: string): string {
const match = AUTH_SCHEME_VALUE_PATTERN.exec(value);
if (!match) return value;
return `${match[1]} [redacted]`;
}
function sanitizeValue(value: unknown, depth: number): unknown {
if (value === null || value === undefined) {
return value;
@@ -20,7 +41,7 @@ function sanitizeValue(value: unknown, depth: number): unknown {
}
if (typeof value === 'string') {
return truncateString(value);
return truncateString(maskAuthSchemeValue(value));
}
if (typeof value === 'number' || typeof value === 'boolean') {
@@ -60,3 +81,23 @@ export function redactContext(
return sanitizeValue(context, 0) as Record<string, unknown>;
}
/**
* Redact sensitive values from a CLI argv array (e.g. for spawn-arg logging).
*
* Pairs every sensitive flag (`--token`, `--api-key`, etc.) with its following
* argument and replaces that argument with `[redacted]`. Non-sensitive args
* pass through unchanged.
*/
export function redactArgv(argv: readonly string[]): string[] {
const out: string[] = [];
for (let i = 0; i < argv.length; i++) {
const arg = argv[i];
out.push(arg);
if (SENSITIVE_ARGV_FLAG_PATTERN.test(arg) && i + 1 < argv.length) {
out.push('[redacted]');
i++;
}
}
return out;
}
+53
View File
@@ -2,6 +2,47 @@ import type { LoggingConfig, LoggingLevel } from '../../config/unified-config-ty
export type { LoggingConfig, LoggingLevel };
/**
* Canonical request lifecycle stages.
*
* Order represents typical flow but stages may be skipped or repeated.
* - 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 to caller (latencyMs typically populated here)
* - cleanup: error path, abort, teardown
*/
export type LogStage =
| 'intake'
| 'route'
| 'auth'
| 'dispatch'
| 'upstream'
| 'transform'
| 'respond'
| 'cleanup';
export const LOG_STAGES: readonly LogStage[] = [
'intake',
'route',
'auth',
'dispatch',
'upstream',
'transform',
'respond',
'cleanup',
] as const;
export interface LogErrorInfo {
name: string;
message: string;
code?: string;
stack?: string;
}
export interface LogEntry {
id: string;
timestamp: string;
@@ -12,6 +53,14 @@ export interface LogEntry {
processId: number;
runId: string;
context?: Record<string, unknown>;
/** Correlates entries belonging to a single inbound request across stages. */
requestId?: string;
/** Lifecycle stage tag — see {@link LogStage}. */
stage?: LogStage;
/** Elapsed time in milliseconds, typically attached to `respond`/`cleanup`. */
latencyMs?: number;
/** Structured error metadata; never stores raw token strings. */
error?: LogErrorInfo;
}
export interface LogSourceSummary {
@@ -45,3 +94,7 @@ export function shouldWriteLogLevel(level: LoggingLevel, configuredLevel: Loggin
export function isLoggingLevel(value: string | undefined): value is LoggingLevel {
return typeof value === 'string' && LOG_LEVELS.includes(value as LoggingLevel);
}
export function isLogStage(value: string | undefined): value is LogStage {
return typeof value === 'string' && LOG_STAGES.includes(value as LogStage);
}
+51 -5
View File
@@ -1,20 +1,29 @@
import { randomUUID } from 'crypto';
import { getResolvedLoggingConfig } from './log-config';
import { getRequestContext } from './log-context';
import { redactContext } from './log-redaction';
import { appendStructuredLogEntry } from './log-storage';
import type { LogEntry, LoggingLevel } from './log-types';
import type { LogEntry, LogStage, LoggingLevel } from './log-types';
const processRunId = `${Date.now()}-${process.pid}-${Math.random().toString(36).slice(2, 10)}`;
interface CreateEntryOptions {
stage?: LogStage;
latencyMs?: number;
error?: LogEntry['error'];
}
function createEntry(
source: string,
level: LoggingLevel,
event: string,
message: string,
context: Record<string, unknown>
context: Record<string, unknown>,
options: CreateEntryOptions = {}
): LogEntry {
const config = getResolvedLoggingConfig();
return {
const reqCtx = getRequestContext();
const entry: LogEntry = {
id: randomUUID(),
timestamp: new Date().toISOString(),
level,
@@ -25,6 +34,20 @@ function createEntry(
runId: processRunId,
context: config.redact ? redactContext(context) : context,
};
if (reqCtx?.requestId) entry.requestId = reqCtx.requestId;
if (options.stage) entry.stage = options.stage;
if (typeof options.latencyMs === 'number') entry.latencyMs = options.latencyMs;
if (options.error) entry.error = options.error;
return entry;
}
export interface StageOptions {
/** Optional level override; default `'info'`. */
level?: LoggingLevel;
/** Optional latency in ms (typically attached to `respond`/`cleanup`). */
latencyMs?: number;
/** Optional structured error info for `cleanup` stages. */
error?: LogEntry['error'];
}
export interface Logger {
@@ -33,6 +56,20 @@ export interface Logger {
info(event: string, message: string, context?: Record<string, unknown>): void;
warn(event: string, message: string, context?: Record<string, unknown>): void;
error(event: string, message: string, context?: Record<string, unknown>): void;
/**
* Emit a stage-tagged log entry.
*
* Locked signature: `stage(stage, event, message, context?, options?)`.
* `options.level` defaults to `'info'`. Use `options.latencyMs` on
* `respond`/`cleanup`. Use `options.error` for structured error info.
*/
stage(
stage: LogStage,
event: string,
message: string,
context?: Record<string, unknown>,
options?: StageOptions
): void;
}
export function createLogger(source: string, baseContext: Record<string, unknown> = {}): Logger {
@@ -40,10 +77,11 @@ export function createLogger(source: string, baseContext: Record<string, unknown
level: LoggingLevel,
event: string,
message: string,
context?: Record<string, unknown>
context?: Record<string, unknown>,
extra: CreateEntryOptions = {}
) => {
appendStructuredLogEntry(
createEntry(source, level, event, message, { ...baseContext, ...(context || {}) })
createEntry(source, level, event, message, { ...baseContext, ...(context || {}) }, extra)
);
};
@@ -63,5 +101,13 @@ export function createLogger(source: string, baseContext: Record<string, unknown
error(event, message, context) {
write('error', event, message, context);
},
stage(stage, event, message, context, options) {
const level = options?.level ?? 'info';
write(level, event, message, context, {
stage,
latencyMs: options?.latencyMs,
error: options?.error,
});
},
};
}
@@ -0,0 +1,76 @@
import { describe, expect, it } from 'bun:test';
import {
getRequestContext,
getRequestId,
mergeRequestContext,
runWithRequestId,
withRequestContext,
} from '../../../../src/services/logging/log-context';
describe('log-context (AsyncLocalStorage)', () => {
it('returns undefined outside any context', () => {
expect(getRequestContext()).toBeUndefined();
expect(getRequestId()).toBeUndefined();
});
it('exposes the active context inside withRequestContext', () => {
withRequestContext({ requestId: 'req-1', method: 'POST' }, () => {
const ctx = getRequestContext();
expect(ctx?.requestId).toBe('req-1');
expect(ctx?.method).toBe('POST');
expect(getRequestId()).toBe('req-1');
});
expect(getRequestContext()).toBeUndefined();
});
it('isolates parallel async tasks (no cross-leak)', async () => {
const observed: string[] = [];
await Promise.all([
withRequestContext({ requestId: 'req-A' }, async () => {
await new Promise((r) => setTimeout(r, 5));
observed.push(`A:${getRequestId()}`);
}),
withRequestContext({ requestId: 'req-B' }, async () => {
await new Promise((r) => setTimeout(r, 1));
observed.push(`B:${getRequestId()}`);
}),
]);
expect(observed.sort()).toEqual(['A:req-A', 'B:req-B']);
});
it('runWithRequestId mints a UUID and exposes it inside fn', () => {
let captured: string | undefined;
const { requestId, result } = runWithRequestId(() => {
captured = getRequestId();
return 42;
});
expect(result).toBe(42);
expect(captured).toBe(requestId);
expect(requestId).toMatch(/^[0-9a-f-]{36}$/i);
});
it('mergeRequestContext returns input unchanged outside ALS', () => {
const merged = mergeRequestContext({ foo: 'bar' });
expect(merged).toEqual({ foo: 'bar' });
});
it('mergeRequestContext merges active context, with input overriding ctx', () => {
withRequestContext({ requestId: 'req-X', method: 'GET' }, () => {
const merged = mergeRequestContext({ method: 'POST', extra: 1 });
expect(merged).toEqual({ requestId: 'req-X', method: 'POST', extra: 1 });
});
});
it('preserves emit-time ordering within a single requestId', async () => {
const order: number[] = [];
await withRequestContext({ requestId: 'req-order' }, async () => {
for (let i = 0; i < 5; i++) {
await Promise.resolve();
order.push(i);
}
});
expect(order).toEqual([0, 1, 2, 3, 4]);
});
});
@@ -0,0 +1,139 @@
import { describe, expect, it } from 'bun:test';
import {
redactArgv,
redactContext,
} from '../../../../src/services/logging/log-redaction';
describe('log redaction (extended sensitive keys)', () => {
const newSensitiveKeys = [
'refresh_token',
'id_token',
'access_token',
'client_secret',
'bearer',
'assertion',
'copilot_token',
'copilot-token',
'cursor_session_key',
'cursor-session-key',
'x-api-key',
'x_goog_api_key',
'proxy-authorization',
'oauth_code',
'auth_code',
'auth_token',
];
it.each(newSensitiveKeys)('redacts %s key (top-level)', (key) => {
const redacted = redactContext({ [key]: 'secret-value', safe: 'ok' });
expect(redacted[key]).toBe('[redacted]');
expect(redacted.safe).toBe('ok');
});
it('redacts new keys nested under headers', () => {
const redacted = redactContext({
headers: {
'x-api-key': 'sk-xxx',
'proxy-authorization': 'Bearer abc',
'copilot-token': 'gho_xxx',
},
});
expect(redacted).toEqual({
headers: {
'x-api-key': '[redacted]',
'proxy-authorization': '[redacted]',
'copilot-token': '[redacted]',
},
});
});
it('redacts Bearer/Basic/Token scheme prefix in raw string values', () => {
const redacted = redactContext({
raw: 'Bearer eyJhbGciOiJIUzI1NiJ9.payload.sig',
basic: 'Basic dXNlcjpwYXNz',
tokenLine: 'Token abc.def',
plain: 'no-scheme-here',
});
expect(redacted.raw).toBe('Bearer [redacted]');
expect(redacted.basic).toBe('Basic [redacted]');
expect(redacted.tokenLine).toBe('Token [redacted]');
expect(redacted.plain).toBe('no-scheme-here');
});
it('passes numeric/boolean values through even if key matches', () => {
// expires_at is not a sensitive key; ensure non-string sensitive values
// would also pass through if pattern matched (defense check).
const redacted = redactContext({
access_token: 'real-secret',
expires_at: 1234567890,
enabled: true,
});
expect(redacted.access_token).toBe('[redacted]');
expect(redacted.expires_at).toBe(1234567890);
expect(redacted.enabled).toBe(true);
});
it('recurses through arrays of objects', () => {
const redacted = redactContext({
tokens: [
{ access_token: 'a' },
{ refresh_token: 'b' },
{ id_token: 'c', meta: 'kept' },
],
});
expect(redacted).toEqual({
tokens: [
{ access_token: '[redacted]' },
{ refresh_token: '[redacted]' },
{ id_token: '[redacted]', meta: 'kept' },
],
});
});
it('fuzz-style: many random token-shaped keys all redact', () => {
const variants = ['token', 'auth_token', 'refresh-token', 'id-token', 'X-API-KEY'];
for (const v of variants) {
const out = redactContext({ [v]: 'secret' });
expect(out[v]).toBe('[redacted]');
}
});
});
describe('redactArgv', () => {
it('redacts the value following sensitive flags', () => {
expect(redactArgv(['--api-key', 'secret', '--other', 'ok'])).toEqual([
'--api-key',
'[redacted]',
'--other',
'ok',
]);
});
it('redacts multiple sensitive flags', () => {
expect(
redactArgv(['--token', 'a', '--secret', 'b', '--bearer', 'c', '--keep', 'd'])
).toEqual(['--token', '[redacted]', '--secret', '[redacted]', '--bearer', '[redacted]', '--keep', 'd']);
});
it('passes argv unchanged when no sensitive flags present', () => {
expect(redactArgv(['build', '--watch', '--out', 'dist'])).toEqual([
'build',
'--watch',
'--out',
'dist',
]);
});
it('handles trailing sensitive flag with no value', () => {
expect(redactArgv(['--api-key'])).toEqual(['--api-key']);
});
it('redacts kebab and snake case flag variants', () => {
expect(redactArgv(['--api_key', 'x', '--auth-token', 'y'])).toEqual([
'--api_key',
'[redacted]',
'--auth-token',
'[redacted]',
]);
});
});
@@ -0,0 +1,94 @@
import { afterEach, beforeEach, describe, expect, it } from 'bun:test';
import * as fs from 'fs';
import * as os from 'os';
import * as path from 'path';
import { createEmptyUnifiedConfig } from '../../../../src/config/unified-config-types';
import { saveUnifiedConfig } from '../../../../src/config/unified-config-loader';
import {
clearRecentLogEntries,
getRecentLogEntries,
} from '../../../../src/services/logging/log-buffer';
import { invalidateLoggingConfigCache } from '../../../../src/services/logging/log-config';
import { withRequestContext } from '../../../../src/services/logging/log-context';
import { createLogger } from '../../../../src/services/logging/logger';
describe('Logger.stage()', () => {
let tempHome = '';
let originalCcsHome: string | undefined;
beforeEach(() => {
originalCcsHome = process.env.CCS_HOME;
tempHome = fs.mkdtempSync(path.join(os.tmpdir(), 'ccs-logger-stages-'));
process.env.CCS_HOME = tempHome;
clearRecentLogEntries();
invalidateLoggingConfigCache();
const config = createEmptyUnifiedConfig();
config.logging = {
...config.logging,
enabled: true,
level: 'debug',
redact: false,
};
saveUnifiedConfig(config);
invalidateLoggingConfigCache();
});
afterEach(() => {
if (originalCcsHome === undefined) delete process.env.CCS_HOME;
else process.env.CCS_HOME = originalCcsHome;
fs.rmSync(tempHome, { recursive: true, force: true });
clearRecentLogEntries();
invalidateLoggingConfigCache();
});
it('emits a stage-tagged entry with default info level', () => {
const logger = createLogger('unit:stages');
logger.stage('upstream', 'fetch.start', 'starting upstream fetch');
const entries = getRecentLogEntries();
expect(entries.length).toBe(1);
expect(entries[0].stage).toBe('upstream');
expect(entries[0].level).toBe('info');
expect(entries[0].event).toBe('fetch.start');
});
it('respects a level override and includes latencyMs + error', () => {
const logger = createLogger('unit:stages');
logger.stage('cleanup', 'request.failed', 'upstream failed', undefined, {
level: 'error',
latencyMs: 123,
error: { name: 'Error', message: 'boom' },
});
const [entry] = getRecentLogEntries();
expect(entry.level).toBe('error');
expect(entry.latencyMs).toBe(123);
expect(entry.error?.message).toBe('boom');
});
it('auto-merges requestId from active ALS context', () => {
const logger = createLogger('unit:stages');
withRequestContext({ requestId: 'req-9' }, () => {
logger.stage('intake', 'http.request', 'in');
});
const [entry] = getRecentLogEntries();
expect(entry.requestId).toBe('req-9');
expect(entry.stage).toBe('intake');
});
it('emits no requestId when called outside ALS', () => {
const logger = createLogger('unit:stages');
logger.info('plain.event', 'msg');
const [entry] = getRecentLogEntries();
expect(entry.requestId).toBeUndefined();
expect(entry.stage).toBeUndefined();
});
it('preserves existing logger.info/warn/error/debug methods', () => {
const logger = createLogger('unit:stages');
logger.info('e1', 'm1');
logger.warn('e2', 'm2');
logger.error('e3', 'm3');
logger.debug('e4', 'm4');
const entries = getRecentLogEntries();
expect(entries.map((e) => e.level)).toEqual(['info', 'warn', 'error', 'debug']);
});
});