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
2026-11-02 18:17:36 +00:00 · 2026-10-29 22:50:41 -07:00
parent 0b2158a394
commit 593e1dbc60
5 changed files with 155 additions and 24 deletions
@@ -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 : ''
@@ -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<string> {
@@ -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<void> } = {}
 ): {
  stopped: Promise<void>
  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<typeof setTimeout> =>
+    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)
@@ -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
+  )
+}
@@ -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)
+  })
+})
@@ -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.