From 593e1dbc60ab61eedc2ad86ed9e253ffe07c1781 Mon Sep 17 00:00:00 2001 From: Neil <4138956+nwparker@users.noreply.github.com> Date: Thu, 29 Oct 2026 22:50:41 -0700 Subject: [PATCH] test(e2e): retry a WSL terminate that never took, once, when Orca launched nothing (#36256) * test(e2e): retry a WSL terminate that never took, once, when Orca launched nothing * test(e2e): log PTY spawns for the E9 guard and refuse the terminate retry after one --- tests/e2e/helpers/wsl-boot-diagnostics-log.ts | 12 ++++ tests/e2e/helpers/wsl-boot-guard.ts | 71 +++++++++++++------ tests/e2e/helpers/wsl-terminate-retry.ts | 35 +++++++++ .../helpers/wsl-terminate-retry.unit.test.ts | 53 ++++++++++++++ .../e2e/wsl-bridge-no-background-boot.spec.ts | 8 ++- 5 files changed, 155 insertions(+), 24 deletions(-) create mode 100644 tests/e2e/helpers/wsl-terminate-retry.ts create mode 100644 tests/e2e/helpers/wsl-terminate-retry.unit.test.ts diff --git a/tests/e2e/helpers/wsl-boot-diagnostics-log.ts b/tests/e2e/helpers/wsl-boot-diagnostics-log.ts index 1b39e727078..989187ef982 100644 --- a/tests/e2e/helpers/wsl-boot-diagnostics-log.ts +++ b/tests/e2e/helpers/wsl-boot-diagnostics-log.ts @@ -11,6 +11,8 @@ import type { ElectronApplication } from '@stablyai/playwright-test' export type DiagnosticRecord = { file: string; args: string[]; at?: number; stack?: string[] } export const UNC_TOUCH = 'fs' +/** A terminal spawn: node-pty launches outside main's child_process, so main's per-spawn history log line stands in. */ +export const PTY_SPAWN = 'pty' /** * Logs main's direct child_process spawns (spawn, exec and execFile all pass through @@ -59,6 +61,16 @@ export async function recordMainProcessWslDiagnostics( logged.orcaE9SpawnLog = true proto.spawn = logged + // Every daemon or local PTY spawn with a worktree logs this line first (logHistoryInjection). + const originalLog = console.log + console.log = function (this: unknown, ...args: unknown[]) { + if (typeof args[0] === 'string' && args[0].startsWith('[pty:history] ')) { + // Keep in sync with PTY_SPAWN; evaluate cannot see module constants. + append('pty', [args[0]]) + } + return originalLog.apply(this, args) + } + const isWslUnc = (value: unknown): boolean => /^([\\/]{2})(wsl\.localhost|wsl\$)[\\/]/i.test( typeof value === 'string' ? value : value instanceof URL ? value.pathname : '' diff --git a/tests/e2e/helpers/wsl-boot-guard.ts b/tests/e2e/helpers/wsl-boot-guard.ts index a52dea65703..18746907b9e 100644 --- a/tests/e2e/helpers/wsl-boot-guard.ts +++ b/tests/e2e/helpers/wsl-boot-guard.ts @@ -6,9 +6,13 @@ import { execFile } from 'node:child_process' import type { Page } from '@stablyai/playwright-test' import { expect } from './orca-app' import { buildWslExecArgs } from '../../../src/shared/wsl-login-shell-command' -import { readDiagnosticLog, UNC_TOUCH, type DiagnosticRecord } from './wsl-boot-diagnostics-log' - -const WSL_EXE = /(^|[\\/])wsl(\.exe)?$/i +import { + PTY_SPAWN, + readDiagnosticLog, + UNC_TOUCH, + type DiagnosticRecord +} from './wsl-boot-diagnostics-log' +import { orcaWslLaunches, shouldRetryTerminate, WSL_EXE } from './wsl-terminate-retry' /** Async with a timeout: a hung wsl.exe must fail the test, never block the worker past its timeout. */ export function wsl(args: readonly string[], timeoutMs = 60_000): Promise { @@ -79,11 +83,13 @@ const TERMINATE_GRACE_MS = 10_000 * Polls the running list once a second, never overlapping, from right after `--terminate`. * `stopped` resolves on the first not-running read, which must come within the grace; only * running reads before it are forgiven, so a real boot is never waited out. Any running read - * after it is a boot. Three failed reads in a row fail the guard. + * after it is a boot. Three failed reads in a row fail the guard. With `retryTerminate`, a terminate + * that never took is re-issued once, and only while Orca has launched nothing since `spawnsBefore`. */ export function watchDistroRunning( distro: string, - spawnLog: string + spawnLog: string, + options: { spawnsBefore?: number; retryTerminate?: () => Promise } = {} ): { stopped: Promise stop: () => Promise<{ seenRunning: boolean; reads: number }> @@ -102,28 +108,30 @@ export function watchDistroRunning( resolveStopped = resolve rejectStopped = reject }) - const grace = setTimeout( - () => - rejectStopped( - new Error(`${distro} was still listed ${TERMINATE_GRACE_MS} ms after --terminate`) - ), - TERMINATE_GRACE_MS - ) + const watchStartedAt = Date.now() + let retried = false + const armGrace = (): ReturnType => + setTimeout( + () => + rejectStopped( + new Error( + `${distro} was still listed ${TERMINATE_GRACE_MS} ms after --terminate${retried ? ' (retried once)' : ''}` + ) + ), + TERMINATE_GRACE_MS + ) + let grace = armGrace() // Spawns are interleaved into the timeline so a boot can be matched to the launch before it. let spawnsSeen = readDiagnosticLog(spawnLog).length const logNewWslSpawns = (): void => { const spawns = readDiagnosticLog(spawnLog) - for (const spawn of spawns.slice(spawnsSeen)) { - if (WSL_EXE.test(spawn.file) || spawn.file === UNC_TOUCH) { - // `at` is when it happened; the line prints at this poll, up to a second later. - timeline( - `${spawn.file === UNC_TOUCH ? 'unc' : 'spawn'} ${spawn.file} ${spawn.args.join(' ')}`, - spawn.at - ) - if (startsDistro(spawn, distro) || spawn.file === UNC_TOUCH) { - for (const frame of spawn.stack ?? []) { - timeline(` ${frame}`, spawn.at) - } + for (const spawn of orcaWslLaunches(spawns.slice(spawnsSeen))) { + const kind = spawn.file === UNC_TOUCH ? 'unc' : spawn.file === PTY_SPAWN ? 'pty' : 'spawn' + // `at` is when it happened; the line prints at this poll, up to a second later. + timeline(`${kind} ${spawn.file} ${spawn.args.join(' ')}`, spawn.at) + if (kind !== 'spawn' || startsDistro(spawn, distro)) { + for (const frame of spawn.stack ?? []) { + timeline(` ${frame}`, spawn.at) } } } @@ -138,6 +146,23 @@ export function watchDistroRunning( timeline(`running list: ${distro} ${running ? 'RUNNING' : 'stopped'}`) if (confirmedStopped) { seenRunning ||= running + } else if ( + running && + options.retryTerminate && + shouldRetryTerminate({ + retried, + confirmedStopped, + msSinceTerminate: Date.now() - watchStartedAt, + spawnsSinceTerminate: readDiagnosticLog(spawnLog).slice(options.spawnsBefore ?? 0) + }) + ) { + retried = true + // Loud on purpose: a pattern of these is a runner problem worth chasing. + timeline(`RETRYING --terminate: ${distro} still listed and Orca launched nothing since`) + console.warn(`[e9-guard] WARNING: --terminate of ${distro} did not take; retrying once`) + clearTimeout(grace) + grace = armGrace() + return options.retryTerminate() } else if (!running) { confirmedStopped = true clearTimeout(grace) diff --git a/tests/e2e/helpers/wsl-terminate-retry.ts b/tests/e2e/helpers/wsl-terminate-retry.ts new file mode 100644 index 00000000000..7f8053be24d --- /dev/null +++ b/tests/e2e/helpers/wsl-terminate-retry.ts @@ -0,0 +1,35 @@ +/** + * When the E9 guard may re-issue `wsl --terminate`: a runner's terminate can fail to take, leaving + * the distro listed with nothing from Orca launched since. Retrying then is safe; retrying after + * any Orca wsl.exe launch, terminal spawn or UNC touch could hide the very boot the guard exists to catch. + */ +import { PTY_SPAWN, UNC_TOUCH, type DiagnosticRecord } from './wsl-boot-diagnostics-log' + +export const WSL_EXE = /(^|[\\/])wsl(\.exe)?$/i + +/** A first terminate gets this long to show before it counts as not having taken. */ +export const TERMINATE_RETRY_AFTER_MS = 2_000 + +export type TerminateRetryState = { + retried: boolean + confirmedStopped: boolean + msSinceTerminate: number + /** Orca's spawn-log records since just before the first terminate. */ + spawnsSinceTerminate: readonly DiagnosticRecord[] +} + +export function orcaWslLaunches(spawns: readonly DiagnosticRecord[]): DiagnosticRecord[] { + return spawns.filter( + (spawn) => WSL_EXE.test(spawn.file) || spawn.file === UNC_TOUCH || spawn.file === PTY_SPAWN + ) +} + +/** One retry only, only while still listed, only once the first had time, only if Orca launched nothing. */ +export function shouldRetryTerminate(state: TerminateRetryState): boolean { + return ( + !state.retried && + !state.confirmedStopped && + state.msSinceTerminate >= TERMINATE_RETRY_AFTER_MS && + orcaWslLaunches(state.spawnsSinceTerminate).length === 0 + ) +} diff --git a/tests/e2e/helpers/wsl-terminate-retry.unit.test.ts b/tests/e2e/helpers/wsl-terminate-retry.unit.test.ts new file mode 100644 index 00000000000..a7767206052 --- /dev/null +++ b/tests/e2e/helpers/wsl-terminate-retry.unit.test.ts @@ -0,0 +1,53 @@ +import { describe, expect, it } from 'vitest' +import { shouldRetryTerminate, TERMINATE_RETRY_AFTER_MS } from './wsl-terminate-retry' + +const stillListed = { + retried: false, + confirmedStopped: false, + msSinceTerminate: TERMINATE_RETRY_AFTER_MS, + spawnsSinceTerminate: [] +} + +describe('shouldRetryTerminate', () => { + it('retries a terminate that never took when Orca launched nothing since', () => { + expect(shouldRetryTerminate(stillListed)).toBe(true) + }) + + it.each([ + [ + 'a wsl.exe launch', + { file: 'C:\\Windows\\System32\\wsl.exe', args: ['-d', 'Ubuntu', '--exec', 'sh'] } + ], + ['a running-list read', { file: 'wsl.exe', args: ['--list', '--running', '--quiet'] }], + ['a UNC touch', { file: 'fs', args: ['stat', '\\\\wsl.localhost\\Ubuntu\\tmp'] }], + [ + 'a terminal spawn', + { file: 'pty', args: ['[pty:history] worktreeId=wt::\\\\wsl.localhost\\Ubuntu shell=bash'] } + ] + ])('fails instead of retrying after %s, which could be the boot', (_label, spawn) => { + expect(shouldRetryTerminate({ ...stillListed, spawnsSinceTerminate: [spawn] })).toBe(false) + }) + + it('ignores spawns that cannot touch WSL', () => { + expect( + shouldRetryTerminate({ + ...stillListed, + spawnsSinceTerminate: [{ file: 'git.exe', args: ['status'] }] + }) + ).toBe(true) + }) + + it('retries at most once', () => { + expect(shouldRetryTerminate({ ...stillListed, retried: true })).toBe(false) + }) + + it('gives the first terminate time to show before retrying', () => { + expect( + shouldRetryTerminate({ ...stillListed, msSinceTerminate: TERMINATE_RETRY_AFTER_MS - 1 }) + ).toBe(false) + }) + + it('never retries once a read saw the distro stopped', () => { + expect(shouldRetryTerminate({ ...stillListed, confirmedStopped: true })).toBe(false) + }) +}) diff --git a/tests/e2e/wsl-bridge-no-background-boot.spec.ts b/tests/e2e/wsl-bridge-no-background-boot.spec.ts index c34588751d3..8ea61ab7d29 100644 --- a/tests/e2e/wsl-bridge-no-background-boot.spec.ts +++ b/tests/e2e/wsl-bridge-no-background-boot.spec.ts @@ -114,7 +114,13 @@ async function expectNothingStartsTheStoppedDistro( await wsl(['--terminate', DISTRO], 30_000) timeline('terminated') // WSL1 instances can live only seconds, so watch the running list from the terminate on. - const watcher = watchDistroRunning(DISTRO, SPAWN_LOG) + const watcher = watchDistroRunning(DISTRO, SPAWN_LOG, { + spawnsBefore, + retryTerminate: async () => { + await wsl(['--terminate', DISTRO], 30_000) + timeline('terminated (retry)') + } + }) let watched: { seenRunning: boolean; reads: number } | undefined try { // The window starts only once a read has seen it stopped, within the grace.