diff --git a/src/services/logging/index.ts b/src/services/logging/index.ts index 68e4b6ad..14efeaa6 100644 --- a/src/services/logging/index.ts +++ b/src/services/logging/index.ts @@ -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'; diff --git a/src/services/logging/log-context.ts b/src/services/logging/log-context.ts new file mode 100644 index 00000000..50503e95 --- /dev/null +++ b/src/services/logging/log-context.ts @@ -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(); + +/** + * 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(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(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>(extra: T): T { + const ctx = storage.getStore(); + if (!ctx) return extra; + return { ...ctx, ...extra } as T; +} diff --git a/src/services/logging/log-redaction.ts b/src/services/logging/log-redaction.ts index ca8446f3..d3045047 100644 --- a/src/services/logging/log-redaction.ts +++ b/src/services/logging/log-redaction.ts @@ -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; } + +/** + * 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; +} diff --git a/src/services/logging/log-types.ts b/src/services/logging/log-types.ts index a3e08c16..10f29d9d 100644 --- a/src/services/logging/log-types.ts +++ b/src/services/logging/log-types.ts @@ -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; + /** 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); +} diff --git a/src/services/logging/logger.ts b/src/services/logging/logger.ts index 3506871c..b2b5459e 100644 --- a/src/services/logging/logger.ts +++ b/src/services/logging/logger.ts @@ -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 + context: Record, + 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): void; warn(event: string, message: string, context?: Record): void; error(event: string, message: string, context?: Record): 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, + options?: StageOptions + ): void; } export function createLogger(source: string, baseContext: Record = {}): Logger { @@ -40,10 +77,11 @@ export function createLogger(source: string, baseContext: Record + context?: Record, + 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 { + 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]); + }); +}); diff --git a/tests/unit/services/logging/log-redaction-extended.test.ts b/tests/unit/services/logging/log-redaction-extended.test.ts new file mode 100644 index 00000000..44b87849 --- /dev/null +++ b/tests/unit/services/logging/log-redaction-extended.test.ts @@ -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]', + ]); + }); +}); diff --git a/tests/unit/services/logging/logger-stages.test.ts b/tests/unit/services/logging/logger-stages.test.ts new file mode 100644 index 00000000..b4ae9cbc --- /dev/null +++ b/tests/unit/services/logging/logger-stages.test.ts @@ -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']); + }); +});