Merge pull request 'fix(test): decide base-path rejection from the server startup line (#93)' (#94) from timmy/93-deterministic-basepath-gate into main

tests/staging-health.test.js

@@ -2,38 +2,77 @@ import test from 'node:test';
 import assert from 'node:assert/strict';
 import { spawn } from 'node:child_process';
 import { chmod, mkdtemp, rm } from 'node:fs/promises';
+import { createServer } from 'node:net';
 import { tmpdir } from 'node:os';
 import { join } from 'node:path';
 import { fileURLToPath } from 'node:url';
 
 const root = fileURLToPath(new URL('..', import.meta.url));
 const hermesFixture = fileURLToPath(new URL('./fixtures/fake-hermes.mjs', import.meta.url));
-let nextPort = 43100;
+
+// A hard-coded base port is not ours to take: 43100 sits inside this host's ephemeral range
+// (32768-60999), so the kernel can already have handed it to an unrelated outbound socket
+// (a Caddy -> Gitea connection held 43102) and the spawn dies with EADDRINUSE before any
+// assertion runs. Ask the kernel for a free port, then retry if one is stolen in the gap.
+function freePort() {
+  return new Promise((resolve, reject) => {
+    const probe = createServer();
+    probe.once('error', reject);
+    probe.listen(0, '127.0.0.1', () => {
+      const { port } = probe.address();
+      probe.close(() => resolve(port));
+    });
+  });
+}
+
+function waitForListening(child, readStdout, timeoutMs = 20_000) {
+  return new Promise(resolve => {
+    let settled = false;
+    const finish = value => {
+      if (settled) return;
+      settled = true;
+      clearTimeout(timer);
+      resolve(value);
+    };
+    const timer = setTimeout(() => finish({ state: 'timeout' }), timeoutMs);
+    child.stdout.on('data', () => {
+      if (/^Timmy is listening on http:\/\//m.test(readStdout())) finish({ state: 'listening' });
+    });
+    child.once('exit', code => finish({ state: 'exit', code }));
+  });
+}
 
 async function startServer(t, env = {}) {
-  const port = nextPort++;
-  const origin = `http://127.0.0.1:${port}`;
-  const child = spawn(process.execPath, ['server.mjs'], {
-    cwd: root,
-    env: { ...process.env, PORT: String(port), ...env, ...(env.TIMMY_PUBLIC_ORIGIN === '__ORIGIN__' ? { TIMMY_PUBLIC_ORIGIN: origin } : {}) },
-    stdio: ['ignore', 'pipe', 'pipe'],
-  });
-  let stderr = '';
-  let stdout = '';
-  child.stdout.on('data', chunk => { stdout += chunk; });
-  child.stderr.on('data', chunk => { stderr += chunk; });
-  t.after(() => child.kill('SIGTERM'));
-  const deadline = Date.now() + 10_000;
-  const basePath = (env.TIMMY_BASE_PATH || '').replace(/\/$/, '');
-  while (Date.now() < deadline) {
-    if (child.exitCode !== null) throw new Error(`server exited ${child.exitCode}: ${stderr}`);
-    try {
-      const response = await fetch(`${origin}${basePath}/api/healthz`);
-      if (response.status) return { origin, child, getStdout: () => stdout };
-    } catch {}
-    await new Promise(resolve => setTimeout(resolve, 40));
+  for (let attempt = 1; attempt <= 4; attempt++) {
+    const port = await freePort();
+    const origin = `http://127.0.0.1:${port}`;
+    const child = spawn(process.execPath, ['server.mjs'], {
+      cwd: root,
+      env: { ...process.env, PORT: String(port), ...env, ...(env.TIMMY_PUBLIC_ORIGIN === '__ORIGIN__' ? { TIMMY_PUBLIC_ORIGIN: origin } : {}) },
+      stdio: ['ignore', 'pipe', 'pipe'],
+    });
+    let stderr = '';
+    let stdout = '';
+    child.stdout.on('data', chunk => { stdout += chunk; });
+    child.stderr.on('data', chunk => { stderr += chunk; });
+
+    const outcome = await waitForListening(child, () => stdout);
+    if (outcome.state === 'listening') {
+      t.after(() => child.kill('SIGTERM'));
+      return { origin, child, getStdout: () => stdout };
+    }
+
+    const closed = new Promise(resolve => child.once('close', resolve));
+    if (child.exitCode === null) child.kill('SIGKILL');
+    await closed;
+
+    const stolen = /EADDRINUSE/.test(stderr);
+    if (!stolen || attempt === 4) {
+      throw new Error(outcome.state === 'timeout'
+        ? `server did not announce listening: ${stderr}`
+        : `server exited ${outcome.code}${stolen ? ' (port stolen again)' : ''}: ${stderr}`);
+    }
   }
-  throw new Error(`server did not become ready: ${stderr}`);
 }
 
 test('staging host can bind loopback instead of every network interface', async t => {
@@ -125,6 +164,30 @@ test('agent cookie is constrained to the normalized base path', async t => {
   assert.match(response.headers.get('set-cookie'), /; Path=\/timmy-staging\//);
 });
 
+// The child's own startup line is the only trustworthy evidence that a base path was accepted.
+// A fixed timer cannot tell "still importing modules" from "server is up": on a loaded host the
+// old 800 ms race killed a correctly-rejecting child and reported it as accepted.
+function startupOutcome(child, deadlineMs = 20_000) {
+  return new Promise(resolve => {
+    let stdout = '';
+    let stderr = '';
+    let settled = false;
+    const finish = outcome => {
+      if (settled) return;
+      settled = true;
+      clearTimeout(timer);
+      resolve({ ...outcome, stdout, stderr });
+    };
+    const timer = setTimeout(() => finish({ timedOut: true }), deadlineMs);
+    child.stdout.on('data', chunk => {
+      stdout += chunk;
+      if (/^Timmy is listening on http:\/\//m.test(stdout)) finish({ listening: true });
+    });
+    child.stderr.on('data', chunk => { stderr += chunk; });
+    child.once('exit', code => finish({ code }));
+  });
+}
+
 test('malformed and escaping base paths are rejected at startup', async () => {
   const invalid = [
     'timmy-staging',
@@ -152,16 +215,17 @@ test('malformed and escaping base paths are rejected at startup', async () => {
     const child = spawn(process.execPath, ['server.mjs'], {
       cwd: root,
       env: { ...process.env, PORT: '0', TIMMY_BASE_PATH: value },
-      stdio: ['ignore', 'ignore', 'pipe'],
+      stdio: ['ignore', 'pipe', 'pipe'],
     });
-    let stderr = '';
-    child.stderr.on('data', chunk => { stderr += chunk; });
-    const exitCode = await Promise.race([
-      new Promise(resolve => child.once('exit', resolve)),
-      new Promise(resolve => setTimeout(() => { child.kill('SIGTERM'); resolve('timeout'); }, 800)),
-    ]);
-    assert.notEqual(exitCode, 'timeout', `${JSON.stringify(value)} was accepted`);
-    assert.notEqual(exitCode, 0, `${JSON.stringify(value)} exited successfully`);
-    assert.match(stderr, /TIMMY_BASE_PATH/);
+    const outcome = await startupOutcome(child);
+    if (outcome.listening) {
+      const closed = new Promise(resolve => child.once('close', resolve));
+      child.kill('SIGKILL');
+      await closed;
+    }
+    assert.equal(outcome.listening, undefined, `${JSON.stringify(value)} was accepted: the server announced it was listening`);
+    assert.notEqual(outcome.timedOut, true, `${JSON.stringify(value)} neither exited nor announced listening within the startup deadline`);
+    assert.notEqual(outcome.code, 0, `${JSON.stringify(value)} exited successfully`);
+    assert.match(outcome.stderr, /TIMMY_BASE_PATH/);
   }
 });