Merge pull request #65 from fiddlerwoaroof/fix/socket-close-routing

fix(harness): restore the watchdog close-routing guard PR #61 deleted

context/code/clients.md

@@ -1189,9 +1189,50 @@ it about", and the browser half has four:
 |---|---|---|
 | `RenderModel` → DOM | every field the render model projects reaches an element | `web/tests/render_surface.test.js` (statically) **and** `harness/tests/contract.spec.js` (on the screen) |
 | JS → wasm | the calls the page makes exist, with the arity the bundle declares, and their answers are painted | `web/tests/bundle/wasm_surface.test.js` (the surface) **and** `contract.spec.js`'s pointer test (the wiring) |
-| page → peer | the handshake goes out first, a frame is answered whole, and a failure is named | `harness/tests/shell.spec.js`, `harness/tests/drill.spec.js` |
+| page → peer | the handshake goes out first, a frame is answered whole, a failure is named, **and the page routes each failure through the call that disarms the watchdog** | `harness/tests/shell.spec.js`, `harness/tests/drill.spec.js` |
 | worker → OPFS | `storage_contract`, run against a real `OpfsFs` | `harness/tests/opfs.spec.js` |
 
+**A unit test of a rule does not test the wiring that reaches it**, and the
+sharpest case in this file is the watchdog. `shell.test.js` proves that
+`createShell.fail()` disarms rather than pre-empts; it cannot prove that
+`app.js`'s socket `close` and `error` listeners call `fail()` rather than
+`setShell()`. That routing is PR #21's other half, the one gotcha 48 says keeps
+getting lost — and PR #61 lost it a third time by keeping the unit test and
+dropping the browser assertion, with 26/26 and 13/13 green. Restored, and the
+rule generalises: **when a unit test replaces a boundary test, ask which of the
+two the regression would have been in.** Here it is the routing, so the guard
+stays in Playwright.
+
+**The faked clock is faithful outside the window and silent inside it.**
+`shell.spec.js` walks past the 8s handshake watchdog with `page.clock`, and the
+question that owes an answer is whether collapsing ten seconds into one
+synchronous step *flattens* an ordering rather than merely skipping the wait.
+Probed for the sharpest case — a peer that opens, stays silent past the window
+and is closed afterwards — the `#status` transcript is **byte-identical** under
+the fake clock and under a real nine-second wait: four states, same order, same
+text. What that does not cover is an event landing **strictly inside** the
+collapsed window, which a synchronous `runFor` gives no opportunity to deliver;
+that is a race whose outcome the page does not promise, so there is nothing to
+assert. State it rather than re-derive it.
+
+**A negative assertion must demonstrate the denied event is reachable on that
+exact code path** — not on a sibling path, and not in the rule's own unit test.
+This file's worked example cost four review rounds. `shell.arm` runs only after
+`await transport.ready`, so on a socket that never opens the watchdog is never
+armed; a test denying "sent no document" there denies nothing, and passed
+against both the routing revert and the disarm regression. `outlastTheWatchdog`
+now asks the page `timesArmed() > 0` first, which turns that review finding into
+a failure by name. Note *ever armed* and not *armed now*: a correct page has
+already disarmed by the time the disconnect test jumps — that is the property —
+so the obvious spelling would have denied the passing case.
+
+**And a constant a test must exceed has one home.** `HANDSHAKE_TIMEOUT_MS` lived
+in `web/app.js` and again in the spec, under a comment saying a silent
+disagreement "would pass for the wrong reason". It did: the spec at 1000 against
+the page's 8000 made the suite green over the reverted routing, because the jump
+landed inside the window. It is exported from `web/shell.js` and imported by
+both, so the disagreement is unconstructible rather than discouraged.
+
 Everything **between** those seams is `node --test web/tests`, and it may assume
 the boundary holds rather than re-establishing it: transport selection from
 `?ws=`, the two facts `#status` composes, the watchdog's arm and disarm, the
@@ -1236,18 +1277,65 @@ the repaint is the boundary; the other seven were the same instance again.
 
 ### Two numbers, and neither is the other
 
-Measured on one machine at `1af51c9` versus this branch, both on a private
+Measured on one machine, in one session, on a private
-`IMPROVISE_HARNESS_PORT`:
+`IMPROVISE_HARNESS_PORT`, with **both trees clean** — `1af51c9` reached by a
+full checkout rather than by restoring paths over a working branch (see the
+trap below). Two runs each; the pair is the variance.
 
-| suite | tests | execution | whole job |
+| suite | chromium | all projects | execution | whole job |
-|---|---|---|---|
+|---|---|---|---|---|
-| Playwright, before | 29 (+3 skipped) | 36.9s | ~4m30s in CI |
+| Playwright, before (`1af51c9`) | 23 | 26 passed + 3 skipped | 36.2s / 36.3s | ~4m30s in CI |
-| Playwright, after | 16 (+3 skipped) | 15.7s | ~4m30s in CI |
+| Playwright, after | 14 | 17 passed + 3 skipped | 15.1s / 14.9s | ~4m30s in CI |
-| `node --test web/tests` | 26 | 0.11s | seconds |
+| `node --test web/tests` | — | 26 | 0.12s | seconds |
 
-**Cutting Playwright tests barely moves the CI number**, because roughly four
+**Two columns because one number was ambiguous three times.** Every spec but
-minutes of that job is three `wasm-pack` builds, `npm ci` and a browser
+`opfs.spec.js` is Chromium-only, so a count taken off a run is three larger than
-download — not test execution. The feedback-time win is the `js` job, which
+the count of tests in the files (Firefox's OPFS battery) with three more skipped
+(WebKit's). The columns must also **agree**: chromium + 3 is the passed total,
+and a row where they do not is a row built from two different trees.
+`npx playwright test --list` prints the per-project truth; quote which one, and
+this is the same "two numbers, not one" the Rust suite learned in
+`design-principles.md` §7.
+
+**The trap that made the first `before` figure wrong.** It was taken by
+`git checkout 1af51c9 -- harness web` inside a working branch — which restores
+*tracked* files and leaves untracked ones **where they are**, so the branch's own
+`contract.spec.js` stayed and the "baseline" ran main's 23 tests **plus three of
+the branch's**. A baseline taken by checking paths out over your own work
+measures a tree that never existed. The full checkout above is the repair.
+
+**What gave it away was the count, not the clock — and that is the lesson.** The
+contaminated run read 29 passed where a clean `1af51c9` reads 26, because three
+extra tests really were there; but it read 36.9s against the clean tree's 36.2s,
+because those three cost under a second between them. **A wall clock absorbs a
+contaminated tree without a trace; an arithmetic identity does not.** The same
+error survived three separate corrections — it reached PR #61's body as "26
+chromium" (23 + the 3), survived a fix that corrected the chromium column and
+left the run count beside it, and was caught each time only by someone checking
+that the columns add up.
+
+**Where the saving actually came from, since the obvious answer is wrong.** The
+eleven per-widget tests that were deleted cost **2.7 seconds of test time
+between them** — restored verbatim and re-measured — against **1.55s** for the
+three contract tests replacing them. Those are the per-test sums, not the two
+wall clocks, which read 3.3s and 3.4s and **flattered the replacements**: they
+were separate `npx playwright test` invocations, so each paid its own cold
+start (~0.6s and ~1.9s) and a near-tie appeared between two things not measured
+the same way. Warm inside a full suite those three cost under a second, which is
+why the contaminated baseline's clock barely moved.
+
+Eleven tests at 2.7s cannot buy a twenty-second saving, and they did not.
+Essentially all of 36.2s → 15s was two
+`shell.spec.js` tests that **waited out the 8s watchdog in real time**, and one
+of those two was the routing guard this section explains should never have gone.
+So the deletion of the eleven bought shape, not speed; the speed came from a
+deletion that cost coverage. Both are back at ~75ms each, because `page.clock`
+fakes the page's timers — the honest version of the trade: *the wait was the
+cost, not the test.*
+
+**Cutting Playwright tests barely moves the CI number** in any case, because
+roughly four minutes of that job is three `wasm-pack` builds, `npm ci` and a
+browser download — not test execution. The feedback-time win is the `js` job, which
 needs **no Rust toolchain and no wasm bundle at all**, and that is a constraint
 rather than an accident: the moment a `web/tests/*.test.js` file needs
 `web/pkg/`, it inherits the four-minute build and the argument for it

context/test-evidence/clients.md

@@ -534,15 +534,33 @@ injected at the *peer*, not in the page** — a mocked socket that answers the
 handshake with a frame the client cannot fold — so this exercises the real
 `on_frame` and the real catch.
 
-#### "a peer that cannot be reached is named, and the watchdog stays out of it"
+#### "a peer that cannot be reached is named, and not called a disconnect"
 
 improvise-hwpi: without an `error` listener, a connection that never opened left
 `#status` blank, and "the server is not running" read exactly like "still
-connecting". The watchdog half is asserted on the same page load rather than in
+connecting". **This test no longer says anything about the watchdog, and the
-its own test, because it needs the same nine-second wait. It holds for a reason
+paragraph below is why it never could.** `shell.arm` runs only after
-its own comment does not lead you to expect: `armWatchdog` runs only after
+`await transport.ready`, which resolves on `open` — so on a socket that never
-`transport.ready` resolves, which happens on `open` — so on a socket that never
+opens the watchdog is **never armed at all**, and denying its message here
-opened the watchdog is never armed at all.
+denies an unreachable event.
+
+**That sentence was already in this file, five lines above an assertion that
+contradicted it.** PR #65 added the watchdog clause *and edited this very
+paragraph*, inserting "`runFor(10s)` advances the watchdog" immediately before
+the sentence saying it is never armed. Reverting PR #21's routing, or stripping
+`fail()` of its `sawFrame()`, both left that clause **passing**. So a PR whose
+subject was "a deleted guard went unnoticed" planted the same shape one level
+up: three injections, three distinct test names, and two of them proving
+nothing. What the test guards now is the **naming** — `close` on a socket that
+never opened must not read as "disconnected" (improvise-taxx) — which is the
+half injection 3 really does exercise.
+
+**The mechanism, so it cannot come back.** `outlastTheWatchdog` now asks the
+page `timesArmed() > 0` before jumping, and a watchdog denial re-added to this
+path **fails by name**. It asks *ever armed* rather than *armed now*: by the
+time the disconnect test jumps, a correct page has already disarmed — that is
+the property — so `armed()` would have denied the passing case. Building that
+guard is what surfaced the distinction, which no amount of reading had.
 
 #### "a socket that opened and then dropped reads as disconnected, and stays that way"
 
@@ -550,7 +568,8 @@ The other arm, which must keep working when the first is fixed: a socket that
 really did open and then dropped IS a disconnect, and saying so is the whole
 reason `close` cannot simply be suppressed.
 
-**It runs past `HANDSHAKE_TIMEOUT_MS` on purpose.** On this arm the watchdog IS
+**It runs past `HANDSHAKE_TIMEOUT_MS` on purpose** — through `page.clock`, not
+through a real wait. On this arm the watchdog IS
 armed — `armWatchdog` runs after `transport.ready` resolves, i.e. on `open` — so
 "disconnected" is written while a timer is pending, and the only reason it
 survives is that `close` goes through `setShellFailure`, which clears it. That
@@ -566,6 +585,45 @@ assertion rather than another paragraph — proved discriminating by making
 `setShellFailure` skip its `clearTimeout`, which makes it fail. Same rule as
 `doctrine(an_injected_fault_must_be_the_fault_you_named)`, one level up.
 
+**And it was lost a third time, by the PR that was arguing about exactly this.**
+PR #61 split the browser tests into boundary contracts (Playwright) and unit
+tests (`node --test`), and merged these two tests into one that kept only the
+last-value assertions. `shell.test.js`'s "a loud failure DISARMS the watchdog"
+covers `createShell` in isolation and **cannot see whether `app.js` routes the
+close event through `fail()` rather than `setShell()`** — which is the half
+PR #21 fixed and the half that keeps getting lost. Reverting both socket arms
+to `setShell` left the node suite 26/26 and Playwright 13/13 green. Restored
+under their original names, and re-proved with that exact revert: the two-arm
+revert and the close-arm-only revert each fail "…and stays that way", and
+dropping the `opened` flag fails "…the watchdog stays out of it". **Three
+injections, three different tests, none of them the unit test.**
+
+**And the helper guards its own premise.** `page.clock.runFor` on a page where
+`clock.install()` was never called does **nothing and throws nothing**, so a test
+that forgot the install would assert "the watchdog never spoke" against a
+watchdog never given the chance — vacuous, and green. `outlastTheWatchdog` reads
+`Date.now()` inside the page either side of the jump and requires it to have
+moved. Demonstrated both ways: with the install removed the suite passed 6/6,
+and with the guard in place the same omission fails by name.
+
+**The window is single-homed, and that is the second half of the same
+finding.** `HANDSHAKE_TIMEOUT_MS` lived twice — once in `web/app.js`, once in
+the spec — with a comment saying a silent disagreement "would pass for the
+wrong reason" and nothing checking it. Setting the spec's copy to 1000 against
+the page's 8000 made the whole suite green **against the reverted routing**:
+the jump landed inside the window, the watchdog had not yet fired, and the
+denial held vacuously. It is now exported from `web/shell.js` and imported by
+both, so the two cannot disagree; shrinking it in its one home still catches
+the routing revert, which is the demonstration that the guard did not go quiet.
+
+**The faked clock is what makes the restoration cheap without weakening it**,
+and the injections are the proof of that too: if `page.clock.runFor` did not
+really advance the page's timers, a broken routing could not surface the
+watchdog's message and those injections would have passed. They failed. The
+test keeps the real page, the real socket, the real listeners and the real
+`setTimeout` call — only the *passage of time* is simulated, and 9 seconds of
+wall clock became 75 milliseconds.
+
 **The measurement that could not become a CI guard.** Both of the above were once
 asserted as `test.fail` expected-failures and **had to be removed**: neither
 reproduced on the GitHub runner, where `close` does not follow `error` within the
@@ -1164,6 +1222,11 @@ Every test below was proved able to fail by patching the code it names,
 checking the patch was on disk, running the suite and reading the failure —
 never by the absence of an error. Thirteen injections, thirteen failures:
 
+**What `shell.test.js` cannot reach, and the PR found out the hard way:** it
+tests `createShell` in isolation, so it sees the watchdog RULE and never the
+`app.js` wiring that calls it. That distinction is now written into
+`context/code/clients.md` and guarded in `shell.spec.js`.
+
 **`shell.test.js`** — `socketUrl` stops upgrading `ws://` on an https page;
 `composeStatus` returns the model fact alone (which fails five tests, because
 the watchdog's messages are shell facts and vanish with it); `fail()` stops

harness/tests/shell.spec.js

@@ -4,6 +4,8 @@
 
 import { test, expect } from "@playwright/test";
 
+import { HANDSHAKE_TIMEOUT_MS } from "../../web/shell.js";
+
 const status = (page) => page.locator("#status");
 
 /// A peer that accepts the TCP connection and then refuses the WebSocket
@@ -11,9 +13,45 @@ const status = (page) => page.locator("#status");
 /// the harness's OWN server, so it follows the port the config chose.
 const NO_WEBSOCKET_HERE = `127.0.0.1:${process.env.IMPROVISE_HARNESS_PORT ?? "8099"}`;
 
-/// `web/app.js`'s own HANDSHAKE_TIMEOUT_MS. One test has to outlast it, and a
+/// The page's own constant, imported rather than copied: a spec that
-/// number that silently disagreed with the page would pass for the wrong reason.
+/// understated it would jump short of the window and every watchdog assertion
-const HANDSHAKE_TIMEOUT_MS = 8_000;
+/// below would pass for the wrong reason — demonstrated, PR #65 review.
+
+/// Record every distinct #status the page shows, not just the last one: the
+/// properties below are about a message being REPLACED, which a final read
+/// cannot see. Installed before the page's own script runs.
+function logStatus() {
+  window.__statusLog = [];
+  new MutationObserver(() => {
+    const text = document.getElementById("status")?.textContent ?? "";
+    if (text && window.__statusLog.at(-1) !== text) window.__statusLog.push(text);
+  }).observe(document, { childList: true, subtree: true, characterData: true });
+}
+
+const json = (v) => JSON.stringify(v);
+
+/// Walk past the watchdog without waiting for it. `page.clock` fakes the
+/// page's own timers, so the 8s is the PAGE's and the wall clock is not.
+async function outlastTheWatchdog(page) {
+  // A negative assertion about the watchdog is vacuous where the watchdog was
+  // never armed, and `shell.arm` runs only after `await transport.ready`. It
+  // asks whether it was EVER armed: by here a correct page has disarmed it,
+  // which is the property, so `armed()` would deny the passing case.
+  expect(
+    await page.evaluate(() => window.__improviseShell?.timesArmed() ?? 0),
+    "the watchdog was never armed on this path: denying its message proves nothing",
+  ).toBeGreaterThan(0);
+  const jump = HANDSHAKE_TIMEOUT_MS + 2_000;
+  const before = await page.evaluate(() => Date.now());
+  await page.clock.runFor(jump);
+  // `runFor` without `clock.install()` does NOTHING and throws nothing, so a
+  // test that forgot it would assert "the watchdog never spoke" vacuously.
+  const after = await page.evaluate(() => Date.now());
+  expect(
+    after - before,
+    "page.clock.install() was not called: the page's timers never advanced",
+  ).toBeGreaterThanOrEqual(jump);
+}
 
 test.describe("the shell reports what its peer is doing", () => {
   // improvise-hwpi. The fault is injected at the *peer*, not in the page, so
@@ -26,15 +64,30 @@ test.describe("the shell reports what its peer is doing", () => {
     await expect(status(page)).toContainText("bad frame", { timeout: 15_000 });
   });
 
-  // A socket that never opened did not "disconnect" (improvise-taxx): nothing
+  // improvise-hwpi. This peer NEVER OPENS, so `await transport.ready` never
-  // on the close event can discriminate, so the page records `opened` itself.
+  // resolves and `shell.arm` never runs — the watchdog is not on this path.
-  // That it then STAYS is the watchdog's disarming, which is Node's now.
+  test("a peer that cannot be reached is named, and not called a disconnect", async ({
-  test("a peer that cannot be reached is named, and one that dropped is not confused with it", async ({
     page,
   }) => {
+    await page.addInitScript(logStatus);
     await page.goto(`/app/index.html?ws=${NO_WEBSOCKET_HERE}`);
     await expect(status(page)).toContainText("cannot reach", { timeout: 15_000 });
 
+    // The naming is the whole property here: `close` on a socket that never
+    // opened must not read as "disconnected" (improvise-taxx).
+    const log = await page.evaluate(() => window.__statusLog);
+    expect(log.some((t) => t.includes("disconnected")), `#status said: ${json(log)}`).toBe(
+      false,
+    );
+  });
+
+  // The arm PR #21 fixed and that gotcha 48 says keeps getting lost: a socket
+  // that never opened did not "disconnect", and the one that did STAYS so.
+  test("a socket that opened and then dropped reads as disconnected, and stays that way", async ({
+    page,
+  }) => {
+    await page.clock.install();
+    await page.addInitScript(logStatus);
     // Closes on the page's first frame, so "it opened first" is true by
     // construction rather than by timer.
     await page.routeWebSocket("ws://127.0.0.1:8790/", (ws) => {
@@ -43,6 +96,16 @@ test.describe("the shell reports what its peer is doing", () => {
     await page.goto("/app/index.html?ws=127.0.0.1:8790");
     await expect(status(page)).toContainText("connected", { timeout: 15_000 });
     await expect(status(page)).toContainText("disconnected", { timeout: 15_000 });
+
+    // Past the watchdog it was armed against: the routing, not the rule, is
+    // what this can see and `shell.test.js` cannot.
+    await outlastTheWatchdog(page);
+    await expect(status(page)).toContainText("disconnected");
+
+    const log = await page.evaluate(() => window.__statusLog);
+    expect(log.some((t) => t.includes("sent no document")), `#status said: ${json(log)}`).toBe(
+      false,
+    );
   });
 
   // The one assertion that needs the real timer: that the watchdog is ARMED

web/app.js

@@ -4,6 +4,7 @@
 import init, { Client } from "./pkg/improvise_wasm_client.js";
 import {
   COL_PX,
+  HANDSHAKE_TIMEOUT_MS,
   ROW_PX,
   createShell,
   extentOf,
@@ -40,13 +41,15 @@ const client = new Client();
 
 // A peer that never answers the handshake, and the two facts `#status` shows.
 // Both are decided in shell.js; this is the wire to the element.
-const HANDSHAKE_TIMEOUT_MS = 8000;
 const shell = createShell({
   onStatus: (text) => {
     el.status.textContent = text;
   },
   timeoutMs: HANDSHAKE_TIMEOUT_MS,
 });
+// The harness asks whether the watchdog is ARMED, because a negative assertion
+// about it is vacuous where it is not (clients.md). Read by tests, nothing else.
+window.__improviseShell = shell;
 
 // What the grid's own frame costs, in whole cells, as of the last repaint —
 // measured off the painted model, never predicted. context/code/clients.md.

web/shell.js

@@ -27,6 +27,11 @@ export function indicator(collapsed) {
 export const ROW_PX = 26;
 export const COL_PX = 110;
 
+/** How long a peer has to answer the handshake. Exported because the harness
+ *  must jump *past* it: a spec with its own copy can understate it silently
+ *  and every watchdog assertion then passes vacuously (clients.md). */
+export const HANDSHAKE_TIMEOUT_MS = 8000;
+
 /** The extent a box of this size can show, in whole DATA cells: the frame is
  *  charged for first, and at least one cell is always asked for. */
 export function extentOf(box, frameCost, metrics = { rowPx: ROW_PX, colPx: COL_PX }) {
@@ -107,6 +112,7 @@ export function createShell({ onStatus, timeoutMs, setTimer = setTimeout, clearT
   let shell = "";
   let model = "";
   let watchdog = null;
+  let arms = 0;
   const paint = () => onStatus(composeStatus(shell, model));
 
   return {
@@ -121,6 +127,7 @@ export function createShell({ onStatus, timeoutMs, setTimer = setTimeout, clearT
     /** A peer that never answers the handshake. Deliberately about the *first
      *  frame*, not either peer's own failure modes — clients.md. */
     arm(message) {
+      arms += 1;
       clearTimer(watchdog);
       watchdog = setTimer(() => {
         watchdog = null;
@@ -140,5 +147,8 @@ export function createShell({ onStatus, timeoutMs, setTimer = setTimeout, clearT
       this.setShell(text);
     },
     armed: () => watchdog !== null,
+    /** How many times the watchdog has been armed. A test denying its message
+     *  needs this to be nonzero, or it is denying an unreachable event. */
+    timesArmed: () => arms,
   };
 }

web/tests/render_surface.test.js

@@ -8,6 +8,13 @@ import { fileURLToPath } from "node:url";
 
 const read = (rel) => readFileSync(fileURLToPath(new URL(rel, import.meta.url)), "utf8");
 
+/// Comments name model fields routinely, so a field mentioned only in one
+/// would read as painted. Strip them before asking what the code touches.
+const code = (rel) =>
+  read(rel)
+    .replace(/\/\*[\s\S]*?\*\//g, " ")
+    .replace(/(^|[^:"'`])\/\/.*$/gm, "$1");
+
 /// Fields the page deliberately does not read, each with the reason. A field
 /// belongs here only with an argument; the list is the debt, written down.
 // improvise-z754 put the title bar's facts in one shared cache and taught
@@ -32,7 +39,7 @@ function renderModelFields() {
 
 test("every field the render model projects is painted, or named as debt", () => {
   // Both halves of the page: `app.js` paints, `shell.js` plans the grid.
-  const page = read("../app.js") + read("../shell.js");
+  const page = code("../app.js") + code("../shell.js");
   const unpainted = renderModelFields().filter((field) => !page.includes(`model.${field}`));
   assert.deepEqual(
     unpainted.sort(),