test: make e2e error attribution total, and fix the README canary text
All checks were successful
check / check (push) Successful in 19s

The error collector had a window API (mark/since) and twice a record fell
outside somebody's window and was silently dropped, producing a green run
that proved nothing: first the mark started after test 1, discarding
everything recorded during launch; then the tail after the final test was
never read at all, so a request escaping the fixtures at the end of the
last test reported 5/5 passed and exit 0.

Rather than patch a second boundary and invite a third, the window
concept is gone. ErrorCollector exposes only take(), which always drains
everything outstanding, so successive takes partition the whole record
stream with no gaps, and seal(), which closes the stream at the end of
the run and routes stragglers straight to a failure. Attribution is
total by construction: launch through test 1 goes to test 1, each
subsequent interval to the test that ends it, the tail to the suite.

The tail also needs to exist before it can be drained. A request a test
fires without awaiting reaches the route handler about 10ms after that
test's function resolves, and closing the context does not wait for it,
so with no window at all it died unobserved. The run now keeps
collecting for a bounded 1.5s after the last test before teardown.

Also:

- README described a canary that was built, found to kill the service
  worker, and deleted. Replaced with what actually runs: the harness
  waits for the background worker's own startup blocklist fetch to reach
  the route handler and aborts if it does not. Documents
  --host-resolver-rules=MAP * ~NOTFOUND as defence in depth.
- The canary's failure message asserted traffic was escaping to the real
  internet and blamed the -e flag. It cannot distinguish that from a lost
  startup race, so it now states what was observed and lists both causes.
- E2E_TRACE_NETWORK was compared strictly to "1", so E2E_TRACE_NETWORK=true
  silently did nothing. Recognised on/off values are accepted and anything
  else is a hard error rather than a quiet default.
- The measured margin that makes the canary sound is route install at
  11-23ms against the worker fetch at 525-883ms, not the 30s timeout
  slack the comment cited.
This commit is contained in:
clawbot
2026-08-09 15:50:45 +00:00
parent a3075f2f47
commit a13862d991
4 changed files with 187 additions and 36 deletions

View File

@@ -104,12 +104,23 @@ allowed.
That interception covers the MV3 background service worker as well as the popup That interception covers the MV3 background service worker as well as the popup
page, which it does not by default — `script/test-e2e` sets page, which it does not by default — `script/test-e2e` sets
`PW_EXPERIMENTAL_SERVICE_WORKER_NETWORK_EVENTS=1` for it. Because that flag is `PW_EXPERIMENTAL_SERVICE_WORKER_NETWORK_EVENTS=1` for it. Because that flag is
experimental, the harness does not take it on trust: at launch it fetches a experimental, the harness does not take it on trust. At launch it waits for the
`.invalid` URL from inside the service worker that only the route handler can background worker's **own** startup request — the phishing blocklist fetch that
answer, and aborts the entire suite if the answer does not come back. Escaping `src/background/index.js` issues unconditionally — to arrive in the route
traffic fails the run instead of disappearing. To see what is actually being handler, and aborts the entire suite if none does within 30 seconds
intercepted, run with `E2E_TRACE_NETWORK=1` and every routed request is printed, (`tests/e2e/harness.js`). The check is passive on purpose: a synthetic probe
tagged `[sw]` or `[page]`. fetched from inside the worker via `worker.evaluate()` was tried first and
rejected, because evaluating in an extension service worker that early kills the
worker outright, destroying the thing being measured. Observing traffic the
extension already generates perturbs nothing. Losing the race fails closed — the
suite refuses to run rather than passing quietly.
As defence in depth, Chrome is also started with
`--host-resolver-rules=MAP * ~NOTFOUND`, so a request that ever did slip past
the route handler could not resolve a host at all. That only bounds the damage;
detecting escaping traffic remains the canary's job. To see what is actually
being intercepted, run with `E2E_TRACE_NETWORK=1` and every routed request is
printed, tagged `[sw]` or `[page]`.
**Any uncaught page error or `console.error` fails the run.** That is the point: **Any uncaught page error or `console.error` fails the run.** That is the point:
a `ReferenceError` from a used-but-not-imported identifier is invisible to a `ReferenceError` from a used-but-not-imported identifier is invisible to

View File

@@ -39,23 +39,55 @@ function isAllowed(text) {
return ALLOWED_ERRORS.some((a) => a.pattern.test(text)); return ALLOWED_ERRORS.some((a) => a.pattern.test(text));
} }
// Collects every uncaught page error, console.error and unstubbed
// request, and hands each one to exactly one reporter.
//
// This deliberately has NO window API. It used to expose mark()/since()
// so a test could ask for "the errors since I started", and that shape
// produced a green run that proved nothing twice over: first the mark
// started after test 1, so everything recorded during launch was
// discarded, then the tail after the final test was never read at all. In
// both cases a record fell outside somebody's window and vanished, which
// is the precise failure this harness exists to prevent.
//
// So there is no window left to fall outside of. take() is the only
// reader and it always takes everything outstanding, so successive takes
// partition the entire record stream with no gaps. seal() closes the
// stream once the run is over and routes anything later straight to a
// callback rather than into a list nobody reads again. Attribution is
// therefore total by construction, and the runner turns every attributed
// record into a failure.
class ErrorCollector { class ErrorCollector {
constructor() { constructor() {
this.entries = []; this.entries = [];
this.taken = 0;
this.onLate = null;
} }
record(kind, text) { record(kind, text) {
const line = kind + ": " + String(text).split("\n")[0]; const line = kind + ": " + String(text).split("\n")[0];
if (isAllowed(line)) return; if (isAllowed(line)) return;
if (this.onLate) {
// Sealed: no test and no suite phase is left to attribute
// this to, so hand it over now instead of accumulating it
// where nothing will look.
this.onLate(line);
return;
}
this.entries.push(line); this.entries.push(line);
} }
mark() { // Everything recorded since the previous take(). Never yields a
return this.entries.length; // record twice and never skips one.
take() {
const out = this.entries.slice(this.taken);
this.taken = this.entries.length;
return out;
} }
since(mark) { // Close the stream: later records go to onLate instead of the list.
return this.entries.slice(mark); seal(onLate) {
this.onLate = onLate;
} }
} }
@@ -89,8 +121,16 @@ async function serviceWorker(ctx) {
} }
// How long to wait for the background worker's first outbound request. // How long to wait for the background worker's first outbound request.
// Measured at roughly 650ms after the route is installed; the margin is //
// for a loaded machine, not for hope. // The margin that actually decides whether this check is sound is not
// this timeout — it is whether the route handler is installed before the
// worker fetches. Measured over several runs: route installation
// completes 11-23ms after the context comes up, and the worker's
// blocklist fetch arrives 525-883ms after that, so the route wins by
// roughly 25-50x. This 30s figure is only slack for a loaded machine on
// top of that; losing the race fails the run rather than passing it
// quietly, which was verified by forcing a 3s delay before route
// installation.
const WORKER_TRAFFIC_TIMEOUT_MS = 30000; const WORKER_TRAFFIC_TIMEOUT_MS = 30000;
// ctx.route() only sees service-worker requests when Playwright runs with // ctx.route() only sees service-worker requests when Playwright runs with
@@ -115,19 +155,29 @@ async function assertWorkerTrafficIntercepted(stubs) {
); );
if (seen) return seen; if (seen) return seen;
// State the observation, not a conclusion. This fires for at least
// two quite different causes and the harness cannot tell them apart
// from here, so guessing one of them in the message sends the reader
// the wrong way.
throw new Error( throw new Error(
"no service-worker request reached the route handler within " + "observed no service-worker request in the route handler within " +
WORKER_TRAFFIC_TIMEOUT_MS + WORKER_TRAFFIC_TIMEOUT_MS +
"ms, so background worker traffic is escaping this harness and " + "ms. Under working interception the background worker's " +
"going to the real internet. Run the suite through " + "startup blocklist fetch (src/background/index.js) reaches the " +
"script/test-e2e, which sets " + "handler about half a second after the route is installed. " +
"PW_EXPERIMENTAL_SERVICE_WORKER_NETWORK_EVENTS=1. If a " + "Two causes are plausible and this check cannot distinguish " +
"Playwright upgrade dropped that flag, replace the mechanism or " + "them: (1) service-worker interception is not in effect, so " +
"downgrade the isolation claims in tests/e2e/network.js and " + "that traffic went to the real internet unobserved — the suite " +
"README.md — do not delete this check. If instead the " + "must be run through script/test-e2e, which sets " +
"background worker legitimately stopped making startup " + "PW_EXPERIMENTAL_SERVICE_WORKER_NETWORK_EVENTS=1, and a " +
"requests, this check needs a new anchor, because there is no " + "Playwright upgrade may have dropped or renamed that flag; " +
"longer any worker traffic to observe", "(2) no worker request was made in the first place — the route " +
"lost the startup race, or the worker no longer fetches at " +
"startup, in which case this check needs a new anchor because " +
"there is no longer any worker traffic to observe. Either way " +
"the fix is a replacement mechanism or an honest downgrade of " +
"the isolation claims in tests/e2e/network.js and README.md — " +
"not deleting this check",
); );
} }

View File

@@ -146,6 +146,33 @@ function handleRpc(route, postData, report) {
return jsonResponse(route, Array.isArray(payload) ? replies : replies[0]); return jsonResponse(route, Array.isArray(payload) ? replies : replies[0]);
} }
const TRACE_TRUE = ["1", "true", "yes", "on"];
const TRACE_FALSE = ["", "0", "false", "no", "off"];
// Whether E2E_TRACE_NETWORK asks for the request trace.
//
// A set-but-unrecognised value is a hard error rather than a quiet
// "off": E2E_TRACE_NETWORK=true asking for a trace and getting silence
// is the operator being lied to about what the harness is doing, which
// is the whole failure mode this suite exists to eliminate. Refusing to
// guess costs one line and one obvious error message.
function traceEnabled(raw) {
if (raw === undefined || raw === null) return false;
const v = String(raw).trim().toLowerCase();
if (TRACE_TRUE.includes(v)) return true;
if (TRACE_FALSE.includes(v)) return false;
throw new Error(
"E2E_TRACE_NETWORK is set to " +
JSON.stringify(String(raw)) +
", which is not a recognised on/off value. Use one of " +
TRACE_TRUE.join(", ") +
" to enable the request trace, or one of " +
TRACE_FALSE.slice(1).join(", ") +
" to disable it. Refusing to guess: a diagnostic that silently " +
"does nothing is worse than one that is not there",
);
}
/** /**
* Route every http(s) request through local fixtures. * Route every http(s) request through local fixtures.
* *
@@ -174,7 +201,7 @@ async function installNetworkStubs(ctx, opts) {
// showing up with an [sw] tag is the proof that the worker really is // showing up with an [sw] tag is the proof that the worker really is
// intercepted and that the raw.githubusercontent.com stub below is // intercepted and that the raw.githubusercontent.com stub below is
// live code rather than decoration. // live code rather than decoration.
const trace = process.env.E2E_TRACE_NETWORK === "1"; const trace = traceEnabled(process.env.E2E_TRACE_NETWORK);
// Regex rather than a glob so chrome-extension:// resource loads are // Regex rather than a glob so chrome-extension:// resource loads are
// never touched — routing those would break the popup itself. // never touched — routing those would break the popup itself.

View File

@@ -20,6 +20,10 @@ const { STUB_TOKEN, STUB_TX_HASH } = require("./network");
const TEST_TIMEOUT_MS = 120000; const TEST_TIMEOUT_MS = 120000;
// How long to keep collecting after the final test returns; see the
// trailing drain in main().
const TRAILING_WATCH_MS = 1500;
const tests = []; const tests = [];
function test(name, fn) { function test(name, fn) {
@@ -152,13 +156,27 @@ async function main() {
page: null, page: null,
}; };
// Attribution of collected errors is total. session.errors has no
// window API at all: take() always drains everything outstanding, so
// successive takes partition the whole stream, and the phases below
// cover the entire life of the run. Nothing the collector holds can
// go unread.
//
// launch .. end of test 1 -> test 1 (so the worker's startup
// fetches land on a test, not
// nowhere)
// end of test k .. end of k+1 -> test k+1
// last test .. teardown -> the suite, via the trailing drain
// after the trailing drain -> seal(), which fails on the spot
//
// Two green-but-vacuous runs on this harness were the same shape: a
// record falling outside somebody's window and being dropped. First
// the mark started after test 1, discarding launch-time records;
// then the tail after the last test was never read. Patching a
// second boundary would have invited a third, so the window concept
// is gone rather than fixed.
let failed = 0; let failed = 0;
let n = 0; let n = 0;
// Starts at zero rather than at the current mark on purpose: errors
// and escaping requests recorded during launch — before any test ran,
// which is when the background worker does its startup fetches — are
// attributed to the first test instead of being discarded.
let mark = 0;
for (const t of tests) { for (const t of tests) {
n += 1; n += 1;
let failure = null; let failure = null;
@@ -168,11 +186,10 @@ async function main() {
failure = e.message; failure = e.message;
} }
// Any uncaught page error or console.error fails the test that // Any uncaught page error, console.error or unstubbed request
// provoked it, whether or not its assertions passed. This is the // fails the test that provoked it, whether or not its assertions
// mechanism that caught #150. // passed. This is the mechanism that caught #150.
const newErrors = session.errors.since(mark); const newErrors = session.errors.take();
mark = session.errors.mark();
if (!failure && newErrors.length > 0) { if (!failure && newErrors.length > 0) {
failure = "uncaught browser errors during this test"; failure = "uncaught browser errors during this test";
} }
@@ -189,12 +206,58 @@ async function main() {
} }
} }
// Keep watching after the last test returns, before tearing the
// browser down. A request a test fires without awaiting is still in
// flight when its function resolves; measured here it reaches the
// route handler about 10ms later, but closing the context does not
// wait for it — with no window at all the request dies unobserved
// and the run goes green, which is exactly how escaping traffic
// stays invisible.
//
// A fixed bounded window rather than a quiescence poll on purpose:
// the collector being quiet is not evidence, because a request that
// has not been dispatched yet has recorded nothing to be quiet
// about. Playwright offers no "is anything in flight" question to
// ask either — the route handler is the only observation point — so
// a grace period is the mechanism available, and this one is ~150x
// the measured latency for 1.5s on a ~25s suite.
await new Promise((resolve) => setTimeout(resolve, TRAILING_WATCH_MS));
await session.close(); await session.close();
// The tail. These cannot be blamed on any single test, so they are
// reported against the suite rather than guessed at — but they are
// reported, and they fail the run.
const trailing = session.errors.take();
// From here the run is over and there is nothing left to attribute a
// record to, so stragglers fail immediately instead of piling up
// where nothing will read them.
let late = 0;
session.errors.seal((line) => {
late += 1;
console.log("# FAILED: browser error recorded after the run ended");
console.log("# " + line);
process.exitCode = 1;
});
console.log( console.log(
"# " + (tests.length - failed) + "/" + tests.length + " passed", "# " + (tests.length - failed) + "/" + tests.length + " tests passed",
); );
if (failed > 0) {
if (trailing.length > 0) {
console.log(
"# " +
trailing.length +
" browser error(s) recorded after the last test finished, " +
"not attributable to any single test:",
);
for (const line of trailing) {
console.log("# " + line);
}
}
if (failed > 0 || trailing.length > 0 || late > 0) {
console.log("# FAILED"); console.log("# FAILED");
process.exitCode = 1; process.exitCode = 1;
} }