From 4934b3ec97c85f0d74a6da8df9777a442b6f69e8 Mon Sep 17 00:00:00 2001 From: Aaron Newton Date: Fri, 31 Jul 2026 00:42:32 -0700 Subject: [PATCH] Fix log/ring merge splicing non-contiguous bytes on log lag (BUG-076) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit readLiveRebuildHistory's merge assumes the ring's overflow tail picks up exactly where the log-covered prefix ends. When the on-disk log lags the ring by more than the ring's own 256KB capacity β€” rare under normal operation, but reachable under a heavy output burst that outpaces a momentarily-slow disk write β€” the old code clamped the overflow and concatenated the log prefix directly with the ring's tail anyway. The two ranges are NOT contiguous in that case: the bytes in between were evicted from the ring before the log could catch up, and are unrecoverable from either source right now. Splicing them together feeds x/vt content whose escape sequences and cursor state were never actually adjacent, producing unexplained missing characters/words and garbled symbols at the seam β€” on an actively-streaming pane with no bind/resize event at all, easy to mistake for BUG-075 (same "no bind involved" signature, different mechanism: BUG-075 was a plain incremental feed with no log involved). Fix: when the gap is unrecoverable, return just the log-covered prefix and its true total (logSize, not ringTotal). The caller records this as emuFedTotal, so understating it defers the unrecoverable range to the next Draw's ring-wrap check, which naturally retries the exact catch-up (readLogRangeForTask, BUG-073) once the log has caught up, instead of permanently losing content and mis-splicing what was captured. πŸ€– Generated with [Claude Code](https://claude.com/claude-code) Co-authored-by: Claude --- context/knowledge/gotchas/pty-terminal.md | 1 + context/knowledge/index.md | 2 +- internal/tui/terminal/terminalpane.go | 21 +++++++++--- internal/tui/terminal/terminalpane_test.go | 38 ++++++++++++++++++++++ 4 files changed, 56 insertions(+), 6 deletions(-) diff --git a/context/knowledge/gotchas/pty-terminal.md b/context/knowledge/gotchas/pty-terminal.md index d6948aac..7377c70c 100644 --- a/context/knowledge/gotchas/pty-terminal.md +++ b/context/knowledge/gotchas/pty-terminal.md @@ -52,6 +52,7 @@ - **The rerender cache must invalidate on every "predicate matched but kick suppressed" outcome so a missed kick can retry at the same cols.** Without invalidation, any non-retryable state at the same cols (busy agent, transient daemon hiccup) would freeze the gate forever β€” the user would have to manually resize the terminal to clear the cache. Helpers `App.invalidateAttachCache(taskID)` (TUI, main-goroutine-only) and `Server.invalidateColsCache(taskID)` (web, mutex-protected) wrap the delete. Invalidating branches: `RerenderDeferBusy` / `!IsIdle()` (busy agent), `RerenderDeferPrompt` / `BlockedOnPrompt` (agent blocked on a user prompt), `sess.Stop()` error / `runner.KickRerender()` error (transient daemon failures), `db.Get()` error (transient DB failures). Only the `task.SessionID == ""` early-return on the web side intentionally leaves the cache populated β€” Codex backends can never resume mid-conversation, so there is no retry semantic. - **Daemon-side kick-restart must skip the InProgressβ†’Review status flip and report Alive=true during the restart gap.** When `Runner.KickRerender` queues a stop+restart, the runner's exit goroutine fires `onFinish` (which would normally `transitionTaskOnExit` to InReview) before the new session is in place. The daemon's onFinish guards on `Runner.HasPendingRestart(taskID)` to skip the transition; without that, the row briefly flips to InReview and the API's `idleWatcher` / web SPA's status polling races the restart and pops a Resume modal. Symmetrically, `RPCService.SessionStatus` must report `Alive=true` when `HasPendingRestart` is set even though `runner.Get` returns nil β€” otherwise the TUI's stream client treats the gap as a real exit and tears down the session. The pending entry is held until the new `runner.Start` returns, closing the window. - **`renderLive`'s ring-buffer-wrap full-replay path must read from the on-disk session log, not just the 256KB ring buffer.** Ring wrap (the incremental tail no longer covers everything since the last feed) β†’ emulator rebuild β†’ feeding only `sess.RecentOutput()` (≀256KB) would drop history that was in the _previous_ emulator's 10K-line scrollback because it never enters the new emu. The live agent then re-emits a status bar at the new bottom row while the previous status bar β€” still in the 256KB ring β€” gets re-played and lands adjacent to it. Visible artifact: two status bars stacked at the pane bottom, no scroll indicator (still in live mode). Fix: `readLiveRebuildHistory` reads the 8MB log tail, merges with `RecentOutputTailWithTotal` to cover bytes that arrived between log read and snapshot, and feeds the result through `AlignToEscBoundary`. **This path is no longer used for a pure dimension change** (see the Resize-in-place entry below) β€” only for a genuine ring-wrap data gap, where there is no alternative to re-deriving from disk. +- **`readLiveRebuildHistory`'s log/ring merge must NEVER splice non-contiguous byte ranges together, even when the gap between them is genuinely unrecoverable (BUG-076).** When the on-disk log lags the ring by MORE than the ring's own 256KB capacity β€” rare under normal operation (readLoop flushes log writes chunk-by-chunk), but reachable under a heavy output burst that outpaces a momentarily-slow disk write (e.g. a bulk git/tag operation streaming a lot of output quickly) β€” the old code clamped the overflow and concatenated the log-covered prefix directly with the ring's overflow tail as if they were adjacent. They are NOT: the bytes in between were evicted from the ring before the log could catch up, and are unrecoverable from either source right now. Splicing them anyway feeds x/vt content whose escape sequences and cursor state were never actually adjacent β€” visible as unexplained missing characters/words and garbled symbols at the seam (a stray "%", a dropped letter mid-word), on an actively-streaming pane with no bind/resize event at all, which made this easy to mistake for BUG-075 (same "no bind involved" signature, different mechanism β€” BUG-075 was a plain incremental feed with no log involved). Fix: when the gap is unrecoverable, return just the log-covered prefix and ITS total (`logSize`, not `ringTotal`) β€” the caller records this as `emuFedTotal`, so understating it defers the unrecoverable range to the next Draw's ring-wrap check, which naturally retries the exact catch-up (`readLogRangeForTask`, BUG-073) once the log has had a chance to catch up, instead of permanently losing content and mis-splicing what little was captured. Regression test: `TestReadLiveRebuildHistory_UnrecoverableGapDoesNotSpliceNonContiguousBytes`. - **A PTY dimension change must resize the EXISTING live emulator in place (`emu.Resize(cols, rows)`), never discard it and replay from the on-disk log tail.** `readLiveRebuildHistory`'s 8MB tail read (`liveRebuildHistorySize`, meant for the ring-wrap case above) is not a safe substitute for a resize: for any session with more than ~8MB of cumulative PTY output, an arbitrary mid-stream 8MB window has no memory of the terminal's true prior state (scrollback depth, cursor position, alt-screen mode) β€” x/vt reconstructs an internally-consistent but WRONG screen from it, and multiple historical redraw frames land on top of each other. Confirmed against real ~10-14MB dogfood session logs: feeding the true full history into one emulator vs. just the last-8MB tail into another (mirroring the exact rebuild-on-resize code path) produced literally dozens of overlapping historical lines (old git/CI status updates, slash-command menu text, PR fragments all jammed together character-by-character on the same rows) β€” this is BUG-068, the "old content bleeds through and overlaps with new content" report. **Why toggling fullscreen (Ctrl+Z) and back "fixed" it before this was patched:** that toggle is itself a dimension change and re-triggered the identical lossy rebuild, but it *also* makes the agent process (ink/React) redraw its entire UI fresh at the new size β€” that genuine incremental repaint painted over the garbage. The resize appeared to be the fix; it was actually incidental cover for a bug in argus's own reconstruction. Fix: `renderLive` distinguishes `emuMissing` (`tp.emu == nil` β€” first attach, nothing to preserve, still rebuilds from the log tail) from `sizeChanged` (emulator already exists, only cols/rows differ β€” call `tp.emu.Resize(ptyCols, ptyRows)`, which x/vt guarantees preserves scrollback, alt-screen mode, cursor position, and SGR state exactly, the same as a real terminal's SIGWINCH). Regression test: `TestTerminalPane_ResizePreservesEmulatorState` (nils the mock session's output after establishing alt-screen content, so a history-rebuild attempt would find nothing and show a placeholder β€” proving the resize path never attempts one). - **Ring-wrap (`newBytes > len(raw)`, `emu != nil`) must recover the EXACT missing bytes from the on-disk log at the precise offset, not discard the emulator and rebuild from the approximate 8MB tail window (BUG-073, the ring-wrap sibling of BUG-068).** BUG-068 fixed the resize trigger of the "old content bleeds through and overlaps with new content" bug but explicitly left the ring-wrap trigger alone β€” there IS no alternative to a log read when the ring has genuinely evicted bytes, so it seemed unavoidable. It isn't: `Session.readLoop` (internal/agent/session.go) writes the ring buffer and the on-disk log from the identical `data` slice in the same iteration, so a `TerminalPane`'s `emuFedTotal` is in the EXACT same coordinate space as the log file's byte offsets β€” a precise incremental catch-up is always possible when the log still has those bytes (it almost always does; the log is append-only and only truncated once, at session start). Ring-wrap is reached by an everyday trigger distinct from resize: `SetSession` only resets `tp.emu`/`emuFedTotal` when the session POINTER changes, so simply viewing a different task's pane (or the rail/task list) while the backgrounded agent produces more than the ring's 256KB capacity leaves the SAME live emulator in place with a stale `emuFedTotal` β€” on return, the incremental tail no longer covers the gap and the old code fell all the way back to the lossy 8MB-window rebuild, discarding the (perfectly fine) existing emulator for no reason. Fix: `readLogRangeForTask(taskID, offset, length)` reads `[emuFedTotal, totalWritten)` straight from the log and feeds it into the EXISTING emulator (no discard, no `AlignToEscBoundary`/oscStrip-reset needed β€” it's contiguous with what's already parsed, exactly like the ordinary incremental-feed branch). Bounded by `logRangeCatchUpMaxBytes` (reuses the 8MB `liveRebuildHistorySize` budget) and falls back to the old approximate rebuild when the exact range isn't on disk (missing log, external truncation) β€” no regression in that residual case. Regression test: `TestRenderLive_RingWrapRecoversExactBytesWithoutDiscardingEmulator` (establishes alt-screen content, forces a ring-wrap gap the mock's short `RecentOutput()` can't cover, asserts the emulator POINTER is unchanged and both pre- and post-gap content survive; fails if the catch-up branch is disabled, confirmed by deliberately breaking it before writing the fix). - **Byte slices from arbitrary file/ring positions can start mid-CSI; align to first ESC before feeding the emulator.** `readLogTailForTask` reads `[fileSize - N, fileSize)` and the ring's `Bytes()` returns whatever wrapped-around position the buffer holds. Either tail can start in the middle of a `\e[5;3H` parameter list. x/vt's parser sees the orphan `5;3H` as printable text and renders a smudge of digits/punctuation at the top of a fresh emulator. `terminal.AlignToEscBoundary` skips to the first ESC byte; if there isn't one, the slice is treated as plain text. Apply to **every** fresh-emulator feed from a tail-positioned source: `renderLive`'s full-replay, `asyncReplayRebuild`'s replay-emu, and `terminal.PreviewVT.Feed`'s full-replay branch (task switch / dimension change / ring wrap). The preview path went unaligned for months and produced visibly torn previews under long sessions β€” doubled status bars and orphan digit smudges in the agent preview rectangle. diff --git a/context/knowledge/index.md b/context/knowledge/index.md index feb3dbea..c8f5fbca 100644 --- a/context/knowledge/index.md +++ b/context/knowledge/index.md @@ -5,7 +5,7 @@ Non-obvious invariants and gotchas, split by topic. Read the relevant file when | File | Topic | Bullets | | --- | --- | --- | | [gotchas/daemon-rpc.md](gotchas/daemon-rpc.md) | Daemon lifecycle, RPC timeouts, reconciliation races, session resume, Claude /clear recapture, binary staleness (SHA-256 content hash, not mtime), self-update, launchd auto-start + PATH, stream Since offset, paste-boundary flush, *.test fork-bomb backstop, singleton flock, PR poller (eligibility, terminal-state skip, batched per-repo graphql w/ alias-safe ids + chunked keep-stale), evidence-based completion (ExitInfo.CleanExit predicate; reconcileβ†’InReview never Complete), hera worker finish policy (BUG-050 RollHeraWorkerToReview), startup hera-binding reconciliation, session-supervisor P1–P4 (dark PTY-owner, daemon-as-client behind cfg.Supervisor.Enabled, re-attach on bounce, default ON + in-process rollback, #707 cache-vs-EOF relay race), callWithTimeout nil-rpc guard, TUI supervisor restart, go-install skew (doctor restart-vs-path-divergence, supervisor-checked-on-auto-start, ProtocolVersion 2β†’3 old-supervisor-unknown, double-confirm supervisor restart), revive-restores-in_progress (BUG-B ReviveHeraWorkerToInProgress, inverse of RollHeraWorkerToReview), host-suspend watchdog (ARGUS_HOST_SUSPENDED advisory note β€” wall-clock gap>3m between 30s ticks, unconditional not Hera-gated, sibling of sendBounceSignals, one-shot no-dedup baseline-before-loop, monotonic-strip required, advisory-only no state mutation), Claude Code's own background-session supervisor (orphaned-worker root cause: single-PID SIGTERM can never reach a session Claude Code itself detached to its per-user supervisor; `claude agents`/`claude stop` detection+fix SHIPPED via internal/claudeagents + Runner.Stop fire-and-forget reap, not a signal-scoping bug), doctor Stop-hook registration check (detect-missing-coord-hook: REGISTERED/NOT REGISTERED/UNKNOWN, advisory-only, never gates the binary-coherence exit code), resume-time session-ID recapture (agent.RefreshResumeSessionID mirrors the exit hook because hera workers idle/StreamLost never reach captureSessionIDPostExit; Claude-only; wired at reattachSupervised orphans + TUI startSession + REST resume/restart; idempotent, never blanks/fabricates), doctor diligence-profile-library check (add-doctor-profile-check: FOUND/NONE FOUND/UNKNOWN, library-existence-only not per-project binding, missing-dir vs unreadable-dir tri-state, advisory-only), hera_revive coordinator PULL-revive (add-hera-revive: third ReviveHeraWorkerToInProgress caller, shared internal/hera.ReviveRole gate, deliberately not unified with the TUI's Enter-key revive) | 109 | -| [gotchas/pty-terminal.md](gotchas/pty-terminal.md) | PTY sizing, x/vt emulator, ring buffer, replay cache, paint cache, lazyScreen, test concurrency, ESC-boundary alignment, live rebuild from log tail, monotonic firstByteOffset, scrollOffset clamp, waitLoop close-after-drain order, rerender gates (unchanged-cols, cache invalidation, blocked-on-prompt), OSC 0x9C-in-UTF8 strip filter, persistent preview emulator (PreviewVT reuse-via-RIS), plugin terminalpane cursor sync, alt-screen keyboard-scroll + scroll-mode-entry suppression (BUG-031, not just the wheel), scroll-past-window lazy extend (BUG-E), scroll replay authored-width emulate-clip (live-scroll corruption), dimension-change resize-in-place instead of lossy 8MB-tail rebuild (BUG-068, overlapping/garbled live-view corruption), ring-wrap exact-offset log catch-up instead of lossy 8MB-tail rebuild (BUG-073, BUG-068's ring-wrap sibling β€” reached by backgrounding a busy agent's pane, not resize), live incremental-feed atomic (raw,total) snapshot instead of two separate racy calls (BUG-075, TOCTOU race distinct from BUG-068/073/074 β€” reachable on an actively-streamed pane with no bind/resize at all, causes a duplicated recent phrase + a couple of dropped characters) | 65 | +| [gotchas/pty-terminal.md](gotchas/pty-terminal.md) | PTY sizing, x/vt emulator, ring buffer, replay cache, paint cache, lazyScreen, test concurrency, ESC-boundary alignment, live rebuild from log tail, monotonic firstByteOffset, scrollOffset clamp, waitLoop close-after-drain order, rerender gates (unchanged-cols, cache invalidation, blocked-on-prompt), OSC 0x9C-in-UTF8 strip filter, persistent preview emulator (PreviewVT reuse-via-RIS), plugin terminalpane cursor sync, alt-screen keyboard-scroll + scroll-mode-entry suppression (BUG-031, not just the wheel), scroll-past-window lazy extend (BUG-E), scroll replay authored-width emulate-clip (live-scroll corruption), dimension-change resize-in-place instead of lossy 8MB-tail rebuild (BUG-068, overlapping/garbled live-view corruption), ring-wrap exact-offset log catch-up instead of lossy 8MB-tail rebuild (BUG-073, BUG-068's ring-wrap sibling β€” reached by backgrounding a busy agent's pane, not resize), live incremental-feed atomic (raw,total) snapshot instead of two separate racy calls (BUG-075, TOCTOU race distinct from BUG-068/073/074 β€” reachable on an actively-streamed pane with no bind/resize at all, causes a duplicated recent phrase + a couple of dropped characters), log/ring merge no-splice-across-unrecoverable-gap (BUG-076, readLiveRebuildHistory understates emuFedTotal to logSize instead of gluing non-contiguous log+ring bytes together when the on-disk log lags the ring by more than 256KB under a heavy output burst β€” distinct root cause from BUG-075 sharing the same no-bind-event signature) | 66 | | [gotchas/ui-threading.md](gotchas/ui-threading.md) | tview thread safety, tick-goroutine rules, lazyScreen fill invariant, paste/input batching, tmux UX-tearing post-mortem (no Sync; 3 legit repair callsites), OnBranchChange log-only contract, EventFocus drift recovery, stderr/stdout-after-Init fd 2 guards, status-bar notice auto-expire (15s TTL, lazy revert via 1s tick, no Sync/timer), SetScreen swallows tcell Init() errors (no-ctty nil-tty EnableMouse panic, probeTerminal preflight guard), probeTerminal false-positive-on-every-real-terminal regression (tcell devTty.Close() nil-`f` β†’ os.ErrInvalid, fix discards Close() err + probeTerminalDev pty-slave test seam) | 29 | | [gotchas/ci-gates.md](gotchas/ci-gates.md) | `make pre-pr` per-gate failure recipes (fmt-check, test-cover-gate floor, lint-pr new-from-rev, vuln stdlib continue-on-error, macOS PTY-exhaustion flake in internal/agent under full-suite -race) | 5 | | [gotchas/sandbox.md](gotchas/sandbox.md) | macOS sandbox-exec SBPL profiles, symlink resolution, allowed paths, Chrome support dir for Playwright, AppleEvent allowlist, Messages.app legacy alias, picker modal, TCC re-prompt fix (stable-signed local binary via workflow-neutral `make install-signed`; first-sign Keychain "Always Allow") | 26 | diff --git a/internal/tui/terminal/terminalpane.go b/internal/tui/terminal/terminalpane.go index 94a941ff..4398df15 100644 --- a/internal/tui/terminal/terminalpane.go +++ b/internal/tui/terminal/terminalpane.go @@ -949,11 +949,22 @@ func readLiveRebuildHistory(sess agentview.TerminalAdapter, taskID string) (raw if overflowInt > len(ringTail) { // Log lags ring by more than the ring's capacity β€” should not // happen under normal operation (readLoop flushes log writes - // chunk-by-chunk). Best effort: concat both. The bytes - // [logSize, ringTotal-len(ringTail)) are unrecoverable; emulator - // will be missing those, but the next incremental feed brings - // it back to live. - overflowInt = len(ringTail) + // chunk-by-chunk), but a heavy output burst can outpace a + // momentarily-slow disk write (BUG-076). The bytes + // [logSize, ringTotal-len(ringTail)) are genuinely unrecoverable + // from either source right now β€” clamping overflowInt and + // concatenating logRaw directly with ringTail's overflow tail + // anyway (the old behavior) would splice two NON-contiguous byte + // ranges together with no realignment, corrupting whatever + // content or escape sequence straddles the gap (unexplained + // missing characters/words, garbled symbols at the seam). Return + // just the log-covered prefix and ITS total (logSize, not + // ringTotal): the caller records this as emuFedTotal, so + // understating it defers the unrecoverable range to the next + // Draw's ring-wrap check, which naturally retries the exact + // catch-up (readLogRangeForTask) once the log has had a chance to + // catch up β€” never silently losing or mis-splicing content. + return logRaw, uint64(logSize) //nolint:gosec // logSize is a file size, always non-negative } extra := ringTail[len(ringTail)-overflowInt:] out := make([]byte, 0, len(logRaw)+len(extra)) diff --git a/internal/tui/terminal/terminalpane_test.go b/internal/tui/terminal/terminalpane_test.go index b43d0c03..51a60338 100644 --- a/internal/tui/terminal/terminalpane_test.go +++ b/internal/tui/terminal/terminalpane_test.go @@ -2606,6 +2606,44 @@ func TestReadLiveRebuildHistory_OverflowMerge(t *testing.T) { testutil.Equal(t, total, uint64(6)) } +// TestReadLiveRebuildHistory_UnrecoverableGapDoesNotSpliceNonContiguousBytes +// is a regression test for a pre-existing gap the function's own comment +// already named ("readLoop flushes log writes chunk-by-chunk... rare") but +// never guarded against: when the on-disk log lags the ring by MORE than the +// ring's own capacity (a heavy output burst that outpaces a momentarily-slow +// disk write), the old code clamped the overflow and concatenated the +// log-covered prefix directly with the ring's overflow tail as if they were +// contiguous β€” but they are NOT: the bytes in between were evicted from the +// ring before the log could catch up, and are unrecoverable from either +// source right now. Splicing them together feeds x/vt content whose escape +// sequences and cursor state were never actually adjacent, producing +// unexplained missing characters/words and garbled symbols at the seam +// (BUG-076) β€” distinct from BUG-075 (which fired on a plain incremental +// feed with no log involved at all) but easy to confuse with it since both +// show up on an actively-streaming pane with no bind event. +func TestReadLiveRebuildHistory_UnrecoverableGapDoesNotSpliceNonContiguousBytes(t *testing.T) { + setupTaskLog(t, "rebuild-gap", "AAAA") // log covers bytes [0,4) + // Ring has wrapped past the gap: it currently holds only the LAST 2 + // bytes ("YY", representing bytes [8,10)) β€” bytes [4,8) were evicted + // from the ring before the log could catch up, and are unrecoverable + // from either source right now. + sess := &mockAdapter{alive: true, totalWritten: 10, output: []byte("YY")} + raw, total := readLiveRebuildHistory(sess, "rebuild-gap") + + // The caller records `total` as emuFedTotal, so raw and total must + // always describe the SAME prefix of the stream β€” never claim more (or + // less) was fed than `raw` actually contains. + if uint64(len(raw)) != total { + t.Fatalf("raw/total mismatch: len(raw)=%d, total=%d β€” caller would believe a different amount was fed than actually was", len(raw), total) + } + if string(raw) != "AAAA" { + t.Errorf("raw = %q, want \"AAAA\" β€” must return only the log-covered prefix, never splice the ring's non-contiguous overflow tail onto it", raw) + } + if total != 4 { + t.Errorf("total = %d, want 4 (logSize) β€” NOT ringTotal (10), which would overstate progress past an unrecoverable gap and permanently strand it", total) + } +} + // TestReadLiveRebuildHistory_NoLogFallback verifies that a missing log // falls back to the ring buffer alone (and uses atomic // RecentOutputTailWithTotal to avoid the tail/total race).