From 5e1b8640ab517109732affd32b430ca0b769996a Mon Sep 17 00:00:00 2001 From: Tam Nhu Tran Date: Thu, 18 Jun 2026 18:48:12 -0400 Subject: [PATCH] feat(logging): P2 traceability foundation - requestId wrap, daemon forwarding (#NNN) Epic P2. Closes the three real traceability gaps so every diagnostic log can carry a requestId from origin (ccs.ts main) through HTTP edges and spawned daemons. - log-context: add REQUEST_ID_HEADER/ENV/PATTERN, resolveRequestIdFromEnv, forwardRequestIdEnv. runWithRequestId now reuses a forwarded CCS_REQUEST_ID when well-formed (child re-anchor), else mints fresh. - request-logging-middleware: wrap the Express dashboard handler chain in withRequestContext so downstream route-handler logs carry requestId (mirrors src/proxy/server/proxy-server.ts, which is untouched prior art). - forward CCS_REQUEST_ID at the 4 child-daemon spawn sites: delegation headless-executor, cursor-daemon, cursor-profile-executor, copilot-executor. - cursor-daemon-entry: re-anchor via runWithRequestId so daemon startup logs correlate with the spawning CLI invocation (ALS does not cross spawn). - logger adoption toe-hold: delegation/session-manager (load/save failures) and docker/supervisord-lifecycle (restart failure) now use createLogger. api/channels/shared have no touchable diagnostic console.error (CLI-UX only or pure data); dispatcher's only diagnostic is in pre-dispatch.ts, owned by plan #1165. Those defer to P3's full per-site sweep. Tests: request-context-middleware (handler log requestId === header), request-id-forwarding (env resolve/reject, re-anchor, forwardRequestIdEnv). validate + validate:ci-parity green. --- src/copilot/copilot-executor.ts | 4 +- src/cursor/cursor-daemon-entry.ts | 20 +++-- src/cursor/cursor-daemon.ts | 3 +- src/cursor/cursor-profile-executor.ts | 3 +- src/delegation/headless-executor.ts | 2 + src/delegation/session-manager.ts | 19 ++++- src/docker/supervisord-lifecycle.ts | 6 +- src/services/logging/index.ts | 5 ++ src/services/logging/log-context.ts | 45 ++++++++++- .../middleware/request-logging-middleware.ts | 7 +- .../logging/request-id-forwarding.test.ts | 65 ++++++++++++++++ .../request-context-middleware.test.ts | 76 +++++++++++++++++++ 12 files changed, 234 insertions(+), 21 deletions(-) create mode 100644 tests/unit/services/logging/request-id-forwarding.test.ts create mode 100644 tests/unit/web-server/request-context-middleware.test.ts diff --git a/src/copilot/copilot-executor.ts b/src/copilot/copilot-executor.ts index 3da1ecf9..e2e5116d 100644 --- a/src/copilot/copilot-executor.ts +++ b/src/copilot/copilot-executor.ts @@ -35,7 +35,7 @@ import { resolveImageAnalysisRuntimeStatus, } from '../utils/hooks'; import { stripClaudeCodeEnv } from '../utils/shell-executor'; -import { createLogger } from '../services/logging'; +import { createLogger, forwardRequestIdEnv } from '../services/logging'; import { getGlobalEnvConfig } from '../config/config-loader-facade'; const logger = createLogger('copilot:executor'); @@ -324,7 +324,7 @@ export async function executeCopilotProfile( const proc = spawn(claudeCliPath, launchArgs, { stdio: 'inherit', - env: { ...env, ...traceEnv }, + env: { ...env, ...traceEnv, ...forwardRequestIdEnv() }, shell: process.platform === 'win32', }); diff --git a/src/cursor/cursor-daemon-entry.ts b/src/cursor/cursor-daemon-entry.ts index 8b0a42ef..5fa89aa6 100644 --- a/src/cursor/cursor-daemon-entry.ts +++ b/src/cursor/cursor-daemon-entry.ts @@ -7,6 +7,7 @@ import * as http from 'http'; import { Readable } from 'stream'; import { CursorExecutor } from './cursor-executor'; +import { runWithRequestId } from '../services/logging'; import { createAnthropicErrorResponse, createAnthropicProxyResponse, @@ -417,13 +418,18 @@ export function startCursorDaemonServer(options: DaemonRuntimeOptions): http.Ser } if (require.main === module) { - const options = parseArgs(process.argv.slice(2)); - const server = startCursorDaemonServer(options); + // Re-anchor to a requestId forwarded by the spawning CLI (CCS_REQUEST_ID env) + // so daemon startup logs correlate with the parent invocation. AsyncLocalStorage + // does not cross the spawn boundary, so the env bridge is mandatory here. + runWithRequestId(() => { + const options = parseArgs(process.argv.slice(2)); + const server = startCursorDaemonServer(options); - const shutdown = () => { - server.close(); - }; + const shutdown = () => { + server.close(); + }; - process.on('SIGTERM', shutdown); - process.on('SIGINT', shutdown); + process.on('SIGTERM', shutdown); + process.on('SIGINT', shutdown); + }); } diff --git a/src/cursor/cursor-daemon.ts b/src/cursor/cursor-daemon.ts index 9c5a5047..41b41f3c 100644 --- a/src/cursor/cursor-daemon.ts +++ b/src/cursor/cursor-daemon.ts @@ -13,7 +13,7 @@ import * as http from 'http'; import type { CursorDaemonConfig, CursorDaemonStatus } from './types'; import { getPidFromFile, writePidToFile, removePidFile } from './cursor-daemon-pid'; import { verifyDaemonOwnership } from './daemon-process-ownership'; -import { createLogger } from '../services/logging'; +import { createLogger, forwardRequestIdEnv } from '../services/logging'; export { getPidFromFile, writePidToFile, removePidFile } from './cursor-daemon-pid'; const logger = createLogger('cursor:daemon'); @@ -226,6 +226,7 @@ export async function startDaemon( detached: true, env: { ...process.env, + ...forwardRequestIdEnv(), CCS_CURSOR_DAEMON_TOKEN: effectiveConfig.daemon_token || '', }, }); diff --git a/src/cursor/cursor-profile-executor.ts b/src/cursor/cursor-profile-executor.ts index 03d4d139..ff71100a 100644 --- a/src/cursor/cursor-profile-executor.ts +++ b/src/cursor/cursor-profile-executor.ts @@ -3,6 +3,7 @@ import { spawn } from 'child_process'; import type { CursorConfig } from '../config/unified-config-types'; import { ensureCliproxyService } from '../cliproxy'; +import { forwardRequestIdEnv } from '../services/logging'; import { resolveLifecyclePort } from '../cliproxy/config/port-manager'; import { fail, info, ok } from '../utils/ui'; import { @@ -194,7 +195,7 @@ export async function executeCursorProfile( const proc = spawn(claudeCliPath, launchArgs, { stdio: 'inherit', - env: { ...env, ...traceEnv }, + env: { ...env, ...traceEnv, ...forwardRequestIdEnv() }, shell: process.platform === 'win32', }); diff --git a/src/delegation/headless-executor.ts b/src/delegation/headless-executor.ts index bc3a0f55..a9eac6a4 100644 --- a/src/delegation/headless-executor.ts +++ b/src/delegation/headless-executor.ts @@ -8,6 +8,7 @@ import { spawn } from 'child_process'; import * as path from 'path'; import { killWithEscalation } from '../utils/process-utils'; +import { forwardRequestIdEnv } from '../services/logging'; import * as fs from 'fs'; import { SessionManager } from './session-manager'; import { SettingsParser } from './settings-parser'; @@ -432,6 +433,7 @@ export class HeadlessExecutor { ...imageAnalysisEnv, ...traceEnv, ...(claudeConfigDir ? { CLAUDE_CONFIG_DIR: claudeConfigDir } : {}), + ...forwardRequestIdEnv(), CCS_PROFILE_TYPE: 'settings', }); diff --git a/src/delegation/session-manager.ts b/src/delegation/session-manager.ts index 79d94438..58783ada 100644 --- a/src/delegation/session-manager.ts +++ b/src/delegation/session-manager.ts @@ -7,6 +7,9 @@ import * as fs from 'fs'; import * as path from 'path'; import { getCcsDir } from '../config/config-loader-facade'; +import { createLogger } from '../services/logging'; + +const logger = createLogger('delegation:session-manager'); interface SessionData { sessionId: string; @@ -145,9 +148,12 @@ class SessionManager { const content = fs.readFileSync(this.sessionsPath, 'utf8'); return JSON.parse(content) as SessionsRegistry; } catch (error) { - if (process.env.CCS_DEBUG) { - console.warn(`[!] Failed to load sessions: ${(error as Error).message}`); - } + logger.warn('session.load.failed', 'Failed to load delegation sessions', { + err: + error instanceof Error + ? { name: error.name, message: error.message } + : { message: String(error) }, + }); return {}; } } @@ -163,7 +169,12 @@ class SessionManager { } fs.writeFileSync(this.sessionsPath, JSON.stringify(sessions, null, 2), { mode: 0o600 }); } catch (error) { - console.error(`[!] Failed to save sessions: ${(error as Error).message}`); + logger.error('session.save.failed', 'Failed to save delegation sessions', { + err: + error instanceof Error + ? { name: error.name, message: error.message } + : { message: String(error) }, + }); } } } diff --git a/src/docker/supervisord-lifecycle.ts b/src/docker/supervisord-lifecycle.ts index 21ca5d0f..db4061c4 100644 --- a/src/docker/supervisord-lifecycle.ts +++ b/src/docker/supervisord-lifecycle.ts @@ -10,9 +10,11 @@ import * as fs from 'fs'; import { execSync } from 'child_process'; import { CLIPROXY_DEFAULT_PORT } from '../cliproxy/config/port-manager'; +import { createLogger } from '../services/logging'; const SUPERVISOR_SOCK = '/var/run/supervisor.sock'; const SUPERVISOR_CONF = '/etc/supervisord.conf'; +const logger = createLogger('docker:supervisord-lifecycle'); /** True when running inside a supervisord-managed container. */ export function isRunningUnderSupervisord(): boolean { @@ -30,7 +32,9 @@ export function restartCliproxyViaSupervisord(): { return { success: true, port: CLIPROXY_DEFAULT_PORT }; } catch (err) { const detail = err instanceof Error ? err.message : String(err); - console.error(`[cliproxy] supervisorctl restart failed: ${detail}`); + logger.error('cliproxy.restart.failed', 'supervisorctl restart failed', { + detail, + }); return { success: false, error: 'supervisorctl restart failed' }; } } diff --git a/src/services/logging/index.ts b/src/services/logging/index.ts index 14efeaa6..dc83c6f8 100644 --- a/src/services/logging/index.ts +++ b/src/services/logging/index.ts @@ -18,6 +18,11 @@ export { getRequestContext, getRequestId, mergeRequestContext, + resolveRequestIdFromEnv, + forwardRequestIdEnv, + REQUEST_ID_HEADER, + REQUEST_ID_ENV, + REQUEST_ID_PATTERN, } from './log-context'; export type { RequestContext } from './log-context'; export { diff --git a/src/services/logging/log-context.ts b/src/services/logging/log-context.ts index 50503e95..e6a91548 100644 --- a/src/services/logging/log-context.ts +++ b/src/services/logging/log-context.ts @@ -1,6 +1,13 @@ import { AsyncLocalStorage } from 'async_hooks'; import { randomUUID } from 'crypto'; +/** Header name used to echo the requestId back on HTTP responses. */ +export const REQUEST_ID_HEADER = 'x-ccs-request-id'; +/** Env var used to forward the requestId across process boundaries (child daemons, spawned CLI). */ +export const REQUEST_ID_ENV = 'CCS_REQUEST_ID'; +// Loose UUID-ish guard: accepts UUIDs and opaque ids; rejects empty / control chars. +export const REQUEST_ID_PATTERN = /^[A-Za-z0-9._-]{8,128}$/; + /** * Per-request context carried via Node.js {@link AsyncLocalStorage}. * @@ -30,11 +37,29 @@ export function withRequestContext(ctx: RequestContext, fn: () => T): T { } /** - * 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. + * Resolve a requestId forwarded across a process boundary (spawned CLI child, + * daemon). Returns the env value when well-formed, otherwise `undefined` so the + * caller mints a fresh id. AsyncLocalStorage does NOT cross child_process.spawn, + * so forwarding via CCS_REQUEST_ID env and re-anchoring at the child entry is + * the only cross-process bridge. + */ +export function resolveRequestIdFromEnv(): string | undefined { + const raw = process.env[REQUEST_ID_ENV]; + if (typeof raw === 'string') { + const trimmed = raw.trim(); + if (REQUEST_ID_PATTERN.test(trimmed)) return trimmed; + } + return undefined; +} + +/** + * Entry-edge wrapper. Reuses a requestId forwarded via CCS_REQUEST_ID when + * present and well-formed (so a spawned child re-anchors to the parent's id); + * otherwise mints a fresh UUID. Use at CLI main, daemon inbound boundaries, and + * spawned CLI children. Returns the requestId so callers can echo it via headers. */ export function runWithRequestId(fn: () => T): { requestId: string; result: T } { - const requestId = randomUUID(); + const requestId = resolveRequestIdFromEnv() ?? randomUUID(); const result = withRequestContext({ requestId }, fn); return { requestId, result }; } @@ -49,6 +74,20 @@ export function getRequestId(): string | undefined { return storage.getStore()?.requestId; } +/** + * Build the env fragment that forwards the active requestId to a child process + * (spawned CLI child, daemon). Returns `{ [REQUEST_ID_ENV]: id }` when a context + * is active, otherwise `{}`. Spread into the `child_process.spawn` env object. + * + * AsyncLocalStorage does not cross process boundaries; this is the parent half + * of the bridge. The child re-anchors via {@link runWithRequestId}, which reads + * the same env var. + */ +export function forwardRequestIdEnv(): Record { + const requestId = getRequestId(); + return requestId ? { [REQUEST_ID_ENV]: requestId } : {}; +} + /** * Merge any active request context into the supplied context object, * preferring explicit keys on the input. Existing `requestId` on `extra` wins diff --git a/src/web-server/middleware/request-logging-middleware.ts b/src/web-server/middleware/request-logging-middleware.ts index 9faca1e5..1c846623 100644 --- a/src/web-server/middleware/request-logging-middleware.ts +++ b/src/web-server/middleware/request-logging-middleware.ts @@ -1,6 +1,6 @@ import { randomUUID } from 'crypto'; import type { Request, Response, NextFunction } from 'express'; -import { createLogger } from '../../services/logging'; +import { createLogger, withRequestContext } from '../../services/logging'; const logger = createLogger('web-server:http'); @@ -26,5 +26,8 @@ export function requestLoggingMiddleware(req: Request, res: Response, next: Next }); }); - next(); + // Wrap the downstream handler chain so structured logs emitted by route + // handlers carry the requestId (the logger auto-attaches it from the active + // request context). Mirrors src/proxy/server/proxy-server.ts. + withRequestContext({ requestId }, () => next()); } diff --git a/tests/unit/services/logging/request-id-forwarding.test.ts b/tests/unit/services/logging/request-id-forwarding.test.ts new file mode 100644 index 00000000..a5ca3eb8 --- /dev/null +++ b/tests/unit/services/logging/request-id-forwarding.test.ts @@ -0,0 +1,65 @@ +import { afterEach, describe, expect, test } from 'bun:test'; +import { + REQUEST_ID_ENV, + forwardRequestIdEnv, + getRequestId, + resolveRequestIdFromEnv, + runWithRequestId, +} from '../../../../src/services/logging'; + +describe('requestId cross-process forwarding', () => { + const originalEnv = process.env[REQUEST_ID_ENV]; + + afterEach(() => { + if (originalEnv === undefined) delete process.env[REQUEST_ID_ENV]; + else process.env[REQUEST_ID_ENV] = originalEnv; + }); + + test('resolveRequestIdFromEnv returns a well-formed forwarded id', () => { + process.env[REQUEST_ID_ENV] = '12345678-1234-1234-1234-1234567890ab'; + expect(resolveRequestIdFromEnv()).toBe('12345678-1234-1234-1234-1234567890ab'); + }); + + test('resolveRequestIdFromEnv trims surrounding whitespace', () => { + process.env[REQUEST_ID_ENV] = ' abcdef123456 '; + expect(resolveRequestIdFromEnv()).toBe('abcdef123456'); + }); + + test('resolveRequestIdFromEnv rejects garbage (too short, spaces, control chars)', () => { + process.env[REQUEST_ID_ENV] = 'short'; + expect(resolveRequestIdFromEnv()).toBeUndefined(); + process.env[REQUEST_ID_ENV] = 'has spaces here'; + expect(resolveRequestIdFromEnv()).toBeUndefined(); + }); + + test('resolveRequestIdFromEnv returns undefined when unset', () => { + delete process.env[REQUEST_ID_ENV]; + expect(resolveRequestIdFromEnv()).toBeUndefined(); + }); + + test('runWithRequestId reuses a forwarded env id (child re-anchor)', () => { + process.env[REQUEST_ID_ENV] = 'forwarded-id-1234'; + const { requestId } = runWithRequestId(() => getRequestId()); + expect(requestId).toBe('forwarded-id-1234'); + }); + + test('runWithRequestId mints a fresh id when no env id is present', () => { + delete process.env[REQUEST_ID_ENV]; + const { requestId } = runWithRequestId(() => undefined); + expect(requestId).toMatch(/^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/); + expect(requestId).not.toBe('forwarded-id-1234'); + }); + + test('forwardRequestIdEnv emits the active id for a child spawn env', () => { + delete process.env[REQUEST_ID_ENV]; + runWithRequestId(() => { + const envFragment = forwardRequestIdEnv(); + expect(envFragment[REQUEST_ID_ENV]).toBe(getRequestId()); + }); + }); + + test('forwardRequestIdEnv is empty when no context is active', () => { + delete process.env[REQUEST_ID_ENV]; + expect(forwardRequestIdEnv()).toEqual({}); + }); +}); diff --git a/tests/unit/web-server/request-context-middleware.test.ts b/tests/unit/web-server/request-context-middleware.test.ts new file mode 100644 index 00000000..1fb2a1e9 --- /dev/null +++ b/tests/unit/web-server/request-context-middleware.test.ts @@ -0,0 +1,76 @@ +import { afterEach, beforeEach, describe, expect, test } 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, + createLogger, + getRecentLogEntries, + invalidateLoggingConfigCache, +} from '../../../src/services/logging'; +import { requestLoggingMiddleware } from '../../../src/web-server/middleware/request-logging-middleware'; + +describe('request-logging-middleware requestId propagation', () => { + let tempHome = ''; + let originalCcsHome: string | undefined; + + beforeEach(() => { + originalCcsHome = process.env.CCS_HOME; + tempHome = fs.mkdtempSync(path.join(os.tmpdir(), 'ccs-req-ctx-mw-')); + 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(); + }); + + test('downstream handler log requestId === response x-ccs-request-id header', () => { + const handlerLogger = createLogger('test:downstream-handler'); + let headerRequestId = ''; + const res = { + locals: {} as Record, + setHeader: (_name: string, value: string) => { + headerRequestId = value; + }, + on: () => {}, + statusCode: 200, + socket: { remoteAddress: null }, + } as unknown as Parameters[1]; + const req = { + originalUrl: '/api/anything', + method: 'GET', + headers: {}, + socket: { remoteAddress: null }, + } as unknown as Parameters[0]; + + requestLoggingMiddleware(req, res, () => { + // Simulate a downstream route handler emitting a structured log inside the chain. + handlerLogger.info('test.handler.ran', 'downstream handler executed'); + }); + + const entries = getRecentLogEntries(); + const handlerEntry = entries.find((e) => e.event === 'test.handler.ran'); + expect(handlerEntry).toBeDefined(); + expect(headerRequestId).toMatch(/^[A-Za-z0-9._-]{8,128}$/); + expect(handlerEntry?.requestId).toBe(headerRequestId); + }); + + test('control: a bare handler log (no middleware) carries no requestId', () => { + const handlerLogger = createLogger('test:bare-handler'); + handlerLogger.info('test.bare.ran', 'no middleware wrap'); + const entry = getRecentLogEntries().find((e) => e.event === 'test.bare.ran'); + expect(entry?.requestId).toBeUndefined(); + }); +});