Repository navigation
fix(terminal): a stripped X-Log-Offset replayed the tail twice (issue #86) - #93
Conversation
… (issue #87) A network blip, a proxy idle timeout or a laptop sleep/wake duplicated or garbled the terminal. ws.onclose reconnects after 5s without clearing the screen, while completeHandshake unconditionally replayed Tail(id, 64*1024) to EVERY connection, so the newest 64 KB landed under whatever the terminal already showed. Root cause: the WS handshake had no offset contract. The connect URL carried only id/token, the handshake threw away Tail's end offset via `_`, and the client's logCursor served only the SSE path -- so the client could not even express a position, let alone have one honoured. Fix: the handshake gains a cursor round-trip. GET /api/instances/tty/ws?id=<id>[&since=<offset>] since absent/unparseable -> -1 sentinel -> Tail, unchanged (first connect). since >= 0 -> catch-up loop, see below. completeHandshake(since) loops ReadSince(id, cursor, 64*1024) until the body comes back empty, retaining only the NEWEST chunk, so peak memory stays ~64KB regardless of the ring cap and the replay is the newest <=64KB contiguous with head. A single capped ReadSince would instead publish a cursor 64KB BEHIND head while the live subscription starts AT head: those bytes land in neither path and, since a client cursor only moves forward, they are never re-requested. Retaining the newest chunk (rather than a rolling 64KB window) keeps the stronger property that every replayed byte is new to the client. After the replay the server emits a TEXT control frame: {"type":"sync","offset":N} even when the replay was empty (0 is a legitimate cursor on a fresh instance). The client stores it as `ttyOffset`, advances it by the wire byte count of every binary frame received after that sync, preserves it across ws.onclose, and sends it back as `since` on reconnect. RingBuffer.ReadSince supplies the silent stale-cursor clamp for free. Cursor invalidation is screen-content driven: callers that wipe the screen (activate(), refreshCurrentInstance, resetTerminalForSwitch) reset BOTH cursors to the -1 sentinel at the clear, and a successful loadLog re-pins ttyOffset to logCursor immediately afterwards (one ring end offset, two consumers). The SSE handler advances both cursors together so a later WS reconnect cannot replay bytes SSE already painted. Because the cursor counts wire bytes, the server must never emit a non-ring binary frame: both handshake error paths now CLOSE the connection with 1013 instead of writing the diagnostic as binary output, matching the existing newTTYClientHandle precedent. The replay write error also aborts the handshake rather than advertising a cursor over undelivered bytes. Defensive: a first read that makes no progress consults Tail for the real head, because ReadSince echoes the caller's own number once the cursor reaches head. A cursor AHEAD of head (not reachable today -- Manager.Restart mints a new instance id, so a given id's ring head is monotonic) degrades to the first-connect tail instead of publishing a cursor the ring never held; output written between that read and the consult is picked up by continuing the loop rather than skipped. Tests: internal/app/tty_ws_test.go gives the endpoint its first coverage -- 8 TestHandleInstanceTTYWS_* cases driving a real ws.Dial against the real handler (no-redelivery / tail / silent clamp / sync offset / over-64KB contiguity / read-failure close / cursor-ahead-of-head / consult-sees-new- bytes), plus the at-head no-op and the non-running instance. The pty driver gains a since>=0 contract test so the app-test mirror cannot drift. Frontend gains 6 cases in testdata/terminal_status.test.mjs (39 total). Docs: docs/API.md (TTY WS section) and docs/ARCHITECTURE.md.
…86) GET /api/instances/log returns the tail and carries the real end offset in the X-Log-Offset header; the browser keeps that byte offset as session.logCursor. If a proxy in front of the daemon strips the header the browser has no cursor, so startSSE omits `since` entirely, the server falls into its tail default, and the tail is painted a second time on top of what loadLog just drew. The WS handshake had the same shape and duplicated the 64KB tail as binary frames. Root cause: TWO different "no valid offset" states were collapsed into one -1 sentinel. nothing painted -> the client genuinely wants the tail painted, offset unknown (header stripped) -> the client wants NO replay at all; it already has the tail Fix: a "follow from live end" sentinel, sinceFollowLiveEnd = -2, meaning send nothing, publish the current end offset, then stream only newly produced data. It is branched on EXPLICITLY in both handleInstanceLogStream and completeHandshake, ahead of their existing `since < 0` tail branch -- parseInt64Default passes any negative through untouched, so an unbranched -2 would behave exactly like an omitted `since` and reproduce the duplication this value exists to prevent. On SSE that is one empty frame `{"chunk":"","next":<head>}` (writeSSELogEvent already always writes both fields, so no new frame format is needed); on WS it is zero binary frames plus the existing `sync` control frame. New Manager.EndOffset(id) returns the head without copying the buffer: it is Tail(id, 0) in every respect that matters -- same lookup, same kind delegation with a negative since, same clamps (a kind without log capture echoes -1 and gets 0; a non-running instance reports 0, exactly as Tail returns ("", 0, nil)) -- except that RingBuffer.Tail short-circuits n <= 0 to ("", head). Tail(id, 0) itself cannot be reused because Manager.Tail clamps n <= 0 to 4096. internal/framework/ kind.go now states the contract this relies on: a tail read must carry its cursor even at maxBytes == 0. Client: CURSOR_UNKNOWN (-1) and CURSOR_FOLLOW_LIVE_END (-2) are named constants in index.html, mirrored (prefixed) in kinds/pty.js. loadLog sets the sentinel only after bytes have actually reached the screen -- the gate is the byte count writeSanitizedTerminalOutput returns, not the response length, because a tail of nothing but stripped escape sequences sanitizes to "" and paints nothing. A failed or aborted fetch leaves CURSOR_UNKNOWN, so an empty screen still asks for the tail. Both transports send the sentinel explicitly; neither ever sends since=0, which the server would read as the oldest live byte (issue #81). GET /api/instances/log now 400s the sentinel rather than silently serving the opposite of what it means. Trade-off, stated honestly in the code, docs and changelog rather than glossed: this trades duplication for a bounded loss. Bytes produced between the head loadLog's tail read (H1) and the head the sentinel publishes (H2) are in no painted body, no replay and no live frame, and the published cursor already sits past them, so no reconnect re-requests them. That is milliseconds normally; on the WS-handshake-timeout -> SSE fallback it is 5s + 500ms of real lost lines. It only applies behind a header-stripping proxy. Also fixed here: a guard test that fails when two classic scripts declare the same top-level name. kinds/pty.js and index.html's inline block both declared `const CURSOR_UNKNOWN`, and classic scripts share one global lexical environment, so index.html's entire application script died at parse time with "Identifier 'CURSOR_UNKNOWN' has already been declared" -- a total SPA outage. The existing node harness slices each function with new Function(...) and so is structurally blind to that constraint.
待评估项(来自 #90 第二轮评审,非本 PR 的缺陷)#90 的第二轮评审记录了一条前瞻性、非阻塞的观察,与本 PR 直接相关,先记在这里免得丢: streaming 之后,WS 握手的 replay→sync 死亡窗口变宽了。 #90 的 catch-up loop 现在把每个 chunk 边读边写,于是「replay 已上屏、 latch 本身是对的,理由是 stale cursor 会被 给本 PR 评审者的具体问题:本 PR(issue #86,follow-from-live-end)正好建立在这个游标契约上,是否值得把 replay 的实际起始 offset 也纳入 我没有在 #90 里实现它——超出该 PR 范围。请在本 PR 评审时决定:纳入、单独开 issue,还是明确不做。取舍要点:多一个字段 vs 客户端一段更简单的游标推进逻辑。 |
Resolve conflicts between issue #86 (follow-from-live-end) and the squash-merged #87/#82/#83 on develop. Resolution principle: union -- both feature sets are preserved intact. develop's #87 squash replaced the branch's "loop ReadSince retaining the newest chunk" handshake with a streaming replay bounded by ttyHandshakeReplayBudget (8MB), so the resolution uses develop's streaming skeleton and drops the branch's TestHandleInstanceTTYWS_LargeDeltaReplaysNewestContiguousChunk in favour of develop's ..._LargeDeltaStreamsEveryByteSinceCursor. Kept from develop (#82/#83): the liveness const block and handleInstanceTTYWSLiveness seam, reader read-deadline, RFC 6455 + TEXT ping heartbeat ticker, isPing->pong before SendInput, overflow subscriber disconnect with exactly-once close and bounded 1013, and all client-side liveness (isTTYHeartbeatStale, watchdog, reconnectStaleTTY, connectTTY FIX-V guard, !stale gates, lastDataAt, ping/pong whitelist). Kept from this branch (#86): sinceFollowLiveEnd = -2 branched before `since < 0` in completeHandshake and handleInstanceLogStream, Manager.EndOffset, the 400 on the plain log endpoint, client cursor states CURSOR_UNKNOWN/CURSOR_FOLLOW_LIVE_END (PTY_CURSOR_UNKNOWN in kinds/pty.js), the painted-byte-count gate in loadLog, three-state since URLs in both transports, and the classic-script top-level-name collision guard. One shared node test was updated to the merged semantics (a stripped header now yields CURSOR_FOLLOW_LIVE_END on both cursors rather than retaining the previous cursor). Node suite: 66 cases, CHANGELOG count re-derived.
独立评审:#93结论:实现正确、覆盖到位,可以合。 MINOR — PR 描述的验证数字自相矛盾,且与仓库不符描述里写 "8 new cases (47 total)"、"node --test 47/47"、"TestTerminalStatusChangelogCount re-derives 47"。实际:
建议描述改成 66,并说明该守卫锚定的是 #80 那条。 MINOR —
|
| 检查 | 结果 |
|---|---|
node --test testdata/terminal_status.test.mjs |
66/66 pass |
test -z "$(gofmt -l .)" |
clean |
go vet ./... |
clean |
go test -count=1 ./... |
全包 ok |
按加载顺序拼接全部 classic script → node --check |
exit 0(SPA 全瘫的修复是真的,守卫也确实成立) |
另外确认了几条容易看漏的:completeHandshake 的两个调用点(app.go:2738 / 2788)都由 !handshakeComplete 守卫,每条连接只跑一次,所以 -2 不会二次发布 head;四个已发布的 kind 都满足 kind.go 新写的"maxBytes == 0 也必须带游标"契约(pty 走 RingBuffer.Tail 的 n <= 0 短路,其余三个 echo since,由 EndOffset 的 off < 0 归一);GET /api/instances/log 的 400 早于 since >= 0 分支,/api/instances/log/stream 与 /api/instances/tty/ws 是仅有的两个 since 消费点,没有第三个会被 -2 误伤;ensureTerminalLiveTransport 的 promote 路径不调 loadLog,游标仍是 -1,所以仍然要 tail——没有被这个 PR 误伤。
formatBytes 重复声明被新守卫降级成 note:(var/function 跨脚本重复声明合法,只是互相遮蔽)是对的,PR 描述也已声明为 follow-up,本 PR 不必处理。
评审补充:回应 #90 轮次显式留给本 PR 的那个问题关于「是否把 replay 的实际起始 offset 一并纳入 前提我复核成立。 但 #93 既不制造也不加剧这个窗口。 -2 模式写零个 binary frame, 若要做,最小正确形态不是把请求里的 为什么不放进 #93: 这是 wire 契约变更,要同时改 app.go / index.html / docs/API.md 三处;而触发条件相当窄——需要重连恰好落在一次 >8MB 的 replay 窗口内,而要凑出 >8MB 的 delta 本身链路已经很慢。建议单开 issue,把上面那个「首个 ReadSince 结果先行下发」的形态写进去即可。 楼上已记录的两点,我独立复核后结论相同,不重复:#93 描述里的 "47" 与仓库不符( |
#93 review) Two findings from the PR93 reviews, both verified accurate against the code before fixing. startSSE's sentinel fallback checked only session.logCursor while its own comment says a real cursor outranks -2 "on either side". The fallback now checks both siblings: else if (logCursor === CURSOR_FOLLOW_LIVE_END || ttyOffset === CURSOR_FOLLOW_LIVE_END) Unreachable today -- the only -2 assignment site (loadLog) sets both cursors together, confirmed by grep -- but a future single-sided ttyOffset assignment would otherwise silently omit `since` and replay the whole tail over the painted screen, the same shape as the #87 duplication. Behaviour is bit-identical in every state that exists today. connectTTY is deliberately unchanged: it reads ttyOffset in both branches, which is complete there because logCursor is only ever written at paired sites while ttyOffset additionally advances alone (WS sync frame, latched binary frames), making ttyOffset the superset cursor. That reasoning is written into both comment blocks, and the ui_test.go source anchor was updated to the new two-sided line. Also narrows writeSanitizedTerminalOutput's return-semantics comment: it returns the sanitized text's `.length` (UTF-16 code units, NOT bytes), used only as a `> 0` boolean gate, and must not be used for byte accounting. Aligned wording in loadLog's painted-gate comment, the harness stubs, docs/API.md and docs/ARCHITECTURE.md. Node suite gains a case driving the split state {logCursor:-1, ttyOffset:-2} asserting `since=-2` still goes on the wire, plus the mirror split, the both-unknown omit, and a real cursor outranking -2 (67 total, CHANGELOG count re-derived).
对两份独立评审的仲裁与处理我逐条对照代码核实了两份评审(09:33 独立评审、09:37 补充评审),结论:三条具体意见全部属实,前瞻问题的处置建议(单独开 issue)予以采纳。处理如下。 1. MINOR — PR 描述数字自相矛盾(47 vs 66)→ 属实,已修 PR 描述核实: 2. MINOR —
|
第二轮评审:#93(
|
| 检查 | 结果 |
|---|---|
grep -c '^test(' |
67(CHANGELOG.md:11 = 67,一致) |
node --test testdata/terminal_status.test.mjs |
67/67 pass |
新用例 red-before-green(/tmp 副本内还原那一行) |
✖ 失败 → 确认真红 |
test -z "$(gofmt -l .)" |
clean |
go vet ./... |
clean |
go test -count=1 ./... |
21 个包全 ok |
go test -race -count=2 -run 'TTYWS|LogStream' ./internal/app/ |
ok |
按加载顺序拼接全部 classic script → node --check |
exit 0 |
gh pr checks 93 |
4/4 pass,mergeable=CLEAN |
结论:可以合。 剩下的是描述数字和一个断行,不涉及代码。
第二轮评审:#93先把结论放前面:代码可以合。 修复本身:我验证过的部分
MINOR —
|
| 检查 | 结果 |
|---|---|
node --test(internal/ui) |
67/67 pass |
gofmt -l . / go build ./... / go vet ./... |
clean |
go test -count=1 ./... |
全包 ok |
^test( 实际条数 vs CHANGELOG.md 首个计数锚 |
67 vs 67,一致 |
| 枚举 index.html + kinds/*.js 全部游标写入点 | 无任何单边 logCursor 写入,ttyOffset >= logCursor 成立 |
#90 那轮交给本 PR 评审者的"replay 起始 offset 是否纳入 sync 契约"问题,结论仍是单开 issue,理由与我上一条评论相同,本次跟进未改变该判断。
…g; wrap a comment (PR #93 review round 2) Second review round on PR #93, both MINORs verified against the files before fixing. CHANGELOG.md's #86 entry was the one place the follow-up's wording change missed: it still claimed the painted-then-stripped gate was on "BYTES REACHING THE SCREEN" and that writeSanitizedTerminalOutput "returns the count of bytes". Aligned with the rest of the tree: it returns the number of CHARACTERS (`.length`, UTF-16 code units, NOT bytes), consumed only as a `> 0` boolean gate. The same entry also undercounted the new node tests -- "seven" became "eight ... (the eighth added by the review follow-up commit)": the PR added seven driver cases plus the scope guard (58 -> 66), and the first-round follow-up added one more driver case (66 -> 67), nine across the PR. Also rewrapped one 103-column comment line in startSSE to the surrounding ~72-column width. No logic changed anywhere.
第二轮评审的仲裁与处理三条意见逐条对文件核实,全部属实,已修复;另按两轮共识把守卫锚点加固单开了 issue。 1. MINOR — CHANGELOG.md:5 漏改措辞 + 计数错 → 已修(
|
Fixes #86.
Problem
GET /api/instances/logcarries the end offset in theX-Log-Offsetheader and the browser keeps it assession.logCursor. If a proxy strips that header:loadLogpaints the tail, but only advances the cursor insideif (Number.isFinite(next) && next >= 0)— so with the header gone neitherlogCursornorttyOffsetmoves.startSSE/connectTTYthen omitsinceentirely (the guard is> 0).→ the tail renders twice, on both SSE and the WebSocket handshake.
Root cause
Two different "no valid offset" states were collapsed into one
-1:Fix
A "follow from live end" sentinel,
sinceFollowLiveEnd = -2: send nothing, publish the current end offset, then stream only new data. It is branched on explicitly, ahead of the existingsince < 0tail branch, in both handlers —parseInt64Defaultpasses any negative through untouched, so an unbranched-2would behave exactly like an omittedsinceand reproduce the duplication it exists to prevent.{"chunk":"","next":<head>}. No new frame format:writeSSELogEventalready always writes both fields.synccontrol frame that [BUG] WS handshake replays the last 64KB on every reconnect, duplicating terminal output #87 introduced.Manager.EndOffset(id)returns the head without copying the buffer. It isTail(id, 0)in every respect that matters — same lookup, same kind delegation, same clamps (a kind without log capture echoes-1→0; a non-running instance reports0, exactly asTailreturns("", 0, nil)) — except thatRingBuffer.Tailshort-circuitsn <= 0to("", head).Tail(id, 0)can't be reused directly becauseManager.Tailclampsn <= 0to 4096.internal/framework/kind.gonow states the contract this relies on: a tail read must carry its cursor even atmaxBytes == 0.loadLogsets the sentinel only after bytes actually reach the screen. The gate is the byte countwriteSanitizedTerminalOutputreturns, not the response length — a tail consisting only of stripped escape sequences sanitizes to""and paints nothing, sotext.lengthwould still have claimed the live end for exactly the state this is guarding. A failed or aborted fetch leavesCURSOR_UNKNOWN, so an empty screen still asks for the tail.Trade-off, stated rather than glossed
This trades duplication for a bounded loss. Bytes produced between the head
loadLog's tail read (H1) and the head the sentinel publishes (H2) are in no painted body, no replay and no live frame — and the published cursor already sits past them, so no reconnect re-requests them. That is milliseconds normally; on the WS-handshake-timeout → SSE fallback it is 5 s + 500 ms of real lost lines. It applies only behind a header-stripping proxy. Documented inapp.go,docs/API.md,docs/ARCHITECTURE.mdand the CHANGELOG.A related non-goal is recorded explicitly: this covers a stripped header, not a rewritten one. A proxy that fabricates
X-Log-Offset: 0over a non-empty ring still gets the duplicate tail — telling a truthful0from a fabricated one needs a second, independently sourced length, which is precisely the datum the proxy is already willing to lie about.Also fixed here: a guard against a total SPA outage
kinds/pty.jsandindex.html's inline block both declared top-levelconst CURSOR_UNKNOWN. Classic scripts share one global lexical environment, so index.html's entire application script died at parse time:— no
state, no sessions, noloadLog/connectTTY/startSSE, no terminal. The existing node harness slices each function withnew Function(...)and is structurally blind to that constraint, which is how it got through the first review round.pty.js's literal is now prefixed (
PTY_CURSOR_UNKNOWN), and a new guard test fails when any two classic scripts declare the same top-level name. It was verified red before green, and independently confirmed by concatenating every classic script in load order and running V8's own parser (node --check→ exit 0). A 15-case injection matrix confirmed the guard agrees with V8 on every collision shape and stays silent on legitimate non-collisions.Tests
internal/app/tty_ws_test.go— 8 sentinel cases: SSE no-replay-then-only-new-bytes, omitted/realsinceregression guard, stopped instance (next:0, no replay), non-capturing kind (theoff < 0clamp on the wire), WS replays nothing, empty ring, stopped instance, read failure, plus400on the plain endpoint.internal/framework/manager_endoffset_test.go(new) — head correctness, non-running → 0, echoed sentinel normalised.internal/ui/testdata/terminal_status.test.mjs— 9 new cases across the PR (67 total: 58 baseline + 8 initial + 1 review follow-up): the two cursor states across both transports, SSE and WS each painting the tail exactly once behind a stripped header, the unpainted and empty-tail cases keeping the unknown cursor, cross-file constant agreement, and the script-collision guard.Verification:
gofmt -l .clean,go build ./...,go vet ./...clean,go test -count=1 ./...all packages ok,node --test67/67,go test -race -count=5on the WS + stream suites clean.TestTerminalStatusChangelogCountre-derives 67 from the file rather than trusting the prose — note its regex anchors on the firstPinned by N \node --test` cases` match, which lives in the #80 entry (CHANGELOG.md:11); that entry's number is the one kept in step with the file (33 → … → 67). CI: all 4 checks green after the merge of develop and the review follow-ups.Follow-up, not in this PR:
index.htmldeclaresfunction formatBytestwice (pre-existing at HEAD, verified untouched here). Hoisting means the second wins for all 9 callers and the first is dead code with different semantics. Worth a separate cleanup issue.🤖 Generated with DeepSeek Code