diff --git a/context/code/clients.md b/context/code/clients.md index a054d12c..33f187f4 100644 --- a/context/code/clients.md +++ b/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 -`IMPROVISE_HARNESS_PORT`: +Measured on one machine, in one session, on a private +`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 | -|---|---|---|---| -| Playwright, before | 29 (+3 skipped) | 36.9s | ~4m30s in CI | -| Playwright, after | 16 (+3 skipped) | 15.7s | ~4m30s in CI | -| `node --test web/tests` | 26 | 0.11s | seconds | +| suite | chromium | all projects | execution | whole job | +|---|---|---|---|---| +| Playwright, before (`1af51c9`) | 23 | 26 passed + 3 skipped | 36.2s / 36.3s | ~4m30s in CI | +| Playwright, after | 14 | 17 passed + 3 skipped | 15.1s / 14.9s | ~4m30s in CI | +| `node --test web/tests` | — | 26 | 0.12s | seconds | -**Cutting Playwright tests barely moves the CI number**, 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 +**Two columns because one number was ambiguous three times.** Every spec but +`opfs.spec.js` is Chromium-only, so a count taken off a run is three larger than +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 diff --git a/context/test-evidence/clients.md b/context/test-evidence/clients.md index f68ffa00..cb394e24 100644 --- a/context/test-evidence/clients.md +++ b/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 -its own test, because it needs the same nine-second wait. It holds for a reason -its own comment does not lead you to expect: `armWatchdog` runs only after -`transport.ready` resolves, which happens on `open` — so on a socket that never -opened the watchdog is never armed at all. +connecting". **This test no longer says anything about the watchdog, and the +paragraph below is why it never could.** `shell.arm` runs only after +`await transport.ready`, which resolves on `open` — so on a socket that never +opens the watchdog is **never armed at all**, and denying its message here +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 diff --git a/harness/tests/shell.spec.js b/harness/tests/shell.spec.js index a0f60fdf..f494c340 100644 --- a/harness/tests/shell.spec.js +++ b/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 -/// number that silently disagreed with the page would pass for the wrong reason. -const HANDSHAKE_TIMEOUT_MS = 8_000; +/// The page's own constant, imported rather than copied: a spec that +/// understated it would jump short of the window and every watchdog assertion +/// 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 - // on the close event can discriminate, so the page records `opened` itself. - // That it then STAYS is the watchdog's disarming, which is Node's now. - test("a peer that cannot be reached is named, and one that dropped is not confused with it", async ({ + // improvise-hwpi. This peer NEVER OPENS, so `await transport.ready` never + // resolves and `shell.arm` never runs — the watchdog is not on this path. + test("a peer that cannot be reached is named, and not called a disconnect", 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 diff --git a/web/app.js b/web/app.js index c1fb2f15..5b1d14da 100644 --- a/web/app.js +++ b/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. diff --git a/web/shell.js b/web/shell.js index ced087f1..3bbf7508 100644 --- a/web/shell.js +++ b/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, }; } diff --git a/web/tests/render_surface.test.js b/web/tests/render_surface.test.js index 1fe8e1b2..aa0766aa 100644 --- a/web/tests/render_surface.test.js +++ b/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(),