fix(logging): harden structured trace redaction

Redact StageOptions error payloads and summarize debug launch args.

Propagate request IDs through Cursor daemon and dashboard completion logs.

Mark remaining P2/P3 maintainability targets as partial instead of overclaiming.
This commit is contained in:
Tam Nhu Tran committed 2026-06-18 18:48:13 -04:00
1 parent 2d48488475
commit 1462823be8
11 files changed
+250 -21

No files matched your search

+5 -5
View File
@@ -93,8 +93,9 @@ Metrics are grep-based and approximate (not a contract). Comments and string/tem
|---|---:|---:|---:|---| |---|---:|---:|---:|---|
| typed-error adoption (locked subdomains) | 0.0% (0/23) | 91.3% (21/23) | >40% | met | | typed-error adoption (locked subdomains) | 0.0% (0/23) | 91.3% (21/23) | >40% | met |
| typed-error adoption (overall) | 0.9% (5/431) | 8.6% (37/431) | rise | met | | typed-error adoption (overall) | 0.9% (5/431) | 8.6% (37/431) | rise | met |
| hotpath `console.error`/`warn` | 928 | 267 | <10 (diagnostics) | diagnostics fully structured; residual is user-facing CLI output (see P3 note) | | hotpath `console.error`/`warn` | 928 | 267 | <10 | partial; high-risk diagnostics migrated + redaction gate closed, but metric target unmet (see P3 note) |
| files with `createLogger` | 35 | 64 | rise | met | | files with `createLogger` | 35 | 64 | rise | met |
| subdomains with zero `createLogger` | 20 | 15 | 0 in named set | partial; logger toe-holds improved coverage but P2 zero-subdomain target unmet |
| files > 400 LOC | 95 | 89 | <60 | partial (P6 deferred 4 targets) | | files > 400 LOC | 95 | 89 | <60 | partial (P6 deferred 4 targets) |
| hardening report freshness | stale | <30d gate | gate | met (P1) | | hardening report freshness | stale | <30d gate | gate | met (P1) |
| ESLint `no-new-throw-error` | not enforced | error + allowlist | enforced | met (P7) | | ESLint `no-new-throw-error` | not enforced | error + allowlist | enforced | met (P7) |
@@ -102,11 +103,10 @@ Metrics are grep-based and approximate (not a contract). Comments and string/tem
### Deferred follow-ups ### Deferred follow-ups
- P2 remaining zero-logger subdomains (`api`, `channels`, `config`, `dispatcher`, `shared`, and others): add lightweight logger toe-holds when those subdomains next receive behavior work. This epic improved coverage but did not satisfy the original `0` target.
- P3 remaining 267 non-exempt `console.error`/`warn` call sites: split into true user-facing terminal output vs diagnostics, then either migrate diagnostics to structured logs or update the metric method to exempt confirmed CLI display helpers.
- P6 remaining 4 targets (`oauth-handler.ts`, `cursor-executor.ts`, `tool-sanitization-proxy.ts`, +1): need dedicated characterization-test work before splitting (the plan's characterization-first hard gate). Each has a clean seam identified in the epic plan. - P6 remaining 4 targets (`oauth-handler.ts`, `cursor-executor.ts`, `tool-sanitization-proxy.ts`, +1): need dedicated characterization-test work before splitting (the plan's characterization-first hard gate). Each has a clean seam identified in the epic plan.
- P3 residual ~267 user-facing `console.error` -> `process.stderr.write`: mechanical, no traceability value; continues incrementally.
### P3 residual note (2026-06-18) ### P3 residual note (2026-06-18)
The remaining ~267 `console.error`/`warn` are user-facing CLI output (interactive flows, arg-parser usage errors, installers, prompts, adapter launch failures, error-display helpers) routed via `fail()`/`info()`/`warn()` from `utils/ui`. They are legitimate stderr output, not diagnostics. The plan's `<10` target assumed these were diagnostics; in practice the diagnostic subset is fully converted to structured logs. Migrating the residual `console.error` -> `process.stderr.write` is mechanical (near-zero behavior change, no traceability value) and continues incrementally; it does not block P4-P7. The redaction gate makes any further conversion safe. The remaining 267 non-exempt `console.error`/`warn` occurrences are not fully resolved by this epic. Many are user-facing terminal display paths (interactive flows, arg-parser usage errors, installers, prompts, adapter launch failures, error-display helpers), but the generated metric still counts them because its exemption list is intentionally conservative. Treat P3 as partial until the residual list is classified file-by-file and either migrated to structured logs or explicitly moved into the CLI-UX exemption method. The redaction gate now covers structured message, context, `Error.message`, and `StageOptions.error` metadata so further diagnostic migration is safe.
+8 -8
View File
@@ -158,17 +158,17 @@
"src/cursor/cursor-client-policy.ts:33", "src/cursor/cursor-client-policy.ts:33",
"src/cursor/cursor-client-policy.ts:81", "src/cursor/cursor-client-policy.ts:81",
"src/cursor/cursor-client-policy.ts:85", "src/cursor/cursor-client-policy.ts:85",
"src/cursor/cursor-daemon-entry.ts:148", "src/cursor/cursor-daemon-entry.ts:183",
"src/cursor/cursor-daemon-entry.ts:153", "src/cursor/cursor-daemon-entry.ts:188",
"src/cursor/cursor-daemon-entry.ts:158", "src/cursor/cursor-daemon-entry.ts:193",
"src/cursor/cursor-daemon-entry.ts:168", "src/cursor/cursor-daemon-entry.ts:203",
"src/cursor/cursor-executor.ts:206", "src/cursor/cursor-executor.ts:206",
"src/cursor/cursor-protobuf.ts:50", "src/cursor/cursor-protobuf.ts:50",
"src/cursor/cursor-translator.ts:189", "src/cursor/cursor-translator.ts:189",
"src/delegation/headless-executor.ts:107", "src/delegation/headless-executor.ts:126",
"src/delegation/headless-executor.ts:122", "src/delegation/headless-executor.ts:141",
"src/delegation/headless-executor.ts:251", "src/delegation/headless-executor.ts:270",
"src/delegation/headless-executor.ts:654", "src/delegation/headless-executor.ts:679",
"src/dispatcher/cli-argument-parser.ts:310", "src/dispatcher/cli-argument-parser.ts:310",
"src/dispatcher/cli-argument-parser.ts:314", "src/dispatcher/cli-argument-parser.ts:314",
"src/dispatcher/cli-argument-parser.ts:324", "src/dispatcher/cli-argument-parser.ts:324",
+40 -3
View File
@@ -5,9 +5,15 @@
*/ */
import * as http from 'http'; import * as http from 'http';
import { randomUUID } from 'crypto';
import { Readable } from 'stream'; import { Readable } from 'stream';
import { CursorExecutor } from './cursor-executor'; import { CursorExecutor } from './cursor-executor';
import { runWithRequestId } from '../services/logging'; import {
REQUEST_ID_HEADER,
REQUEST_ID_PATTERN,
runWithRequestId,
withRequestContext,
} from '../services/logging';
import { import {
createAnthropicErrorResponse, createAnthropicErrorResponse,
createAnthropicProxyResponse, createAnthropicProxyResponse,
@@ -143,6 +149,35 @@ function hasValidDaemonToken(req: http.IncomingMessage): boolean {
return false; return false;
} }
function resolveInboundRequestId(req: http.IncomingMessage): string | undefined {
const raw = req.headers[REQUEST_ID_HEADER];
const value = Array.isArray(raw) ? raw[0] : raw;
if (typeof value !== 'string') {
return undefined;
}
const requestId = value.trim();
return REQUEST_ID_PATTERN.test(requestId) ? requestId : undefined;
}
function withCursorDaemonRequestContext<T>(
req: http.IncomingMessage,
res: http.ServerResponse,
fn: () => T
): T {
const requestId = resolveInboundRequestId(req) ?? randomUUID();
res.setHeader(REQUEST_ID_HEADER, requestId);
return withRequestContext(
{
requestId,
method: req.method || 'GET',
path: req.url || '/',
},
fn
);
}
function normalizeMessages(raw: unknown): NormalizedOpenAIMessage[] { function normalizeMessages(raw: unknown): NormalizedOpenAIMessage[] {
if (!Array.isArray(raw)) { if (!Array.isArray(raw)) {
throw new Error('messages must be an array'); throw new Error('messages must be an array');
@@ -229,7 +264,8 @@ function parseArgs(argv: string[]): DaemonRuntimeOptions {
export function startCursorDaemonServer(options: DaemonRuntimeOptions): http.Server { export function startCursorDaemonServer(options: DaemonRuntimeOptions): http.Server {
const executor = new CursorExecutor(); const executor = new CursorExecutor();
const server = http.createServer(async (req, res) => { const server = http.createServer((req, res) =>
withCursorDaemonRequestContext(req, res, async () => {
const method = req.method || 'GET'; const method = req.method || 'GET';
const requestUrl = req.url || '/'; const requestUrl = req.url || '/';
const isOpenAiRoute = method === 'POST' && requestUrl === '/v1/chat/completions'; const isOpenAiRoute = method === 'POST' && requestUrl === '/v1/chat/completions';
@@ -411,7 +447,8 @@ export function startCursorDaemonServer(options: DaemonRuntimeOptions): http.Ser
}); });
} }
} }
}); })
);
server.listen(options.port, '127.0.0.1'); server.listen(options.port, '127.0.0.1');
return server; return server;
+26 -1
View File
@@ -66,6 +66,25 @@ export type { ExecutionOptions, ExecutionResult, StreamMessage } from './executo
const logger = createLogger('delegation:headless-executor'); const logger = createLogger('delegation:headless-executor');
export function summarizeClaudeLaunchArgsForLog(
args: readonly string[],
filteredExtraArgCount: number
): Record<string, unknown> {
return {
argCount: args.length,
hasPrompt: args.includes('-p'),
hasSettings: args.includes('--settings'),
outputFormat: args.includes('--output-format') ? 'configured' : 'default',
verbose: args.includes('--verbose'),
hasResume: args.includes('--resume'),
hasPermissionMode: args.includes('--permission-mode'),
bypassPermissions: args.includes('--dangerously-skip-permissions'),
hasAllowedTools: args.includes('--allowedTools'),
hasDisallowedTools: args.includes('--disallowedTools'),
filteredExtraArgCount,
};
}
/** /**
* Headless executor for Claude CLI delegation * Headless executor for Claude CLI delegation
*/ */
@@ -338,6 +357,7 @@ export class HeadlessExecutor {
// Passthrough extra args (catch-all for new/unknown flags) // Passthrough extra args (catch-all for new/unknown flags)
// Filter out duplicates of explicitly handled flags // Filter out duplicates of explicitly handled flags
let filteredExtraArgCount = 0;
if (extraArgs.length > 0) { if (extraArgs.length > 0) {
const explicitFlags = new Set(['--max-turns', '--fallback-model', '--agents', '--betas']); const explicitFlags = new Set(['--max-turns', '--fallback-model', '--agents', '--betas']);
const filteredExtras: string[] = []; const filteredExtras: string[] = [];
@@ -353,6 +373,7 @@ export class HeadlessExecutor {
} }
if (filteredExtras.length > 0) { if (filteredExtras.length > 0) {
args.push(...filteredExtras); args.push(...filteredExtras);
filteredExtraArgCount = filteredExtras.length;
} }
} }
@@ -371,7 +392,11 @@ export class HeadlessExecutor {
}); });
if (process.env.CCS_DEBUG) { if (process.env.CCS_DEBUG) {
logger.info('claude_cli_args', 'Claude CLI args', { args: launchArgs }); logger.info(
'claude_cli_args',
'Claude CLI args prepared',
summarizeClaudeLaunchArgsForLog(launchArgs, filteredExtraArgCount)
);
} }
// Initialize UI before spawning // Initialize UI before spawning
+10
View File
@@ -1,3 +1,5 @@
import type { LogErrorInfo } from './log-types';
/** /**
* Sensitive log key matcher (single source of truth). * Sensitive log key matcher (single source of truth).
* *
@@ -105,6 +107,14 @@ export function redactContext(
return sanitizeValue(context, 0) as Record<string, unknown>; return sanitizeValue(context, 0) as Record<string, unknown>;
} }
export function redactErrorInfo(error: LogErrorInfo | undefined): LogErrorInfo | undefined {
if (!error) {
return undefined;
}
return sanitizeValue(error, 0) as LogErrorInfo;
}
/** /**
* Redact sensitive values from a CLI argv array (e.g. for spawn-arg logging). * Redact sensitive values from a CLI argv array (e.g. for spawn-arg logging).
* *
+2 -2
View File
@@ -1,7 +1,7 @@
import { randomUUID } from 'crypto'; import { randomUUID } from 'crypto';
import { getResolvedLoggingConfig } from './log-config'; import { getResolvedLoggingConfig } from './log-config';
import { getRequestContext } from './log-context'; import { getRequestContext } from './log-context';
import { maskSecretTokens, redactContext } from './log-redaction'; import { maskSecretTokens, redactContext, redactErrorInfo } from './log-redaction';
import { appendStructuredLogEntry } from './log-storage'; import { appendStructuredLogEntry } from './log-storage';
import type { LogEntry, LogStage, LoggingLevel } from './log-types'; import type { LogEntry, LogStage, LoggingLevel } from './log-types';
@@ -37,7 +37,7 @@ function createEntry(
if (reqCtx?.requestId) entry.requestId = reqCtx.requestId; if (reqCtx?.requestId) entry.requestId = reqCtx.requestId;
if (options.stage) entry.stage = options.stage; if (options.stage) entry.stage = options.stage;
if (typeof options.latencyMs === 'number') entry.latencyMs = options.latencyMs; if (typeof options.latencyMs === 'number') entry.latencyMs = options.latencyMs;
if (options.error) entry.error = options.error; if (options.error) entry.error = redactErrorInfo(options.error);
return entry; return entry;
} }
@@ -15,6 +15,7 @@ export function requestLoggingMiddleware(req: Request, res: Response, next: Next
if (shouldSkipLogging) { if (shouldSkipLogging) {
return; return;
} }
withRequestContext({ requestId }, () => {
logger.info('request.completed', 'Dashboard request completed', { logger.info('request.completed', 'Dashboard request completed', {
requestId, requestId,
method: req.method, method: req.method,
@@ -25,6 +26,7 @@ export function requestLoggingMiddleware(req: Request, res: Response, next: Next
userAgent: req.headers['user-agent'] || null, userAgent: req.headers['user-agent'] || null,
}); });
}); });
});
// Wrap the downstream handler chain so structured logs emitted by route // Wrap the downstream handler chain so structured logs emitted by route
// handlers carry the requestId (the logger auto-attaches it from the active // handlers carry the requestId (the logger auto-attaches it from the active
@@ -0,0 +1,73 @@
import { afterEach, beforeEach, describe, expect, test } from 'bun:test';
import * as http from 'http';
import { startCursorDaemonServer } from '../../../src/cursor/cursor-daemon-entry';
import { REQUEST_ID_HEADER } from '../../../src/services/logging';
function listenAddress(server: http.Server): { port: number } {
const address = server.address();
if (!address || typeof address === 'string') {
throw new Error('Unable to resolve test server address');
}
return { port: address.port };
}
async function requestHealth(port: number, requestId?: string): Promise<http.IncomingMessage> {
return new Promise((resolve, reject) => {
const req = http.request(
{
host: '127.0.0.1',
port,
path: '/health',
method: 'GET',
headers: {
'x-ccs-cursor-token': 'test-token',
...(requestId ? { [REQUEST_ID_HEADER]: requestId } : {}),
},
},
(res) => {
res.resume();
res.on('end', () => resolve(res));
}
);
req.on('error', reject);
req.end();
});
}
describe('cursor daemon request context', () => {
let originalToken: string | undefined;
let server: http.Server | undefined;
beforeEach(() => {
originalToken = process.env.CCS_CURSOR_DAEMON_TOKEN;
process.env.CCS_CURSOR_DAEMON_TOKEN = 'test-token';
});
afterEach(async () => {
if (server) {
await new Promise<void>((resolve) => server?.close(() => resolve()));
server = undefined;
}
if (originalToken === undefined) delete process.env.CCS_CURSOR_DAEMON_TOKEN;
else process.env.CCS_CURSOR_DAEMON_TOKEN = originalToken;
});
test('echoes a valid inbound requestId header', async () => {
server = startCursorDaemonServer({ port: 0, ghostMode: true });
const { port } = listenAddress(server);
const res = await requestHealth(port, 'req-cursor-123');
expect(res.statusCode).toBe(200);
expect(res.headers[REQUEST_ID_HEADER]).toBe('req-cursor-123');
});
test('mints a requestId when no valid inbound header exists', async () => {
server = startCursorDaemonServer({ port: 0, ghostMode: true });
const { port } = listenAddress(server);
const res = await requestHealth(port, 'bad id with spaces');
expect(res.statusCode).toBe(200);
expect(res.headers[REQUEST_ID_HEADER]).toMatch(/^[A-Za-z0-9._-]{8,128}$/);
expect(res.headers[REQUEST_ID_HEADER]).not.toBe('bad id with spaces');
});
});
@@ -4,6 +4,7 @@
*/ */
import { describe, it, expect } from 'bun:test'; import { describe, it, expect } from 'bun:test';
import { summarizeClaudeLaunchArgsForLog } from '../../../src/delegation/headless-executor';
describe('HeadlessExecutor flag construction', () => { describe('HeadlessExecutor flag construction', () => {
// Test the flag construction logic by simulating the filtering behavior // Test the flag construction logic by simulating the filtering behavior
@@ -88,6 +89,37 @@ describe('HeadlessExecutor flag construction', () => {
}); });
}); });
describe('Debug launch-arg logging', () => {
it('summarizes launch args without persisting prompt text or passthrough secret values', () => {
const prompt = 'please analyze api_key=plainsecretvalue in this prompt';
const args = [
'-p',
prompt,
'--settings',
'/tmp/settings.json',
'--output-format',
'stream-json',
'--verbose',
'--api-key',
'plainsecretvalue',
];
const summary = summarizeClaudeLaunchArgsForLog(args, 2);
const serialized = JSON.stringify(summary);
expect(serialized).not.toContain(prompt);
expect(serialized).not.toContain('plainsecretvalue');
expect(summary).toMatchObject({
argCount: args.length,
hasPrompt: true,
hasSettings: true,
outputFormat: 'configured',
verbose: true,
filteredExtraArgCount: 2,
});
});
});
describe('Flag undefined vs truthy checks', () => { describe('Flag undefined vs truthy checks', () => {
// Simulate the flag construction logic // Simulate the flag construction logic
function buildArgs(options: { function buildArgs(options: {
@@ -90,7 +90,9 @@ describe('hotpath redaction regression (token-laden payloads)', () => {
test(`scrubs ${name} token in a context value (under a non-sensitive key)`, () => { test(`scrubs ${name} token in a context value (under a non-sensitive key)`, () => {
const token = buildToken(); const token = buildToken();
const logger = createLogger('test:redaction'); const logger = createLogger('test:redaction');
logger.error('test.token.in.value', `token shape ${name}`, { detail: `request failed: ${token}` }); logger.error('test.token.in.value', `token shape ${name}`, {
detail: `request failed: ${token}`,
});
const entry = getRecentLogEntries().find((e) => e.event === 'test.token.in.value'); const entry = getRecentLogEntries().find((e) => e.event === 'test.token.in.value');
expect(entry).toBeDefined(); expect(entry).toBeDefined();
expect(JSON.stringify(entry)).not.toContain(token); expect(JSON.stringify(entry)).not.toContain(token);
@@ -107,6 +109,22 @@ describe('hotpath redaction regression (token-laden payloads)', () => {
expect(JSON.stringify(entry)).not.toContain(token); expect(JSON.stringify(entry)).not.toContain(token);
}); });
test('scrubs token embedded in stage options.error metadata', () => {
const token = anthropicToken();
const logger = createLogger('test:redaction');
logger.stage('cleanup', 'test.stage.error', 'structured error carrying token', undefined, {
level: 'error',
error: {
name: 'Error',
message: `Auth failed: ${token}`,
stack: `Error: Auth failed: ${token}\n at test`,
},
});
const entry = getRecentLogEntries().find((e) => e.event === 'test.stage.error');
expect(entry).toBeDefined();
expect(JSON.stringify(entry)).not.toContain(token);
});
test('scrubs token shapes that leak into the message string (defense-in-depth)', () => { test('scrubs token shapes that leak into the message string (defense-in-depth)', () => {
const token = anthropicToken(); const token = anthropicToken();
const logger = createLogger('test:redaction'); const logger = createLogger('test:redaction');
@@ -118,7 +136,9 @@ describe('hotpath redaction regression (token-laden payloads)', () => {
test('preserves non-sensitive prose messages unchanged', () => { test('preserves non-sensitive prose messages unchanged', () => {
const logger = createLogger('test:redaction'); const logger = createLogger('test:redaction');
logger.error('test.prose', 'Delegation failed: target adapter not found', { provider: 'codex' }); logger.error('test.prose', 'Delegation failed: target adapter not found', {
provider: 'codex',
});
const entry = getRecentLogEntries().find((e) => e.event === 'test.prose'); const entry = getRecentLogEntries().find((e) => e.event === 'test.prose');
expect(entry?.message).toBe('Delegation failed: target adapter not found'); expect(entry?.message).toBe('Delegation failed: target adapter not found');
expect((entry?.context as Record<string, unknown>)?.provider).toBe('codex'); expect((entry?.context as Record<string, unknown>)?.provider).toBe('codex');
@@ -67,6 +67,36 @@ describe('request-logging-middleware requestId propagation', () => {
expect(handlerEntry?.requestId).toBe(headerRequestId); expect(handlerEntry?.requestId).toBe(headerRequestId);
}); });
test('completion log carries top-level requestId for trace grouping', () => {
let finishHandler: (() => void) | undefined;
let headerRequestId = '';
const res = {
locals: {} as Record<string, unknown>,
setHeader: (_name: string, value: string) => {
headerRequestId = value;
},
on: (event: string, handler: () => void) => {
if (event === 'finish') finishHandler = handler;
},
statusCode: 204,
socket: { remoteAddress: '127.0.0.1' },
} as unknown as Parameters<typeof requestLoggingMiddleware>[1];
const req = {
originalUrl: '/api/anything',
method: 'POST',
headers: { 'user-agent': 'test-agent' },
socket: { remoteAddress: '127.0.0.1' },
} as unknown as Parameters<typeof requestLoggingMiddleware>[0];
requestLoggingMiddleware(req, res, () => {});
finishHandler?.();
const entry = getRecentLogEntries().find((e) => e.event === 'request.completed');
expect(entry).toBeDefined();
expect(entry?.requestId).toBe(headerRequestId);
expect((entry?.context as Record<string, unknown>)?.requestId).toBe(headerRequestId);
});
test('control: a bare handler log (no middleware) carries no requestId', () => { test('control: a bare handler log (no middleware) carries no requestId', () => {
const handlerLogger = createLogger('test:bare-handler'); const handlerLogger = createLogger('test:bare-handler');
handlerLogger.info('test.bare.ran', 'no middleware wrap'); handlerLogger.info('test.bare.ran', 'no middleware wrap');