fix(extensions): the runtime harness no longer races a test-local 3 s startup deadline

docs/plans/2026-09-27-extension-runtime-harness-startup-deadline.md

@@ -0,0 +1,26 @@
+# The managed-runtime Electron check fails under load: a test-local 3 s startup deadline (#1334)
+
+## Problem
+`src/main/extensions/electron.system.test.ts` › "keeps one managed runtime across commands, view requests, updates and uninstall" failed once in a full local run under load, and passed alone. The failing run's error text was not captured.
+
+## Evidence (reproduced; the machine's own load plus parallel harness runs)
+- The test runs `scripts/check-extension-frames.mjs --runtime-only`. That bundles `src/main/extensions/testing/runtimeHarness.ts` and runs it in a hidden Electron app; alone it takes about 8.6 s, inside its 70 s budget.
+- 12 parallel runs, with a temporary probe that logged the cold-command results:
+  - **6 of 12 failed** at the first assertion, "bounded cold commands": `0 !== 32`.
+  - All 40 cold calls were rejected with `Extension runtime did not finish starting before the deadline.` (and `Too many extension calls are pending.`).
+  - The other 6 passed, logging 32 fulfilled.
+- **Cause.** The harness constructs `ExtensionRuntimeService` with `startupTimeoutMs: 3000`, a test-local tightening of the product default of 10 s (`runtimeService.ts`). (The `hung-engine` case does test a startup-deadline retirement; it now runs at the product's 10 s value, about 7 s slower.) Under load, a COLD Electron activation takes longer than 3 s, so the runtime is retired and every queued cold command is rejected.
+
+## Decision
+Drop the harness's `startupTimeoutMs` override so the harness uses the product's startup deadline. The 3 s value raced a cold Electron start in the bounded-cold case, where the deadline is not what is being tested. The deadline itself stays tested by `hung-engine`, at the product value.
+- `invocationTimeoutMs: 1500` stays, because the stalled-engine case needs an invocation deadline that fires quickly.
+- `until`'s 3 s poll budget was not observed failing in any run, so it is left as is.
+
+## Verification
+With the change, 24 of 24 parallel runs passed (two rounds of 12, load average about 40). Without it, 6 of 12 failed at the same load.
+
+## Review a
+- **A second load race.** The view case "close during an in-flight request" gated the request on an 80 ms sleep. Under 24-way load the sleep could end before the harness detached the view: 1 of 24 runs had a missing rejection. `slowIdentity` now waits for an explicit `releaseSlowIdentity` storage flag, which the harness sets only after the detach and the asserted rejection.
+- **The comment said no assertion tests the startup deadline.** Wrong: `hung-engine` does. The comment and plan are corrected.
+- **A third load race (found while verifying the second fix).** Under 24-way load, "updated startup runtime" timed out in 2 of 24 runs. That `until` wait includes a cold re-activation and had 3 s. `until` now takes a budget. The two waits that include an activation ("updated startup runtime", and "last command entered" after the stalled engine was destroyed) use `ACTIVATION_WAIT_MS`, which is the product's own startup deadline, now exported from `runtimeService.ts` as `EXTENSION_RUNTIME_STARTUP_TIMEOUT_MS`. Ordinary polls keep 3 s.
+- **Verification after review a:** 48 of 48 runs at 24-way parallel load (load average up to 103). `src/main/extensions`: 23 files, 346 tests. `npx tsc -b` clean.

src/main/extensions/runtimeService.ts

@@ -54,6 +54,11 @@ export type ExtensionRuntimeOptions = {
 // therefore cannot destroy extension-wide state. No extension receives the host
 // preload or a generic IPC channel: the dedicated runtime preload exposes only
 // this module's schema-validated, sender-bound transport.
+/** How long an extension runtime may take to finish starting before it is
+ *  retired. Exported so the Electron harness can bound its own activation
+ *  waits by the same value instead of racing a shorter one (#1334/#1436). */
+export const EXTENSION_RUNTIME_STARTUP_TIMEOUT_MS = 10_000
+
 export class ExtensionRuntimeService {
   private readonly runtimes = new Map<string, ManagedRuntime>()
   private readonly senders = new Map<number, ManagedRuntime>()
@@ -293,7 +298,7 @@ export class ExtensionRuntimeService {
       installation, revision, window, senderId: window.webContents.id, session: isolated,
       url: `agent-code-ext://${extensionId}/__bundle/${encodeURIComponent(revision)}/${RUNTIME_DOCUMENT}`,
       state: 'starting', ready, resolveReady, rejectReady,
-      startupTimer: setTimeout(() => this.retire(runtime, 'Extension runtime did not finish starting before the deadline.'), this.options.startupTimeoutMs ?? 10_000),
+      startupTimer: setTimeout(() => this.retire(runtime, 'Extension runtime did not finish starting before the deadline.'), this.options.startupTimeoutMs ?? EXTENSION_RUNTIME_STARTUP_TIMEOUT_MS),
       pending: new Map(), viewStates: new Map(), apiInFlight: 0, credits: 128, creditedAt: performance.now(),
     }
     this.runtimes.set(extensionId, runtime)

src/main/extensions/testing/runtimeHarness.ts

@@ -9,7 +9,7 @@ import { installExtensionFromPath } from '../install.js'
 import { removeExtension } from '../ledger.js'
 import { registerExtensionScheme } from '../scheme.js'
 import { extensionStorageGet } from '../storage.js'
-import { ExtensionRuntimeService } from '../runtimeService.js'
+import { EXTENSION_RUNTIME_STARTUP_TIMEOUT_MS, ExtensionRuntimeService } from '../runtimeService.js'
 import { ExtensionRuntimeViews } from '../runtimeViews.js'
 import { ExtensionCapabilityService, MAX_EXTENSION_TEXT_FILE_BYTES } from '../capabilityService.js'
 import { ExtensionServiceHost } from '../serviceHost.js'
@@ -41,8 +41,16 @@ function object(value: ExtensionJson | undefined): Record<string, ExtensionJson>
   return value
 }
 
-async function until(predicate: () => Promise<boolean>, label: string): Promise<void> {
-  const deadline = performance.now() + 3000
+// WHY two budgets (#1436 review a): an ordinary poll gets 3 s, but a wait
+// that includes a COLD activation (a reinstall, or reactivation after the
+// stalled engine was destroyed) cannot be given less time than the product
+// gives activation itself: under 24-way load "updated startup runtime" timed
+// out at 3 s in 2 of 24 runs while the product's deadline would have let it
+// finish. Those waits pass ACTIVATION_WAIT_MS, the product's own value.
+const ACTIVATION_WAIT_MS = EXTENSION_RUNTIME_STARTUP_TIMEOUT_MS
+
+async function until(predicate: () => Promise<boolean>, label: string, budgetMs = 3000): Promise<void> {
+  const deadline = performance.now() + budgetMs
   while (performance.now() < deadline) {
     if (await predicate()) return
     await new Promise(resolve => setTimeout(resolve, 20))
@@ -112,7 +120,17 @@ void (async () => {
     // keychain. Production wires createSafeStorageCodec (src/main/index.ts).
     secrets: createExtensionSecretStore({ isEncryptionAvailable: () => true, encrypt: value => Buffer.from(value, 'utf8'), decrypt: cipher => cipher.toString('utf8') }, harnessSecretsDirectory),
   })
-  const service = new ExtensionRuntimeService({ preload: process.env.AGENT_CODE_EXTENSION_RUNTIME_PRELOAD ?? join(root!, 'preload.cjs'), capabilities, startupTimeoutMs: 3000, invocationTimeoutMs: 1500, onStatus: status => statuses.push(status) })
+  // WHY no startupTimeoutMs override (#1334): the harness used to set 3000 ms,
+  // a test-local tightening of the product's 10 s default. Under load a COLD
+  // Electron activation takes longer than 3 s: in 12 parallel runs of this
+  // harness, 6 retired the runtime with "did not finish starting before the
+  // deadline", so all 40 cold commands were rejected and the bounded-cold
+  // assertion read 0 of 32. The startup deadline IS tested below (the
+  // `hung-engine` case never finishes activating and must be retired), now at
+  // the product's own 10 s value, which costs that case about 7 s more.
+  // invocationTimeoutMs stays short on purpose: the stalled-engine case needs
+  // an invocation deadline to fire quickly, and nothing cold races it.
+  const service = new ExtensionRuntimeService({ preload: process.env.AGENT_CODE_EXTENSION_RUNTIME_PRELOAD ?? join(root!, 'preload.cjs'), capabilities, invocationTimeoutMs: 1500, onStatus: status => statuses.push(status) })
 
   const viewEvents: Array<{ owner: number; event: RuntimeViewEvent }> = []
   const views = new ExtensionRuntimeViews(service, (owner, event) => viewEvents.push({ owner, event }))
@@ -127,7 +145,7 @@ void (async () => {
       id, name: id, description: 'Managed runtime integration fixture', version: String(generation), apiVersion: activationMode ? 2 : 1, entry: 'index.js',
       ...(activationMode ? { activationEvents: activationMode === 'startup' ? ['onStartupFinished'] : [`onCommand:${id}.increment`, `onCommand:${id}.read`, `onCommand:${id}.write`, `onView:${id}.main`] } : {}),
       ...(permissions.length ? { permissions } : {}),
-      contributes: { commands: ['increment', 'snapshot', 'fail', 'hang', 'arm', 'disarm', 'sandbox', 'navigate', 'read', 'write'].map(name => ({ id: `${id}.${name}`, title: name })),
+      contributes: { commands: ['increment', 'snapshot', 'fail', 'hang', 'arm', 'disarm', 'sandbox', 'navigate', 'read', 'write', 'releaseSlow'].map(name => ({ id: `${id}.${name}`, title: name })),
         views: [{ id: `${id}.main`, title: id, mount: 'panel', ...(activationMode ? { entry: 'view.js' } : {}) }] },
     }))
     if (activationMode) await writeFile(join(source, 'view.js'), 'export function mount() {}')
@@ -167,8 +185,13 @@ void (async () => {
         await ctx.api.storage.set('entered', ${generation});
         await new Promise(() => {});
       });
+      // Released by the harness only after it has detached the view (see the
+      // in-flight request case); engine memory, since main-side storage writes
+      // are not visible to a running extension's storage reads.
+      let slowReleased = false;
       ctx.registerRequest('identity', (_input, view) => view);
-      ctx.registerRequest('slowIdentity', async (_input, view) => { await ctx.api.storage.set('viewCalls', (await ctx.api.storage.get('viewCalls') || 0) + 1); await new Promise(resolve => setTimeout(resolve, 80)); return view; });
+      ctx.registerRequest('slowIdentity', async (_input, view) => { await ctx.api.storage.set('viewCalls', (await ctx.api.storage.get('viewCalls') || 0) + 1); while (!slowReleased) await new Promise(resolve => setTimeout(resolve, 10)); return view; });
+      ctx.registerCommand('${id}.releaseSlow', () => { slowReleased = true; });
       ctx.registerRequest('increment', async (amount, view) => {
         const next = count += amount;
         await publish();
@@ -232,7 +255,17 @@ void (async () => {
     await views.attach(22, 'view', 'engine', revision, 'engine.main')
     const running = views.request(22, 'view', 'slowIdentity', null)
     await until(async () => await extensionStorageGet('engine', 'viewCalls') === 1, 'view request entered')
+    // WHY a gate and not a sleep (#1436 review a): `slowIdentity` used to sleep
+    // 80 ms after entering. Under load that sleep could end before this
+    // continuation detached the view, so the request FULFILLED and the
+    // rejection below was missing (1 of 24 parallel runs). The handler now
+    // waits for an explicit release that is sent only AFTER the detach. The
+    // rejection is delivered when the handler's result comes back to a closed
+    // connection, so the release must come before awaiting it: detach, then
+    // release, then the rejection. The ordering the case checks is forced,
+    // not raced.
     views.detachOwner(22)
+    await command('releaseSlow')
     await assert.rejects(running, /connection is closed/)
     assert.equal(await extensionStorageGet('engine', 'viewCalls'), 1, 'an already dispatched request is never replayed')
     const abandoned = views.attach(44, 'race', 'engine', revision, 'engine.main')
@@ -285,7 +318,7 @@ void (async () => {
     console.log('PASS runtime: invocation deadline destroys the stalled engine and never replays the action')
 
     const removed = command('hang').then(() => 'unexpected success', error => String(error))
-    await until(async () => await extensionStorageGet('engine', 'runs') === 3, 'last command entered')
+    await until(async () => await extensionStorageGet('engine', 'runs') === 3, 'last command entered', ACTIVATION_WAIT_MS)
     await removeExtension('engine')
     assert.match(await removed, /updated or removed/)
     await assert.rejects(service.start('engine', revision), /no longer active/)
@@ -310,7 +343,7 @@ void (async () => {
     await service.activateStartupExtensions()
     assert.equal(await extensionStorageGet('startup-engine', 'activations'), 1, 'startup reconciliation must not activate a live engine twice')
     await install(2, 'startup-engine', undefined, '', 'startup')
-    await until(async () => await extensionStorageGet('startup-engine', 'activations') === 2, 'updated startup runtime')
+    await until(async () => await extensionStorageGet('startup-engine', 'activations') === 2, 'updated startup runtime', ACTIVATION_WAIT_MS)
     await assert.rejects(service.start('startup-engine', extensionRevision(startup)), /no longer active/)
     await removeExtension('startup-engine')
     await removeExtension('lazy-engine')