diff --git a/.gitea/workflows/e2e.yml b/.gitea/workflows/e2e.yml index 448040d..30fc7d3 100644 --- a/.gitea/workflows/e2e.yml +++ b/.gitea/workflows/e2e.yml @@ -35,10 +35,10 @@ on: [push] jobs: e2e-chrome: runs-on: ubuntu-latest - # Bounds the image build, a cold cache included, and both Chrome + # Bounds the image build, a cold cache included, and the three Chrome # programs, so a hung browser frees the shared runner. README.md # "In CI" has the measured times. - timeout-minutes: 20 + timeout-minutes: 40 steps: # actions/checkout v4.2.2, 2026-02-22 - uses: actions/checkout@11bd71901bbe5b1630ceea73d27597364c9af683 diff --git a/README.md b/README.md index 54a5f07..bc81dc2 100644 --- a/README.md +++ b/README.md @@ -527,6 +527,24 @@ one profile yields a single extension id, not two: Chrome does not load a second copy of an id it already has. The assertions are annotated as observations, so a Chrome that ever changes this fails the run instead of passing it. +Last, `make test-e2e` runs `tests/e2e/slowApproval.js`, which leaves a +transaction approval and a signature approval open for seven minutes, then +approves both and requires the site to receive the hash of the transaction the +stub node received and a signature that recovers to the address. Before the +approval window kept the background worker running, Chrome stopped it about six +minutes in and neither request was ever answered +([#540](https://git.eeqj.de/sneak/AutistMask/issues/540)). It is its own program +and does not use Playwright: Playwright keeps DevTools attached to the +background worker, and Chrome never stops a worker DevTools is attached to, so +no wait in the suite above can show the worker stopping. It starts Chromium +itself, speaks the DevTools protocol over `--remote-debugging-pipe`, and +attaches to pages only. Before raising the approvals it requires the worker to +stop on its own with nothing pending, so a run in which something else keeps the +worker running fails. The site is connected and the RPC endpoint set through the +extension's own screens, against the Firefox suite's loopback dApp page and stub +node (`tests/e2e/firefox/dapp.js`). Unlike the suite above, it does not fail on +page errors. + ### Firefox (`make test-e2e-firefox`) `make test-e2e-firefox` builds `dist/firefox/` and drives the **real popup in a @@ -707,11 +725,13 @@ installing Firefox, geckodriver and their system libraries. Both scripts now build their image with `--no-cache`, so every run pays the cold figure. Those `e2e-chrome` runs predate the cases that wait in real time for a receipt to end in error. `make test-e2e` took 3m51s locally with its image cached, so with the -image rebuilt every run, an `e2e-chrome` run comes to about seven minutes. +image rebuilt every run, an `e2e-chrome` run comes to about seven minutes. The +approvals left open for seven minutes (`tests/e2e/slowApproval.js`) add about +eight more, so about fifteen. Each e2e job has a `timeout-minutes` cap, so a hung build or browser ends the job instead of holding the shared runner: `e2e-firefox` 15 minutes and -`e2e-chrome` 20, each over two and a half times the job's slowest cold run. A +`e2e-chrome` 40, each over two and a half times the job's slowest cold run. A job that reaches its cap has hung; read it as a hang, not as a slow run to retry. The `check` job has no cap: `.gitea/workflows/check.yml` is the canonical copy from `sneak/prompts`, kept byte-identical. @@ -806,6 +826,16 @@ on the next event. Two consequences shape every recurring job in the background: service worker at all — the one remaining user of it, `src/shared/ens.js`, runs only in the popup and is marked as such. +Pending approvals are the exception: an approval waiting for the user, and the +site's request waiting on it, live only in the worker's memory, and only the +worker that received the request can answer it. Chrome stopped the worker about +six minutes after a site's request even with the approval window still open, and +the user's answer then reached nobody. So while an approval window is open it +posts an empty message on its approval port every 20 seconds, and each message +is an event that keeps the worker running: an approval stays answerable however +long the user takes. A worker that stops for another reason, a crash say, still +loses the approvals open in it. + The job also carries a freshness guard, and a guard must never be timed to the alarm period it gates. The guard is measured from the moment the last run finished, which is one run-duration after the alarm that started it, so a guard diff --git a/script/test-e2e b/script/test-e2e index 2246905..8ee9932 100755 --- a/script/test-e2e +++ b/script/test-e2e @@ -97,6 +97,18 @@ main() { -e HOME=/tmp \ "$(cat "$IIDFILE")" \ node tests/e2e/storagePartition.js + + # Approvals left open for seven minutes, past the point where Chrome + # stopped the background worker before the approval window kept it + # running. Its own program, without Playwright: Playwright keeps DevTools + # attached to the worker, and Chrome never stops a worker DevTools is + # attached to. It reaches nothing but its own loopback server. + echo "Running the approvals left open for seven minutes..." + docker run --rm \ + --ipc=host \ + -e HOME=/tmp \ + "$(cat "$IIDFILE")" \ + node tests/e2e/slowApproval.js } main "$@" diff --git a/src/background/index.js b/src/background/index.js index 00fa439..d755075 100644 --- a/src/background/index.js +++ b/src/background/index.js @@ -649,6 +649,9 @@ runtime.onConnect.addListener((port) => { pendingApprovals[id].portConnected = true; } port.onMessage.addListener((msg) => { + // The window also posts an empty message every 20 seconds while + // it is open, only so that Chrome keeps this worker, and the + // approval in it, running (src/popup/views/approval.js, show()). if (!msg || msg.type !== "AUTISTMASK_APPROVAL_DECISION") return; if (!isExtensionSender(port.sender)) return; const approval = pendingApprovals[id]; diff --git a/src/popup/views/approval.js b/src/popup/views/approval.js index 823e465..4124b2e 100644 --- a/src/popup/views/approval.js +++ b/src/popup/views/approval.js @@ -784,6 +784,22 @@ async function show(id) { approvalId = id; approvalPort = runtimeApi().connect({ name: "approval:" + id }); + // The approval this window answers, and the site's request waiting on it, + // exist only in the background worker's memory. Chrome stops that worker + // about six minutes after the site's request even while the user is still + // deciding, and the approval is lost with it. A message on this port is an + // event, and an event keeps the worker running, so one is sent every 20 + // seconds for as long as this window is open. The background ignores it. + const port = approvalPort; + const timer = setInterval(() => { + try { + port.postMessage({}); + } catch { + // The worker is gone anyway, and the port with it. + clearInterval(timer); + } + }, 20000); + let details = null; try { details = await sendMessage({ type: "AUTISTMASK_GET_APPROVAL", id }); diff --git a/tests/e2e/slowApproval.js b/tests/e2e/slowApproval.js new file mode 100644 index 0000000..6e6b7bd --- /dev/null +++ b/tests/e2e/slowApproval.js @@ -0,0 +1,495 @@ +// A transaction approval and a signature approval the user leaves open for +// seven minutes are still answered, and the site receives both results +// (https://git.eeqj.de/sneak/AutistMask/issues/540). +// +// Both approvals, and the site's requests waiting on them, live only in the +// background worker's memory. With nothing else going on, Chrome stopped that +// worker about six minutes after the site's request, while the window was +// still open, and the user's answer then reached nobody. The approval window +// now posts on its approval port every 20 seconds, which keeps the worker +// running (src/popup/views/approval.js, show()). +// +// A separate program from run.js, and not driven by Playwright: Playwright +// keeps DevTools attached to the background worker, and Chrome never stops a +// worker DevTools is attached to, so in run.js the worker outlives any wait +// and a wait there proves nothing. This program starts Chromium itself and +// speaks the DevTools protocol over the pipe Chromium opens for it +// (--remote-debugging-pipe), attaching to pages only, never to the worker. +// Before the approvals are raised it watches the worker stop on its own, so a +// run in which something else keeps the worker running cannot pass. +// +// The dApp page and the stub node are the Firefox suite's loopback ones +// (tests/e2e/firefox/dapp.js). The site is connected and the node chosen +// through the extension's own screens, so nothing is written to its storage +// from outside. +// +// Run through script/test-e2e, which builds the extension and the pinned +// container. +// +// node tests/e2e/slowApproval.js + +"use strict"; + +const fs = require("fs"); +const os = require("os"); +const path = require("path"); +const { spawn } = require("child_process"); + +const { chromium } = require("playwright-core"); +const { + Transaction, + getAddress, + getBytes, + hexlify, + parseEther, + toQuantity, + toUtf8Bytes, + verifyMessage, +} = require("ethers"); + +const { PASSWORD } = require("./harness"); +const { STUB_COUNTERPARTY } = require("./network"); +const { startDappServer } = require("./firefox/dapp"); + +const DIST_CHROME = path.resolve(__dirname, "..", "..", "dist", "chrome"); + +// Chrome stopped the worker six minutes after the site's request when nothing +// kept it running, so the approvals are left open for longer than that. +const APPROVAL_WAIT_MS = 7 * 60 * 1000; + +// With nothing pending, Chrome stops the worker 30 seconds after its last +// event; this is how long the program waits to see that. +const IDLE_STOP_TIMEOUT_MS = 90000; + +const SIGN_HEX = hexlify(toUtf8Bytes("AutistMask e2e: a slow signature")); + +const checks = []; +let failed = 0; + +function check(name, cond, detail) { + checks.push(name); + if (cond) { + console.log("ok " + checks.length + " - " + name); + } else { + failed += 1; + console.log("not ok " + checks.length + " - " + name); + if (detail) console.log(" " + detail); + } +} + +function sleep(ms) { + return new Promise((resolve) => setTimeout(resolve, ms)); +} + +// Poll `probe` until it returns something truthy, and return that. +async function until(what, probe, timeout = 30000) { + const deadline = Date.now() + timeout; + for (;;) { + const value = await probe().catch(() => null); + if (value) return value; + if (Date.now() > deadline) { + throw new Error( + "gave up after " + timeout + "ms waiting for " + what, + ); + } + await sleep(250); + } +} + +// The DevTools protocol over Chromium's pipe: commands go to its fd 3, and +// replies and events come back on its fd 4, each one JSON message ended by a +// NUL byte. Events are not used and are dropped. Returns send(method, params, +// sessionId), which resolves with the command's result. +function devtools(browser) { + const waiting = new Map(); + let nextId = 1; + let pending = ""; + const replies = browser.stdio[4]; + replies.setEncoding("utf8"); + replies.on("data", (chunk) => { + pending += chunk; + let end; + while ((end = pending.indexOf("\0")) !== -1) { + const message = JSON.parse(pending.slice(0, end)); + pending = pending.slice(end + 1); + const caller = waiting.get(message.id); + if (!caller) continue; + waiting.delete(message.id); + if (message.error) { + caller.reject( + new Error(caller.method + ": " + message.error.message), + ); + } else { + caller.resolve(message.result); + } + } + }); + replies.on("close", () => { + for (const caller of waiting.values()) { + caller.reject(new Error("the browser exited")); + } + waiting.clear(); + }); + return (method, params = {}, sessionId) => + new Promise((resolve, reject) => { + const id = nextId++; + waiting.set(id, { method, resolve, reject }); + browser.stdio[3].write( + JSON.stringify({ id, method, params, sessionId }) + "\0", + ); + }); +} + +// Attach to a page and return a function that evaluates an expression in it, +// awaiting a promise it returns, and resolves with the value. +async function attach(send, targetId) { + const { sessionId } = await send("Target.attachToTarget", { + targetId, + flatten: true, + }); + return async (expression) => { + const r = await send( + "Runtime.evaluate", + { expression, awaitPromise: true, returnByValue: true }, + sessionId, + ); + if (r.exceptionDetails) { + throw new Error( + "evaluating " + + expression.slice(0, 80) + + " threw: " + + JSON.stringify(r.exceptionDetails.exception || {}), + ); + } + return r.result.value; + }; +} + +// Whether the page has loaded and shows the element with this id: the +// `hidden` class showView() keeps on every other view is on neither it nor +// anything around it. +function shows(id) { + return ( + "document.readyState === 'complete' &&" + + " !!document.getElementById(" + + JSON.stringify(id) + + ") && !document.getElementById(" + + JSON.stringify(id) + + ").closest('.hidden')" + ); +} + +// Set an input's value and fire the input event typing would fire. +function typeInto(id, value) { + return ( + "(() => { const el = document.getElementById(" + + JSON.stringify(id) + + "); el.value = " + + JSON.stringify(value) + + "; el.dispatchEvent(new Event('input', { bubbles: true })); })()" + ); +} + +function click(id) { + return "document.getElementById(" + JSON.stringify(id) + ").click()"; +} + +// The outcome of a request the dApp page started with __dapp.start(), or +// {settled: "pending"} if it has not settled within `timeout`. +function settled(key, timeout = 30000) { + return ( + "Promise.race([window.__dapp.settle(" + + JSON.stringify(key) + + "), new Promise((r) => setTimeout(() => r({ settled: 'pending' }), " + + timeout + + "))])" + ); +} + +async function main() { + if (!fs.existsSync(path.join(DIST_CHROME, "manifest.json"))) { + console.error( + "slowApproval: no unpacked build at " + + DIST_CHROME + + " — run make build first", + ); + process.exitCode = 1; + return; + } + + const node = await startDappServer(); + const profile = fs.mkdtempSync( + path.join(os.tmpdir(), "autistmask-slow-approval-"), + ); + const browser = spawn( + chromium.executablePath(), + [ + "--headless", + // The container runs unprivileged, as in harness.js. + "--no-sandbox", + "--remote-debugging-pipe", + "--user-data-dir=" + profile, + "--disable-extensions-except=" + DIST_CHROME, + "--load-extension=" + DIST_CHROME, + // Nothing but the loopback dApp page and stub node can be reached. + "--host-resolver-rules=MAP * ~NOTFOUND, EXCLUDE 127.0.0.1", + "about:blank", + ], + { stdio: ["ignore", "ignore", "ignore", "pipe", "pipe"] }, + ); + + try { + const send = devtools(browser); + const targets = async () => + (await send("Target.getTargets")).targetInfos; + + const worker = await until("the background worker", async () => + (await targets()).find( + (t) => + t.type === "service_worker" && + t.url.startsWith("chrome-extension://"), + ), + ); + // The extension id is the host of the worker's URL, as in harness.js. + const popupUrl = + "chrome-extension://" + + new URL(worker.url).host + + "/src/popup/index.html"; + const workerRunning = async () => + (await targets()).some((t) => t.url === worker.url); + const openPage = async (url) => { + const { targetId } = await send("Target.createTarget", { url }); + return { targetId, evaluate: await attach(send, targetId) }; + }; + const approvalPages = async () => + (await targets()).filter( + (t) => t.type === "page" && t.url.includes("?approval="), + ); + + // A wallet, through the popup's own screens, and the stub node as its + // RPC endpoint, through Settings. + const popup = await openPage(popupUrl); + await until("the welcome screen", () => + popup.evaluate(shows("view-welcome")), + ); + await popup.evaluate(click("btn-welcome-add")); + await until("the add wallet screen", () => + popup.evaluate(shows("view-add-wallet")), + ); + await popup.evaluate(click("btn-generate-phrase")); + await until("a generated recovery phrase", () => + popup.evaluate( + "document.getElementById('wallet-mnemonic').value.trim()" + + ".split(/\\s+/).length >= 12", + ), + ); + await popup.evaluate(typeInto("add-wallet-password", PASSWORD)); + await popup.evaluate(typeInto("add-wallet-password-confirm", PASSWORD)); + await popup.evaluate(click("btn-add-wallet-confirm")); + await until( + "the main screen", + () => popup.evaluate(shows("view-main")), + 60000, + ); + await popup.evaluate(click("btn-settings")); + await until("the settings screen", () => + popup.evaluate(shows("view-settings")), + ); + await popup.evaluate(typeInto("settings-rpc", node.rpcUrl)); + await popup.evaluate(click("btn-save-rpc")); + await until("the stub node saved as the RPC endpoint", () => + popup.evaluate( + "new Promise((resolve) => chrome.storage.local.get(" + + "'autistmask', (r) => resolve(r.autistmask.rpcUrl === " + + JSON.stringify(node.rpcUrl) + + ")))", + ), + ); + await send("Target.closeTarget", { targetId: popup.targetId }); + + // The site, connected through the real prompt with "Remember", so + // the connection is stored rather than held by the worker. + const dapp = await openPage(node.url); + await until("the injected provider", () => + dapp.evaluate("!!window.ethereum && !!window.__dapp"), + ); + await dapp.evaluate( + "window.__dapp.start('accounts', 'eth_requestAccounts', [])", + ); + const prompt = await until( + "the connection prompt", + async () => (await approvalPages())[0], + ); + const inPrompt = await attach(send, prompt.targetId); + await until("the connection prompt's screen", () => + inPrompt(shows("view-approve-site")), + ); + await inPrompt( + "document.getElementById('approve-remember').checked = true", + ); + // The prompt closes itself on the click. + await inPrompt(click("btn-approve")).catch(() => {}); + const accounts = await dapp.evaluate(settled("accounts")); + if (accounts.settled !== "resolved") { + throw new Error( + "the site could not be connected: " + JSON.stringify(accounts), + ); + } + const address = getAddress(accounts.result[0]); + console.log("# address " + address + ", site " + node.origin); + + // The control: with nothing pending, the worker stops on its own. + // Were something else keeping it running, the wait below would + // prove nothing. + const idleStart = Date.now(); + const stoppedWhenIdle = await until( + "the idle worker to stop", + async () => !(await workerRunning()), + IDLE_STOP_TIMEOUT_MS, + ).catch(() => false); + check( + "with nothing pending, Chrome stops the background worker on its own", + stoppedWhenIdle, + "the worker was still running " + + IDLE_STOP_TIMEOUT_MS / 1000 + + "s after its last event, so something other than the " + + "approval windows is keeping it running", + ); + console.log( + "# idle worker stopped after " + + Math.round((Date.now() - idleStart) / 1000) + + "s", + ); + + // A transaction approval and a signature approval, both open at once. + await dapp.evaluate( + "window.__dapp.start('tx', 'eth_sendTransaction', [" + + JSON.stringify({ + from: address, + to: STUB_COUNTERPARTY, + value: toQuantity(parseEther("0.01")), + }) + + "])", + ); + await until("the transaction approval window", async () => + (await approvalPages()).length === 1 ? true : null, + ); + await dapp.evaluate( + "window.__dapp.start('sign', 'personal_sign', [" + + JSON.stringify(SIGN_HEX) + + ", " + + JSON.stringify(address) + + "])", + ); + const windows = await until("both approval windows", async () => { + const pages = await approvalPages(); + return pages.length === 2 ? pages : null; + }); + let txWindow = null; + let signWindow = null; + for (const page of windows) { + const evaluate = await attach(send, page.targetId); + const view = await until("an approval screen", () => + evaluate( + "(" + + shows("view-approve-tx") + + ") ? 'tx' : (" + + shows("view-approve-sign") + + ") ? 'sign' : null", + ), + ); + if (view === "tx") txWindow = evaluate; + if (view === "sign") signWindow = evaluate; + } + if (!txWindow || !signWindow) { + throw new Error("the two windows are not one of each kind"); + } + + // The user takes seven minutes. The worker is checked every two + // seconds, and the wait ends early if Chrome stops it. + const opened = Date.now(); + let stoppedAfter = null; + while (Date.now() - opened < APPROVAL_WAIT_MS) { + if (!(await workerRunning())) { + stoppedAfter = Math.round((Date.now() - opened) / 1000); + break; + } + await sleep(2000); + } + check( + "the background worker keeps running while both approvals are open", + stoppedAfter === null, + "Chrome stopped the worker " + + stoppedAfter + + "s after the approvals opened", + ); + + await txWindow(typeInto("approve-tx-password", PASSWORD)); + await txWindow(click("btn-approve-tx")); + await signWindow(typeInto("approve-sign-password", PASSWORD)); + // The window closes itself once the signature is handed over. + await signWindow(click("btn-approve-sign")).catch(() => {}); + + const tx = await dapp.evaluate(settled("tx")); + const broadcast = node.broadcast.map((raw) => Transaction.from(raw)); + check( + "the transaction approved after seven minutes reaches the site", + tx.settled === "resolved" && + broadcast.length === 1 && + tx.result === broadcast[0].hash && + getAddress(broadcast[0].from) === address, + "the page got " + + JSON.stringify(tx) + + " and the node received " + + broadcast.length + + " transaction(s)", + ); + + const sign = await dapp.evaluate(settled("sign")); + check( + "the signature approved after seven minutes reaches the site", + sign.settled === "resolved" && + getAddress(verifyMessage(getBytes(SIGN_HEX), sign.result)) === + address, + "the page got " + JSON.stringify(sign), + ); + } catch (e) { + failed += 1; + console.log("# ERROR: " + (e && e.stack ? e.stack : e)); + } finally { + if (browser.exitCode === null && browser.signalCode === null) { + const exited = new Promise((resolve) => + browser.once("exit", resolve), + ); + browser.kill(); + await exited; + } + await node.close(); + // Chromium's helper processes can still be writing to the profile + // for a moment after the browser process itself has exited. + fs.rmSync(profile, { recursive: true, force: true, maxRetries: 5 }); + } + + console.log("1.." + checks.length); + if (checks.length === 0) { + console.log("# FAILED: this program asserted nothing"); + process.exitCode = 1; + return; + } + console.log( + "# " + + (checks.length - failed) + + "/" + + checks.length + + " checks passed", + ); + if (failed > 0) { + console.log("# FAILED"); + process.exitCode = 1; + } +} + +main().catch((e) => { + console.error("slowApproval: " + (e && e.stack ? e.stack : e)); + process.exitCode = 1; +});