diff --git a/packages/cli/src/services/housekeeping/scheduler.ts b/packages/cli/src/services/housekeeping/scheduler.ts index a4a86a9b0b2..4e389cb7f7c 100644 --- a/packages/cli/src/services/housekeeping/scheduler.ts +++ b/packages/cli/src/services/housekeeping/scheduler.ts @@ -272,49 +272,57 @@ async function drainNonInteractiveQueue(): Promise { 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; + } } } diff --git a/packages/core/src/config/config.test.ts b/packages/core/src/config/config.test.ts index b3928c65999..5d9023386d7 100644 --- a/packages/core/src/config/config.test.ts +++ b/packages/core/src/config/config.test.ts @@ -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, + ): Promise { 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, @@ -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', () => { diff --git a/packages/core/src/utils/debugLogger.test.ts b/packages/core/src/utils/debugLogger.test.ts index 8a68fef0ed4..7779b1f0ada 100644 --- a/packages/core/src/utils/debugLogger.test.ts +++ b/packages/core/src/utils/debugLogger.test.ts @@ -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();