Bug: mux heartbeat kills a healthy browser WebSocket (endless ~10s reconnect loop)

[zhanghunuaa]

Component: packages/api/gateway (RemoteStreamMuxServer / TypertGatewayService) — client symptom lands in packages/client/connection and packages/api/session-controller/src/client/sessions/session.ts
Version: dsh@0.1.2-rc.1 (commit a66e4702, @deepseek-ai/dsh-api-gateway@0.1.2-rc.1)
Platform: Windows 10 Pro 19045, Node v24.14.0, Edge 152.0.4191.66, dsh web on 127.0.0.1:3080 (loopback, no NAT/VPN/proxy in the path)
Related: #3030 and #2842 report the mirror image (WebSocket paths that lack a heartbeat); #3102 is a reconnect-resync race that this loop makes far more likely.
Checked against master: origin/master d347e703 (0.1.3-alpha.1) has no diff for packages/api/gateway/src/stream-server.ts relative to the release, so the defect is still present.

中文摘要

宿主端 RemoteStreamMuxServer 的心跳用「2 次没收到 pong（约 4–6 秒）就认定对端已死」来判定存活，却完全不看这条 socket 上还积压着多少没写完的数据。而浏览器端每次（重）连接都会为它持有的每一个会话重开一路 session/follow 并回放完整快照（实测 12+ 个会话 ≈ 28 MB）。于是形成闭环：重连 → 28 MB 洪峰 → 浏览器还在消化，ping 帧排在数据后面，pong 来不及回来 → 服务端 terminate() → 再次重连。用户看到的就是连接指示灯每十几秒闪一次「连接中 / 连接异常 / 连接成功」，而主机、网络、会话本身全都正常。

把 websocketHeartbeatIntervalMs 从 2000 改成 30000（profile 补丁层，loader 热生效）后，同一个浏览器、同一份数据洪峰，连接稳定 10 分钟以上 —— 说明客户端从未真的掉线，是看门狗的判据有问题。

建议：服务端在判定 missedHeartbeats 之前先看 socket.bufferedAmount（有积压就不能判死），并以 ping 的 flush 回调作为计时起点；客户端则避免在一次重连中回放 N 份全量快照（按可见性懒开、给首屏快照加字节预算、把重开串行化）。

---

Symptom

The browser's connection indicator flickers 连接中 → 连接异常 → 连接成功 roughly every 10 seconds, forever. It auto-recovers without any user action, so it reads like a flaky network or a slow host, but the host process is healthy (16 h uptime, no errors logged), all HTTP APIs answer instantly, and the machine shows no connectivity change at the time.

Summary

The mux watchdog treats "no pong within 2 missed heartbeats (~4–6 s)" as a dead peer. But the same socket may be carrying a multi-megabyte burst, and a pong can only be produced by the peer after it has read past that burst. So a perfectly healthy — merely busy — browser is terminated, and because the reconnect replays the burst, the disconnect becomes self-sustaining.

Two defects compound:

1. Server — startHeartbeat() counts a heartbeat before/independently of the ping frame actually being flushed, and never consults the carrier's write backlog, so backpressure is indistinguishable from death.
2. Client transport — a reconnect re-opens a session/follow stream for every session the page holds, each replaying a full snapshot; with a workspace of a dozen sessions that is ~28 MB in one burst.

Evidence

Measured by wrapping the host's /api/remote.mux upgrade route and the gateway's openRemoteEvents, logging to a JSONL file (in-process instrumentation of a live dsh web; no source changes).

1. Every disconnect is the server terminating the carrier

Destroy stack on the raw socket (40/40 samples):

socket.destroy
socket.destroy
WebSocket.terminate            <- ws
Immediate._onImmediate         <- the setImmediate in startHeartbeat()
process.processImmediate

i.e. it is RemoteStreamMuxServer.startHeartbeat and not the client, not TCP, and not the OS. peerFinMs: null, readableEnded: false on those sockets: no FIN was received from the browser first.

2. The socket was never dead — it was behind

One representative connection (lifetime 9052 ms):

{"kind":"ws3-close","ms":9052,"pongs":2,"lastPongMs":3052,
 "dataInBytes":5378,"bytesWritten":27840800,"bytesRead":6203}

• the server wrote 27.8 MB to the socket in 9.0 s;
• the browser's last pong arrived at t+3052 ms, then silence until the kill at t+9052 ms;
• dataInBytes: 5378 shows the browser was still sending its own frames — the client was alive and reading the whole time.

3. What the burst is

Outbound text frames sampled during the first ~1.5 s of one connection (12 distinct streams, one per followed session):

1.42 MB  session-621760ec…   {"type":"item","value":{"type":"snapshot",…}}
1.12 MB  session-f566a129…
0.42 MB  session-f543e60d…
1.15 MB  session-14ba940e…
1.22 MB  session-4dac4cfe…
1.00 MB  session-11169a1a…
1.77 MB  session-14d052e7…
1.68 MB  session-340b244a…
1.28 MB  session-5f18315e…
2.27 MB  session-572cc262…
1.66 MB  session-a9561068…
1.30 MB  session-4daba0e6…

Total per connection: 27.7–32.7 MB (totalWritten: 27733865 / 27842938 / 28167293 / 32743992 over 9–164 s lifetimes). The snapshot replay is byte-blind: packages/api/session-controller/src/client/sessions/session.ts:601 opens with { maxMessages: PAGE_MESSAGES } (PAGE_MESSAGES = 50, line 47) while the payload is dominated by large tool records.

4. The loop is self-sustaining

02:31:00–02:42:00Z, Edge client, one mux socket per cycle:

lifetimes (ms): 8926, 9052, 9346, 10895, 11883, 12792, 12955, 13904, 13910, 17614, 26829, 36789, 156763, 164168
gaps between kill and next connect (ms): 6392, 7775, 8657, 8955, 9141, 9430, 9696, 10097, 11053, 11114, 11852, 13092, 16103

38 sockets in 35 minutes (02:06:47Z–02:41:55Z). Each cycle: terminate → client backoff 5–16 s → new socket → 28 MB replay → pong starved → terminate.

5. Confirmation: the same client, only the heartbeat interval changed

Setting websocketHeartbeatIntervalMs: 30000 for the typert-gateway loader entry (profile patch layer; the loader hot-applied it and re-created the mux):

{"kind":"ping-first","bytesWritten":33249322,"t":"…02:46:26.148Z"}
{"kind":"ping-progress","pings":4,"gaps":[30000,30000,30001],"t":"…02:47:56.149Z"}

Same browser, same workspace, same 34 MB burst: no disconnect, connection stable for 10+ minutes. The client was never unhealthy — only the watchdog was wrong.

Root cause

A. Server: a liveness deadline that a busy carrier cannot meet

packages/api/gateway/src/stream-server.ts:

const MAX_MISSED_HEARTBEATS = 2                                    // line 22

private startHeartbeat(): void {
  if (this.heartbeatTimer !== undefined) return
  this.heartbeatTimer = setInterval(() => {
    for (const socket of this.server.clients) {
      if (socket.readyState !== WebSocket.OPEN) continue
      const missed = this.missedHeartbeats.get(socket) as number
      if (missed >= MAX_MISSED_HEARTBEATS) {
        setImmediate(() => {
          if ((this.missedHeartbeats.get(socket) as number) >= MAX_MISSED_HEARTBEATS) {
            socket.terminate()                                     // line 84
          }
        })
        continue
      }
      this.missedHeartbeats.set(socket, missed + 1)                // counted at send time
      socket.ping()                                                // flush is never awaited
    }
  }, this.heartbeatIntervalMs)                                     // default 2_000 (index.ts:116)
  this.heartbeatTimer.unref()
}

With the default interval the peer has ~4–6 s to answer a ping. In that window this session's carrier legitimately had tens of megabytes in flight: send() (line 180) serializes frames through this.writes and resolves on the ws write callback, which means "handed to the kernel", never "consumed by the peer". On loopback the kernel happily absorbs megabytes, so the ping frame — a normal frame in the same FIFO TCP stream — is queued behind them, and the pong cannot be produced until the peer reads that far. The watchdog then kills a socket that is merely behind, and it does so at exactly the moment the client is working hardest.

B. Client transport: one reconnect ⇒ N full snapshot replays

The page holds a client Session per followed session (packages/api/session-controller/src/client/sessions/session.ts:601 → events.open({ maxMessages: PAGE_MESSAGES }) → session/follow). A transport reset makes every one of them re-open at once and each replay is a full snapshot (0.4–2.2 MB here, 12+ sessions). The result is a ~28 MB burst on a socket that the watchdog allows 4 s of silence.

Note this also means a single genuine blip is enough to enter the loop, so the user-visible failure mode is "the GUI never stops reconnecting" rather than "one reconnect".

Suggested fixes

A. Make the watchdog backpressure-aware (small, server-only)

1. Never judge liveness while the carrier has a backlog:

const BACKLOG_BYTES = 1 << 20
if (missed >= MAX_MISSED_HEARTBEATS) {
  // A backed-up carrier is not a dead peer: its pong is queued behind data we
  // are still writing. Refresh the window instead of killing the socket.
  if (socket.bufferedAmount > BACKLOG_BYTES) {
    this.missedHeartbeats.set(socket, 0)
    continue
  }
  setImmediate(…)
}

2. Count the heartbeat only once the ping is actually flushed, e.g. socket.ping(undefined, undefined, () => {…}) (or reset the counter when the frame is written) so the peer's budget starts when the ping leaves the host.
3. Make the deadline self-scaling: require max(3 × interval, 30_000) of silence, and consider raising DEFAULT_WEBSOCKET_HEARTBEAT_INTERVAL_MS (2 000 currently).
4. Longer term, keep the carrier responsive by pacing the pump on bufferedAmount instead of only awaiting the write callback; then a ping can never queue behind 28 MB of session replay.

B. Stop the reconnect amplification (client)

1. Follow only sessions that are actually visible; close the stream when a session stops being displayed.
2. Give the initial replay a byte budget (not only maxMessages) and backfill the rest on demand.
3. Coalesce/defer the re-open storm after a transport reset (serialize stream opens, backoff between them) so a reconnect cannot generate a multi-megabyte burst.

C. Diagnostics

A terminated-by-watchdog event (missedHeartbeats, bufferedAmount, lifetime, bytes written) would have made this a five-minute diagnosis instead of a morning of packet forensics.

Reproduction

1. A workspace with ~10+ sessions whose transcripts contain large tool records (snapshot per session ≈ 0.4–2.2 MB).
2. Open the web UI so the client follows all of them, and make the renderer busy enough that it needs >5 s to digest the replay (a slow machine, a background/throttled tab, or a large burst will do).
3. Force one disconnect (restart the host, or let the renderer stall once).
4. Observe: the mux socket is terminated by WebSocket.terminate from startHeartbeat every 10–30 s, the client reconnects with 5–16 s of backoff, and the connection indicator flickers forever.

Workaround

# ~/.dsh/profiles/web/cordis.patch.yml
- id: typert-gateway
  config:
    websocketHeartbeatIntervalMs: 30000

The loader applies this live (it re-creates the mux); no host restart needed. It removes the symptom but not the underlying burst — fix A is still the right place for it.

[argszero]

Thanks for the forensic write-up — the destroy-stack samples plus the "same client, only the interval changed" control make this one of the more useful mux reports so far. I re-derived the mechanism from source on master (2377c272a8, dsh-v0.1.5-rc.1) and both halves of your diagnosis hold. Three additions, because I think one suggested fix would not actually work as written.

Confirmed from source

• packages/api/gateway/src/stream-server.ts:22 — MAX_MISSED_HEARTBEATS = 2. The counter is incremented at :89, before socket.ping() at :90, and no code path consults the carrier's write state. DEFAULT_WEBSOCKET_HEARTBEAT_INTERVAL_MS = 2_000 (packages/api/gateway/src/index.ts:115, schema default at :172), so the peer gets ~2 intervals (4–6 s) to prove itself. Your reading is exact.
• RemoteStreamMuxConnection.send() (:180) serializes frames through this.writes and resolves on the ws write callback — i.e. "handed to the kernel" is treated as delivery, and the pump is never paced against a peer that has not drained. Root cause A is real.
• Client side: RemoteJournalStream retains this.initialRequest and hands it to follow() for every physical generation (packages/api/gateway/src/client/journal-stream.ts:118-119). Each open journal therefore replays its full opening window on each reconnect — not only after a page re-open. repairRequest() (unbounded tail) exists but is wired only to gap repair, not to transport-driven re-open.

1. bufferedAmount alone is not a sufficient liveness gate

I would not ship fix A.1 as written. In ws 8.21.0, get bufferedAmount() is this._socket._writableState.length + this._sender._bufferedBytes — it is a sender-side gauge. It goes non-zero when backpressure has propagated back to the host, which is not the same condition as "the peer has not read past the ping". On loopback the kernel accepts megabytes before TCP backpressure appears, and the browser's own ws receiver queue absorbs more after that; in exactly that window the host can have ~0 sender backlog while the peer is tens of MB behind. If bufferedAmount reads ~0 at the kill instant, the proposed > BACKLOG_BYTES guard passes the kill straight through and the bug survives the fix.

This is falsifiable with your existing instrumentation: log bufferedAmount at the moment the setImmediate fires. Your root cause predicts it is large; if it comes back near zero, the backlog check is not the lever.

2. Your data already contains a better liveness signal

dataInBytes: 5378 was non-zero while the pong drought ran from t+3052 ms to the kill at t+9052 ms. A peer that keeps sending is alive by definition — its pong is merely queued behind data it is still reading. The TCP-level equivalent is there too: a dead peer stops ACKing, so socket.write() stops being accepted and the sender backlog grows for a different reason than a slow-but-alive peer.

So the robust gate is positive evidence, not a buffer threshold: treat a missed pong as no evidence rather than bad evidence, and only kill when the socket is silent in both directions (no inbound bytes since the last heartbeat, no pong) and the send path is healthy. Backlog stays as a guard, but as a second condition after the liveness check, not the primary one. That also scales the deadline for free: a peer that is still talking should never be timed out at 4 s no matter how large the burst is.

3. The client replay is structural — the cheaper lever is in the journal layer

Because the reopening request is the retained opening window, "follow only visible sessions" plus a byte budget (B.1/B.2) reduces the size but not the shape: any transport reset still re-opens every live journal with a full snapshot. Worth checking whether a transport-driven generation should instead resume from the retained cursor with repairRequest() and let only a real gap fall back to a snapshot replay. That is a much smaller change than visibility-driven lazy open, it fixes the amplification for every Domain at once (session events, session control baseline, workspace streams), and it preserves the existing "a snapshot is the repair of last resort" contract rather than adding a second, weaker one.

One note on the amplification bound: maxMessages: 50 (session.ts:621, PAGE_MESSAGES) is not what makes the burst multi-megabyte — the page is dominated by individual tool records, so a record-count cap and a byte budget are genuinely different knobs. A reconnect that replays 12 × 50 large records is ~28 MB regardless of the count. Confirms your B.2 point.

On diagnostics (C) — I agree, and I'd add that this is not currently reachable from a plugin: RemoteStreamMuxServer is constructed inside TypertGatewayService and its upgrade route (/api/remote.mux) is registered at packages/api/gateway/src/index.ts:212 through registerUpgrade, which throws on a duplicate path (packages/host/webserver/src/index.ts:180). There is no per-connection hook and no socket-liveness surface to observe, so a watchdog event has to come from the gateway itself. (A client plugin can legally wrap ctx.remote.$stream() to time per-stream opening bytes and generation re-opens, but that is host-side blind.) If a watchdog event lands, it would be worth emitting alongside the existing gateway failure vocabulary rather than as a bare log line.

Finally: the websocketHeartbeatIntervalMs: 30000 workaround is a good control but a poor setting — with MAX_MISSED_HEARTBEATS = 2 it also means 60–90 s to notice a genuinely dead peer, while the renderer reconnect storm continues underneath. It confirms the diagnosis; it should not be the resting state.

---

中文补充（三条）

1. bufferedAmount 单独不足以判活：ws 的 bufferedAmount 是发送端积压（_writableState.length + _sender._bufferedBytes），只有 TCP 背压传回宿主时才非零。回环下内核和浏览器 ws 接收队列会先吃掉数 MB，此时宿主侧积压可能接近 0，而 ping 确实排在数据后面——那样 A.1 的 > BACKLOG_BYTES 判断会放行 kill，缺陷依旧。可在你现有埋点里直接验证：setImmediate 触发瞬间记一次 bufferedAmount。
2. 更好的判据已在你数据里：dataInBytes: 5378 说明 pong 空档期内对端仍在发帧。把「漏拍」当无证据而非坏证据，只在收发双静默且发送路径健康时才 terminate，积压检查降为第二条件。
3. 客户端放大的更省力落点：重开用的是保留的开窗请求，所以「只跟随可见会话 + 字节预算」减小体量但不改变形状；可考虑传输重连时用 repairRequest() 从游标续传，仅真实 gap 才回落快照。改动更小，且一次修好所有 Domain。