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] 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();
+  });
+});