From 214aec3f97f991170042fc5374f57577c9340e37 Mon Sep 17 00:00:00 2001 From: Markus Hartung Date: Thu, 20 Aug 2026 20:34:47 -0300 Subject: [PATCH] fix(executors): report WS readyState in Meta AI timeout error (#10727) The muse-spark-web wsChat timeout previously reported a flat 'Meta AI WebSocket timed out' with no way to tell whether the socket never opened or opened and then went silent. Report readyState at the moment the 30s timeout fires so the next occurrence of #10727 is diagnosable from logs alone. This does not fix the underlying protocol drift (Meta's reverse-engineered private WS gateway silently dropping frames) -- that requires a live meta.ai session + fresh DevTools capture per the triage plan-file's needs-vps verdict, which is not achievable in this sandbox. --- .../10727-meta-ai-ws-timeout-diagnostics.md | 1 + open-sse/executors/muse-spark-web.ts | 2 +- ...spark-ws-timeout-diagnostics-10727.test.ts | 164 ++++++++++++++++++ 3 files changed, 166 insertions(+), 1 deletion(-) create mode 100644 changelog.d/fixes/10727-meta-ai-ws-timeout-diagnostics.md create mode 100644 tests/unit/muse-spark-ws-timeout-diagnostics-10727.test.ts diff --git a/changelog.d/fixes/10727-meta-ai-ws-timeout-diagnostics.md b/changelog.d/fixes/10727-meta-ai-ws-timeout-diagnostics.md new file mode 100644 index 0000000000..f204684baa --- /dev/null +++ b/changelog.d/fixes/10727-meta-ai-ws-timeout-diagnostics.md @@ -0,0 +1 @@ +- **fix(executors):** the Meta AI (muse-spark-web) WebSocket send-message timeout now reports the socket's `readyState` at the moment it fires, so a "Meta AI WS timed out" failure can be told apart as either the connection never opening (`readyState=0`) or opening successfully and then going silent (`readyState=1`) — the exact ambiguity that made #10727 undiagnosable from logs alone (#10727). diff --git a/open-sse/executors/muse-spark-web.ts b/open-sse/executors/muse-spark-web.ts index f93191c312..a8052c4c65 100644 --- a/open-sse/executors/muse-spark-web.ts +++ b/open-sse/executors/muse-spark-web.ts @@ -1070,7 +1070,7 @@ async function wsChat( const fail = (error: string) => finish({ content: "", deltas: [], error }); - timeout = setTimeout(() => fail("Meta AI WebSocket timed out"), 30000); + timeout = setTimeout(() => fail(`Meta AI WS timed out (readyState=${ws.readyState})`), 30000); abortHandler = () => fail("Request aborted"); signal?.addEventListener("abort", abortHandler, { once: true }); diff --git a/tests/unit/muse-spark-ws-timeout-diagnostics-10727.test.ts b/tests/unit/muse-spark-ws-timeout-diagnostics-10727.test.ts new file mode 100644 index 0000000000..98de83cce7 --- /dev/null +++ b/tests/unit/muse-spark-ws-timeout-diagnostics-10727.test.ts @@ -0,0 +1,164 @@ +import test from "node:test"; +import assert from "node:assert/strict"; +import { + MuseSparkWebExecutor, + __resetMuseSparkConversationCacheForTesting, + __setMuseSparkWebSocketForTesting, +} from "../../open-sse/executors/muse-spark-web.ts"; +import { WebSocket } from "ws"; + +// #10727: Meta AI (muse-spark-web) times out on the WS send-message step at +// exactly the executor's hardcoded 30s timeout, with no onerror/onclose +// firing first. The reporter's log shows the flow reaching wsChat and +// hanging until the timeout fires, meaning Meta's gateway either never +// truly opens the socket or silently drops frames after opening — but the +// old flat "Meta AI WebSocket timed out" message could not distinguish +// those two failure modes for whoever debugs the next occurrence. +// +// Root-causing (and fixing) the reverse-engineered private WS protocol +// itself requires a live meta.ai session + a fresh DevTools capture (see +// the plan-file's `needs-vps` verdict) — not achievable in this sandbox. +// This regression test locks in the diagnosability improvement that *is* +// verifiable here: the timeout error now reports the socket's readyState +// at the moment it fires, so a future report can tell "never opened" +// (readyState 0) apart from "opened but Meta went silent" (readyState 1). + +/** + * Intercepts only the wsChat 30000ms timeout registration and lets every + * other setTimeout (including the mock WebSocket's own onopen scheduling) + * run for real. Firing the captured callback directly — instead of + * advancing a fake clock — keeps the test fast and avoids interleaving + * bugs between fake timers and the executor's real async/await chain. + */ +function interceptWsTimeout(): { fire: () => void; restore: () => void } { + const original = globalThis.setTimeout; + let captured: (() => void) | null = null; + globalThis.setTimeout = ((cb: (...a: unknown[]) => void, ms?: number, ...args: unknown[]) => { + if (ms === 30000 && captured === null) { + captured = cb as () => void; + return 0 as unknown as ReturnType; + } + return original(cb as () => void, ms, ...args); + }) as typeof setTimeout; + return { + fire: () => { + assert.ok(captured, "the 30000ms wsChat timeout was never registered"); + captured?.(); + }, + restore: () => { + globalThis.setTimeout = original; + }, + }; +} + +class NeverOpensWebSocket { + onopen: (() => void) | null = null; + onmessage: ((evt: { data: string }) => void) | null = null; + onclose: (() => void) | null = null; + onerror: ((evt: Error) => void) | null = null; + readyState = WebSocket.CONNECTING; + url: string; + constructor(url: string) { + this.url = url; + // Never calls onopen, onmessage, onerror, or onclose — mirrors the + // reported symptom exactly: the socket just hangs until the timeout. + } + send(_data: Uint8Array | string) {} + close() {} +} + +class OpensThenSilentWebSocket { + onopen: (() => void) | null = null; + onmessage: ((evt: { data: string }) => void) | null = null; + onclose: (() => void) | null = null; + onerror: ((evt: Error) => void) | null = null; + readyState = WebSocket.CONNECTING; + url: string; + constructor(url: string) { + this.url = url; + setTimeout(() => { + this.readyState = WebSocket.OPEN; + this.onopen?.(); + }, 0); + } + send(_data: Uint8Array | string) {} + close() {} +} + +function baseInput(connectionId: string): Parameters[0] { + return { + model: "muse-spark", + body: { messages: [{ role: "user", content: "ping" }] }, + stream: false, + credentials: { + apiKey: "ecto_1_sess=test123", + connectionId, + providerSpecificData: { authorization: "ecto1:test-auth-token" }, + }, + signal: null, + log: null, + upstreamExtraHeaders: undefined, + } as Parameters[0]; +} + +test("#10727: WS timeout while still CONNECTING reports readyState=0 (never opened)", async () => { + __resetMuseSparkConversationCacheForTesting(); + const executor = new MuseSparkWebExecutor(); + const originalFetch = globalThis.fetch; + globalThis.fetch = async () => new Response("{}", { status: 200 }); + const restore = __setMuseSparkWebSocketForTesting( + NeverOpensWebSocket as unknown as typeof WebSocket + ); + const timeoutHook = interceptWsTimeout(); + try { + const resultPromise = executor.execute(baseInput("conn-10727-never-opens")); + // Let the GraphQL warmup/mode-switch awaits and the WS constructor run + // before the 30s timeout is registered. + await new Promise((r) => setTimeout(r, 20)); + timeoutHook.fire(); + + const result = await resultPromise; + assert.equal(result.response.status, 502); + const body = await result.response.json(); + assert.match( + body.error.message, + /readyState=0/, + "timeout while the socket never left CONNECTING must report readyState=0" + ); + } finally { + globalThis.fetch = originalFetch; + restore(); + timeoutHook.restore(); + } +}); + +test("#10727: WS timeout after a successful open reports readyState=1 (opened, then silent)", async () => { + __resetMuseSparkConversationCacheForTesting(); + const executor = new MuseSparkWebExecutor(); + const originalFetch = globalThis.fetch; + globalThis.fetch = async () => new Response("{}", { status: 200 }); + const restore = __setMuseSparkWebSocketForTesting( + OpensThenSilentWebSocket as unknown as typeof WebSocket + ); + const timeoutHook = interceptWsTimeout(); + try { + const resultPromise = executor.execute(baseInput("conn-10727-opens-silent")); + // Let the GraphQL awaits run, the WS open (its own real setTimeout(...,0)), + // and the intro/prompt frames send before the 30s timeout is registered. + await new Promise((r) => setTimeout(r, 20)); + timeoutHook.fire(); + + const result = await resultPromise; + assert.equal(result.response.status, 502); + const body = await result.response.json(); + assert.match( + body.error.message, + /readyState=1/, + "timeout after the socket reached OPEN must report readyState=1, not the never-opened case" + ); + } finally { + globalThis.fetch = originalFetch; + restore(); + timeoutHook.restore(); + } +});