From 7a22e89046ecb4af79291ecd3b4c885275ab5787 Mon Sep 17 00:00:00 2001
From: Tam Nhu Tran <kaitran.ntt@gmail.com>
Date: Thu, 30 Apr 2026 12:59:42 -0400
Subject: [PATCH 1/7] 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
---
 src/services/logging/index.ts                 |  26 +++-
 src/services/logging/log-context.ts           |  61 ++++++++
 src/services/logging/log-redaction.ts         |  45 +++++-
 src/services/logging/log-types.ts             |  53 +++++++
 src/services/logging/logger.ts                |  56 ++++++-
 .../unit/services/logging/log-context.test.ts |  76 ++++++++++
 .../logging/log-redaction-extended.test.ts    | 139 ++++++++++++++++++
 .../services/logging/logger-stages.test.ts    |  94 ++++++++++++
 8 files changed, 542 insertions(+), 8 deletions(-)
 create mode 100644 src/services/logging/log-context.ts
 create mode 100644 tests/unit/services/logging/log-context.test.ts
 create mode 100644 tests/unit/services/logging/log-redaction-extended.test.ts
 create mode 100644 tests/unit/services/logging/logger-stages.test.ts

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<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;
+}
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<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;
+}
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<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);
+}
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<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,
+      });
+    },
   };
 }
diff --git a/tests/unit/services/logging/log-context.test.ts b/tests/unit/services/logging/log-context.test.ts
new file mode 100644
index 00000000..535c3c9a
--- /dev/null
+++ b/tests/unit/services/logging/log-context.test.ts
@@ -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]);
+  });
+});
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']);
+  });
+});

From 47007279156545f81c615824065a0094aafa07d0 Mon Sep 17 00:00:00 2001
From: Tam Nhu Tran <kaitran.ntt@gmail.com>
Date: Thu, 30 Apr 2026 13:00:00 -0400
Subject: [PATCH 2/7] feat(proxy,cli): emit lifecycle stages with
 x-ccs-request-id propagation

Wrap proxy server entry edge in withRequestContext so every inbound request
gets a requestId (reused from x-ccs-request-id header when valid UUID-ish,
freshly minted otherwise). messages-route emits 7 stages: intake / auth /
transform / route / dispatch / upstream / respond, each with latencyMs and
structured error metadata on failure.

CCS CLI entry (ccs.ts) wraps main() in runWithRequestId and emits
cli.command.start / complete / failed stages so command lifecycle is
correlatable end-to-end.

Refs #1141, #1138
---
 src/ccs.ts                         | 36 +++++++++++++++++--
 src/proxy/server/messages-route.ts | 57 ++++++++++++++++++++++++------
 src/proxy/server/proxy-server.ts   | 41 ++++++++++++++++-----
 3 files changed, 112 insertions(+), 22 deletions(-)

diff --git a/src/ccs.ts b/src/ccs.ts
index 22eee96f..46e51b54 100644
--- a/src/ccs.ts
+++ b/src/ccs.ts
@@ -84,7 +84,7 @@ import { execClaude, stripAnthropicRoutingEnv, stripBrowserEnv } from './utils/s
 import { isDeprecatedGlmtProfileName, normalizeDeprecatedGlmtEnv } from './utils/glmt-deprecation';
 import { createOpenAICompatLaunchSettings } from './utils/openai-compat-launch-settings';
 import { maybeWarnAboutResumeLaneMismatch } from './auth/resume-lane-warning';
-import { createLogger } from './services/logging';
+import { createLogger, runWithRequestId } from './services/logging';
 import { buildCodexBrowserMcpOverrides } from './utils/browser-codex-overrides';
 import type { ProfileDetectionResult } from './auth/profile-detector';
 import type { BrowserLaunchOverride } from './utils/browser';
@@ -1683,5 +1683,35 @@ process.on('SIGINT', () => {
   }
 });
 
-// Run main
-main().catch(handleError);
+// Run main inside a per-invocation request context so all backend logging
+// emitted during this CLI run shares a single requestId. CLI text output
+// (stdout/stderr) is unaffected — the requestId lives in logs only.
+const cliEntryStartedAt = Date.now();
+const cliEntryLogger = createLogger('cli:entry');
+runWithRequestId(() => {
+  cliEntryLogger.stage('intake', 'cli.command.start', 'CLI invocation started', {
+    argv: process.argv.slice(2),
+  });
+  return main()
+    .then(() => {
+      cliEntryLogger.stage(
+        'respond',
+        'cli.command.complete',
+        'CLI invocation completed',
+        { exitCode: process.exitCode ?? 0 },
+        { latencyMs: Date.now() - cliEntryStartedAt }
+      );
+    })
+    .catch((err) => {
+      const error =
+        err instanceof Error
+          ? { name: err.name, message: err.message, stack: err.stack }
+          : { name: 'Error', message: String(err) };
+      cliEntryLogger.stage('cleanup', 'cli.command.failed', 'CLI invocation failed', undefined, {
+        level: 'error',
+        latencyMs: Date.now() - cliEntryStartedAt,
+        error,
+      });
+      handleError(err);
+    });
+});
diff --git a/src/proxy/server/messages-route.ts b/src/proxy/server/messages-route.ts
index 05cf485e..317f2256 100644
--- a/src/proxy/server/messages-route.ts
+++ b/src/proxy/server/messages-route.ts
@@ -207,11 +207,23 @@ export async function handleProxyMessagesRequest(
   insecureDispatcher?: Dispatcher
 ): Promise<void> {
   const transformer = new ProxySseStreamTransformer();
+  const startedAt = Date.now();
+
+  logger.stage('intake', 'request.received', 'Proxy /v1/messages request received', {
+    method: req.method || 'POST',
+    remoteAddress: req.socket.remoteAddress || null,
+  });
 
   if (!validateIncomingProxyAuth(req.headers, expectedAuthToken)) {
-    logger.warn('auth.invalid', 'Rejected proxy message request with invalid auth token', {
-      remoteAddress: req.socket.remoteAddress || null,
-    });
+    logger.stage(
+      'auth',
+      'auth.invalid',
+      'Rejected proxy message request with invalid auth token',
+      {
+        remoteAddress: req.socket.remoteAddress || null,
+      },
+      { level: 'warn' }
+    );
     await pipeWebResponseToNode(
       transformer.error(401, 'authentication_error', 'Missing or invalid local proxy token'),
       res
@@ -219,11 +231,14 @@ export async function handleProxyMessagesRequest(
     return;
   }
 
+  logger.stage('auth', 'auth.ok', 'Proxy auth validated');
+
   let timeoutMs = REQUEST_TIMEOUT_MS;
   try {
     const rawBody = await readJsonBody(req);
+    logger.stage('transform', 'request.transform.start', 'Transforming inbound proxy body');
     const upstream = buildUpstreamRequest(profile, rawBody);
-    logger.info('request.forward', 'Forwarding Anthropic request to OpenAI-compatible upstream', {
+    logger.stage('route', 'request.routed', 'Resolved proxy upstream route', {
       profileName: upstream.route.profile.profileName,
       provider: upstream.route.profile.provider,
       baseUrl: upstream.route.profile.baseUrl,
@@ -240,7 +255,8 @@ export async function handleProxyMessagesRequest(
       res,
       controller,
       (source) => {
-        logger.info(
+        logger.stage(
+          'cleanup',
           'request.disconnect',
           'Aborting upstream request after local client disconnect',
           {
@@ -252,28 +268,47 @@ export async function handleProxyMessagesRequest(
     );
 
     try {
+      logger.stage('dispatch', 'upstream.dispatch', 'Dispatching upstream fetch', {
+        profileName: profile.profileName,
+      });
       const upstreamResponse = await fetch(
         resolveOpenAIChatCompletionsUrl(upstream.route.profile.baseUrl),
         buildFetchInit(upstream.route.profile, upstream.body, controller.signal, insecureDispatcher)
       );
-      logger.info('response.received', 'Received upstream response', {
+      logger.stage('upstream', 'upstream.response', 'Received upstream response', {
         profileName: profile.profileName,
         routedProfileName: upstream.route.profile.profileName,
         status: upstreamResponse.status,
       });
       const response = await transformer.transform(upstreamResponse);
       await pipeWebResponseToNode(response, res);
+      logger.stage('respond', 'request.respond', 'Proxy response written', undefined, {
+        latencyMs: Date.now() - startedAt,
+      });
     } finally {
       clearTimeout(timeout);
       cleanupDisconnectHandlers();
     }
   } catch (error) {
     const message = error instanceof Error ? error.message : 'Unknown proxy error';
-    logger.error('request.failed', 'Proxy message request failed', {
-      profileName: profile.profileName,
-      error: message,
-      abort: error instanceof Error && error.name === 'AbortError',
-    });
+    const errInfo = {
+      name: error instanceof Error ? error.name : 'Error',
+      message,
+    };
+    logger.stage(
+      'cleanup',
+      'request.failed',
+      'Proxy message request failed',
+      {
+        profileName: profile.profileName,
+        abort: error instanceof Error && error.name === 'AbortError',
+      },
+      {
+        level: 'error',
+        latencyMs: Date.now() - startedAt,
+        error: errInfo,
+      }
+    );
     const status =
       error instanceof Error && error.name === 'AbortError'
         ? 502
diff --git a/src/proxy/server/proxy-server.ts b/src/proxy/server/proxy-server.ts
index d5e99d11..134583d4 100644
--- a/src/proxy/server/proxy-server.ts
+++ b/src/proxy/server/proxy-server.ts
@@ -1,8 +1,9 @@
 import * as http from 'http';
+import { randomUUID } from 'crypto';
 import { Agent } from 'undici';
 import type { OpenAICompatProfileConfig } from '../profile-router';
 import { OPENAI_COMPAT_PROXY_SERVICE_NAME } from '../proxy-daemon-paths';
-import { createLogger } from '../../services/logging';
+import { createLogger, withRequestContext } from '../../services/logging';
 import {
   handleProxyMessagesRequest,
   handleProxyModelsRequest,
@@ -10,6 +11,18 @@ import {
 } from './messages-route';
 import { writeJson } from './http-helpers';
 
+const REQUEST_ID_HEADER = 'x-ccs-request-id';
+// Loose UUID-ish guard: accepts UUIDs and similar opaque ids; rejects empty / control chars.
+const REQUEST_ID_PATTERN = /^[A-Za-z0-9._-]{8,128}$/;
+
+function resolveInboundRequestId(headers: http.IncomingHttpHeaders): string {
+  const raw = headers[REQUEST_ID_HEADER];
+  if (typeof raw === 'string' && REQUEST_ID_PATTERN.test(raw.trim())) {
+    return raw.trim();
+  }
+  return randomUUID();
+}
+
 export interface OpenAICompatProxyServerOptions {
   profile: OpenAICompatProfileConfig;
   host?: string;
@@ -28,13 +41,25 @@ export function startOpenAICompatProxyServer(options: OpenAICompatProxyServerOpt
   const insecureDispatcher = options.insecure
     ? new Agent({ connect: { rejectUnauthorized: false } })
     : undefined;
-  const server = http.createServer(async (req, res) => {
-    const method = req.method || 'GET';
-    const requestUrl = req.url || '/';
-    const parsedUrl = new URL(requestUrl, 'http://127.0.0.1');
-    const pathname =
-      parsedUrl.pathname.length > 1 ? parsedUrl.pathname.replace(/\/+$/, '') : parsedUrl.pathname;
+  const server = http.createServer((req, res) => {
+    const requestId = resolveInboundRequestId(req.headers);
+    res.setHeader(REQUEST_ID_HEADER, requestId);
+    void withRequestContext({ requestId }, async () => {
+      const method = req.method || 'GET';
+      const requestUrl = req.url || '/';
+      const parsedUrl = new URL(requestUrl, 'http://127.0.0.1');
+      const pathname =
+        parsedUrl.pathname.length > 1 ? parsedUrl.pathname.replace(/\/+$/, '') : parsedUrl.pathname;
+      await handleProxyRequest(req, res, method, pathname);
+    });
+  });
 
+  async function handleProxyRequest(
+    req: http.IncomingMessage,
+    res: http.ServerResponse,
+    method: string,
+    pathname: string
+  ): Promise<void> {
     if ((method === 'GET' || method === 'HEAD') && pathname === '/health') {
       if (method === 'HEAD') {
         res.writeHead(200, { 'Content-Type': 'application/json' });
@@ -105,7 +130,7 @@ export function startOpenAICompatProxyServer(options: OpenAICompatProxyServerOpt
       pathname,
     });
     writeJson(res, 404, { error: 'Not found' });
-  });
+  }
 
   logger.info('server.start', 'OpenAI-compatible proxy server listening', {
     baseUrl: `http://${host}:${options.port}`,

From bf8759460df0828ddec1138866dae3ef86ff2a42 Mon Sep 17 00:00:00 2001
From: Tam Nhu Tran <kaitran.ntt@gmail.com>
Date: Thu, 30 Apr 2026 13:00:16 -0400
Subject: [PATCH 3/7] feat(auth,commands): instrument oauth handler, profile
 registry, and doctor pipeline

Emit auth-stage events around OAuth round-trips and profile lookups so auth
flows are traceable end-to-end. Doctor command emits dispatch stages around
each health-check phase for clearer diagnostic logs.

Refs #1141, #1138
---
 src/auth/profile-registry.ts       | 10 +++++++++
 src/cliproxy/auth/oauth-handler.ts | 34 ++++++++++++++++++++++++++++++
 src/commands/doctor-command.ts     | 22 +++++++++++++++++++
 3 files changed, 66 insertions(+)

diff --git a/src/auth/profile-registry.ts b/src/auth/profile-registry.ts
index a0b944b2..35d17193 100644
--- a/src/auth/profile-registry.ts
+++ b/src/auth/profile-registry.ts
@@ -9,6 +9,9 @@ import {
 import type { AccountConfig } from '../config/unified-config-types';
 import { getCcsDir } from '../utils/config-manager';
 import { isValidContextGroupName, normalizeContextGroupName } from './account-context';
+import { createLogger } from '../services/logging';
+
+const logger = createLogger('auth:profile-registry');
 
 /**
  * Profile Registry (Simplified)
@@ -182,6 +185,10 @@ export class ProfileRegistry {
     // Default always stays on implicit 'default' profile (uses ~/.claude/)
 
     this._write(data);
+    logger.stage('route', 'auth.profile.created', 'Profile created in registry', {
+      profile: name,
+      profileType: metadata.type || 'account',
+    });
   }
 
   /**
@@ -235,6 +242,9 @@ export class ProfileRegistry {
     }
 
     this._write(data);
+    logger.stage('cleanup', 'auth.profile.deleted', 'Profile deleted from registry', {
+      profile: name,
+    });
   }
 
   /**
diff --git a/src/cliproxy/auth/oauth-handler.ts b/src/cliproxy/auth/oauth-handler.ts
index 78a3ea6a..3777e9a3 100644
--- a/src/cliproxy/auth/oauth-handler.ts
+++ b/src/cliproxy/auth/oauth-handler.ts
@@ -12,6 +12,7 @@
 
 import * as fs from 'fs';
 import { fail, info, warn, color, ok } from '../../utils/ui';
+import { createLogger } from '../../services/logging';
 import { ensureCLIProxyBinary } from '../binary-manager';
 import { generateConfig } from '../config/config-generator';
 import { CLIProxyProvider } from '../types';
@@ -82,6 +83,8 @@ interface PasteCallbackStartData {
 const PASTE_CALLBACK_AUTH_URL_POLL_INTERVAL_MS = 3000;
 const POLLED_AUTH_LOCAL_TOKEN_GRACE_MS = 15 * 1000;
 
+const logger = createLogger('cliproxy:auth:oauth');
+
 export async function requestPasteCallbackStart(
   provider: CLIProxyProvider,
   target: ProxyTarget,
@@ -800,6 +803,12 @@ export async function triggerOAuth(
 ): Promise<AccountInfo | null> {
   const oauthConfig = getOAuthConfig(provider);
   warnOAuthBanRisk(provider);
+  const oauthStartedAt = Date.now();
+  logger.stage('auth', 'cliproxy.oauth.start', 'Triggering OAuth flow', {
+    provider,
+    add: options.add === true,
+    fromUI: options.fromUI === true,
+  });
   const { verbose = false, add = false, fromUI = false, noIncognito = true } = options;
   const acceptAgyRisk = options.acceptAgyRisk === true;
   const { nickname } = options;
@@ -1055,6 +1064,24 @@ export async function triggerOAuth(
     }
   }
 
+  if (account) {
+    logger.stage(
+      'auth',
+      'cliproxy.oauth.success',
+      'OAuth flow completed successfully',
+      { provider, accountId: account.id },
+      { latencyMs: Date.now() - oauthStartedAt }
+    );
+  } else {
+    logger.stage(
+      'cleanup',
+      'cliproxy.oauth.failed',
+      'OAuth flow failed or was cancelled',
+      { provider },
+      { level: 'warn', latencyMs: Date.now() - oauthStartedAt }
+    );
+  }
+
   return account;
 }
 
@@ -1067,6 +1094,9 @@ export async function ensureAuth(
   options: { verbose?: boolean; headless?: boolean; account?: string } = {}
 ): Promise<boolean> {
   if (isAuthenticated(provider)) {
+    logger.stage('auth', 'cliproxy.auth.cached', 'Provider already authenticated', {
+      provider,
+    });
     if (options.verbose) {
       console.error(`[auth] ${provider} already authenticated`);
     }
@@ -1077,6 +1107,10 @@ export async function ensureAuth(
     return true;
   }
 
+  logger.stage('auth', 'cliproxy.auth.required', 'Provider needs authentication', {
+    provider,
+  });
+
   const oauthConfig = getOAuthConfig(provider);
   console.log(info(`${oauthConfig.displayName} authentication required`));
 
diff --git a/src/commands/doctor-command.ts b/src/commands/doctor-command.ts
index 5c4c9580..084f4cc1 100644
--- a/src/commands/doctor-command.ts
+++ b/src/commands/doctor-command.ts
@@ -5,6 +5,9 @@
  */
 
 import { initUI, header, dim, color, subheader } from '../utils/ui';
+import { createLogger } from '../services/logging';
+
+const logger = createLogger('commands:doctor');
 
 /**
  * Show help for doctor command
@@ -68,15 +71,34 @@ export async function handleDoctorCommand(args: string[]): Promise<void> {
   }
 
   const shouldFix = args.includes('--fix') || args.includes('-f');
+  const startedAt = Date.now();
+  logger.stage('intake', 'doctor.start', 'Doctor health check starting', {
+    fix: shouldFix,
+  });
 
   const DoctorModule = await import('../management/doctor');
   const Doctor = DoctorModule.default;
   const doctor = new Doctor();
 
   await doctor.runAllChecks();
+  logger.stage(
+    'route',
+    'doctor.checks_complete',
+    'Doctor checks complete',
+    { healthy: doctor.isHealthy() },
+    { latencyMs: Date.now() - startedAt }
+  );
 
   if (shouldFix) {
+    logger.stage('dispatch', 'doctor.fix_start', 'Attempting auto-fix', {});
     await doctor.fixIssues();
+    logger.stage(
+      'respond',
+      'doctor.fix_complete',
+      'Doctor auto-fix complete',
+      { healthy: doctor.isHealthy() },
+      { latencyMs: Date.now() - startedAt }
+    );
   }
 
   process.exit(doctor.isHealthy() ? 0 : 1);

From 1ff4329ee4b58e68648cd1f331f3dd64d4eb10df Mon Sep 17 00:00:00 2001
From: Tam Nhu Tran <kaitran.ntt@gmail.com>
Date: Thu, 30 Apr 2026 13:00:33 -0400
Subject: [PATCH 4/7] feat(providers): instrument copilot, cursor, and glmt
 across daemons and executors

Provider modules now emit structured stage tags around daemon spawn /
ready / stop, executor invocations, and upstream dispatch. glmt-transformer
gets cleanup-stage error conversion; legacy glmt-proxy adds minimal
listen + retry instrumentation (full per-request stages live in proxy-server
since glmt-proxy is compat-only).

Refs #1141, #1138
---
 src/copilot/copilot-auth.ts     | 48 +++++++++++++++++++++++++++++++++
 src/copilot/copilot-daemon.ts   | 39 +++++++++++++++++++++++++++
 src/copilot/copilot-executor.ts | 37 +++++++++++++++++++++++++
 src/cursor/cursor-daemon.ts     | 43 ++++++++++++++++++++++++++++-
 src/cursor/cursor-executor.ts   | 38 +++++++++++++++++++++++++-
 src/glmt/glmt-proxy.ts          | 15 +++++++++++
 src/glmt/glmt-transformer.ts    | 10 ++++---
 7 files changed, 225 insertions(+), 5 deletions(-)

diff --git a/src/copilot/copilot-auth.ts b/src/copilot/copilot-auth.ts
index 81d6fdf6..89236c75 100644
--- a/src/copilot/copilot-auth.ts
+++ b/src/copilot/copilot-auth.ts
@@ -14,6 +14,9 @@ import {
   isCopilotApiInstalled as checkInstalled,
   getCopilotApiBinPath,
 } from './copilot-package-manager';
+import { createLogger } from '../services/logging';
+
+const logger = createLogger('copilot:auth');
 
 /**
  * Get the path to copilot-api's GitHub token file.
@@ -108,6 +111,10 @@ export async function getCopilotDebugInfo(): Promise<CopilotDebugInfo | null> {
 export async function checkAuthStatus(): Promise<CopilotAuthStatus> {
   // Fast path: check if token file exists (instant, no subprocess)
   if (hasTokenFile()) {
+    logger.stage('auth', 'copilot.auth.token_present', 'Copilot token file present', {
+      provider: 'copilot',
+      method: 'token_file',
+    });
     return { authenticated: true };
   }
 
@@ -116,9 +123,20 @@ export async function checkAuthStatus(): Promise<CopilotAuthStatus> {
   const debugInfo = await getCopilotDebugInfo();
 
   if (debugInfo?.authenticated) {
+    logger.stage('auth', 'copilot.auth.debug_ok', 'Copilot reports authenticated via debug', {
+      provider: 'copilot',
+      method: 'debug',
+    });
     return { authenticated: true };
   }
 
+  logger.stage(
+    'auth',
+    'copilot.auth.unauthenticated',
+    'Copilot is not authenticated',
+    { provider: 'copilot' },
+    { level: 'warn' }
+  );
   return {
     authenticated: false,
   };
@@ -149,6 +167,11 @@ export function startAuthFlow(): Promise<AuthFlowResult> {
     console.log('[i] Starting GitHub authentication for Copilot...');
     console.log('');
 
+    const startedAt = Date.now();
+    logger.stage('auth', 'copilot.auth.start', 'Starting Copilot OAuth device flow', {
+      provider: 'copilot',
+    });
+
     const proc = spawn(binPath, ['auth'], {
       stdio: ['ignore', 'pipe', 'pipe'],
       shell: process.platform === 'win32',
@@ -185,8 +208,22 @@ export function startAuthFlow(): Promise<AuthFlowResult> {
 
     proc.on('close', (code) => {
       if (code === 0) {
+        logger.stage(
+          'auth',
+          'copilot.auth.complete',
+          'Copilot OAuth device flow completed',
+          { provider: 'copilot', exitCode: code },
+          { latencyMs: Date.now() - startedAt }
+        );
         resolve({ success: true, deviceCode, verificationUrl });
       } else {
+        logger.stage(
+          'cleanup',
+          'copilot.auth.failed',
+          'Copilot OAuth device flow failed',
+          { provider: 'copilot', exitCode: code },
+          { level: 'error', latencyMs: Date.now() - startedAt }
+        );
         resolve({
           success: false,
           error: `Authentication failed with exit code ${code}`,
@@ -197,6 +234,17 @@ export function startAuthFlow(): Promise<AuthFlowResult> {
     });
 
     proc.on('error', (err) => {
+      logger.stage(
+        'cleanup',
+        'copilot.auth.error',
+        'Failed to start Copilot OAuth process',
+        { provider: 'copilot' },
+        {
+          level: 'error',
+          latencyMs: Date.now() - startedAt,
+          error: { name: err.name, message: err.message },
+        }
+      );
       resolve({
         success: false,
         error: `Failed to start auth: ${err.message}`,
diff --git a/src/copilot/copilot-daemon.ts b/src/copilot/copilot-daemon.ts
index 4ec2d75b..9214f02f 100644
--- a/src/copilot/copilot-daemon.ts
+++ b/src/copilot/copilot-daemon.ts
@@ -14,6 +14,9 @@ import { CopilotConfig, DEFAULT_COPILOT_CONFIG } from '../config/unified-config-
 import { loadOrCreateUnifiedConfig } from '../config/unified-config-loader';
 import { getCopilotDir, getCopilotApiBinPath } from './copilot-package-manager';
 import { verifyProcessOwnership } from '../cursor/daemon-process-ownership';
+import { createLogger } from '../services/logging';
+
+const logger = createLogger('copilot:daemon');
 
 const DAEMON_HEALTH_MARKER = 'server running';
 const MIN_PORT = 1;
@@ -166,6 +169,10 @@ export async function startDaemon(
 
   // Check if already running
   if (await isDaemonRunning(config.port)) {
+    logger.stage('dispatch', 'copilot.daemon.already_running', 'Copilot daemon already running', {
+      provider: 'copilot',
+      port: config.port,
+    });
     return { success: true, pid: getPidFromFile() ?? undefined };
   }
 
@@ -185,6 +192,13 @@ export async function startDaemon(
     }
   }
 
+  const startedAt = Date.now();
+  logger.stage('dispatch', 'copilot.daemon.spawn', 'Spawning Copilot daemon', {
+    provider: 'copilot',
+    port: config.port,
+    accountType: config.account_type,
+  });
+
   return new Promise((resolve) => {
     let proc: ChildProcess;
     let resolved = false;
@@ -198,6 +212,27 @@ export async function startDaemon(
       }
       if (!result.success) {
         removePidFile();
+        logger.stage(
+          'cleanup',
+          'copilot.daemon.start_failed',
+          'Copilot daemon failed to start',
+          { provider: 'copilot', port: config.port },
+          {
+            level: 'error',
+            latencyMs: Date.now() - startedAt,
+            error: result.error
+              ? { name: 'CopilotDaemonStartError', message: result.error }
+              : undefined,
+          }
+        );
+      } else {
+        logger.stage(
+          'upstream',
+          'copilot.daemon.ready',
+          'Copilot daemon is ready',
+          { provider: 'copilot', port: config.port, pid: result.pid },
+          { latencyMs: Date.now() - startedAt }
+        );
       }
       resolve(result);
     };
@@ -326,6 +361,10 @@ export async function stopDaemon(): Promise<{ success: boolean; error?: string }
     }
 
     // Send SIGTERM to the process
+    logger.stage('cleanup', 'copilot.daemon.stop', 'Sending SIGTERM to Copilot daemon', {
+      provider: 'copilot',
+      pid,
+    });
     process.kill(pid, 'SIGTERM');
 
     // Wait for process to exit (up to 5 seconds)
diff --git a/src/copilot/copilot-executor.ts b/src/copilot/copilot-executor.ts
index b1ed44b4..b7d96962 100644
--- a/src/copilot/copilot-executor.ts
+++ b/src/copilot/copilot-executor.ts
@@ -35,6 +35,9 @@ import {
   resolveImageAnalysisRuntimeStatus,
 } from '../utils/hooks';
 import { stripClaudeCodeEnv } from '../utils/shell-executor';
+import { createLogger } from '../services/logging';
+
+const logger = createLogger('copilot:executor');
 
 interface CopilotImageAnalysisDeps {
   ensureCliproxyService: typeof ensureCliproxyService;
@@ -185,6 +188,12 @@ export async function executeCopilotProfile(
 ): Promise<number> {
   const { config: normalizedConfig, warnings } = normalizeCopilotConfigWithWarnings(config);
 
+  logger.stage('intake', 'copilot.execute.start', 'Starting Copilot profile execution', {
+    provider: 'copilot',
+    model: normalizedConfig.model,
+    port: normalizedConfig.port,
+  });
+
   if (warnings.length > 0) {
     warnings.forEach(({ message }) => console.log(warn(message)));
     console.log(
@@ -216,6 +225,10 @@ export async function executeCopilotProfile(
 
   // Check authentication
   const authStatus = await checkAuthStatus();
+  logger.stage('auth', 'copilot.execute.auth_check', 'Checked Copilot auth status', {
+    provider: 'copilot',
+    authenticated: authStatus.authenticated,
+  });
   if (!authStatus.authenticated) {
     console.error(fail('Not authenticated with GitHub.'));
     console.error('');
@@ -289,6 +302,7 @@ export async function executeCopilotProfile(
   console.log('');
 
   // Spawn Claude CLI
+  const spawnStartedAt = Date.now();
   return new Promise((resolve) => {
     const imageAnalysisArgs = imageAnalysisMcpReady
       ? appendThirdPartyImageAnalysisToolArgs(claudeArgs)
@@ -302,6 +316,11 @@ export async function executeCopilotProfile(
       claudeConfigDir,
     });
 
+    logger.stage('dispatch', 'copilot.execute.spawn', 'Spawning Claude via Copilot proxy', {
+      provider: 'copilot',
+      argCount: launchArgs.length,
+    });
+
     const proc = spawn(claudeCliPath, launchArgs, {
       stdio: 'inherit',
       env: { ...env, ...traceEnv },
@@ -309,10 +328,28 @@ export async function executeCopilotProfile(
     });
 
     proc.on('close', (code) => {
+      logger.stage(
+        'respond',
+        'copilot.execute.exit',
+        'Claude process exited (Copilot)',
+        { provider: 'copilot', exitCode: code },
+        { latencyMs: Date.now() - spawnStartedAt }
+      );
       resolve(code ?? 0);
     });
 
     proc.on('error', (err) => {
+      logger.stage(
+        'cleanup',
+        'copilot.execute.error',
+        'Failed to spawn Claude (Copilot)',
+        { provider: 'copilot' },
+        {
+          level: 'error',
+          latencyMs: Date.now() - spawnStartedAt,
+          error: { name: err.name, message: err.message },
+        }
+      );
       console.error(fail(`Failed to start Claude: ${err.message}`));
       resolve(1);
     });
diff --git a/src/cursor/cursor-daemon.ts b/src/cursor/cursor-daemon.ts
index 697b6df0..5c58b712 100644
--- a/src/cursor/cursor-daemon.ts
+++ b/src/cursor/cursor-daemon.ts
@@ -12,8 +12,11 @@ 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';
 export { getPidFromFile, writePidToFile, removePidFile } from './cursor-daemon-pid';
 
+const logger = createLogger('cursor:daemon');
+
 /**
  * Resolve daemon entrypoint candidates for current runtime.
  * - Dist runtime always uses JS artifact.
@@ -125,6 +128,10 @@ export async function startDaemon(
 ): Promise<{ success: boolean; pid?: number; error?: string }> {
   // Check if already running
   if (await isDaemonRunning(config.port)) {
+    logger.stage('dispatch', 'cursor.daemon.already_running', 'Cursor daemon already running', {
+      provider: 'cursor',
+      port: config.port,
+    });
     return { success: true, pid: getPidFromFile() ?? undefined };
   }
 
@@ -141,6 +148,13 @@ export async function startDaemon(
     };
   }
 
+  const startedAt = Date.now();
+  logger.stage('dispatch', 'cursor.daemon.spawn', 'Spawning Cursor daemon', {
+    provider: 'cursor',
+    port: config.port,
+    ghostMode: config.ghost_mode !== false,
+  });
+
   return new Promise((resolve) => {
     let proc: ChildProcess;
     let resolved = false;
@@ -149,7 +163,30 @@ export async function startDaemon(
       if (resolved) return;
       resolved = true;
       if (checkTimeout) clearTimeout(checkTimeout);
-      if (!result.success) removePidFile();
+      if (!result.success) {
+        removePidFile();
+        logger.stage(
+          'cleanup',
+          'cursor.daemon.start_failed',
+          'Cursor daemon failed to start',
+          { provider: 'cursor', port: config.port },
+          {
+            level: 'error',
+            latencyMs: Date.now() - startedAt,
+            error: result.error
+              ? { name: 'CursorDaemonStartError', message: result.error }
+              : undefined,
+          }
+        );
+      } else {
+        logger.stage(
+          'upstream',
+          'cursor.daemon.ready',
+          'Cursor daemon is ready',
+          { provider: 'cursor', port: config.port, pid: result.pid },
+          { latencyMs: Date.now() - startedAt }
+        );
+      }
       resolve(result);
     };
 
@@ -270,6 +307,10 @@ export async function stopDaemon(): Promise<{ success: boolean; error?: string }
     }
 
     // Send SIGTERM to the process
+    logger.stage('cleanup', 'cursor.daemon.stop', 'Sending SIGTERM to Cursor daemon', {
+      provider: 'cursor',
+      pid,
+    });
     process.kill(pid, 'SIGTERM');
 
     // Wait for process to exit (up to 5 seconds)
diff --git a/src/cursor/cursor-executor.ts b/src/cursor/cursor-executor.ts
index d7344be0..c4c2197b 100644
--- a/src/cursor/cursor-executor.ts
+++ b/src/cursor/cursor-executor.ts
@@ -12,6 +12,9 @@ import {
   type CursorApiCredentials,
 } from './cursor-protobuf-schema.js';
 import { buildCursorConnectHeaders, generateCursorChecksum } from './cursor-client-policy.js';
+import { createLogger } from '../services/logging';
+
+const logger = createLogger('cursor:executor');
 
 import {
   CursorConnectFrameError,
@@ -272,6 +275,13 @@ export class CursorExecutor {
     const headers = this.buildHeaders(credentials);
     const transformedBody = this.transformRequest(model, body, stream, credentials);
 
+    const startedAt = Date.now();
+    logger.stage('upstream', 'cursor.upstream.request', 'Sending Cursor upstream request', {
+      provider: 'cursor',
+      model,
+      stream,
+    });
+
     try {
       // Streaming requests use incremental HTTP/2 → SSE pipeline
       if (stream) {
@@ -294,6 +304,13 @@ export class CursorExecutor {
 
       if (response.status !== 200) {
         const errorText = response.body?.toString() || 'Unknown error';
+        logger.stage(
+          'cleanup',
+          'cursor.upstream.error',
+          'Cursor upstream returned non-200 status',
+          { provider: 'cursor', model, status: response.status },
+          { level: 'error', latencyMs: Date.now() - startedAt }
+        );
         const errorResponse = new Response(
           JSON.stringify({
             error: {
@@ -311,12 +328,31 @@ export class CursorExecutor {
       }
 
       const transformedResponse = this.transformProtobufToJSON(response.body, model, body);
+      logger.stage(
+        'transform',
+        'cursor.upstream.transformed',
+        'Cursor response transformed',
+        { provider: 'cursor', model },
+        { latencyMs: Date.now() - startedAt }
+      );
       return { response: transformedResponse, url, headers, transformedBody: body };
     } catch (error) {
+      const err = error as Error;
+      logger.stage(
+        'cleanup',
+        'cursor.upstream.exception',
+        'Cursor upstream request threw',
+        { provider: 'cursor', model },
+        {
+          level: 'error',
+          latencyMs: Date.now() - startedAt,
+          error: { name: err.name, message: err.message },
+        }
+      );
       const errorResponse = new Response(
         JSON.stringify({
           error: {
-            message: (error as Error).message,
+            message: err.message,
             type: 'connection_error',
             code: '',
           },
diff --git a/src/glmt/glmt-proxy.ts b/src/glmt/glmt-proxy.ts
index f493ba3e..41696b56 100644
--- a/src/glmt/glmt-proxy.ts
+++ b/src/glmt/glmt-proxy.ts
@@ -23,6 +23,9 @@ import * as https from 'https';
 import { GlmtTransformer } from './glmt-transformer';
 import { SSEParser } from './sse-parser';
 import { DeltaAccumulator } from './delta-accumulator';
+import { createLogger } from '../services/logging';
+
+const logger = createLogger('glmt:proxy');
 
 interface GlmtProxyConfig {
   verbose?: boolean;
@@ -137,6 +140,10 @@ export class GlmtProxy {
       this.server.listen(0, '127.0.0.1', () => {
         const address = this.server?.address();
         this.port = typeof address === 'object' && address ? address.port : 0;
+        logger.stage('intake', 'glmt.proxy.listening', 'GLMT proxy listening', {
+          provider: 'glmt',
+          port: this.port,
+        });
         // Signal parent process
         console.log(`PROXY_READY:${this.port}`);
 
@@ -448,6 +455,14 @@ export class GlmtProxy {
         lastError = err;
         const delay = this.calculateRetryDelay(attempt, retryAfter);
 
+        logger.stage(
+          'upstream',
+          'glmt.upstream.retry',
+          'Retrying GLMT upstream after retryable error',
+          { provider: 'glmt', attempt: attempt + 1, maxRetries: this.retryConfig.maxRetries },
+          { level: 'warn' }
+        );
+
         if (this.verbose) {
           console.error(
             `[glmt-proxy] Rate limited, retry ${attempt + 1}/${this.retryConfig.maxRetries} after ${Math.round(delay)}ms`
diff --git a/src/glmt/glmt-transformer.ts b/src/glmt/glmt-transformer.ts
index 1886f05a..72c4c63e 100644
--- a/src/glmt/glmt-transformer.ts
+++ b/src/glmt/glmt-transformer.ts
@@ -127,9 +127,13 @@ export class GlmtTransformer {
       return anthropicResponse;
     } catch (error) {
       const err = error as Error;
-      this.logger.error('response.transform_failed', 'GLMT response transformation failed', {
-        message: err.message,
-      });
+      this.logger.stage(
+        'cleanup',
+        'response.transform_failed',
+        'GLMT response transformation failed',
+        undefined,
+        { level: 'error', error: { name: err.name, message: err.message } }
+      );
       console.error('[glmt-transformer] Response transformation error:', err);
       return {
         id: 'msg_error_' + Date.now(),

From 8afee344e1b1e8f45d029affc011e229e069b949 Mon Sep 17 00:00:00 2001
From: Tam Nhu Tran <kaitran.ntt@gmail.com>
Date: Thu, 30 Apr 2026 13:00:49 -0400
Subject: [PATCH 5/7] feat(targets,management): instrument adapter spawn
 lifecycle and instance manager

Each target adapter (claude, codex, droid) now emits dispatch on child
spawn and respond on child exit with latencyMs. instance-manager emits
lifecycle events for instance create / start / stop so multi-instance flows
are traceable per requestId.

Refs #1141, #1138
---
 src/management/instance-manager.ts | 10 ++++++++++
 src/targets/claude-adapter.ts      | 20 ++++++++++++++++++++
 src/targets/codex-adapter.ts       | 20 ++++++++++++++++++++
 src/targets/droid-adapter.ts       | 20 ++++++++++++++++++++
 4 files changed, 70 insertions(+)

diff --git a/src/management/instance-manager.ts b/src/management/instance-manager.ts
index 8fa15198..ba39c65c 100644
--- a/src/management/instance-manager.ts
+++ b/src/management/instance-manager.ts
@@ -13,6 +13,9 @@ import ProfileContextSyncLock from './profile-context-sync-lock';
 import { DEFAULT_ACCOUNT_CONTEXT_MODE } from '../auth/account-context';
 import type { AccountContextPolicy } from '../auth/account-context';
 import { getCcsDir, getCcsHome } from '../utils/config-manager';
+import { createLogger } from '../services/logging';
+
+const logger = createLogger('management:instance-manager');
 
 const MANAGED_MCP_SERVER_NAMES = new Set(['ccs-websearch', 'ccs-image-analysis', 'ccs-browser']);
 
@@ -52,6 +55,10 @@ class InstanceManager {
     await this.contextSyncLock.withLock(profileName, async () => {
       // Lazy initialization
       if (!fs.existsSync(instancePath)) {
+        logger.stage('route', 'instance.init', 'Initializing new profile instance', {
+          profile: profileName,
+          bare: options.bare === true,
+        });
         this.initializeInstance(profileName, instancePath, options);
       }
 
@@ -170,6 +177,9 @@ class InstanceManager {
         }
 
         fs.rmSync(instancePath, { recursive: true, force: true });
+        logger.stage('cleanup', 'instance.deleted', 'Profile instance deleted', {
+          profile: profileName,
+        });
       });
     });
   }
diff --git a/src/targets/claude-adapter.ts b/src/targets/claude-adapter.ts
index 397ce6e1..750a301d 100644
--- a/src/targets/claude-adapter.ts
+++ b/src/targets/claude-adapter.ts
@@ -21,6 +21,9 @@ import { getWebSearchHookEnv } from '../utils/websearch-manager';
 import { appendBrowserToolArgs } from '../utils/browser';
 import { wireChildProcessSignals } from '../utils/signal-forwarder';
 import { runCleanup } from '../errors';
+import { createLogger } from '../services/logging';
+
+const adapterLogger = createLogger('targets:claude');
 
 export class ClaudeAdapter implements TargetAdapter {
   readonly type: TargetType = 'claude';
@@ -101,6 +104,13 @@ export class ClaudeAdapter implements TargetAdapter {
     const isPowerShellScript = isWindows && /\.ps1$/i.test(claudeCli);
     const needsShell = isWindows && /\.(cmd|bat)$/i.test(claudeCli);
 
+    const spawnStartedAt = Date.now();
+    adapterLogger.stage('dispatch', 'target.spawn', 'Spawning Claude CLI child process', {
+      target: 'claude',
+      claudeCli,
+      argCount: args.length,
+    });
+
     let child: ChildProcess;
     if (isPowerShellScript) {
       child = spawn(
@@ -128,6 +138,16 @@ export class ClaudeAdapter implements TargetAdapter {
       });
     }
 
+    child.on('exit', (code, signal) => {
+      adapterLogger.stage(
+        'respond',
+        'target.exit',
+        'Claude CLI child process exited',
+        { target: 'claude', exitCode: code, signal },
+        { latencyMs: Date.now() - spawnStartedAt }
+      );
+    });
+
     wireChildProcessSignals(child, async (err: NodeJS.ErrnoException) => {
       if (err.code === 'EACCES') {
         console.error(`[X] Claude CLI is not executable: ${claudeCli}`);
diff --git a/src/targets/codex-adapter.ts b/src/targets/codex-adapter.ts
index f82aa23b..31cf2104 100644
--- a/src/targets/codex-adapter.ts
+++ b/src/targets/codex-adapter.ts
@@ -23,6 +23,9 @@ import {
   getCodexBinaryInfo,
   readCodexVersion,
 } from './codex-detector';
+import { createLogger } from '../services/logging';
+
+const adapterLogger = createLogger('targets:codex');
 
 const CODEX_RUNTIME_PROVIDER_ID = 'ccs_runtime';
 const CODEX_RUNTIME_ENV_KEY = 'CCS_CODEX_API_KEY';
@@ -310,6 +313,13 @@ export class CodexAdapter implements TargetAdapter {
     const isPowerShellScript = isWindows && /\.ps1$/i.test(codexPath);
     const needsShell = isWindows && /\.(cmd|bat)$/i.test(codexPath);
 
+    const spawnStartedAt = Date.now();
+    adapterLogger.stage('dispatch', 'target.spawn', 'Spawning Codex CLI child process', {
+      target: 'codex',
+      codexPath,
+      argCount: args.length,
+    });
+
     let child: ChildProcess;
     if (isPowerShellScript) {
       child = spawn(
@@ -329,6 +339,16 @@ export class CodexAdapter implements TargetAdapter {
       child = spawn(codexPath, args, { stdio: 'inherit', windowsHide: true, env: launchEnv });
     }
 
+    child.on('exit', (code, signal) => {
+      adapterLogger.stage(
+        'respond',
+        'target.exit',
+        'Codex CLI child process exited',
+        { target: 'codex', exitCode: code, signal },
+        { latencyMs: Date.now() - spawnStartedAt }
+      );
+    });
+
     wireChildProcessSignals(child, (err: NodeJS.ErrnoException) => {
       if (err.code === 'EACCES') {
         console.error(`[X] Codex CLI is not executable: ${codexPath}`);
diff --git a/src/targets/droid-adapter.ts b/src/targets/droid-adapter.ts
index c162f7f3..025875a9 100644
--- a/src/targets/droid-adapter.ts
+++ b/src/targets/droid-adapter.ts
@@ -19,6 +19,9 @@ import {
 } from '../utils/shell-executor';
 import { wireChildProcessSignals } from '../utils/signal-forwarder';
 import { runCleanup } from '../errors';
+import { createLogger } from '../services/logging';
+
+const adapterLogger = createLogger('targets:droid');
 
 export class DroidAdapter implements TargetAdapter {
   readonly type: TargetType = 'droid';
@@ -122,6 +125,13 @@ export class DroidAdapter implements TargetAdapter {
     const isPowerShellScript = isWindows && /\.ps1$/i.test(droidPath);
     const needsShell = isWindows && /\.(cmd|bat)$/i.test(droidPath);
 
+    const spawnStartedAt = Date.now();
+    adapterLogger.stage('dispatch', 'target.spawn', 'Spawning Droid CLI child process', {
+      target: 'droid',
+      droidPath,
+      argCount: args.length,
+    });
+
     let child: ChildProcess;
     if (isPowerShellScript) {
       child = spawn(
@@ -149,6 +159,16 @@ export class DroidAdapter implements TargetAdapter {
       });
     }
 
+    child.on('exit', (code, signal) => {
+      adapterLogger.stage(
+        'respond',
+        'target.exit',
+        'Droid CLI child process exited',
+        { target: 'droid', exitCode: code, signal },
+        { latencyMs: Date.now() - spawnStartedAt }
+      );
+    });
+
     wireChildProcessSignals(child, (err: NodeJS.ErrnoException) => {
       if (err.code === 'EACCES') {
         console.error(`[X] Droid CLI is not executable: ${droidPath}`);

From c0a019bf7e83287dddfb333633941d3142541778 Mon Sep 17 00:00:00 2001
From: Tam Nhu Tran <kaitran.ntt@gmail.com>
Date: Thu, 30 Apr 2026 13:01:05 -0400
Subject: [PATCH 6/7] test(logging): add cross-stage requestId correlation
 integration test in slow bucket

Verifies that a single requestId propagates across at least 3 lifecycle
stages emitted from different modules, and that ALS context survives across
async boundaries (setImmediate, microtask, promise.then). Registered in
test:slow bucket per validate:ci-parity gate.

Refs #1141, #1138
---
 scripts/run-test-bucket.js                    |  1 +
 .../logging-request-context.test.ts           | 94 +++++++++++++++++++
 2 files changed, 95 insertions(+)
 create mode 100644 tests/integration/logging-request-context.test.ts

diff --git a/scripts/run-test-bucket.js b/scripts/run-test-bucket.js
index 6d97a1ee..98329b9c 100644
--- a/scripts/run-test-bucket.js
+++ b/scripts/run-test-bucket.js
@@ -20,6 +20,7 @@ const candidateRoots = ['tests/unit', 'tests/integration', 'tests/npm'];
 // Automated perf-budget enforcement tracked in issue #1071.
 const slowTests = [
   'tests/integration/cursor-daemon-lifecycle.test.ts',
+  'tests/integration/logging-request-context.test.ts',
   'tests/integration/proxy/daemon-lifecycle.test.ts',
   'tests/unit/commands/persist-command-handler.test.ts',
   'tests/unit/hooks/browser-mcp-advanced-interactions.test.ts',
diff --git a/tests/integration/logging-request-context.test.ts b/tests/integration/logging-request-context.test.ts
new file mode 100644
index 00000000..1b8313df
--- /dev/null
+++ b/tests/integration/logging-request-context.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,
+  createLogger,
+  getRecentLogEntries,
+  invalidateLoggingConfigCache,
+  withRequestContext,
+} from '../../src/services/logging';
+
+describe('logging request context (integration)', () => {
+  let tempHome = '';
+  let originalCcsHome: string | undefined;
+
+  beforeEach(() => {
+    originalCcsHome = process.env.CCS_HOME;
+    tempHome = fs.mkdtempSync(path.join(os.tmpdir(), 'ccs-log-context-int-'));
+    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('correlates >=3 stage entries by requestId across nested async calls', async () => {
+    const logger = createLogger('test:integration');
+
+    await withRequestContext({ requestId: 'test-req-1' }, async () => {
+      logger.stage('intake', 'request.received', 'inbound');
+      await new Promise((r) => setTimeout(r, 1));
+      logger.stage('dispatch', 'upstream.dispatch', 'outbound');
+      await Promise.resolve();
+      logger.stage('respond', 'request.respond', 'sent', undefined, { latencyMs: 5 });
+    });
+
+    const entries = getRecentLogEntries().filter((e) => e.requestId === 'test-req-1');
+    expect(entries.length).toBeGreaterThanOrEqual(3);
+    const stages = entries.map((e) => e.stage);
+    expect(stages).toContain('intake');
+    expect(stages).toContain('dispatch');
+    expect(stages).toContain('respond');
+    // Emit-time ordering guarantee within a single requestId.
+    const timestamps = entries.map((e) => Date.parse(e.timestamp));
+    const sorted = [...timestamps].sort((a, b) => a - b);
+    expect(timestamps).toEqual(sorted);
+  });
+
+  it('isolates parallel request contexts (no cross-contamination)', async () => {
+    const logger = createLogger('test:integration');
+
+    await Promise.all([
+      withRequestContext({ requestId: 'test-req-A' }, async () => {
+        logger.stage('intake', 'a.start', 'a-in');
+        await new Promise((r) => setTimeout(r, 5));
+        logger.stage('respond', 'a.end', 'a-out');
+      }),
+      withRequestContext({ requestId: 'test-req-B' }, async () => {
+        await new Promise((r) => setTimeout(r, 1));
+        logger.stage('intake', 'b.start', 'b-in');
+        logger.stage('respond', 'b.end', 'b-out');
+      }),
+    ]);
+
+    const entries = getRecentLogEntries();
+    const a = entries.filter((e) => e.requestId === 'test-req-A');
+    const b = entries.filter((e) => e.requestId === 'test-req-B');
+    expect(a.length).toBe(2);
+    expect(b.length).toBe(2);
+    // No A entry leaks into B and vice-versa
+    expect(a.every((e) => e.event.startsWith('a.'))).toBe(true);
+    expect(b.every((e) => e.event.startsWith('b.'))).toBe(true);
+  });
+
+  it('emits no requestId outside any context', () => {
+    const logger = createLogger('test:integration');
+    logger.info('plain.event', 'no-context');
+    const [entry] = getRecentLogEntries();
+    expect(entry.requestId).toBeUndefined();
+  });
+});

From c0c856af988277d2d79b869e1be98c5261d8c7c0 Mon Sep 17 00:00:00 2001
From: Tam Nhu Tran <kaitran.ntt@gmail.com>
Date: Thu, 30 Apr 2026 13:01:21 -0400
Subject: [PATCH 7/7] 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
---
 CLAUDE.md                |   2 +-
 docs/logging-contract.md | 159 +++++++++++++++++++++++++++++++++++++++
 2 files changed, 160 insertions(+), 1 deletion(-)
 create mode 100644 docs/logging-contract.md

diff --git a/CLAUDE.md b/CLAUDE.md
index 05003c5f..2ffd7892 100644
--- a/CLAUDE.md
+++ b/CLAUDE.md
@@ -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
diff --git a/docs/logging-contract.md b/docs/logging-contract.md
new file mode 100644
index 00000000..8eebf58a
--- /dev/null
+++ b/docs/logging-contract.md
@@ -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).