coilyco-flight-deck/mcp-beaver

Watch

Upstream reconnect still fails with #67 Bad Request on the `94e4050` image, now instantly rather than after a hang #85

New issue

Closed

opened 2026-08-19 04:15:28 +00:00 by coilyco-ops · 1 comment

coilyco-ops commented

2026-08-19 04:15:28 +00:00

Member

Read-only inspection of the running sirens-dowel-playwright-mcp pod. Nothing changed.

94e4050 ("fix(upstream): hold the standalone stream, or every tool call hangs") closed #80. The hang it measured is gone. The reconnect failure #80 was actually titled for is not, and it reproduces on the fixed image.

The image is the fixed one

Image:         mcp-beaver:94e40505b0c61763f37120e5cde604afc4e68631
Started:       2026-08-19T02:50:23Z
Restart Count: 0

94e4050 was committed at 02:41Z and deploy rolled it out at 03:00Z. Both failures below are after that.

Same error string, same duration, post-fix

{"time":"2026-08-19T04:04:41Z","tool":"browser_navigate","duration_ms":7,
 "reason":"refresh upstream tools: calling \"tools/list\": sending \"tools/list\": Bad Request
           (reconnect also failed: reconnect upstream MCP \"http://127.0.0.1:8931/mcp\":
            sending \"notifications/initialized\": Bad Request)"}

{"time":"2026-08-19T04:12:00Z","tool":"browser_navigate","duration_ms":4,
 "reason":"mcp-beaver: upstream MCP session is closed
           (reconnect also failed: reconnect upstream MCP \"http://127.0.0.1:8931/mcp\":
            sending \"notifications/initialized\": Bad Request)"}

Those are #80's two quoted blocks, near enough verbatim, including duration_ms: 4.

Why the fix does not cover it, as I read it

94e4050 reasons that a call answered on the standalone stream no longer hangs, so the session stops dying, so the broken reconnect is never reached. The first half held and the second did not. The session still reaches a closed state, and when it does, notifications/initialized still comes back Bad Request, which is #67's string.

Duration is the discriminator worth keeping: #80's hang was 59.9s. These are 4ms and 7ms. The failure is now instant rather than slow, which is consistent with the hang being fixed and the recovery path still being broken underneath it.

It is not the whole server

Another client ran a clean sequence against this same pod at 03:23:53 to 03:24:06 with every call ok: browser_wait_for, browser_snapshot, browser_click, browser_navigate, browser_type. So the browser and the fixed wrapper both work. Splitting the pod log by trace id, every call carrying one is the Dowel lane's and every one of those failed.

Two theories I built and discarded, so nobody rebuilds them

Shared-session contention between clients. sirens-dowel-playwright-mcp-values.yaml records --shared-browser-context as deliberately absent on this lane, and #80 already refuted a one-session-at-a-time upstream by dialling a second session cleanly.
A stale image carrying the pre-fix build. The digest above is 94e4050.

94e4050's own warning is the reason I am filing rather than guessing further: a dead upstream session makes the next call reconnect, that dial also fails, and the reported reason is the reconnect's rather than the cause beneath it. So this error string has now misdirected at least three investigations, mine included. Whatever closes this should probably make the underlying cause visible rather than only the reconnect's complaint.

Standing, and why the timing matters

sirens-dowel has made 14 browser tool calls in 7 days and all 14 failed, measured in SigNoz on attribute.mcp.tool.name LIKE 'browser%' grouped by outcome. There is no successful call on this lane at any point in that window.

The lane advertises playwright in its tool list and offers it when asked what it can do, and it is live on a stream at 11:00 PT today. A capability with a 0% lifetime success rate is being advertised as available.

Complete when

A Dowel browser call succeeds against a running pod, evidenced by a log line rather than by a healthy pod.
The failure surfaces the cause rather than the reconnect's complaint, so the next occurrence does not cost another investigation.
Consider reopening #80 rather than tracking this separately, since this is the failure its title names.

Refs: #80, #67, #79

**Read-only inspection of the running `sirens-dowel-playwright-mcp` pod. Nothing changed.** `94e4050` ("fix(upstream): hold the standalone stream, or every tool call hangs") closed #80. The hang it measured is gone. **The reconnect failure #80 was actually titled for is not**, and it reproduces on the fixed image. ## The image is the fixed one ``` Image: mcp-beaver:94e40505b0c61763f37120e5cde604afc4e68631 Started: 2026-08-19T02:50:23Z Restart Count: 0 ``` `94e4050` was committed at 02:41Z and deploy rolled it out at 03:00Z. Both failures below are after that. ## Same error string, same duration, post-fix ```json {"time":"2026-08-19T04:04:41Z","tool":"browser_navigate","duration_ms":7, "reason":"refresh upstream tools: calling \"tools/list\": sending \"tools/list\": Bad Request (reconnect also failed: reconnect upstream MCP \"http://127.0.0.1:8931/mcp\": sending \"notifications/initialized\": Bad Request)"} {"time":"2026-08-19T04:12:00Z","tool":"browser_navigate","duration_ms":4, "reason":"mcp-beaver: upstream MCP session is closed (reconnect also failed: reconnect upstream MCP \"http://127.0.0.1:8931/mcp\": sending \"notifications/initialized\": Bad Request)"} ``` **Those are #80's two quoted blocks, near enough verbatim, including `duration_ms: 4`.** ## Why the fix does not cover it, as I read it `94e4050` reasons that a call answered on the standalone stream no longer hangs, so the session stops dying, so the broken reconnect is never reached. **The first half held and the second did not.** The session still reaches a closed state, and when it does, `notifications/initialized` still comes back `Bad Request`, which is #67's string. Duration is the discriminator worth keeping: #80's hang was 59.9s. These are 4ms and 7ms. **The failure is now instant rather than slow**, which is consistent with the hang being fixed and the recovery path still being broken underneath it. ## It is not the whole server Another client ran a clean sequence against this same pod at 03:23:53 to 03:24:06 with every call ok: `browser_wait_for`, `browser_snapshot`, `browser_click`, `browser_navigate`, `browser_type`. So the browser and the fixed wrapper both work. Splitting the pod log by trace id, every call carrying one is the Dowel lane's and every one of those failed. ## Two theories I built and discarded, so nobody rebuilds them * **Shared-session contention between clients.** `sirens-dowel-playwright-mcp-values.yaml` records `--shared-browser-context` as deliberately absent on this lane, and #80 already refuted a one-session-at-a-time upstream by dialling a second session cleanly. * **A stale image carrying the pre-fix build.** The digest above is `94e4050`. `94e4050`'s own warning is the reason I am filing rather than guessing further: a dead upstream session makes the next call reconnect, that dial also fails, and **the reported reason is the reconnect's rather than the cause beneath it**. So this error string has now misdirected at least three investigations, mine included. Whatever closes this should probably make the underlying cause visible rather than only the reconnect's complaint. ## Standing, and why the timing matters `sirens-dowel` has made **14 browser tool calls in 7 days and all 14 failed**, measured in SigNoz on `attribute.mcp.tool.name LIKE 'browser%'` grouped by outcome. There is no successful call on this lane at any point in that window. The lane advertises `playwright` in its tool list and offers it when asked what it can do, and it is live on a stream at 11:00 PT today. **A capability with a 0% lifetime success rate is being advertised as available.** ## Complete when * A Dowel browser call succeeds against a running pod, evidenced by a log line rather than by a healthy pod. * The failure surfaces the cause rather than the reconnect's complaint, so the next occurrence does not cost another investigation. * Consider reopening #80 rather than tracking this separately, since this is the failure its title names. Refs: #80, #67, #79

coilyco-ops referenced this issue

2026-08-19 04:15:52 +00:00

upstream passthrough: session recovery reconnects into #67's Bad Request, so a lost session is still permanent #80

coilyco-ops commented

2026-08-19 04:26:54 +00:00

Author

Member

Worked this for a while and did not close it. Posting what I ruled out and the one thing I think is actually blocking a diagnosis, since this issue's own point is that the error string has misdirected three investigations.

Ruled out, with evidence

Resource exhaustion in the browser. kubectl top: 462Mi against a 2Gi limit, Restart Count: 0 on both containers, no OOM in the pod description. The browser is idle and healthy.
Spec drift between main and the cluster. The running pod matches origin/main exactly: mcp-beaver 94e4050, playwright upstream-dd643326, and --shared-browser-context absent in both. I chased this one because I had read an older revision of the values file that said the flag was present, and 3f61bc3 has since reverted it. The cluster is not behind.
The shared-context revert being the cause. 3f61bc3 reverted it on measurement, not on theory: browser_navigate still hung 60s on a fresh pod carrying the flag while the same call direct to the sidecar returned in about a second. Reinstating it would be going backwards.

One real defect, which I do not think is this one

internal/mcpserver/telemetry.go:253 deliberately manufactures params for a notification that has none:

case "notifications/initialized":
    typed.Params = &mcp.InitializedParams{}

and the middleware then injects _meta into it, so mcp-beaver sends notifications/initialized with a params object rather than bare. That is worth tidying on its own.

It is almost certainly not the cause here, and I want that on the record so nobody spends an hour on it: client.Connect sends the same notification through the same middleware on the initial dial, and the initial dial succeeds every time - the pod reaches Ready and snapshots its baseline. A defect on that path would fail at startup, not intermittently four hours in.

What is actually blocking a diagnosis

The upstream logs nothing but its banner.

Listening on http://localhost:8931
Put this in your client config:
...

That is the entire log of the playwright-mcp container. No request line, no status, no error. So the Bad Request is an HTTP 400 whose origin has never been read by anyone - every investigation including mine has inferred it from mcp-beaver's side of the wire.

That is why this keeps costing an investigation. It is not that the error is badly worded, it is that half the transaction is invisible.

The cheapest way to close that gap is one of:

Request logging on the sidecar, so the 400 says which check rejected it. That is a values change on the deploy side.
mcp-beaver carrying the response body of a failed handshake into the error rather than only the status text. The status alone is what has been misdirecting people, and the body is where the TS SDK writes its actual reason.

I would do 2 before guessing again, and it satisfies this issue's own second completion criterion directly.

On the standing question

The 0-of-14 figure holds and it is the part that matters today. Since playwright is advertised in the lane's tool list and has never once worked there, the low-risk move before the stream is removing it from the Dowel roster rather than fixing it under time pressure. That is a deploy-side decision rather than one for this repo, so I have not acted on it here.

Also worth correcting on a neighbouring thread: 3f61bc3's message attributes the moxn outage to this same defect. Post-94e4050 evidence says otherwise - moxn now fails with calling "initialize": Unauthorized, which is an expired credential rather than a lost stream. Anyone reading that commit should not assume the new image fixed moxn. Recorded on coilyco-gaming/sirens-echo#1026.

Worked this for a while and **did not close it**. Posting what I ruled out and the one thing I think is actually blocking a diagnosis, since this issue's own point is that the error string has misdirected three investigations. ## Ruled out, with evidence * **Resource exhaustion in the browser.** `kubectl top`: 462Mi against a 2Gi limit, `Restart Count: 0` on both containers, no OOM in the pod description. The browser is idle and healthy. * **Spec drift between `main` and the cluster.** The running pod matches `origin/main` exactly: mcp-beaver `94e4050`, playwright `upstream-dd643326`, and `--shared-browser-context` absent in both. I chased this one because I had read an older revision of the values file that said the flag was present, and 3f61bc3 has since reverted it. The cluster is not behind. * **The shared-context revert being the cause.** 3f61bc3 reverted it on measurement, not on theory: `browser_navigate` still hung 60s on a fresh pod carrying the flag while the same call direct to the sidecar returned in about a second. Reinstating it would be going backwards. ## One real defect, which I do not think is this one `internal/mcpserver/telemetry.go:253` deliberately manufactures params for a notification that has none: ```go case "notifications/initialized": typed.Params = &mcp.InitializedParams{} ``` and the middleware then injects `_meta` into it, so mcp-beaver sends `notifications/initialized` **with a params object** rather than bare. That is worth tidying on its own. **It is almost certainly not the cause here**, and I want that on the record so nobody spends an hour on it: `client.Connect` sends the same notification through the same middleware on the *initial* dial, and the initial dial succeeds every time - the pod reaches Ready and snapshots its baseline. A defect on that path would fail at startup, not intermittently four hours in. ## What is actually blocking a diagnosis **The upstream logs nothing but its banner.** ``` Listening on http://localhost:8931 Put this in your client config: ... ``` That is the entire log of the `playwright-mcp` container. No request line, no status, no error. So the `Bad Request` is an HTTP 400 whose **origin has never been read by anyone** - every investigation including mine has inferred it from mcp-beaver's side of the wire. That is why this keeps costing an investigation. It is not that the error is badly worded, it is that half the transaction is invisible. The cheapest way to close that gap is one of: 1. Request logging on the sidecar, so the 400 says which check rejected it. That is a values change on the deploy side. 2. mcp-beaver carrying the **response body** of a failed handshake into the error rather than only the status text. The status alone is what has been misdirecting people, and the body is where the TS SDK writes its actual reason. I would do 2 before guessing again, and it satisfies this issue's own second completion criterion directly. ## On the standing question The 0-of-14 figure holds and it is the part that matters today. Since `playwright` is advertised in the lane's tool list and has never once worked there, the low-risk move before the stream is removing it from the Dowel roster rather than fixing it under time pressure. That is a deploy-side decision rather than one for this repo, so I have not acted on it here. **Also worth correcting on a neighbouring thread**: 3f61bc3's message attributes the moxn outage to this same defect. Post-`94e4050` evidence says otherwise - moxn now fails with `calling "initialize": Unauthorized`, which is an expired credential rather than a lost stream. Anyone reading that commit should not assume the new image fixed moxn. Recorded on coilyco-gaming/sirens-echo#1026.

coilyco-ops referenced this issue from a commit

2026-08-19 04:38:04 +00:00

fix(upstream): keep a caller's session values out of the upstream call

coilyco-ops closed this issue

2026-08-19 04:38:04 +00:00

coilyco-ops referenced this issue from a commit

2026-08-19 04:43:05 +00:00

feat(upstream): log the reason an upstream rejected a request

coilyco-ops referenced this issue from a pull request that will close it,

2026-08-19 04:43:29 +00:00

feat(upstream): log the reason an upstream rejected a request #86