diff --git a/CHANGELOG.md b/CHANGELOG.md index d42bd124..5e350506 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,29 @@ All notable changes to this project are documented here. This project adheres to ## [Unreleased] +### Fixed + +- **Setting a widget no longer hangs for 30 seconds after a ComfyUI restart (#1161).** + Once ComfyUI had been restarted mid-session, setting any widget on any node timed out, + every time, while every other panel command answered instantly — reading the graph, + renaming a node, listing workflows, queueing a run. Setting a widget is the one action + that reads the backend's node definitions before it writes, and a restart can leave the + browser holding a connection that never answers and never fails, so that read waited + forever. + The panel already had a second way to ask — a direct request that keeps working when + the first route does not — but it was never reached, because nothing gave up on the + first one. The lookup now has an overall time budget, so a route that stops answering falls + through to the one that does and the write simply succeeds. The budget covers the whole + lookup rather than being handed to each step in turn, so the wait cannot stack — but the + second route is also guaranteed a share of it, because a first route that stops answering + would otherwise use the budget up and leave nothing for the route that still works. A + route that answers quickly hands back the time it did not use, so a slow install still + gets the whole budget to finish in. + The budget is twenty seconds, which is generous rather than tight: fetching the whole + node-definition document was measured at well under a second even on a large install with + sixty-odd node packs. If nothing answers, the refusal names every attempt and says how + long each one was actually given, rather than quoting a wait it never spent. + ## [0.14.24] - 2026-08-12 ### Fixed diff --git a/browser_tests/unit/media-preview.test.mjs b/browser_tests/unit/media-preview.test.mjs index ac9a44e8..45a6e982 100644 --- a/browser_tests/unit/media-preview.test.mjs +++ b/browser_tests/unit/media-preview.test.mjs @@ -1419,3 +1419,27 @@ test("a late fulfilment after the bound fired does not overwrite the fallback", settle("too late"); assert.equal(await p, "fallback"); }); + +test("#1161 withTimeout: a `timers` object that cannot be READ is treated as absent, never a rejection", async () => { + // bounded-step.js's own header argues that every injected guard is an operation that can + // fail, and wraps `onTimeout` and `clearTimer` accordingly — but READING the injected + // object was itself unguarded. A throwing getter, or a Proxy whose get trap throws, threw + // synchronously before the returned promise existed, so withTimeout REJECTED out of a + // function documented three lines above its signature as never rejecting. The + // /object_info oracle passes this object straight through, and two panel commands await + // that oracle with no catch of their own. + const hostile = [ + { get setTimer() { throw new Error("hostile getter"); } }, + new Proxy({}, { get() { throw new Error("proxy trap"); } }), + { setTimer: 5, clearTimer: "no" }, // present, but not callable + ]; + for (const timers of hostile) { + const value = await withTimeout(Promise.resolve("answered"), 1000, () => "timed out", timers); + assert.equal(value, "answered", "an unreadable timers object must fall back to the real timer"); + } + // …and the bound must still WORK through that fallback, not merely avoid throwing. + const timedOut = await withTimeout(new Promise(() => {}), 1, () => "timed out", { + get setTimer() { throw new Error("hostile getter"); }, + }); + assert.equal(timedOut, "timed out", "the real timer still bounds the step"); +}); diff --git a/browser_tests/unit/object-info-oracle.test.mjs b/browser_tests/unit/object-info-oracle.test.mjs index e469707e..f2674982 100644 --- a/browser_tests/unit/object-info-oracle.test.mjs +++ b/browser_tests/unit/object-info-oracle.test.mjs @@ -24,7 +24,14 @@ import test from "node:test"; import assert from "node:assert/strict"; import { readFileSync } from "node:fs"; -import { fetchWholeObjectInfo, objectInfoOracleFailureNote } from "../../web/js/lib/object-info-oracle.js"; +import { + fetchWholeObjectInfo, + objectInfoOracleFailureNote, + // The SHIPPED budget, so a test cannot pass against a value the panel does not use. + OBJECT_INFO_DEADLINE_MS, + outcomeKind, + TRANSPORT_SENTINELS, +} from "../../web/js/lib/object-info-oracle.js"; const SCHEMA = { KSampler: { input: {} }, VAELoader: { input: {} } }; const okResponse = (body) => ({ ok: true, status: 200, json: async () => body }); @@ -302,3 +309,814 @@ test("#982 (codex r4) blank entries: the slice-first order is documented, not ac assert.equal(objectInfoOracleFailureNote(["", "", "", "", "x"]), "", "four blanks consume the window"); assert.match(objectInfoOracleFailureNote(["x", "", "", "", ""]), /Tried 5 routes: x \(and 1 more not shown\)\./); }); + +// ── #1161: a transport that never ANSWERS must not park the whole oracle ───── +// +// The P1. After a ComfyUI restart the tab can hold a half-open connection, so +// `api.getNodeDefs()` never settles — it does not throw, it simply never answers. Both +// awaits here were unbounded, so the oracle parked on the first transport and the second +// route — added by #982 for exactly this failure — was never asked. Every command that +// consults it hung until its caller timed out at 30s. +// +// The bound is not a way to fail faster. Its point is that the SECOND route usually +// answers, so the write SUCCEEDS. That is why it belongs here and not around the cache, +// where three attempts on #1178 could only choose how to give up. +// +// Timers are injected and fired by hand, so nothing here waits on a real clock and a +// regression fails with a named assertion rather than wedging `node --test`. +// +// THE CLOCK ADVANCES WHEN A TIMER FIRES, and that is not a detail. The first version of +// this harness fired the injected timer while leaving `now()` at 0, so every test ran with +// the full budget still unspent — a state production CANNOT reach, since a timer armed for +// `ms` only fires once `ms` has passed. Under that harness the flagship test below passed +// while the shipped code never issued the fallback at all (`fetchApi` call count 0). The +// clock is therefore owned here and moved by `fire()`, so a test cannot assert an outcome +// the real clock would not produce. +function harness() { + const timers = new Set(); + const armedMs = []; + let clock = 0; + return { + timers: { + setTimer: (fn, ms) => { const t = { fn, ms }; timers.add(t); armedMs.push(ms); return t; }, + clearTimer: (t) => timers.delete(t), + }, + now: () => clock, + armed: () => timers.size, + armedMs: () => armedMs.slice(), + at: () => clock, + fire: () => { + const due = [...timers]; + // Firing a timer means its full duration elapsed — the longest one pins the clock. + clock += due.reduce((max, t) => Math.max(max, t.ms), 0); + due.forEach((t) => { timers.delete(t); t.fn(); }); + }, + }; +} +const DEFS_1161 = { KSampler: {} }; +// Never await an oracle call unbounded: node --test has no default timeout, so a +// regression would wedge the suite instead of naming itself. The previous branch was +// caught doing exactly this. +const settled = (p, what) => + Promise.race([ + p, + new Promise((_, reject) => + setTimeout(() => reject(new Error(`${what} never settled — a transport was not bounded`)), 250), + ), + ]); +// Let the oracle reach its next await and arm THAT timer before firing. A macrotask +// flushes every pending microtask, which counting ticks does not reliably do — an earlier +// draft fired the response timer before it had unwrapped and timed out the wrong stage. +const tick = () => new Promise((r) => setTimeout(r, 0)); +const never = () => new Promise(() => {}); + +test("#1161: a hung client route falls through to the fallback, which ANSWERS", async () => { + // The whole point: not a faster refusal — a successful write. + const h = harness(); + let fetchCalls = 0; + const out = fetchWholeObjectInfo({ + getNodeDefs: never, + fetchApi: async () => { fetchCalls += 1; return { ok: true, json: async () => DEFS_1161 }; }, + deadlineMs: 6000, + timers: h.timers, + now: h.now, + }); + await tick(); + h.fire(); // the client route gives up, and the clock moves to when it did + const result = await settled(out, "the oracle call"); + // ASSERT THE REQUEST WAS ACTUALLY SENT, not merely that the outcome looks right. This is + // the fact the earlier version of this branch got wrong while its suite stayed green: the + // client route consumed the entire shared budget, so the fallback was skipped unsent + // (call count 0) and the refusal then named a route nothing had contacted. An outcome + // assertion alone cannot see that; a call count can. + assert.equal(fetchCalls, 1, "the fallback must be ISSUED — a reserved floor is what guarantees it"); + assert.deepEqual(result.defs, DEFS_1161, "the fallback answered, so the caller is authorized"); + assert.match(result.failures.join(" | "), /api\.getNodeDefs\(\) did not answer within its \d+ms share of the 6000ms budget/); +}); + +test("#1161: no route is ever REPORTED as timing out when it was never sent", async () => { + // #982's original defect was a refusal naming a cause it had not established. A step + // reached with no budget left must say so in its own words rather than borrow the + // timeout's, or the fix reintroduces the bug it was written to remove. + // A zero budget is the one input that still reaches this branch, now that the floor + // makes a hung client route unable to starve the fallback. It is a REAL path — the + // caller injects the budget — and it pins the wording for whatever else reaches it. + let fetchCalls = 0; + const result = await fetchWholeObjectInfo({ + getNodeDefs: never, + fetchApi: async () => { fetchCalls += 1; return { ok: true, json: async () => DEFS_1161 }; }, + deadlineMs: 0, + }); + const note = result.failures.join(" | "); + assert.equal(fetchCalls, 0, "this test only means something if the route really was skipped"); + assert.equal(result.defs, null, "and nothing unasked-for is authorized"); + assert.doesNotMatch(note, /did not answer within/, "an unsent request cannot have failed to answer"); + assert.match(note, /GET \/object_info was not attempted/, "…it reports what actually happened instead"); + assert.match(note, /api\.getNodeDefs\(\) was not attempted/, "both routes speak for themselves"); +}); + +test("#1161: the fallback's budget is a FLOOR, not merely what the first step left over", async () => { + // Subtracting a reserve makes the fallback depend on the client route finishing on time. + // Measured: at small deadlines the per-step overhead alone overran the subtraction and + // the fallback was skipped again — the exact defect being fixed, back by another door. + // Taking the max() instead makes the guarantee independent of the first step entirely. + for (const deadlineMs of [5, 10, 50, 200]) { + let fetchCalls = 0; + const result = await fetchWholeObjectInfo({ + getNodeDefs: never, + fetchApi: async () => { fetchCalls += 1; return { ok: true, json: async () => DEFS_1161 }; }, + deadlineMs, + }); + assert.equal(fetchCalls, 1, `deadlineMs=${deadlineMs}: the fallback must still be issued`); + assert.deepEqual(result.defs, DEFS_1161, `deadlineMs=${deadlineMs}: and its answer used`); + } +}); + +test("#1161: the timeout is reported as a timeout, not as a throw", async () => { + // withTimeout never rejects by contract, so a naive wrap would collapse "it threw" into + // "it timed out" and the refusal would name the wrong cause — the trap that bit #1178. + const h = harness(); + const out = fetchWholeObjectInfo({ + getNodeDefs: async () => { throw new Error("client exploded"); }, + fetchApi: never, + deadlineMs: 6000, + timers: h.timers, + now: h.now, + }); + await tick(); + h.fire(); + const result = await settled(out, "the oracle call"); + const note = result.failures.join(" | "); + assert.match(note, /api\.getNodeDefs\(\) threw: client exploded/, "a throw keeps its own cause"); + assert.match(note, /GET \/object_info did not answer within its \d+ms share of the 6000ms budget/, "…and a hang keeps its own"); +}); + +test("#1161: both transports hanging still returns, and names both", async () => { + const h = harness(); + const out = fetchWholeObjectInfo({ getNodeDefs: never, fetchApi: never, deadlineMs: 6000, timers: h.timers, now: h.now }); + await tick(); + h.fire(); + await tick(); + h.fire(); + const result = await settled(out, "the oracle call"); + assert.equal(result.defs, null, "nothing answered, so nothing is authorized — still fail-closed"); + assert.equal(result.failures.length, 2, "each route reports for itself"); + for (const f of result.failures) assert.match(f, /did not answer within its \d+ms share of the 6000ms budget/); +}); + +test("#1161: a hung BODY is bounded too — the response is not the body", async () => { + // res.json() is a second I/O step and was inside the try/catch the bound replaced. A 5MB + // schema over a half-open connection can stall after the headers arrive. + const h = harness(); + const out = fetchWholeObjectInfo({ + getNodeDefs: async () => null, + fetchApi: async () => ({ ok: true, json: never }), + deadlineMs: 6000, + timers: h.timers, + now: h.now, + }); + await tick(); + h.fire(); + const result = await settled(out, "the oracle call"); + assert.equal(result.defs, null); + assert.match(result.failures.join(" | "), /body did not arrive within its \d+ms share of the 6000ms budget/); +}); + +test("#1161: a healthy client route is untouched by the bound", async () => { + const h = harness(); + const result = await fetchWholeObjectInfo({ + getNodeDefs: async () => DEFS_1161, + fetchApi: () => { throw new Error("must not be consulted"); }, + deadlineMs: 6000, + timers: h.timers, + now: h.now, + }); + assert.deepEqual(result.defs, DEFS_1161); + assert.deepEqual(result.failures, [], "a route that answers records no failure"); + assert.equal(h.armed(), 0, "and leaves no timer armed"); +}); + +test("#1161: the SHIPPED budget is a real bound, sized for the payload not a ping", async () => { + // Every other #1161 test injects its own budget, so none of them would notice the + // shipped constant being set to 0 — which disables the bound entirely by withTimeout's + // contract and reinstates the P1 with a green suite. Review caught that gap twice. + assert.ok(OBJECT_INFO_DEADLINE_MS > 0, "a non-positive budget disables the bound"); + // WHAT THE MEASUREMENT IS. The bounded work is one GET of the whole document: 5,413,770 + // bytes / 167ms on a 63-pack install (#767), cited independently in object-info-cache.js + // and single-node-def.js, and measured live at ~450ms on a 4304-type install. The ~14.5s + // figure from #610 measures "/object_info + combo refresh" — the download PLUS + // registerNodesFromDefs plus rebuilding every combo widget — which this oracle does not + // do. An earlier revision of this file asserted 14.5s here as the download time, and + // three review rounds then cited that assertion back as the repo's measurement. + // + // So the floor is set against the real figure with room to spare: the smallest share any + // single step gets is half the deadline, which must still clear the measured download by + // a wide margin rather than merely exceed it. + assert.ok( + OBJECT_INFO_DEADLINE_MS / 2 >= 5000, + "a step's own share must clear the ~167ms measured download by a wide margin, not merely exceed it", + ); + // …and it must still land inside the bridge's 30s command timeout, so the caller sees + // this oracle's own answer rather than a bare timeout with no routes named. + assert.ok(OBJECT_INFO_DEADLINE_MS < 30000, "past the command budget the refusal never reaches the caller"); +}); + +test("#1161: an unreadable response is a failure, never a rejection", async () => { + // The contract this module states two screens up: "every failure path returns defs: + // null". Replacing the try/catch with a bound re-protected only the awaits, so reading + // `ok`/`status` off a proxied or lazily-evaluated response rejected instead. Two callers + // await this with no try/catch of their own. + const hostile = { get ok() { throw new Error("wrapped api"); } }; + const result = await fetchWholeObjectInfo({ + getNodeDefs: async () => null, + fetchApi: async () => hostile, + deadlineMs: 6000, + }); + assert.equal(result.defs, null); + assert.match(result.failures.join(" | "), /unreadable response: wrapped api/); +}); + +test("#1161: a payload whose own shape cannot be inspected is a failure, never a rejection", async () => { + // Object.keys invokes a Proxy's ownKeys trap, which can throw — same contract, different + // entry point, and also proven against main by the review. + const trapped = new Proxy({}, { ownKeys() { throw new Error("proxy"); } }); + const result = await fetchWholeObjectInfo({ + getNodeDefs: async () => trapped, + fetchApi: async () => ({ ok: true, json: async () => ({ KSampler: {} }) }), + deadlineMs: 6000, + }); + // Nothing rejected — that is the contract this asserts, and the whole point. + // + // The OUTCOME is `defs: null` rather than the fallback's schema, and that is correct + // rather than a shortfall: an uninspectable object still satisfies the "is an object, + // is not an array" test, so it takes the deliberate-empty branch and is treated as the + // client's own answer. That is the direction this module already chose for an empty + // map — the fallback must never widen an answer the client gave — and it fails closed, + // which is the safe reading of "I could not tell what it said". + assert.equal(result.defs, null); +}); + +test("#1161: the budget is shared, so three steps cannot each spend it", async () => { + // A per-step bound multiplies: three 6s bounds is an 18s worst case nobody chose, + // stacked on the 8s startup seed wait. One budget makes the worst case one number. + // + // But SHARING ALONE IS NOT ENOUGH, which is the correction this test now carries. A + // purely first-come budget lets step one take all of it, and then the fallback — the + // entire reason this oracle exists — is skipped rather than merely hurried. So the + // invariant has two halves: the total never exceeds the deadline, AND no single step can + // reduce a later one to nothing. + const h = harness(); + const out = fetchWholeObjectInfo({ + getNodeDefs: never, + fetchApi: never, + deadlineMs: 6000, + timers: h.timers, + now: h.now, + }); + await tick(); + h.fire(); // the client route hangs for everything it was given + await tick(); + const budgets = h.armedMs(); + assert.ok(budgets.length >= 2, "both transports were bounded"); + assert.ok(budgets[0] <= 3000, "the first step may not take more than its share"); + assert.ok(budgets[1] > 0, "the fallback is left a real budget — a zero here is the P1 back"); + h.fire(); + const result = await settled(out, "the oracle call"); + assert.equal(result.defs, null); + assert.equal(result.failures.length, 2, "each route reports for itself"); + assert.ok(h.at() <= 6000, "and the whole question still costs no more than the one deadline"); +}); + +test("#1161: the reserve holds when the client route hangs for its FULL share", async () => { + // The production shape of the P1, at the shipped constant rather than a test one: a + // half-open socket that never settles. The fallback must still be sent. + const h = harness(); + let fetchCalls = 0; + const out = fetchWholeObjectInfo({ + getNodeDefs: never, + fetchApi: async () => { fetchCalls += 1; return { ok: true, json: async () => DEFS_1161 }; }, + deadlineMs: OBJECT_INFO_DEADLINE_MS, + timers: h.timers, + now: h.now, + }); + await tick(); + h.fire(); + const result = await settled(out, "the oracle call"); + assert.equal(fetchCalls, 1, "the shipped budget must reserve room for the fallback too"); + assert.deepEqual(result.defs, DEFS_1161); +}); + +test("#1161: a status that cannot be STRINGIFIED is a failure, never a rejection", async () => { + // Guarding the property READ was not enough: `${responseStatus}` interpolates it below + // the try, and `Object.create(null)` has no toString to convert with. Proven by running + // this input against the previous commit, which rejected with a TypeError where two + // callers have no catch of their own. + const result = await fetchWholeObjectInfo({ + getNodeDefs: async () => null, + fetchApi: async () => ({ ok: false, status: Object.create(null) }), + }); + assert.equal(result.defs, null); + assert.match(result.failures.join(" | "), /GET \/object_info was not OK/); +}); + +test("#1161: a thrown value that cannot be stringified is a failure, never a rejection", async () => { + // describeFailure called String(err) OUTSIDE every guard, so a rejection value with a + // throwing toString escaped the module — the same contract break by a third entry point. + // The sanitizer already handled this; the defect was stringifying before reaching it. + const result = await fetchWholeObjectInfo({ + getNodeDefs: async () => { throw { toString() { throw new Error("unprintable"); } }; }, + fetchApi: async () => ({ ok: true, json: async () => DEFS_1161 }), + }); + // And because it is only a FAILURE, the fallback still runs and the write is authorized. + assert.deepEqual(result.defs, DEFS_1161, "a hostile error value must not cost the user their answer"); + assert.match(result.failures.join(" | "), /api\.getNodeDefs\(\) threw: \(an unprintable value\)/); +}); + +test("#1161: a refusal quotes the budget the step ACTUALLY got, not the whole deadline", async () => { + // Browser-verified against a live 4304-type install: the client route is capped at half + // the deadline, but the message quoted the deadline — telling the reader it had waited + // 20000ms when it had waited 10000ms. Naming a number that was never spent is the same + // defect as #982's "unreachable or the fetch failed": a refusal asserting what it did + // not establish. Both numbers appear, so the share and the whole are each readable. + const h = harness(); + const out = fetchWholeObjectInfo({ + getNodeDefs: never, + fetchApi: never, + deadlineMs: 6000, + timers: h.timers, + now: h.now, + }); + await tick(); + h.fire(); + await tick(); + h.fire(); + const result = await settled(out, "the oracle call"); + const client = result.failures.find((f) => f.startsWith("api.getNodeDefs()")); + assert.match(client, /within its 3000ms share of the 6000ms budget/, "half the deadline, said plainly"); + assert.doesNotMatch(client, /within the 6000ms budget/, "the un-spent whole must not be quoted as the wait"); +}); + +test("#1161: a timer that fires LATE cannot starve the fallback", async () => { + // Chrome clamps hidden-tab timers to ~1/min after five minutes backgrounded; laptop + // sleep/resume and an NTP forward jump do the same. `spent()` clamps a BACKWARD jump but + // must not clamp a forward one — that would be lying about elapsed time — so the timer + // can fire long after its bound and leave the deadline already overrun. + // + // Under a subtracted reserve that produced fetchApi call count 0: the P1 exactly, in a + // tab that was merely in the background. The floor is what makes it survivable, because + // the fallback's budget stops depending on when the first step finished. + for (const lateBy of [0, 10_000, 60_000, 600_000]) { + const pending = []; + let clock = 0; + const timers = { + setTimer: (fn, ms) => { const t = { fn, ms }; pending.push(t); return t; }, + clearTimer: (t) => { const i = pending.indexOf(t); if (i >= 0) pending.splice(i, 1); }, + }; + let calls = 0; + const out = fetchWholeObjectInfo({ + getNodeDefs: never, + fetchApi: async () => { calls += 1; return { ok: true, json: async () => DEFS_1161 }; }, + deadlineMs: OBJECT_INFO_DEADLINE_MS, + timers, + now: () => clock, + }); + for (let i = 0; i < 8 && pending.length; i++) { + await tick(); + const t = pending.shift(); + if (!t) break; + clock += t.ms + lateBy; // the timer fires late, and the clock says so + t.fn(); + } + const result = await settled(out, `the oracle call (lateBy=${lateBy})`); + assert.equal(calls, 1, `lateBy=${lateBy}: the fallback must still be issued`); + assert.deepEqual(result.defs, DEFS_1161, `lateBy=${lateBy}: and its answer used`); + } +}); + +test("#1161: an injected clock that THROWS cannot reject out of this module", async () => { + // The structural version of an invariant that three previous designs asserted in prose + // and none actually held. Each of those tried to make an untrustworthy `Date.now()` safe: + // clamping negative readings refunded everything spent (one call ran ~50s against a 20s + // deadline); a high-water ratchet only sampled at step boundaries, and its test passed + // with AND without it; charging measured elapsed let a stalled clock refund real time. + // + // A clock that THROWS must not cost the caller their answer. The accounting DOES read a + // clock now — on `performance.now()`, which is monotonic — but `now` is an injected seam, + // and this module's header promises every failure path returns `defs: null` to two + // callers that await it with no catch of their own. + const exploding = () => { throw new Error("the clock is not to be trusted"); }; + const granted = []; + const result = await fetchWholeObjectInfo({ + getNodeDefs: async () => null, + fetchApi: async () => ({ ok: true, json: async () => DEFS_1161 }), + deadlineMs: 20000, + now: exploding, + timers: { setTimer: (fn, ms) => { granted.push(ms); return { fn, ms }; }, clearTimer: () => {} }, + }); + assert.deepEqual(result.defs, DEFS_1161, "a hostile clock cannot cost the user their answer"); + assert.ok( + granted.reduce((a, b) => a + b, 0) <= 20000, + `granted ${granted.join("+")}ms against a 20000ms budget`, + ); +}); + +test("#1161: a hung route is CAPPED at its share; a fast one hands the rest back", async () => { + // BOTH halves matter, and each was broken on its own during this issue. + // + // The CAP stops a hung client route consuming the budget and starving the fallback — the + // original P1, fetchApi call count 0. The RECLAIM stops a client route that answers + // instantly from spending 10s it never used: charging the full grant there was a shipped + // regression that refused a 5.4MB payload at 5.5s which both the parent and main + // delivered at 7.5s. + const granted = []; + const armed = []; + const timers = { + setTimer: (fn, ms) => { granted.push(ms); const t = { fn, ms }; armed.push(t); return t; }, + clearTimer: (t) => { const i = armed.indexOf(t); if (i >= 0) armed.splice(i, 1); }, + }; + const out = fetchWholeObjectInfo({ + getNodeDefs: never, + fetchApi: async () => ({ ok: true, json: async () => DEFS_1161 }), + deadlineMs: OBJECT_INFO_DEADLINE_MS, + timers, + }); + await tick(); + armed.shift().fn(); // only the CLIENT route hangs; the fallback answers normally + const result = await settled(out, "the oracle call"); + assert.deepEqual(result.defs, DEFS_1161, "the fallback still answers after the cap fires"); + assert.equal(granted[0], 10000, "the client route is capped at its half — this is the P1 fix"); + assert.ok(granted[1] <= 10000, `the fallback got ${granted[1]}ms, which cannot exceed what was left`); + assert.ok(granted[1] > 0, "and it is a real budget, not a token one"); + + // Now the reclaim: a client route that answers immediately must cost almost nothing. + const fast = []; + await fetchWholeObjectInfo({ + getNodeDefs: async () => null, + fetchApi: async () => ({ ok: true, json: async () => DEFS_1161 }), + deadlineMs: OBJECT_INFO_DEADLINE_MS, + timers: { setTimer: (fn, ms) => { fast.push(ms); return { fn, ms }; }, clearTimer: () => {} }, + }); + assert.equal(fast.length, 3, "client route, response and body are each bounded"); + assert.equal(fast[0], 10000, "the cap on the client route is unchanged"); + assert.ok(fast[1] > 9000, `the response kept ${fast[1]}ms the client route did not use`); + // Bound tightly enough to SEE the share: with BODY_SHARE at 1 the body keeps what the + // response left (~20s); at 0.5 it would keep ~10s, which a looser bound accepted — that + // mutation survived the suite until this assertion was tightened. + assert.ok(fast[2] > 15000, `the body kept ${fast[2]}ms — main gave it ~19.5s, not 5s or 10s`); + for (const [i, ms] of fast.entries()) assert.ok(ms > 0, `step ${i} was granted ${ms}ms`); +}); + +test("#1161: on a clock that ADVANCES, real elapsed stays inside the budget", async () => { + // The previous version of this test summed only FIRED timer durations, so it could not + // see the overrun it was named for: a step that ANSWERS costs real time too, and that + // time went uncounted. Here each answering step advances the clock by exactly what it + // took, so the reclaim is charged against real work. + // + // WHAT IS AND IS NOT GUARANTEED. The cap alone bounds a hung step. The reclaim depends on + // the clock telling the truth about an answering one — which is what `performance.now()` + // guarantees, and why it is the default rather than a preference. + let clock = 0; + const armed = []; + const timers = { + setTimer: (fn, ms) => { const t = { fn, ms }; armed.push(t); return t; }, + clearTimer: (t) => { const i = armed.indexOf(t); if (i >= 0) armed.splice(i, 1); }, + }; + const took = (ms, value) => async () => { clock += ms; return value; }; + + // Three honest, slow steps: 18s of real work inside a 20s budget must ANSWER, and must + // not add up past the budget on the way. + const slow = await fetchWholeObjectInfo({ + getNodeDefs: took(6000, null), + fetchApi: took(6000, { ok: true, json: took(6000, DEFS_1161) }), + deadlineMs: 20000, + timers, + now: () => clock, + }); + assert.deepEqual(slow.defs, DEFS_1161, "18s of honest work inside a 20s budget must ANSWER"); + assert.ok(clock <= 20000, `ran ${clock}ms against a 20000ms budget`); + + // A hung client route, then a slow-but-working fallback: the cap fires and what is left + // is still enough to answer. + clock = 0; + armed.length = 0; + const out = fetchWholeObjectInfo({ + getNodeDefs: never, + fetchApi: took(300, { ok: true, json: took(4000, DEFS_1161) }), + deadlineMs: 20000, + timers, + now: () => clock, + }); + await tick(); + const t = armed.shift(); + clock += t.ms; // the client route hung for exactly as long as it was allowed to + t.fn(); + const hung = await settled(out, "the oracle call"); + assert.deepEqual(hung.defs, DEFS_1161, "the P1 case still recovers"); + assert.ok(clock <= 20000, `ran ${clock}ms against a 20000ms budget`); +}); + +test("#1161: a non-finite budget cannot poison the arithmetic", async () => { + // `deadlineMs: Infinity` made `consumed` infinite, `budget - consumed` NaN, and every + // later grant NaN — and `Math.max(0, NaN)` is NaN rather than 0, so the fallback was + // SKIPPED ENTIRELY (call count 0) on an input the unbounded original handled fine. + // + // The first fix normalised such a budget to zero, which merely relocated the damage: the + // oracle then attempted nothing at all. A value that cannot be a budget takes the shipped + // default instead, so a caller passing garbage still gets a working oracle. + for (const deadlineMs of [Infinity, -Infinity, NaN, undefined]) { + let calls = 0; + const result = await fetchWholeObjectInfo({ + getNodeDefs: async () => null, + fetchApi: async () => { calls += 1; return { ok: true, json: async () => DEFS_1161 }; }, + deadlineMs, + }); + assert.equal(calls, 1, `deadlineMs=${String(deadlineMs)}: the fallback must still be ISSUED`); + assert.deepEqual(result.defs, DEFS_1161, `deadlineMs=${String(deadlineMs)}: and answer`); + } + // An explicit non-positive NUMBER is a real choice, and is obeyed rather than overridden. + for (const deadlineMs of [0, -1]) { + let calls = 0; + const result = await fetchWholeObjectInfo({ + getNodeDefs: async () => null, + fetchApi: async () => { calls += 1; return { ok: true, json: async () => DEFS_1161 }; }, + deadlineMs, + }); + assert.equal(calls, 0, `deadlineMs=${deadlineMs}: nothing may be attempted`); + assert.equal(result.defs, null, "…and nothing is authorized"); + assert.match(result.failures.join(" | "), /was not attempted/, "…and it says so plainly"); + } +}); + +test("#1161: outcomeKind names all four outcomes, including both Symbols", () => { + // The share-based budget makes "not-tried" unreachable through the public function on a + // usable budget — every step is reserved a share, so none can be starved to a zero grant. + // The branch is still live code, and an untested branch here does not misbehave quietly: + // `"err" in outcome` on a Symbol is a TypeError out of a module documented to always + // resolve, which two callers await with no catch. That bug shipped once during this issue + // when a patch replaced a branch instead of adding beside it, so the demux is pinned here + // directly rather than through a path that can stop reaching it. + assert.equal(outcomeKind({ err: new Error("boom") }), "threw"); + assert.equal(outcomeKind({ value: { KSampler: {} } }), "value"); + assert.equal(outcomeKind({ value: undefined }), "value", "an undefined payload is still an answer"); + assert.equal(outcomeKind({ err: undefined }), "threw", "presence of `err`, not its truthiness"); + // Both sentinels are Symbols, and neither may reach the `in` test. + for (const sentinel of TRANSPORT_SENTINELS) { + const kind = outcomeKind(sentinel); + assert.ok(kind === "not-tried" || kind === "no-answer", `a sentinel must be named, got ${kind}`); + } +}); + +test("#1161: a refusal quotes the budget in force, not the argument it was given", async () => { + // Reverting the three failure strings from `${budget}` to `${deadlineMs}` survived the + // whole suite. It matters because the two now DIFFER: a value that cannot be a budget is + // replaced by the default, and a refusal saying "within its 10000ms share of the + // Infinityms budget" states something that was never true. + const result = await fetchWholeObjectInfo({ + getNodeDefs: () => new Promise(() => {}), + fetchApi: () => new Promise(() => {}), + deadlineMs: Infinity, + timers: { setTimer: (fn) => { fn(); return {}; }, clearTimer: () => {} }, + }); + const note = result.failures.join(" | "); + assert.match(note, new RegExp(`share of the ${OBJECT_INFO_DEADLINE_MS}ms budget`), "the budget actually in force"); + assert.doesNotMatch(note, /Infinity/, "never the uninterpretable argument"); +}); + +test("#1161: a tiny budget still ISSUES the fallback rather than attempting nothing", async () => { + // `Math.floor(left * share)` truncates to 0 on a small budget, and a zero grant is not a + // short wait — it is the step never being attempted. Verified before the fix: deadlineMs + // of 1 or 2 gave fetchApi call count 0, the exact signature this change exists to remove. + for (const deadlineMs of [2, 3, 5, 50]) { + let calls = 0; + await fetchWholeObjectInfo({ + getNodeDefs: async () => null, + fetchApi: async () => { calls += 1; return { ok: true, json: async () => DEFS_1161 }; }, + deadlineMs, + }); + assert.equal(calls, 1, `deadlineMs=${deadlineMs}: the fallback must still be issued`); + } + // At 1ms there is genuinely nothing to divide across three steps. It must still fail + // CLOSED and, critically, must not claim a budget was "already spent" when none was. + const one = await fetchWholeObjectInfo({ getNodeDefs: async () => null, fetchApi: async () => ({ ok: true }), deadlineMs: 1 }); + assert.equal(one.defs, null); + assert.doesNotMatch(one.failures.join(" | "), /already spent/, "nothing had been spent when the first step ran"); +}); + +test("#1161: an explicitly NULL timers object is not a rejection", async () => { + // `timers: null` is not `timers: undefined`, and only the latter reaches withTimeout's own + // default — an explicit null read `.setTimer` off null and rejected out of a module whose + // header promises every failure path returns `defs: null`, to callers with no catch. + const result = await fetchWholeObjectInfo({ + getNodeDefs: async () => null, + fetchApi: async () => ({ ok: true, json: async () => DEFS_1161 }), + timers: null, + }); + assert.deepEqual(result.defs, DEFS_1161); +}); + +test("#1161: a forward clock jump during a step cannot starve the steps after it", async () => { + // The reclaim charges what a step actually used, which means a clock that leaps FORWARD + // mid-step reports a spend far larger than the grant that step was even allowed. Without + // clamping to the grant, that overcharge exhausts the budget and the fallback is skipped + // — the fetchApi-call-count-0 signature again, arriving through the reclaim rather than + // through the cap. `performance.now()` should never do this, but `now` is injectable and + // the Date.now fallback exists, so the clamp is what makes the direction safe. + let calls = 0; + let reading = 0; + const result = await fetchWholeObjectInfo({ + // Answers immediately, but the clock leaps a billion ms while it does. + getNodeDefs: async () => { reading = 1e9; return null; }, + fetchApi: async () => { calls += 1; return { ok: true, json: async () => DEFS_1161 }; }, + deadlineMs: 20000, + now: () => reading, + }); + assert.equal(calls, 1, "the fallback must still be issued — a step cannot spend more than it was granted"); + assert.deepEqual(result.defs, DEFS_1161); +}); + +test("#1161: a clock returning a non-number cannot reject out of this module", async () => { + // Guarding the clock CALL was not enough: `readClock() - startedStep` is its own + // operation, and it throws for a Symbol ("Cannot convert a Symbol value to a number") and + // for a null-prototype object. This is the third time in this issue a guarded read was + // undone by an unguarded use of the same value, after `${responseStatus}` and + // `String(err)` — so the reading is normalised at the source instead. + for (const now of [() => Symbol("t"), () => Object.create(null), () => 1n, () => "later", () => ({}), () => null]) { + const result = await fetchWholeObjectInfo({ + getNodeDefs: async () => null, + fetchApi: async () => ({ ok: true, json: async () => DEFS_1161 }), + now, + }); + assert.deepEqual(result.defs, DEFS_1161, `now returning ${String(typeof now())} must not cost the answer`); + } +}); + +test("#1161: the DEFAULT clock is the monotonic one — the property everything rests on", () => { + // Nothing pinned this: swapping the default to Date.now left the whole suite green, while + // being the single choice the current design depends on. Every scenario that broke the + // three earlier clock-based designs — an NTP step, a DST or manual change, a VM + // suspend/resume, a frozen reading — is a WALL-CLOCK hazard specifically. + // + // A source guard, in the idiom this suite already uses for the #982 refusal wording, + // because the choice is a default the tests otherwise always override. + const src = readFileSync(new URL("../../web/js/lib/object-info-oracle.js", import.meta.url), "utf8"); + // Pin the ARM, not merely the appearance of the identifier. "performance.now" also occurs + // in the rationale comment and in the capability check just above the selection, so the + // first version of this guard — a bare match on that identifier — stayed true for the + // exact mutation its own comment names, and was vacuous. + assert.match(src, /\?\s*\(\)\s*=>\s*performance\.now\(\)/, "the default arm must BE the monotonic clock"); + // Strip comments before counting Date.now uses: the first filter only skipped lines + // STARTING with a marker, so a trailing same-line comment counted as a use. + // + // SPLIT ON /\r?\n/. This file is CRLF, so a line ends "…\r" — and `//.*$` never matches + // there, because `.` excludes the carriage return and `$` sits after it. The strip + // silently did nothing and the assertion failed on unmutated source. + const code = src + .replace(/\/\*[\s\S]*?\*\//g, "") + .split(/\r?\n/) + .map((l) => l.replace(/\/\/.*$/, "")); + const dateNowUses = code.filter((l) => /Date\.now\(\)/.test(l)); + assert.equal(dateNowUses.length, 1, `Date.now may appear only as the last-resort fallback, found: ${dateNowUses.join(" | ")}`); + assert.match(dateNowUses[0], /=>\s*Date\.now\(\)/, "and only as the fallback arm of the clock selection"); +}); + +test("#1161: an unreadable elapsed reading charges the FULL grant, never zero", () => { + // The documented conservative direction. Flipping this arm to charge 0 left the suite + // green, so a clock that cannot be read would have silently handed every later step a + // fresh budget — the refund defect that produced the ~50s overruns. + const src = readFileSync(new URL("../../web/js/lib/object-info-oracle.js", import.meta.url), "utf8"); + assert.match( + src, + /Number\.isFinite\(spent\) && spent >= 0 \? Math\.min\(spent, grant\) : grant/, + "unmeasurable elapsed must fall back to the whole grant, not to nothing", + ); +}); + +test("#1161: a budget beyond the timer's range takes the default, and does not park", async () => { + // setTimeout coerces a delay above 2^31-1 to 1ms, so an over-range budget hands every step + // a grant whose timer fires immediately — the bound silently becoming no bound. + // + // CLAMPING to 2^31-1 was the first fix and was worse: it turns the nonsense input into a + // ~24.8-day grant, so a hung client route PARKS instead of failing fast. Measured on real + // timers at deadlineMs 5e9, the clamped version never returned at all with fetchApi call + // count 0 — the canonical #1161 signature, reintroduced by a guard written to prevent it. + // Both halves are pinned here so neither fix can be undone in favour of the other. + for (const deadlineMs of [2 ** 31, 5e9, Number.MAX_SAFE_INTEGER, Infinity, NaN]) { + const granted = []; + let calls = 0; + const result = await fetchWholeObjectInfo({ + getNodeDefs: async () => null, + fetchApi: async () => { calls += 1; return { ok: true, json: async () => DEFS_1161 }; }, + deadlineMs, + timers: { setTimer: (fn, ms) => { granted.push(ms); return { fn, ms }; }, clearTimer: () => {} }, + }); + assert.equal(calls, 1, `deadlineMs=${deadlineMs}: the fallback is still issued`); + assert.deepEqual(result.defs, DEFS_1161); + assert.equal( + granted[0], + OBJECT_INFO_DEADLINE_MS / 2, + `deadlineMs=${deadlineMs}: an unusable budget must take the DEFAULT, not a multi-day clamp`, + ); + } + // A hung route on an over-range budget must fail fast rather than park for days. + { + let calls = 0; + const refused = await fetchWholeObjectInfo({ + getNodeDefs: () => new Promise(() => {}), + fetchApi: async () => { calls += 1; return { ok: true, json: async () => DEFS_1161 }; }, + deadlineMs: 5e9, + timers: { setTimer: (fn) => { fn(); return {}; }, clearTimer: () => {} }, + }); + // Timers fire immediately here, so every step times out by construction — the point is + // not that it answers, but that it REACHES the fallback and reports, rather than sitting + // on a multi-day grant with the raw route never contacted. + assert.equal(calls, 1, "the fallback is reached instead of the call parking"); + assert.equal(refused.defs, null, "with every timer firing at once nothing can answer"); + assert.match( + refused.failures.join(" | "), + new RegExp(`share of the ${OBJECT_INFO_DEADLINE_MS}ms budget`), + "and the refusal quotes the budget actually in force, not a nine-digit one", + ); + } + // A budget AT the ceiling is expressible, so it is honoured rather than overridden. + { + const granted = []; + await fetchWholeObjectInfo({ + getNodeDefs: async () => null, + fetchApi: async () => ({ ok: true, json: async () => DEFS_1161 }), + deadlineMs: 2 ** 31 - 1, + timers: { setTimer: (fn, ms) => { granted.push(ms); return { fn, ms }; }, clearTimer: () => {} }, + }); + assert.equal(granted[0], Math.floor((2 ** 31 - 1) / 2), "an expressible budget is the caller's to choose"); + } +}); + +test("#1161: a hung step really is charged, so it cannot leave the next one the whole budget", async () => { + // Deleting the timeout charge entirely left the whole suite green — including the test + // rewritten specifically to see that overrun. The observable consequence is simple: if a + // hung client route costs nothing, the fallback draws the FULL budget rather than what is + // left, and the total is no longer bounded by anything. + const granted = []; + const armed = []; + const out = fetchWholeObjectInfo({ + getNodeDefs: never, + fetchApi: async () => ({ ok: true, json: async () => DEFS_1161 }), + deadlineMs: 20000, + timers: { + setTimer: (fn, ms) => { granted.push(ms); const t = { fn, ms }; armed.push(t); return t; }, + clearTimer: (t) => { const i = armed.indexOf(t); if (i >= 0) armed.splice(i, 1); }, + }, + now: () => 0, // a clock that reveals nothing: only the timeout charge can bound this + }); + await tick(); + armed.shift().fn(); + await settled(out, "the oracle call"); + assert.equal(granted[0], 10000, "the client route's share"); + assert.ok( + granted[1] <= 10000, + `the fallback was granted ${granted[1]}ms — a hung step that costs nothing leaves the budget unspent`, + ); +}); + +test("#1161: BOTH fallback shares are pinned, not just the body's", async () => { + // BODY_SHARE was re-pinned after it survived a mutation; FALLBACK_RESPONSE_SHARE was left + // free, and 0.5 -> 0.9 survived the suite. Pin the response's share the same way, on the + // path where the client route has already spent its half so the arithmetic is unambiguous. + const granted = []; + const armed = []; + const out = fetchWholeObjectInfo({ + getNodeDefs: never, + fetchApi: async () => ({ ok: true, json: async () => DEFS_1161 }), + deadlineMs: 20000, + timers: { + setTimer: (fn, ms) => { granted.push(ms); const t = { fn, ms }; armed.push(t); return t; }, + clearTimer: (t) => { const i = armed.indexOf(t); if (i >= 0) armed.splice(i, 1); }, + }, + now: () => 0, + }); + await tick(); + armed.shift().fn(); // the client route burns its 10s + await settled(out, "the oracle call"); + assert.equal(granted[1], 5000, "the response takes half of what the client route left, not more"); +}); + +test("#1161: a Number-coercible clock keeps the reclaim, it does not silently disable it", async () => { + // Demanding `typeof === "number"` rejected every clock the subtraction itself would have + // accepted — a Date, or a numeric string — so those charged the full grant and the + // reclaim vanished, restoring the 10000/5000/5000 shape that round 8 proved refuses + // payloads main serves. The guard must coerce exactly as the arithmetic would. + for (const make of [ + () => { let t = 0; return () => new Date((t += 100)); }, + () => { let t = 0; return () => String((t += 100)); }, + () => { let t = 0; return () => (t += 100); }, + ]) { + const granted = []; + await fetchWholeObjectInfo({ + getNodeDefs: async () => null, + fetchApi: async () => ({ ok: true, json: async () => DEFS_1161 }), + deadlineMs: 20000, + now: make(), + timers: { setTimer: (fn, ms) => { granted.push(ms); return { fn, ms }; }, clearTimer: () => {} }, + }); + assert.ok(granted[2] > 15000, `the body kept ${granted[2]}ms — the reclaim must survive this clock`); + } +}); diff --git a/web/js/lib/bounded-step.js b/web/js/lib/bounded-step.js index 18a3b8f7..17fd2977 100644 --- a/web/js/lib/bounded-step.js +++ b/web/js/lib/bounded-step.js @@ -48,8 +48,26 @@ * @returns {Promise} never rejects */ export function withTimeout(promise, ms, onTimeout, timers = {}) { - const setTimer = timers.setTimer ?? ((fn, delay) => setTimeout(fn, delay)); - const clearTimer = timers.clearTimer ?? ((t) => clearTimeout(t)); + // #1161 — READING the injected object is itself an operation that can fail, which is the + // one case the note above missed while making exactly that argument about `onTimeout` and + // `clearTimer`. A `timers` whose `setTimer` is a throwing getter, or a Proxy whose get + // trap throws, threw HERE — synchronously, before the returned promise exists — so + // `withTimeout` rejected out of a function whose contract three lines up says it never + // does. Two panel commands await the oracle that calls this with no catch of their own. + // + // A `timers` that cannot be read is treated as one that was not supplied: the real timer + // is used, which is the same answer as the default and always safe. + let setTimer; + let clearTimer; + try { + setTimer = timers?.setTimer; + clearTimer = timers?.clearTimer; + } catch { + setTimer = undefined; + clearTimer = undefined; + } + if (typeof setTimer !== "function") setTimer = (fn, delay) => setTimeout(fn, delay); + if (typeof clearTimer !== "function") clearTimer = (t) => clearTimeout(t); if (!(ms > 0)) return promise; return new Promise((resolve) => { let settled = false; diff --git a/web/js/lib/object-info-oracle.js b/web/js/lib/object-info-oracle.js index dd340b7c..4e7c3768 100644 --- a/web/js/lib/object-info-oracle.js +++ b/web/js/lib/object-info-oracle.js @@ -39,13 +39,53 @@ * broader than the client route, and this comment is where that would need re-checking. * The fallback is only ever consulted when the client route returned NOTHING usable, so * it can never override a narrower answer the client actually gave. + * + * #1161 WIDENS THAT LAST SENTENCE, and it is recorded here rather than waved past. The + * deadline below treats a client route that does not answer IN TIME as one that answered + * nothing — so a client which would have replied with a deliberately narrow schema, and is + * merely SLOW rather than broken, now has the raw route consulted over it. Reproduced in + * review: a `getNodeDefs` resolving the deny-all `{}` just after the budget expires is + * abandoned, and the fallback's full schema is used. + * + * The alternative is to refuse whenever the client route does not answer, which is exactly + * the P1 this exists to remove — three attempts on #1178 established that a bound which can + * only choose HOW TO FAIL leaves the reported hang in place under a different name. So the + * trade is deliberate: an install whose client route filters AND is slower than the budget + * can have a write authorized against a type it meant to withhold. + * + * The exposure is bounded by the same direction the original note relies on. An INSTALL is + * harmless (a type missing from the answer is refused, which fails closed); only a + * deliberate NARROWING can be overridden, and only for a write to a type it withheld. + * + * HOW SLOW IS "TOO SLOW" — stated exactly, because the window is WIDER than this note first + * claimed. It is not the whole deadline. The client route is granted at most + * CLIENT_ROUTE_SHARE of the budget, which is HALF (10s of the shipped 20s), so a + * filtering client is overridden once it takes longer than that — twice as readily as + * "slower than the budget" implied. The floor is what makes the fallback reachable at all, + * so the two properties are in direct tension and this is the side that was chosen. + * + * Anyone revisiting this should know it was a decision and not an oversight, that the + * number to check is the client route's SHARE rather than the deadline, and that the honest + * fix is a client route which fails fast rather than one which is merely waited on longer. */ import { CACHE_OUTCOME } from "./object-info-cache.js"; +// #1161 — the repo's one bounded-step primitive. A second timeout helper is how this +// repo keeps producing near-duplicate bugs, per that file's own header. +import { withTimeout } from "./bounded-step.js"; /** A payload that can actually answer "does the backend define this type?" */ function usableDefs(value) { - return !!value && typeof value === "object" && !Array.isArray(value) && Object.keys(value).length > 0; + // #1161 — `Object.keys` INVOKES a Proxy's ownKeys trap, which can throw. This module + // promises that "every failure path returns `defs: null`", and a diagnostic that raises + // an exception of its own breaks that for callers which (correctly) do not wrap it. A + // payload whose own shape cannot be inspected is not usable, which is the same answer + // this returns for every other unusable value. + try { + return !!value && typeof value === "object" && !Array.isArray(value) && Object.keys(value).length > 0; + } catch { + return false; + } } /** How much of a thrown value's own words may ride into a refusal message. */ @@ -81,12 +121,129 @@ function sanitizeDetail(value) { } function describeFailure(label, err, extra = "") { - const raw = err instanceof Error ? err.message : err == null ? "" : String(err); + // #1161 — `String(err)` HERE was outside every guard, so a rejection value with a + // throwing toString escaped as a rejection from a module that documents the opposite two + // screens up. `sanitizeDetail` already handles exactly this; the bug was stringifying + // before reaching it. Reading `.message` off an Error is safe (own data property), but a + // getter-backed subclass is not, so that read is guarded too. + let raw = ""; + try { + raw = err instanceof Error ? err.message : err == null ? "" : err; + } catch { + raw = "(an unprintable value)"; + } const detail = sanitizeDetail(raw); const suffix = detail ? `: ${detail}` : ""; return `${label}${extra}${suffix}`; } +/** + * #1161 — the TOTAL time this oracle may spend before it answers with what it has. + * + * The P1: after a ComfyUI restart the tab can hold a half-open connection, so + * `api.getNodeDefs()` never settles — it does not throw, it simply never answers. Every + * await here was unbounded, so the oracle parked on the first transport and the second + * route, added by #982 for exactly this failure, was never asked. Every command that + * consults it hung until its caller timed out. + * + * A DEADLINE, NOT A PER-STEP BOUND. There are three I/O steps (client route, response, + * body), and giving each its own budget multiplies: three 6s bounds is an 18s worst case + * that nobody chose, stacked on top of the 8s startup seed wait. A single deadline makes + * the worst case one number, and lets a fast first step hand its unused time to a slow + * second one — which is what actually happens when the client route fails instantly and + * the fallback has a 5MB payload to move. + * + * WHAT THE MEASUREMENT ACTUALLY IS, because a wrong one was written here and then reasoned + * from twice. This repo has measured the thing being bounded — ONE GET of the whole + * document — on a 63-pack install: **5,413,770 bytes / 167 ms** (#767). The same pair of + * numbers is cited independently in `object-info-cache.js`, `single-node-def.js` and the + * panel's own add_node path. Measured again live while fixing this issue, on a 4304-type + * install: `api.getNodeDefs()` 366ms, the raw GET plus its JSON parse ~450ms. + * + * ~14.5s (#610) IS A DIFFERENT OPERATION and must not be used to size this. That issue + * measured "the forced /object_info + combo refresh" — the download PLUS + * registerNodesFromDefs plus rebuilding every combo widget in the graph. This oracle does + * none of that; it fetches a document and reads it. An earlier revision of this comment + * cited 14.5s as the download time, and later reviews then cited THIS COMMENT back as the + * repo's measurement — a loop that turned an unmeasured number into a fact. Anyone + * re-sizing this bound should re-measure rather than trust either figure secondhand. + * + * SO 20s IS GENEROUS, NOT TIGHT, and it stays that way once split three ways: 10s for the + * client route, then 5s for the fallback's response and 5s for its body. The SMALLEST of + * those is 5s — about 30x the measured download and 10x the slowest figure actually + * observed. (An earlier revision of this sentence still said 10s after the body was given + * its own share, which is the same stale-number trap the ~14.5s figure came from; the + * arithmetic is spelled out here so a later change to the shares has to update it.) + * + * WHY A SIBLING FILE LEGITIMATELY USES 14.5s. `get-errors-budget.js` sizes + * GET_ERRORS_REFRESH_CAP_MS at 15000 citing that same #610 figure, and it is CORRECT to: + * it bounds the forced refresh — the download plus registerNodesFromDefs plus rebuilding + * every combo in the graph. This module bounds only the fetch. Two files, two operations, + * two right answers; noticing that they disagree is what produced the wrong number here. + * + * It remains inside the bridge's 30s command timeout, so the caller sees this oracle's own + * answer rather than a bare timeout. + */ +export const OBJECT_INFO_DEADLINE_MS = 20000; + +/** Distinguishes "this transport did not answer in time" from any value it could return. */ +const NO_ANSWER = Symbol("object-info-transport-timeout"); +/** Distinguishes "the budget was gone before this route was contacted" from a timeout. */ +const NOT_TRIED = Symbol("object-info-transport-not-tried"); + +/** + * The two non-value outcomes, EXPORTED so the demux below can be tested against them + * directly. Both are Symbols, and a Symbol reaching the `in` test is a TypeError out of a + * module documented to always resolve — so this is the one place a missed branch throws + * rather than misbehaving quietly, and it must be coverable without depending on some + * public-API path happening to reach it. + */ +export const TRANSPORT_SENTINELS = Object.freeze([NO_ANSWER, NOT_TRIED]); + +/** + * Name which of the four things a transport outcome IS, in ONE place. + * + * The sentinels are Symbols, so `"err" in outcome` is a TypeError rather than a false — + * the branch order is load-bearing, not stylistic. Hand-writing that order at each of the + * three call sites shipped exactly that bug once already during this issue: a patch + * replaced the NO_ANSWER branch instead of adding beside it, and every fallback timeout + * began throwing out of a module which documents that it always resolves. + * + * Callers switch on the returned tag, so each keeps its own control flow — two of the + * three return early from the whole function on a usable payload — while the one + * dangerous test lives here. + */ +export function outcomeKind(outcome) { + if (outcome === NOT_TRIED) return "not-tried"; + if (outcome === NO_ANSWER) return "no-answer"; + return "err" in outcome ? "threw" : "value"; +} + +/** + * Run one I/O step against the SHARED deadline, preserving the difference between the + * three outcomes the failure list already distinguishes: it answered, it threw, or it + * never answered in time. + * + * `withTimeout` NEVER rejects by contract, so a naive wrap would collapse "threw" into + * "timed out" and the refusal would name the wrong cause. The outcome is therefore + * reified before bounding and unwrapped after. + */ +async function runTransport(attempt, remainingMs, timers) { + // Out of budget before we even start. Reported as its OWN outcome, never as a timeout: + // saying a route "did not answer" when it was never contacted is the #982 defect of + // asserting a cause that was never established. + if (!(remainingMs > 0)) return NOT_TRIED; + const settled = await withTimeout( + Promise.resolve() + .then(attempt) + .then((value) => ({ value }), (err) => ({ err })), + remainingMs, + () => NO_ANSWER, + timers, + ); + return settled; +} + /** * Fetch the whole `/object_info` schema, trying the frontend client first and the raw * HTTP route second. @@ -95,12 +252,224 @@ function describeFailure(label, err, extra = "") { * payload, and `failures` names every route that did not, in order. An empty `failures` * with a null `defs` cannot happen: a route that answers nothing is itself a failure. */ -export async function fetchWholeObjectInfo({ getNodeDefs, fetchApi } = {}) { +export async function fetchWholeObjectInfo({ + getNodeDefs, + fetchApi, + // Injected so a test can drive the deadline without waiting on a real clock. + deadlineMs = OBJECT_INFO_DEADLINE_MS, + timers, + // MONOTONIC BY DEFAULT, and that is the whole reason a clock is admissible here again. + now, +} = {}) { + // WHY THIS READS `performance.now()` AND NOT `Date.now()`. + // + // Three earlier designs were broken by a clock, and every scenario that broke them — + // an NTP step correction, a DST or manual change, a VM suspend/resume, a frozen reading + // — is a WALL-CLOCK hazard. `Date.now()` was the default, so all of them landed: + // measured at 49,998ms and 46,091ms against a 20,000ms deadline. + // + // `performance.now()` is monotonic by specification. It does not step backwards and is + // not repointed by the system clock, which is why this repo already measures its other + // elapsed-time windows on it — see `monotonicNow()` in the panel, `session-rebind.js` + // and `reconnect-staleness.js`, all of which say so in as many words. + // + // The reaction to those three rounds was to stop measuring entirely and charge every + // step its full grant. That bounded the total, but it stranded the unused time and + // REFUSED payloads both the parent and main delivered. The defect was never measurement; + // it was measuring with the one clock in the platform that is allowed to lie. + // + // A reading that is still somehow unusable (negative, non-finite — reachable only on the + // `Date.now` fallback where `performance` is absent) charges the FULL grant, so the + // budget can only ever be over-spent in the conservative direction. + const clockSource = + typeof now === "function" + ? now + : typeof performance !== "undefined" && typeof performance.now === "function" + ? () => performance.now() + : () => Date.now(); + // READING THE CLOCK MUST NOT BE ABLE TO THROW OUT OF THIS MODULE. `now` is an injected + // option, and this module's header promises every failure path returns `defs: null` to + // two callers that await it with no catch. An unreadable clock yields NaN, which the + // accounting below already treats as "unmeasurable" and charges in full. + const readClock = () => { + // COERCE, don't just typecheck. Guarding the CALL is not enough — the ARITHMETIC below + // is its own operation, and `readClock() - startedStep` throws for a Symbol ("Cannot + // convert a Symbol value to a number") and for a null-prototype object. That was the + // third time in this issue a guarded READ was undone by an unguarded USE of the same + // value, after `${responseStatus}` and `String(err)`. + // + // But the first fix for it demanded `typeof === "number"`, which REJECTED every clock + // the subtraction would have accepted — a `now` returning a Date, or a numeric string, + // reads as unmeasurable, charges the full grant, and so silently disables the reclaim: + // measured grants fell back to 10000/5000/5000, which is the round-8 regression shape + // reintroduced by a fix for something else. Coercing exactly as the subtraction would, + // inside the guard, accepts what worked before and rejects only what actually throws. + try { + const value = Number(clockSource()); + return Number.isFinite(value) ? value : NaN; + } catch { + return NaN; + } + }; + // ONE budget for the whole question, DIVIDED IN ADVANCE, with each step CAPPED at a share + // of what is left and charged only for what it actually used. Five designs were tried to + // get here; each is recorded because each looked correct and had a green suite. + // + // 1. Measure with `Date.now()`, clamping each negative READING to zero. It refunded + // everything already spent, so one call ran ~50s against a 20s deadline — past the + // bridge's 30s command timeout, so the agent got a bare timeout naming no routes. + // That IS the #1161 symptom, produced by the fix for it. + // 2. A high-water RATCHET over the same clock. It samples only at step boundaries, so a + // jump between two samples still refunds — and the test written for it passed with + // AND without the ratchet, which is how it was caught. + // 3. Charge the grant on timeout, measured elapsed otherwise, still on `Date.now()`. A + // frozen clock then ran a call 49,998ms against 20,000ms, and the "unmeasurable" arm + // charged a whole remaining grant for one bad reading, starving the step after it. + // 4. STOP MEASURING — charge every step its full grant. That bounded the total but + // stranded the time a fast step never used, and it REFUSED payloads both the parent + // and `main` delivered: a client route answering in 200ms was still charged 10s, so + // a 5.4MB body served at 7.5s elsewhere was refused here at 5.5s. + // + // The first three failed to a clock and the fourth failed by avoiding one, which is the + // actual lesson: every scenario that broke 1–3 is a WALL-CLOCK hazard, and the default + // was `Date.now()`. The available conclusion was never "do not measure" — it was "do not + // measure with the one clock in the platform that is allowed to lie." `performance.now()` + // is monotonic by specification, and this repo already measures its other elapsed windows + // on it (`monotonicNow()` in the panel, `session-rebind.js`, `reconnect-staleness.js`). + // + // SO: a step that TIMES OUT is charged its full grant with nothing measured — the timer + // is real-time truth. A step that ANSWERS is charged what the monotonic clock says it + // used, clamped to its grant, so the remainder goes back to the steps after it. The CAP + // is what stops a hung route starving the fallback; the RECLAIM is what stops a fast one + // spending time it never used. Both halves are load-bearing, and each was broken on its + // own in the rounds above. + // + // WHERE THIS STILL DEPENDS ON THE CLOCK, stated rather than glossed: the reclaim believes + // a clock that ADVANCES. One that under-reports without going backwards (a stub, or the + // `Date.now` fallback on a platform with no `performance`) charges an answering step too + // little, and real elapsed can then exceed the budget. `performance.now()` cannot do this, + // which is exactly why it is the default and why `now` is a test seam rather than a + // configuration knob. + // + // A NON-FINITE BUDGET IS NORMALISED ONCE, HERE. `deadlineMs: Infinity` used to make + // `consumed` infinite, `budget - consumed` NaN, and every later grant NaN — and since + // `Math.max(0, NaN)` is NaN rather than 0, the fallback was skipped entirely (call count + // 0) on an input the unbounded original handled. Normalising at the boundary keeps every + // later number finite by construction. + // A NON-NUMBER FALLS BACK TO THE DEFAULT; AN EXPLICIT ZERO IS OBEYED. Normalising a + // non-finite budget to 0 was the first attempt and it is wrong in its own way: it makes a + // caller who passes garbage get an oracle that attempts NOTHING, which is a worse answer + // than the unbounded original gave. NaN and Infinity are not budgets a caller can have + // meant, so they take the shipped default. A non-positive NUMBER is a real choice and is + // obeyed — every step is then unattempted, and says so. + // …and a budget a TIMER CANNOT EXPRESS is treated exactly like one that is not a number. + // + // `setTimeout` coerces a delay above 2^31-1 to 1ms, so an over-range budget hands every + // step a grant whose timer fires immediately — the bound silently becoming no bound. + // CLAMPING to 2^31-1 was tried first and is worse: it turns the nonsense input into a + // ~24.8-DAY grant, so a hung client route parks instead of failing fast. Measured on real + // timers at deadlineMs 5e9 — the unclamped version answered in 3ms with the fallback + // issued, the clamped one never returned at all, fetchApi call count 0. That is the + // canonical #1161 signature, reintroduced by a guard written to prevent it. + // + // Neither behaviour is what a caller meant by a nine-digit millisecond count, so it takes + // the shipped default like any other unusable value. + const MAX_EXPRESSIBLE_MS = 2 ** 31 - 1; + const budget = + Number.isFinite(deadlineMs) && deadlineMs <= MAX_EXPRESSIBLE_MS + ? Math.max(0, deadlineMs) + : OBJECT_INFO_DEADLINE_MS; + let consumed = 0; + /** + * Run one step CAPPED at `share` of what is LEFT, charging it for what it used — its + * whole grant if it timed out, the measured elapsed if it answered early. + * + * The fractional share is what reserves room for the steps after it. The client route + * takes half, so the fallback always has half; the fallback's RESPONSE takes half of what + * remains, so its BODY always has the rest. Reserving for the fallback but not for the + * body was the same starvation defect one level down — a response that used everything + * left the body unreadable, and a body that cannot be read authorizes nothing. + */ + const runStep = async (attempt, share) => { + const left = budget - consumed; + // AT LEAST A MILLISECOND WHILE ANY BUDGET REMAINS. Plain `Math.floor(left * share)` + // truncates to 0 on a tiny budget, and a zero grant is not a small wait — it is the + // step never being attempted: at deadlineMs=2 the fallback was never issued (fetchApi + // call count 0), the exact signature this change exists to remove, reproduced by the + // arithmetic meant to prevent it. + // + // Two earlier revisions of this comment got the tiny-budget case wrong in opposite + // directions — first claiming the floor made every budget reachable, then claiming it + // could not rescue deadlineMs=1. Measured: at deadlineMs of 1 and 2 the fallback IS + // issued and DOES answer, because a client route that returns instantly hands its grant + // back and the next step draws from what is left. Neither claim was checked before it + // was written, which is how a comment becomes the thing a later reader trusts. + // `share` is never above 1 for any step here, so `floor(left * share) <= left` already; + // the min() is a guard for a future share, not something that binds today. + const grant = left > 0 ? Math.max(1, Math.min(left, Math.floor(left * share))) : 0; + const startedStep = readClock(); + // `timers: null` is not `timers: undefined`, and only the latter reaches `withTimeout`'s + // own default — an explicit null read `.setTimer` off null and REJECTED out of a module + // that documents it always resolves, which two callers await with no catch of their own. + const outcome = await runTransport(attempt, grant, timers ?? undefined); + if (outcome === NO_ANSWER) { + // It ran out its whole grant — certain without measuring anything. + // + // A LATE TIMER IS DELIBERATELY NOT CHARGED, and this was tried the other way first. + // Chrome clamps hidden-tab timers to ~1/min after five minutes backgrounded, and a + // laptop resume does the same, so real elapsed can exceed the budget however this + // accounts for it — that is the environment, not the arithmetic. Charging the true + // overrun makes the accounting honest and the OUTCOME worse: a tab backgrounded for + // ten minutes reaches the fallback with a zero budget, so the write is refused + // outright instead of being retried by the route that still works. The command has + // already blown its 30s budget in that world; the useful thing left is to ASK, and + // the fallback usually answers in ~450ms. Preserving a number the environment has + // already broken, at the cost of the one route that can still answer, is exactly the + // trade that produced the earlier "refuses what main serves" regressions. + consumed += grant; + } else { + // IT ANSWERED EARLY, so the time it did not use goes back. Charging the full grant + // here was a real shipped regression, reproduced against both the parent and main: a + // client route that answers `null` in 200ms was still charged 10s, leaving the + // fallback 5s + 5s instead of ~19.8s, so a 5.4MB payload over a tunnel that BOTH + // other trees delivered at 7.5s was refused at 5.5s with most of the budget never + // granted to anything. The fallback is the entire reason this oracle exists; starving + // it to satisfy a bound is the wrong trade. + const spent = readClock() - startedStep; + consumed += Number.isFinite(spent) && spent >= 0 ? Math.min(spent, grant) : grant; + } + return { outcome, grant }; + }; + // On the shipped 20s budget: 10s for the client route, 5s for the response, 5s for the + // body. Every one of those is more than an order of magnitude above what this actually + // measures at. + const CLIENT_ROUTE_SHARE = 0.5; + const FALLBACK_RESPONSE_SHARE = 0.5; + const BODY_SHARE = 1; const failures = []; if (typeof getNodeDefs === "function") { - try { - const defs = await getNodeDefs(); + const { outcome, grant: clientMs } = await runStep(getNodeDefs, CLIENT_ROUTE_SHARE); + const kind = outcomeKind(outcome); + if (kind === "not-tried") { + // TRUE OF THE FIRST STEP, WHICH HAS SPENT NOTHING. "the budget was already spent" is + // a false cause here: on a degenerate budget nothing had been drawn when this ran. + // Naming a cause that did not happen is #982's original defect, and it is no more + // acceptable in a branch that is hard to reach than in one that is not. + failures.push(`api.getNodeDefs() was not attempted — the ${budget}ms budget leaves it no time`); + } else if (kind === "no-answer") { + // The #1161 case. Recorded as a failure like any other, and — critically — execution + // CONTINUES to the second transport, which is what this bound exists to reach. + // THE STEP'S OWN BUDGET, not the whole deadline. Browser-verified against a live + // 4304-type install: the client route is capped at half, so quoting `deadlineMs` + // here told the reader it had waited 20000ms when it had waited 10000ms. Naming a + // number that was never spent is the same defect as #982's "unreachable or the + // fetch failed" — a refusal asserting something it did not establish. + failures.push(`api.getNodeDefs() did not answer within its ${Math.round(clientMs)}ms share of the ${budget}ms budget`); + } else if (kind === "threw") { + failures.push(describeFailure("api.getNodeDefs() threw", outcome.err)); + } else { + const defs = outcome.value; if (usableDefs(defs)) return { [CACHE_OUTCOME]: true, defs, failures }; // AN EMPTY MAP IS AN ANSWER, NOT AN ABSENCE (codex). A client that deliberately // filters could express deny-all as `{}`, and consulting the raw route would then @@ -118,8 +487,6 @@ export async function fetchWholeObjectInfo({ getNodeDefs, fetchApi } = {}) { ` (${defs === null ? "null" : Array.isArray(defs) ? "an array" : typeof defs})`, ), ); - } catch (err) { - failures.push(describeFailure("api.getNodeDefs() threw", err)); } } else { failures.push("api.getNodeDefs is not a function on this frontend"); @@ -128,17 +495,62 @@ export async function fetchWholeObjectInfo({ getNodeDefs, fetchApi } = {}) { // SECOND TRANSPORT, same question. The reporter proved this route answers when the // client call does not — it is the one they ran by hand to show the backend was fine. if (typeof fetchApi === "function") { - try { - const res = await fetchApi("/object_info"); - if (!res || res.ok !== true) { - failures.push(describeFailure("GET /object_info was not OK", null, ` (status ${res?.status ?? "unknown"})`)); + const { outcome, grant: fallbackMs } = await runStep(() => fetchApi("/object_info"), FALLBACK_RESPONSE_SHARE); + const kind = outcomeKind(outcome); + if (kind === "not-tried") { + // TRUTHFUL ABOUT WHAT WAS NOT DONE. Saying this route "did not answer" when no + // request was ever sent is #982's original defect — a refusal asserting a cause it + // never established. The reserve above exists so this stays unreachable in practice. + failures.push("GET /object_info was not attempted — the budget was spent before it was reached"); + } else if (kind === "no-answer") { + failures.push(`GET /object_info did not answer within its ${Math.round(fallbackMs)}ms share of the ${budget}ms budget`); + } else if (kind === "threw") { + failures.push(describeFailure("GET /object_info threw", outcome.err)); + } else { + const res = outcome.value; + // #1161 — reading `ok`/`status` off the response is itself an operation that can + // throw: an extension may monkey-patch fetchApi and hand back a lazily-evaluated or + // proxied object. These reads used to sit inside this route's try/catch, and + // replacing that with a bound left them exposed — verified against main, where the + // same input produced a failures entry and here produced a rejection. + let responseOk = false; + let responseStatus = "unknown"; + try { + responseOk = !!res && res.ok === true; + // SANITIZE INSIDE THE GUARD. Reading `.status` is not the only operation that can + // throw — INTERPOLATING it does too (`Object.create(null)` cannot convert to a + // primitive), and that interpolation sits below this try. Verified against main, + // which returned a failures entry where this rejected. + responseStatus = sanitizeDetail(res?.status ?? "unknown") || "unknown"; + } catch (err) { + failures.push(describeFailure("GET /object_info returned an unreadable response", err)); + return { [CACHE_OUTCOME]: true, defs: null, failures }; + } + if (!responseOk) { + failures.push(describeFailure("GET /object_info was not OK", null, ` (status ${responseStatus})`)); } else { - const defs = await res.json(); - if (usableDefs(defs)) return { [CACHE_OUTCOME]: true, defs, failures }; - failures.push("GET /object_info returned no usable schema (an empty or non-object body)"); + // The BODY is a second I/O step, and it was inside the try/catch this bound + // replaced — an existing #982 test caught the escape. Reading a 5MB schema over a + // half-open connection can also stall, so it is bounded as well rather than merely + // re-caught: the response arriving is not the same event as the body arriving. + const { outcome: body, grant: bodyMs } = await runStep(() => res.json(), BODY_SHARE); + const bodyKind = outcomeKind(body); + if (bodyKind === "not-tried") { + failures.push("GET /object_info answered but its body was not read — the budget was spent"); + } else if (bodyKind === "no-answer") { + failures.push(`GET /object_info answered but its body did not arrive within its ${Math.round(bodyMs)}ms share of the ${budget}ms budget`); + } else if (bodyKind === "threw") { + // Deliberately the SAME wording as before. A parse failure used to surface + // through this route's catch, and an existing #982 test pins the sentence a user + // reads. This change is about bounding the waits, not about rewording refusals — + // improving the phrasing here would be a separate, reviewable decision. + failures.push(describeFailure("GET /object_info threw", body.err)); + } else { + const defs = body.value; + if (usableDefs(defs)) return { [CACHE_OUTCOME]: true, defs, failures }; + failures.push("GET /object_info returned no usable schema (an empty or non-object body)"); + } } - } catch (err) { - failures.push(describeFailure("GET /object_info threw", err)); } } else { failures.push("no fetchApi is wired for the fallback route");