Skip to content

fix(cli): outwait the main process on browser commands, and say what timed out - #153

Open
capad-xyz wants to merge 1 commit into
amirlehmam:masterfrom
capad-xyz:fix/cli-browser-timeout
Open

fix(cli): outwait the main process on browser commands, and say what timed out#153
capad-xyz wants to merge 1 commit into
amirlehmam:masterfrom
capad-xyz:fix/cli-browser-timeout

Conversation

@capad-xyz

Copy link
Copy Markdown
Contributor

Summary

wmux browser open <url> fails with a bare Error: timeout after ~5s on any page that takes longer than that to load — while the navigation itself goes on to succeed. The CLI applies one flat 5s deadline to every V2 method, but the main process is allowed to spend considerably longer serving a browser command.

The deeper problem is the second-order one: because the client deadline is shorter than the server's own budget, the server's real error message can never reach the user. A bare timeout is the only thing a slow or broken browser command can print, and it reads like a broken install.

Repro

Against a healthy wmux (v0.46.0, Windows 11), with a browser pane open and CDP attached. Any page slower than 5s will do; a local server makes it deterministic:

// slow-server.js — headers immediately, body finishes at 12s
require('http').createServer((req, res) => {
  res.writeHead(200, { 'Content-Type': 'text/html' });
  res.write('<html><body>loading');
  setTimeout(() => res.end('done</body></html>'), 12000);
}).listen(8931, '127.0.0.1');
$ wmux browser open http://127.0.0.1:8931/
Error: timeout
exit=1  elapsed_ms=5157

The navigation was not the problem. Sending the identical request over the pipe by hand, with a 40s deadline instead of 5s:

replied after 12017ms: {"result":{"ok":true},"id":1}

The server answered correctly. The CLI just stopped listening at 5s.

Root cause

sendV2 hard-codes 5000ms and rejects with new Error('timeout'):

const timer = setTimeout(() => { client.end(); reject(new Error('timeout')); }, 5000);

Three main-process budgets sit at or above that number, so the CLI is structurally guaranteed to lose the race:

Server-side wait Budget Source
navigate() waiting for did-finish-load 30000ms cdp-bridge.ts#L212
wait() polling for a ref 10000ms cdp-bridge.ts#L373
readying a browser (pane split, then poll for CDP attach) 5000ms v2-browser.ts#L33-L37, #L100

Two consequences, and the second is the one that costs debugging time:

  1. A command that succeeds late is reported as a failure. browser open is effectively nondeterministic — it passes or fails on page speed, and when it "fails" the navigation has still happened.
  2. The server's own diagnosis is unreachable. Could not open browser panel, browser_not_open and the careful ref_not_found: … the last snapshot of this browser has @e1..@eN message from browser.click/get_text always fail with ref_not_found right after a fresh browser.snapshot #121 all arrive after the CLI has hung up. The user gets timeout instead.

A note on the obvious-looking diagnosis

I first went after this as a missing-caller bug: no WMUX_SURFACE_ID outside a pane → no caller attached → main can't route the request. That turns out not to be what is happening, and I want to flag it since it is the intuitive reading.

With no caller, resolveBrowserWcId deliberately falls back to legacyWcId() — the documented shared-browser path for manual human use (v2-browser.ts#L8-L9, #L68). That path works fine:

$ wmux browser open https://example.com     # no WMUX_SURFACE_ID anywhere
{ "ok": true }                               # 1709ms

And the failure reproduces just as reliably with a valid caller set:

$ WMUX_SURFACE_ID=surf-617012f2-… wmux browser open http://127.0.0.1:8931/
Error: timeout
exit=1  elapsed_ms=5124

Same result, 5124ms. The caller is irrelevant to this failure; the deadline is the whole story. Anywhere setting WMUX_SURFACE_ID appears to fix it, what actually changed is which resolution path ran and whether it happened to finish inside 5s.

The fix

Derive each browser verb's client deadline from the budget the server may spend on it, so the main process always loses the race and its own error is what surfaces. BROWSER_READY_MS + verbBudget + slack: 40s for open, 20s for wait (or the explicit ms plus headroom), 10s for everything else. The 5s default is unchanged for every other V2 method.

Make the timeout message diagnostic. It now names the method and the deadline actually waited, and says the command may have completed anyway — because it may have.

Make the two cdp-bridge timeouts earn their keep. They also threw a bare new Error('timeout'). That was invisible before (the CLI's own timeout always fired first); now that it is what the user reads, it should say which operation stalled, for how long, and on what. This is the same treatment ref_not_found got in #121.

Add --surface to the browser verbs, matching send / read-screen / agent-activity / report-agent. A shell wmux did not spawn has no $WMUX_SURFACE_ID and so had no way to say which pane's browser it meant; the legacy fallback picks the most-recently-attached one, which is arbitrary when several exist. The flag is stripped before the verb reads its positional args, so browser type e5 --surface surf-x hello world still types hello world.

Options I considered

  1. Fail fast when there is no caller, with an actionable message. Rejected: it would turn a working path into an error. The no-caller fallback is deliberate and, as shown above, works — and it is not what breaks here.
  2. --surface alone. Useful, and included, but it does not fix the reported bug at all: the failure reproduces with a valid caller.
  3. Fall back to the active surface when no caller is set. Rejected, and I would push back on it: resolveBrowserWcId binds a caller to its own browser and records it in boundBrowserSurfaces so a second agent never adopts the first agent's browser. Silently substituting "the active surface" for an absent caller would let an agent-less invocation adopt a browser an agent already owns — exactly the Concurrent agents share a single browser window, causing interference #62 clobbering, reintroduced through the back door.
  4. Raise the flat deadline for everything. Rejected: it would slow the failure path for every method that legitimately answers in milliseconds, and it papers over the client/server mismatch rather than fixing it.

What I deliberately did not change

  • The isolation contract (Concurrent agents share a single browser window, causing interference #62). No change to resolveBrowserWcId, to how callers bind to browser surfaces, or to the no-caller fallback. --surface only supplies from a flag what a pane already supplies from the environment.
  • The server-side budgets themselves. 30s/10s/5s are the main process's calls to make; the CLI now accommodates them instead of contradicting them. The tests read those numbers out of the main-process source rather than restating them, so changing one there fails here rather than silently reintroducing the mismatch.
  • The 5s default for non-browser methods.
  • browser.batch, which the CLI does not expose.
  • The diff-provider snapshot code, untouched.

Tests

tests/unit/browser-timeout.test.ts (new, 12 cases) and 2 added to tests/unit/cdp-bridge.test.ts. Following the approach in packaging.test.ts, the deadline assertions are derived from the main-process source rather than restated, so a raised default in cdp-bridge.ts fails the test instead of quietly recreating the bug.

Confirmed the tests fail against the old behaviour: pinning browserDeadline back to a flat 5000 fails exactly the 4 cases that describe the bug.

To make the CLI importable by tests at all, main() is now guarded by require.main === module. Nothing imports src/cli/wmux.ts as a module today — it is only ever executed as a script, where the guard is true. I kept everything in the one file rather than extracting a module, since the release process copies dist/cli/wmux.js individually and a new sibling would not be packaged.

Test Files  1 failed | 72 passed (73)
Tests       1 failed | 848 passed (849)

The one failure is tests/unit/cdp-proxy.test.ts > falls back to a free port instead of raising an uncaught error. It fails identically on a clean master checkout with nothing applied, so it is pre-existing and not from this PR — it looks environment-dependent (the default port being free on this machine). I left it alone rather than fold an unrelated fix in here.

Verification

Built and run against a live wmux instance, same command, before and after:

### BEFORE (shipped 0.46.0 CLI)
$ wmux browser open http://127.0.0.1:8931/
Error: timeout
exit=1  elapsed_ms=5157

### AFTER (this branch)
$ node dist/cli/wmux.js browser open http://127.0.0.1:8931/
{ "ok": true }
exit=0  elapsed_ms=12212

Also verified live: --surface <id> drives the named pane's browser from a shell wmux did not spawn; browser snapshot still returns in ~215ms (no added latency on the fast path); non-browser methods unaffected; unknown verbs still exit 1.

On a URL that never finishes loading, the CLI now waits and receives the server's answer at 30s rather than its own at 5s — which is the plumbing fix working end to end. The running instance there was 0.46.0, so the text it returned was still the old bare timeout; the new cdp-bridge wording is covered by unit tests rather than that live run, since exercising it would have meant restarting the instance.

…timed out

`wmux browser open <url>` printed a bare `Error: timeout` after ~5s on any page
slower than that — while the navigation itself went on to succeed.

sendV2 applied one flat 5000ms deadline to every V2 method, but the main process
is allowed to spend far longer serving a browser command: cdp-bridge's navigate()
waits 30s for did-finish-load and wait() polls for 10s, and before either runs
v2-browser may split a pane and poll a further 5s for CDP to attach. The client
deadline was therefore shorter than the server's own budget, which had two
consequences — the second worse than the first:

  1. A command that succeeded late was reported as a failure.
  2. The server's real diagnosis ('Could not open browser panel',
     'browser_not_open', 'ref_not_found: …') could never reach the user, because
     it arrived after the CLI had already hung up. A bare `timeout` was all that
     was left, which reads like a broken install rather than a slow page.

Give each browser verb a deadline derived from the budget the server may spend on
it, so the main process always loses the race and its own error is what surfaces.
The 5s default is unchanged for every other method.

Both cdp-bridge timeouts then had to earn their keep, since they are now actually
read: they named neither the operation, nor its budget, nor what it was waiting
on. They do now.

Also add --surface to the browser verbs, matching send / read-screen /
agent-activity. A shell wmux did not spawn has no $WMUX_SURFACE_ID and so had no
way to say which pane's browser it meant. This only supplies from a flag what a
pane supplies from the environment — the issue amirlehmam#62 isolation routing, and the
no-caller fallback to the shared browser, are untouched.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant