Fix: endSub has no timeout on readDone, unlike closeSub (#17)

src/recorder.ts

@@ -86,6 +86,31 @@ function appendCapped(entry: PendingExecution, chunk: string): void {
   entry.truncated = true;
 }
 
+/**
+ * Resolves once `promise` settles, or after `timeoutMs` elapses, whichever
+ * comes first - swallowing a rejection either way, since callers only care
+ * that the wait ended, not why. Used to bound the wait on `entry.readDone`
+ * before finalizing a record: `read()` may never finish (e.g. a
+ * backgrounded/detached child process keeping the terminal's output stream
+ * open after the shell reports the command ended, or a terminal that's gone
+ * by the time its stream is read), and a record that arrives with slightly
+ * clipped output beats one that never arrives at all.
+ *
+ * Exported for tests: forcing a genuine TerminalShellExecution.read() to
+ * hang isn't something this test harness can do from outside VS Code's own
+ * shell integration implementation, so the bounded-wait behavior itself is
+ * regression-tested directly here instead.
+ */
+export function waitAtMost(promise: Promise<unknown>, timeoutMs: number): Promise<void> {
+  return Promise.race([
+    promise.then(
+      () => undefined,
+      () => undefined
+    ),
+    new Promise<void>((resolve) => setTimeout(resolve, timeoutMs)),
+  ]);
+}
+
 /**
  * Appends one of TruthLog's own diagnostic notes (e.g. "terminal closed
  * before this command finished") unconditionally, bypassing the maxBytes cap
@@ -153,7 +178,11 @@ export function createRecorder(callbacks: RecorderCallbacks): vscode.Disposable[
         if (entry) {
           // The END event can fire slightly before the read() async
           // iterable finishes draining; wait for it so output isn't cut off.
-          await entry.readDone.catch(() => undefined);
+          // Bounded, like closeSub's wait below, for the same reason: the
+          // shell has already given us a real exit code here, so there is no
+          // excuse for a slow-to-drain (or stuck) read() to make this row
+          // never appear at all.
+          await waitAtMost(entry.readDone, 1000);
         }
 
         const execution: Execution = {

src/test/suite/checklist.test.ts

@@ -2,6 +2,7 @@ import * as assert from 'assert';
 import * as path from 'path';
 import * as vscode from 'vscode';
 import type { TruthLogTestApi } from '../../extension';
+import type { Execution } from '../../types';
 
 const FAILING_TEST_FIXTURE = path.resolve(__dirname, '..', 'fixtures', 'failing.test.js');
 
@@ -27,21 +28,43 @@ async function waitForShellIntegration(
   });
 }
 
-async function runAndGetEnd(
-  terminal: vscode.Terminal,
+/**
+ * Runs a command and waits for TruthLog's store to actually record it,
+ * rather than for the raw onDidEndTerminalShellExecution event.
+ *
+ * Those are not the same moment: recorder.ts's END handler still has to
+ * finish waiting on entry.readDone (bounded, but not zero) before it calls
+ * store.add(), and this suite's own listener for the raw event is registered
+ * after recorder.ts's, so it always resolves first regardless. Checking
+ * api.store.getAll() immediately after the raw event resolves was a latent
+ * race this file had from the start; it happened to resolve in the store's
+ * favor often enough not to notice until the bounded-wait timing changed
+ * enough to expose it consistently. Every assertion below now reads from the
+ * recorded Execution (which carries exitCode itself) instead of a
+ * separately-captured end event.
+ */
+async function runAndWaitForRecord(
+  store: TruthLogTestApi['store'],
   shellIntegration: vscode.TerminalShellIntegration,
-  commandLine: string
-): Promise<vscode.TerminalShellExecutionEndEvent> {
-  const endEventPromise = new Promise<vscode.TerminalShellExecutionEndEvent>((resolve) => {
-    const disposable = vscode.window.onDidEndTerminalShellExecution((e) => {
-      if (e.terminal === terminal) {
+  commandLine: string,
+  timeoutMs = 30000
+): Promise<Execution> {
+  const recorded = new Promise<Execution>((resolve, reject) => {
+    const timeout = setTimeout(() => {
+      disposable.dispose();
+      reject(new Error(`timed out waiting for store to record: ${commandLine}`));
+    }, timeoutMs);
+    const disposable = store.onDidChange(() => {
+      const top = store.getAll()[0];
+      if (top && top.command === commandLine) {
+        clearTimeout(timeout);
         disposable.dispose();
-        resolve(e);
+        resolve(top);
       }
     });
   });
   shellIntegration.executeCommand(commandLine);
-  return endEventPromise;
+  return recorded;
 }
 
 describe('VERIFICATION CHECKLIST', function () {
@@ -64,50 +87,48 @@ describe('VERIFICATION CHECKLIST', function () {
   });
 
   it('echo hello -> exit 0', async () => {
-    const end = await runAndGetEnd(terminal, shellIntegration, 'echo hello');
-    console.log('RAW echo hello exitCode:', end.exitCode);
-    assert.strictEqual(end.exitCode, 0);
+    const recorded = await runAndWaitForRecord(api.store, shellIntegration, 'echo hello');
+    console.log('RAW echo hello exitCode:', recorded.exitCode);
+    assert.strictEqual(recorded.exitCode, 0);
   });
 
   it('node -e "process.exit(1)" -> exit 1', async () => {
-    const end = await runAndGetEnd(terminal, shellIntegration, 'node -e "process.exit(1)"');
-    console.log('RAW process.exit(1) exitCode:', end.exitCode);
-    assert.strictEqual(end.exitCode, 1);
+    const recorded = await runAndWaitForRecord(
+      api.store,
+      shellIntegration,
+      'node -e "process.exit(1)"'
+    );
+    console.log('RAW process.exit(1) exitCode:', recorded.exitCode);
+    assert.strictEqual(recorded.exitCode, 1);
   });
 
   it('a real failing test suite -> non-zero exit, output contains failure text', async () => {
     // node's built-in test runner, no extra dependency needed.
-    const end = await runAndGetEnd(
-      terminal,
+    const recorded = await runAndWaitForRecord(
+      api.store,
       shellIntegration,
       `node --test "${FAILING_TEST_FIXTURE}"`
     );
-    console.log('RAW failing test suite exitCode:', end.exitCode);
-    assert.notStrictEqual(end.exitCode, 0);
-
-    const recorded = api.store.getAll().find((e) => e.command.includes('--test'));
-    assert.ok(recorded, 'expected the failing test-suite run to be recorded');
-    console.log('RAW failing test suite output snippet:', recorded!.output.slice(0, 500));
+    console.log('RAW failing test suite exitCode:', recorded.exitCode);
+    assert.notStrictEqual(recorded.exitCode, 0);
+    console.log('RAW failing test suite output snippet:', recorded.output.slice(0, 500));
     assert.ok(
-      /fail/i.test(recorded!.output),
+      /fail/i.test(recorded.output),
       'expected captured output to contain failure text from the test runner'
     );
   });
 
   it('a long-running command -> duration recorded correctly', async function () {
     this.timeout(15000);
-    const before = Date.now();
-    const end = await runAndGetEnd(terminal, shellIntegration, 'node -e "setTimeout(() => process.exit(0), 3000)"');
-    const wallClockMs = Date.now() - before;
-    console.log('RAW long-running exitCode:', end.exitCode, 'wall clock ms:', wallClockMs);
-    assert.strictEqual(end.exitCode, 0);
-    // wall clock around the test itself should be at least ~3s; the actual
-    // per-execution duration is verified against store timestamps below.
-
-    const recorded = api.store.getAll().find((e) => e.command.includes('setTimeout'));
-    assert.ok(recorded, 'expected the long-running command to be recorded');
-    assert.ok(recorded!.endedAt !== undefined);
-    const durationMs = recorded!.endedAt! - recorded!.startedAt;
+    const recorded = await runAndWaitForRecord(
+      api.store,
+      shellIntegration,
+      'node -e "setTimeout(() => process.exit(0), 3000)"'
+    );
+    console.log('RAW long-running exitCode:', recorded.exitCode);
+    assert.strictEqual(recorded.exitCode, 0);
+    assert.ok(recorded.endedAt !== undefined);
+    const durationMs = recorded.endedAt! - recorded.startedAt;
     console.log('RAW recorded duration ms:', durationMs);
     assert.ok(durationMs >= 2500, `expected recorded duration >= ~3000ms, got ${durationMs}`);
   });
@@ -118,25 +139,21 @@ describe('VERIFICATION CHECKLIST', function () {
     const configuredMax = config.get<number>('maxOutputBytes', 102400);
     assert.strictEqual(configuredMax, 102400, 'this test assumes the default maxOutputBytes');
 
-    const end = await runAndGetEnd(
-      terminal,
+    const recorded = await runAndWaitForRecord(
+      api.store,
       shellIntegration,
       `node -e "process.stdout.write('y'.repeat(150000))"`
     );
-    console.log('RAW >100KB command exitCode:', end.exitCode);
-    assert.strictEqual(end.exitCode, 0);
-
-    const recorded = api.store.getAll().find((e) => e.command.includes("'y'.repeat"));
-    assert.ok(recorded, 'expected the large-output command to be recorded (no crash)');
-    const byteLength = Buffer.byteLength(recorded!.output, 'utf8');
-    console.log('RAW recorded output byteLength:', byteLength, 'truncated:', recorded!.truncated);
-    assert.ok(recorded!.truncated, 'expected truncated flag to be set');
+    console.log('RAW >100KB command exitCode:', recorded.exitCode);
+    assert.strictEqual(recorded.exitCode, 0);
+    const byteLength = Buffer.byteLength(recorded.output, 'utf8');
+    console.log('RAW recorded output byteLength:', byteLength, 'truncated:', recorded.truncated);
+    assert.ok(recorded.truncated, 'expected truncated flag to be set');
     assert.ok(byteLength <= 102400, `expected output capped at 102400 bytes, got ${byteLength}`);
   });
 
   it('reload window -> history persists (simulated via fresh store against same workspaceState)', async () => {
-    const end = await runAndGetEnd(terminal, shellIntegration, 'echo reload-check');
-    void end;
+    await runAndWaitForRecord(api.store, shellIntegration, 'echo reload-check');
     const before = api.store.getAll().length;
     const raw = api.context.workspaceState.get<unknown[]>('truthlog.executions');
     console.log('RAW workspaceState entry count before reload:', raw?.length);

src/test/suite/endSubTimeout.test.ts

@@ -0,0 +1,55 @@
+import * as assert from 'assert';
+import { waitAtMost } from '../../recorder';
+
+/**
+ * Regression tests for the bug where endSub awaited entry.readDone with no
+ * timeout, unlike closeSub's already-bounded wait. A command whose output
+ * stream doesn't resolve promptly after the shell reports it finished (e.g.
+ * a backgrounded/detached child process keeping the terminal's stream open)
+ * would make endSub's handler hang forever, so the command never got
+ * recorded despite the shell having already reported a real exit code.
+ *
+ * waitAtMost is the extracted bounded-wait mechanism both endSub and
+ * closeSub now rely on. Forcing a genuine TerminalShellExecution.read() to
+ * hang isn't something this test harness can do from outside VS Code's own
+ * shell integration implementation, so these tests exercise the mechanism
+ * directly instead: a promise that never settles is the exact shape of a
+ * stuck read() drain, and proving waitAtMost doesn't hang on one proves
+ * endSub can't hang on one either.
+ */
+describe('waitAtMost (the bounded wait behind endSub and closeSub)', () => {
+  it('resolves promptly when the promise settles well before the timeout', async () => {
+    const start = Date.now();
+    await waitAtMost(Promise.resolve('done'), 5000);
+    const elapsed = Date.now() - start;
+    assert.ok(elapsed < 1000, `expected an already-settled promise to resolve fast, took ${elapsed}ms`);
+  });
+
+  it('resolves promptly when the promise rejects well before the timeout', async () => {
+    const start = Date.now();
+    await waitAtMost(Promise.reject(new Error('read failed')), 5000);
+    const elapsed = Date.now() - start;
+    assert.ok(elapsed < 1000, `expected a rejected promise to resolve fast (not throw), took ${elapsed}ms`);
+  });
+
+  it('does not hang forever on a promise that never settles - this is the regression case', async () => {
+    const neverSettles = new Promise<void>(() => undefined);
+    const start = Date.now();
+    await waitAtMost(neverSettles, 300);
+    const elapsed = Date.now() - start;
+    console.log('RAW elapsed waiting on a never-settling promise (timeoutMs=300):', elapsed);
+
+    assert.ok(
+      elapsed < 1000,
+      `waitAtMost must return once the timeout elapses instead of hanging forever, took ${elapsed}ms`
+    );
+    assert.ok(
+      elapsed >= 300,
+      `waitAtMost must not return before the timeout when the promise hasn't settled, took ${elapsed}ms`
+    );
+  });
+
+  it('never throws or rejects, even when racing a rejecting promise against the timeout', async () => {
+    await assert.doesNotReject(() => waitAtMost(Promise.reject(new Error('boom')), 50));
+  });
+});