mirror of
https://github.com/tiennm99/ccs.git
synced 2026-07-16 04:18:05 +00:00
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
This commit is contained in:
@@ -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',
|
||||
|
||||
@@ -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();
|
||||
});
|
||||
});
|
||||
Reference in New Issue
Block a user