Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
92 changes: 50 additions & 42 deletions packages/cli/src/services/housekeeping/scheduler.ts
Original file line number Diff line number Diff line change
Expand Up @@ -272,49 +272,57 @@ async function drainNonInteractiveQueue(): Promise<void> {
const abortController = new AbortController();
activeNonInteractiveAbortController = abortController;

await sessionIdContext.exit(async () => {
try {
const result = await runOpenAILogCleanup(
job.target,
job.markerPath,
abortController.signal,
);
if (nonInteractiveStopping) return;

switch (result.status) {
case 'completed':
scheduleNonInteractiveJob(job, RECURRING_INTERVAL_MS);
break;
case 'fresh':
scheduleNonInteractiveJob(
job,
Math.min(
RECURRING_INTERVAL_MS,
Math.max(NON_INTERACTIVE_LOCK_RETRY_MS, result.retryAfterMs),
),
);
break;
case 'locked':
scheduleNonInteractiveJob(job, NON_INTERACTIVE_LOCK_RETRY_MS);
break;
case 'incomplete':
break;
default:
break;
}
} catch (err) {
debugLogger.error(
`non-interactive OpenAI log cleanup failed for ${job.target.logDir}`,
err,
);
if (!nonInteractiveStopping) {
scheduleNonInteractiveJob(job, NON_INTERACTIVE_FAILURE_RETRY_MS);
}
} finally {
activeNonInteractiveJob = undefined;
activeNonInteractiveAbortController = undefined;
// No sessionIdContext.exit here: every path into this drain — the
// start-side kick, the .finally re-kick, and the retry timers — already
// runs context-free because startNonInteractiveOpenAILogHousekeeping
// exits the context around enqueue and the worker start, and timers
// registered inside that scope inherit it. A second wrapper here was
// unreachable defensive code no test could pin (recorded in #9930's
// round-4 review); the single tested choke point is the start-side
// sessionIdContext.exit in startNonInteractiveOpenAILogHousekeeping. Any
// NEW way into this drain must enter through that exited scope, or it
// will start propagating a session id into process-scoped housekeeping.
try {
const result = await runOpenAILogCleanup(
job.target,
job.markerPath,
abortController.signal,
);
if (nonInteractiveStopping) continue;

switch (result.status) {
case 'completed':
scheduleNonInteractiveJob(job, RECURRING_INTERVAL_MS);
break;
case 'fresh':
scheduleNonInteractiveJob(
job,
Math.min(
RECURRING_INTERVAL_MS,
Math.max(NON_INTERACTIVE_LOCK_RETRY_MS, result.retryAfterMs),
),
);
break;
case 'locked':
scheduleNonInteractiveJob(job, NON_INTERACTIVE_LOCK_RETRY_MS);
break;
case 'incomplete':
break;
default:
break;
}
});
} catch (err) {
debugLogger.error(
`non-interactive OpenAI log cleanup failed for ${job.target.logDir}`,
err,
);
if (!nonInteractiveStopping) {
scheduleNonInteractiveJob(job, NON_INTERACTIVE_FAILURE_RETRY_MS);
}
} finally {
activeNonInteractiveJob = undefined;
activeNonInteractiveAbortController = undefined;
}
}
}

Expand Down
122 changes: 85 additions & 37 deletions packages/core/src/config/config.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -614,28 +614,53 @@ describe('Server Config (config.ts)', () => {
});
});

it('does not replace the global debug fallback during daemon Config creation or rotation', async () => {
// Shared isolation for the debug-fallback tests below. The module-level
// vi.mock('node:fs') factory overrides only the sync fs API, so any
// un-spied fs.promises call the debug logger makes would hit the real
// filesystem (writing into the actual global debug dir). Spy the full
// surface the fallback/alias path touches — mkdir, appendFile, unlink,
// symlink AND readlink — in one place so the two tests can't drift out of
// lockstep, then restore env + logger state on the way out. The body reads
// the appendFile spy back via vi.mocked(fs.promises.appendFile) — passing it
// as a typed callback argument runs into vi.spyOn's generic-overload return
// type, which the concrete spy is not assignable to (TS2345).
async function withDebugFallbackIsolation(
run: () => Promise<void>,
): Promise<void> {
Comment on lines +627 to +629

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[Critical] R1-1: (fix-induced) [fails-closed] [regression] The new withDebugFallbackIsolation helper types its callback as ReturnType<typeof vi.spyOn>, which resolves to vitest's generic-constraint overload MockInstance<(this: unknown, ...args: unknown[]) => unknown> — the concrete vi.spyOn(fs.promises, 'appendFile') spy is not assignable to it, so npm run build --workspace=packages/core fails with TS2345. The round-1 fix for R1-1 (extracting this shared helper) introduced it: every build or typecheck of packages/core — the CI Test job, npm run typecheck, npm run preflight, and dependent workspaces — exits non-zero at src/config/config.test.ts(650,17) on await run(appendFileSpy);. vitest transpiles without type-checking, so the two tests still run green and the failure is invisible to a test-only run; live CI on this commit is red with exactly this error.

Witness:

npm run build --workspace=packages/core → exit 1, single error:
src/config/config.test.ts(650,17): error TS2345: Argument of type
'MockInstance<(path: PathLike | FileHandle, data: string | Uint8Array<ArrayBufferLike>, ...) => Promise<...>>'
is not assignable to parameter of type 'MockInstance<(this: unknown, ...args: unknown[]) => unknown>'.
Identical failure in live CI: Test (ubuntu-latest, Node 22.x), run 33240215927.

Fix (two spots — repo precedent at packages/core/src/services/sessionService.test.ts:74):

// config.test.ts:8 — extend the existing type import
import type { Mock, MockInstance } from 'vitest';

// helper signature
async function withDebugFallbackIsolation(
  run: (appendFileSpy: MockInstance<typeof fs.promises.appendFile>) => Promise<void>,
): Promise<void> {

The annotation must stay assignable where the spy is passed — await run(appendFileSpy) at config.test.ts:650, with the spy produced as vi.spyOn(fs.promises, 'appendFile').mockResolvedValue(undefined) (config.test.ts:637-639) and consumed in both test bodies via toHaveBeenCalledWith(path, expect.stringContaining(...), 'utf8') — so it must not be widened to a bare Mock/vi.fn() type that drops the call-argument typing.

Acceptance criterion: npm run build --workspace=packages/core must go green — it is red today with TS2345 at config.test.ts:650, and reverting the annotation to ReturnType<typeof vi.spyOn> reproduces the failure (no runtime test pins a type annotation, so the build itself is the mutation check).

中文说明

R1-1:(修复引入)新的 withDebugFallbackIsolation 辅助函数把回调参数标注为 ReturnType<typeof vi.spyOn>,它解析到 vitest 的泛型约束重载 MockInstance<(this: unknown, ...args: unknown[]) => unknown> —— 具体的 vi.spyOn(fs.promises, 'appendFile') spy 无法赋给该类型,导致 npm run build --workspace=packages/core 报 TS2345 失败。本缺陷由第 1 轮 R1-1 的修复(提取这个共享辅助函数)引入:所有对 packages/core 的构建或类型检查 —— CI 的 Test 任务、npm run typechecknpm run preflight、以及依赖它的工作区 —— 都会在 src/config/config.test.ts(650,17)await run(appendFileSpy); 处非零退出。vitest 转译时不做类型检查,所以这两个测试仍然绿灯,仅跑测试看不到该失败;当前提交上的 CI 正是因为这个错误而红。

修复(两处 —— 仓库先例见 packages/core/src/services/sessionService.test.ts:74):把类型导入扩展为 import type { Mock, MockInstance } from 'vitest';,并把辅助函数签名改为 run: (appendFileSpy: MockInstance<typeof fs.promises.appendFile>) => Promise<void>

约束:该标注必须保持可赋值 —— await run(appendFileSpy)(config.test.ts:650)处的 spy 由 vi.spyOn(fs.promises, 'appendFile').mockResolvedValue(undefined)(config.test.ts:637-639)产生,并被两个测试体以 toHaveBeenCalledWith(path, expect.stringContaining(...), 'utf8') 消费 —— 因此不能放宽为丢失调用参数类型的裸 Mock/vi.fn() 类型。

验收标准:npm run build --workspace=packages/core 必须变绿 —— 当前因 config.test.ts:650 的 TS2345 而红,把标注还原为 ReturnType<typeof vi.spyOn> 会复现该失败(类型标注没有运行时测试可钉,构建本身就是变异检验)。

— qwen3.8-max via Qwen Code /review (v0.22.3)

const previousDebugLogFileEnv = process.env['QWEN_DEBUG_LOG_FILE'];
const previousSessionIdEnv = process.env['QWEN_CODE_SESSION_ID'];
const bootstrapSessionId = '550e8400-e29b-41d4-a716-446655440000';
const daemonSessionId = '6ba7b810-9dad-11d1-80b4-00c04fd430c8';
const rotatedSessionId = '7ba7b810-9dad-11d1-80b4-00c04fd430c8';
const mkdirSpy = vi
.spyOn(fs.promises, 'mkdir')
.mockResolvedValue(undefined);
const appendFileSpy = vi
.spyOn(fs.promises, 'appendFile')
.mockResolvedValue(undefined);
const unlinkSpy = vi
.spyOn(fs.promises, 'unlink')
.mockResolvedValue(undefined);
const symlinkSpy = vi
.spyOn(fs.promises, 'symlink')
.mockResolvedValue(undefined);

const spies = [
vi.spyOn(fs.promises, 'mkdir').mockResolvedValue(undefined),
vi.spyOn(fs.promises, 'appendFile').mockResolvedValue(undefined),
vi.spyOn(fs.promises, 'unlink').mockResolvedValue(undefined),
vi.spyOn(fs.promises, 'symlink').mockResolvedValue(undefined),
vi.spyOn(fs.promises, 'readlink').mockResolvedValue(''),
];
const restoreEnv = (key: string, previous: string | undefined) => {
if (previous === undefined) {
delete process.env[key];
} else {
process.env[key] = previous;
}
};
try {
delete process.env['QWEN_DEBUG_LOG_FILE'];
resetDebugLoggingState();
await run();
} finally {
for (const spy of spies) spy.mockRestore();
resetDebugLoggingState();
setDebugLogSession(null);
restoreEnv('QWEN_DEBUG_LOG_FILE', previousDebugLogFileEnv);
restoreEnv('QWEN_CODE_SESSION_ID', previousSessionIdEnv);
}
}

it('does not replace the global debug fallback during daemon Config creation or rotation', async () => {
await withDebugFallbackIsolation(async () => {
const bootstrapSessionId = '550e8400-e29b-41d4-a716-446655440000';
const daemonSessionId = '6ba7b810-9dad-11d1-80b4-00c04fd430c8';
const rotatedSessionId = '7ba7b810-9dad-11d1-80b4-00c04fd430c8';
new Config({ ...baseParams, sessionId: bootstrapSessionId });
const daemonConfig = sessionIdContext.run(
daemonSessionId,
Expand All @@ -649,35 +674,58 @@ describe('Server Config (config.ts)', () => {
createDebugLogger('DAEMON_FALLBACK').info('process-scoped message');

await vi.waitFor(() =>
expect(appendFileSpy).toHaveBeenCalledWith(
expect(vi.mocked(fs.promises.appendFile)).toHaveBeenCalledWith(
Storage.getDebugLogPath(bootstrapSessionId),
expect.stringContaining('[DAEMON_FALLBACK] process-scoped message'),
'utf8',
),
);
expect(appendFileSpy).not.toHaveBeenCalledWith(
expect(vi.mocked(fs.promises.appendFile)).not.toHaveBeenCalledWith(
Storage.getDebugLogPath(rotatedSessionId),
expect.stringContaining('[DAEMON_FALLBACK] process-scoped message'),
'utf8',
);
} finally {
mkdirSpy.mockRestore();
appendFileSpy.mockRestore();
unlinkSpy.mockRestore();
symlinkSpy.mockRestore();
resetDebugLoggingState();
setDebugLogSession(null);
if (previousDebugLogFileEnv === undefined) {
delete process.env['QWEN_DEBUG_LOG_FILE'];
} else {
process.env['QWEN_DEBUG_LOG_FILE'] = previousDebugLogFileEnv;
}
if (previousSessionIdEnv === undefined) {
delete process.env['QWEN_CODE_SESSION_ID'];
} else {
process.env['QWEN_CODE_SESSION_ID'] = previousSessionIdEnv;
}
}
});
});

it('claims the global debug fallback on un-contexted rotation (single-session CLI)', async () => {
// The other direction of the guard above: a single-session CLI /clear
// rotates the Config OUTSIDE any sessionIdContext, and the process-wide
// debug session must follow the rotated id — otherwise post-rotation
// logs keep landing in the pre-rotation session's file.
await withDebugFallbackIsolation(async () => {
const initialSessionId = '550e8400-e29b-41d4-a716-446655440000';
const rotatedSessionId = '7ba7b810-9dad-11d1-80b4-00c04fd430c8';
// The fallback holds a live Config reference, so rotating the SAME
// Config reroutes writes even without the rotation-time claim. The
// claim is load-bearing for RE-claiming: another Config (transcript
// replay, bootstrap) may have taken the fallback since, and an
// un-contexted rotation must hand it back to the rotating CLI Config.
const cliConfig = new Config({
...baseParams,
sessionId: initialSessionId,
});
const interloperSessionId = '6ba7b810-9dad-11d1-80b4-00c04fd430c8';
new Config({ ...baseParams, sessionId: interloperSessionId });

cliConfig.startNewSession(rotatedSessionId);

process.env['QWEN_DEBUG_LOG_FILE'] = '1';
createDebugLogger('CLI_ROTATION').info('post-rotation message');

await vi.waitFor(() =>
expect(vi.mocked(fs.promises.appendFile)).toHaveBeenCalledWith(
Storage.getDebugLogPath(rotatedSessionId),
expect.stringContaining('[CLI_ROTATION] post-rotation message'),
'utf8',
),
);
expect(vi.mocked(fs.promises.appendFile)).not.toHaveBeenCalledWith(
Storage.getDebugLogPath(interloperSessionId),
expect.stringContaining('[CLI_ROTATION] post-rotation message'),
'utf8',
);
});
});

describe('shell execution config', () => {
Expand Down
47 changes: 47 additions & 0 deletions packages/core/src/utils/debugLogger.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -574,6 +574,53 @@ describe('debugLogger', () => {
vi.mocked(fs.readlink).mockResolvedValue('');
});

it('recovers from the streak cap when a later alias update succeeds', async () => {
// The cap must behave like a circuit breaker, not a latch: a capped
// streak still attempts on a session CHANGE (different dedup key), and
// one success re-opens retries for subsequent transient failures.
resetDebugLoggingState();
const otherSession = '6ba7b810-9dad-11d1-80b4-00c04fd430c8';
vi.mocked(fs.symlink).mockResolvedValue(undefined);
vi.mocked(fs.readlink)
// A's three failures reach the cap.
.mockRejectedValueOnce(new Error('ENOENT'))
.mockRejectedValueOnce(new Error('ENOENT'))
.mockRejectedValueOnce(new Error('ENOENT'))
// B's attempt succeeds and resets the streak.
.mockResolvedValueOnce('6ba7b810-9dad-11d1-80b4-00c04fd430c8.txt')
// A's post-recovery failure must retry again.
.mockRejectedValue(new Error('ENOENT'));

setDebugLogSession(uuidSession);
await vi.runAllTimersAsync();
const logger = createDebugLogger();
logger.info('A failure 2');
await vi.runAllTimersAsync();
logger.info('A failure 3');
await vi.runAllTimersAsync();
logger.info('A at cap — sticky');
await vi.runAllTimersAsync();
expect(fs.symlink).toHaveBeenCalledTimes(3);

// Session change: the capped streak must not block B's attempt.
sessionIdContext.run(otherSession, () => {
logger.info('B succeeds');
});
await vi.runAllTimersAsync();
expect(fs.symlink).toHaveBeenCalledTimes(4);

// B's success re-opened the breaker: A's next failure retries again.
logger.info('A fails after recovery');
await vi.runAllTimersAsync();
logger.info('A retries');
await vi.runAllTimersAsync();
expect(fs.symlink).toHaveBeenCalledTimes(6);

// Restore the factory defaults for later tests.
vi.mocked(fs.symlink).mockResolvedValue(undefined);
vi.mocked(fs.readlink).mockResolvedValue('');
});

it('does not let a stale failed update clear a newer session marker', async () => {
resetDebugLoggingState();
vi.clearAllMocks();
Expand Down
Loading