Repository navigation
fix(copilot): a lookup while Copilot moves its log copies up waits for the rotation - #3122
Conversation
…r the rotation Copilot CLI 1.0.105 rotates its process log by renaming the copies up one by one, oldest first (.3 to .4, .2 to .3, .1 to .2), then renaming the new copy into .1 and emptying the open log. A lookup whose checkpoint predates the previous rotation and lands while the copies move found no .1.log (or a hole further up), stopped looking, and stored copilot_log_truncated/rewritten: Copilot Chat stayed unavailable until Copilot registered a session again, even after the new copy was in place. A missing copy while an older one is still there now answers that lookup alone as copilot_log_read_raced and stores nothing, so the next lookup compares with the same checkpoint and follows the rotation as before. A missing copy with nothing older (no rotation yet, or the chain pruned) is still the lasting rejection it was. Fixes #3109
|
Warning Review limit reachedYou've used all free OSS reviews for now. Wait for the free limit to reset to keep reviewing this public repository. Next included review available in 1 minute. View limit details
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. |
…copy is missing Review follow-up. With a copy missing for good (for example .1 deleted while .2 remains), every lookup answered copilot_log_read_raced, even after the open log registered a session that main binds. Inside the gap the open log now decides as it does on main: a lifecycle line there is applied and stored as before; only a lookup without one is skipped, so the next lookup compares with the same checkpoint.
Review round 1 and the 1000-run batchReviews on 5d15085. omo: CLEAR. Codex (Terra, xhigh), asked to break the safety claim: "CLAIM HOLDS" (no sequence where the fix returns a session main would not), with one reproduced MEDIUM: a copy missing for good (.1 deleted, .2 kept) kept answering 1000 interleaved runs each (real Copilot 1.0.105 logger, lookups with 5% pauses, stderr logging of failed chain lookups as in the odd run, plus an in-memory trace of each lookup, 10 workers):
The one wrong run, explained. This time the trace caught it, and it is not the new path: the run's trace has no
So Copilot's rotation dropped B's line (its copy ended before the line, and the truncate removed it), and the reader followed what was on disk: the copy continued the checkpoint exactly, with no B after it. main takes the same path for that sequence. The early unexplained run had the same shape (A after B, ending on A), so I take it to be the same Copilot-side loss. Not every attempt to show the loss directly caught it: marks written right after bursts lost none in 8 runs, so the exact timing in Copilot's logger is not pinned down. Nothing on the reader side can see a line that is no longer in any file. |
Reviews at a527984
LOWs left as they are:
|
|
Merge note: all GitHub checks green at this head (browser included), omo CLEAR at this head, Codex Terra xhigh twice could not break the safety claim (every state the fix reaches is one main reaches by not doing that lookup; its MEDIUM about a permanent gap blocking a new registration is fixed here), threads resolved, merges cleanly. CodeRabbit did not review (rate limit). Real Copilot 1.0.105 logger, 1000 interleaved runs each: lasting unavailable after a rotation 210/1000 on main -> 124/997 here; wrong session 0 on main, 1 here, and that run did not take the new gap path: B's registration line was in no file (Copilot's copy ended just before it and the open log was emptied), and replaying the same file order as a fixed test gives A on main too, so it is a line lost on Copilot's side, not a state only this fix reaches. Fixes #3109. |
Summary
Fixes #3109. Copilot Chat stayed unavailable (Terminal fallback) until Copilot registered a session again when a lookup landed while Copilot CLI 1.0 was moving its log copies up for a rotation.
How Copilot 1.0.105 rotates
Traced with
strace -fon its own native logger (runnerCreateFileLoggerinruntime.node), per rotation:.4to.4.log.rotation-backup(then unlinked),.3to.4,.2to.3,.1to.2..1.log.rotation-staging..1.log.O_TRUNC.So during steps 1-3 there is a hole in the copy numbers (no
.1.log, or a missing.2/.3while the shift runs) while an older copy is still there. Copilot loses no line across rotations (60,005 numbered lines through its logger, 6 runs: none missing).What went wrong
A lookup whose checkpoint predates the previous rotation and lands in that hole stopped at the first missing copy, found nothing continuing the bytes it had read, and stored
copilot_log_truncated/copilot_log_rewrittenas the selection. Later lookups kept that until a new registration line.The change
In
rotatedLifecycle, a missing copy while an older copy still exists returns a newROTATION_GAPresult. The caller then reads the open log as it does on main when no copy continues (main'srotated === nullpath):LOG_READ_CHANGED: it answerscopilot_log_read_racedand stores nothing (it only setsreadConflicton the existing checkpoint, which makes the next lookup take the full check instead of the unchanged-file shortcut).A missing copy with nothing older (no rotation yet, or the chain pruned) is still the lasting rejection it was, as is every other path.
Safety argument. Each lookup on the new path either does exactly what main does for that lookup (a lifecycle line in the open log) or stores nothing beyond
readConflict(no lifecycle line). So every state the reader can reach with the fix is a state main reaches when that one lookup simply does not happen (for example, nobody looked during the hole), except thatreadConflictforces the next lookup to rehash instead of trusting unchanged timestamps, which can only find more. The fix therefore cannot return a session that main would not return for some timing of lookups; it only removes main's lastingtruncated/rewrittenoutcome for lookups that land in the hole.Validation
waits out a rotation moving its copies up after output / after another registration, then follows itfail on main (copilot_log_truncatedwherecopilot_log_read_racedis expected, and the later lookups stay unavailable) and pass here. The registration case checks that the hole never shows the session the copies already left behind.binds a registration in the open log while a log copy stays missing(review follow-up, below) fails on the first head 5d15085 and passes here; it passes on main too.bun test ./server/copilot.test.ts: 99 pass.bun run check fast: green (workflow syntax, generated types/themes, typecheck, build, unit tests 12585 pass).Real-logger harness (scratch, not committed)
Copilot 1.0.105's own logger writes and rotates 6 times while the reader looks up the session (A) continuously; then B registers (waiting until B's line is on disk) and 2 more rotations follow. "Wrong" counts every lookup that returned B before B registered, or A after B's line was on disk. "Lasting" counts runs that ended the rotations on
truncated,rewritten,metadata_changedorambiguous(a one-offread_racedsample is not counted).Traces of the remaining fix-side lasting cases show they are not the hole. At about 70 MB/s of continuous writes, the read of the open log after a rotation keeps racing with appends (
copilot_log_read_raced), so no new checkpoint is stored, and after four more rotations the copy that continues the checkpoint is deleted. That is the designed fail-closed answer; with bursty writes neither side fails. Everyholeevent in the traces was followed by a lookup that found the chain again.1000 interleaved runs each (same harness with 5% pauses, stderr logging of failed chain lookups as in the early odd run below, plus an in-memory trace of every lookup, 10 workers):
The wrong-session runs come from Copilot dropping B's line, and main gives the same answer. The trace of the fix-side run above has no
holeevent, so every lookup took main's own code path. What the files show:reg Bwas appended to the open log, where the harness saw it on disk..1copy is exactly 1,535,130 bytes (the log before B's line), and the open log (same inode) was then emptied.Replaying that file sequence in a fixture (checkpoint A; append B; write a
.1copy that ends before B; empty the open log; append output) returns A on both origin/main and this head (scratch test, not committed). The reader follows what is on disk, and the line is gone. An early diagnostic run of the fix, before the trace existed, showed the same shape (A on 7 lookups after B's line was on disk, ending on A), and I take it to be the same Copilot-side loss. Not every attempt to show the loss directly caught it: marks written right after write bursts lost none in 8 runs, so the exact timing inside Copilot's logger is not pinned down.Reviews. omo on 5d15085: CLEAR. Codex (Terra, xhigh), asked to break the safety claim on 5d15085 and again on a527984: "CLAIM HOLDS" both times. The one reproduced MEDIUM from the first pass (a copy missing for good kept answering
read_racedafter a fresh registration in the open log) is fixed in a527984, and Codex confirmed the fix against main and 5d15085. Known LOWs, not changed:copilot_log_read_racedinstead of the lastingcopilot_log_truncatedand re-hashes the checkpoint (up to 64 MiB). It is unavailable either way, and a registration in the open log still binds..2; this PR conservatively answers unavailable for that one lookup.Checks skipped: the integration and browser suites (no client, HTTP or WebSocket change).