Repository navigation
Fix the debug.log tail showing a line twice and replaying a file saved over itself - #637
Conversation
…d over itself Every read the tail plans now ends at the size it was planned from. A stream opened with a `start` alone reads to wherever the file ends when it gets round to reading, which is after the stat that planned it, so a line WordPress appended in between arrived from that stream and again from the next 'change' event, whose read starts at the remembered size. The panel showed those lines twice, and counted them once. A debug.log replaced under the watcher, as an editor saves it, reports 'rename' with the file still at the path. The tail used to forget its offset and replay the file, so every line it held was shown a second time and counted as unseen. It now carries on from where it stopped, by the same rule a change uses: a larger file is read from the old offset, an unchanged one not at all, a smaller one from its start. The offset is forgotten only when the file is actually gone, so what appears at the path later is read whole, as before. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
A 5-byte file after a 20-byte one is read from its start by either rule, so the test passed with the reset removed. The file now comes back longer than the old one, which is the realistic shape too: a `grunt clean` removes a short file and the first notice WordPress writes to the new one is longer. Found by the pre-PR review. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
|
Important Review skippedAuto reviews are disabled on this repository. Please check the settings in the CodeRabbit UI or the ⚙️ Run configuration
You can disable this status message by setting the Use the checkbox below for a quick retry:
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configuration
📒 Files selected for processing (5)
Included review availability: This review used your included allowance. Your plan provides up to 1 included review per hour; 0 remain after this review. 📝 WalkthroughWalkthroughInitial and tail reads now end at the final byte observed when the read is planned. Watcher reattachment resumes from the previous offset after a file replacement. If the file is absent, the offset resets so a returning file is read from the beginning. Unit and end-to-end tests cover bounded reads, replacement, removal, recreation, and subsequent appends. Priority: ⬇️ Low Merge Risk: 🔵 Low · up to A line appended during log-file reattachment may not appear until another change. The PR is mergeable with awareness of this narrow delay. 🚥 Pre-merge checks | ✅ 1✅ Passed checks (1 passed)
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. Comment |
|
@coderabbitai review |
✅ Action performedReview finished.
|
1 participant
Why
Two findings from a code review of the debug.log tail, both read from the code; both are confirmed here, by a script against Node's
fsand by tests that are red ontrunk.A line WordPress writes just as the tail is reading shows up in the Debug.log pane twice. The tail stats the file, opens a stream from an offset with no end, and attaches the watcher; the stream reads to wherever the file ends by the time it gets round to it, and the
changeevent for the same write reads from the stat's size again. The footer's badge counts the line once, so the pane and the badge disagree.Saving
debug.logfrom an editor refills the pane with every line it already showed, and the footer counts all of them as unseen. An editor's save writes a new file and renames it over the path, the watcher on the old file reportsrename, and the tail forgot its offset and replayed the file as if it had just appeared.What changes
Every range the tail plans ends at the size it was planned from.
planInitialReadandplanTailReadinsrc/log-tail.jsreturn{ start, end }withendinclusive, asfs.createReadStreamtakes it. Each read ends where the next one begins, so a byte is sent exactly once, by the read whose size saw it.startWpDebugTailalready passes the range object straight to the stream; it needed no change for this half.A file still at the path after a
renameis the file the tail was reading, until its size says otherwise.attachFileWatchernow plans withplanTailReadwhen it has an offset, by the same rule achangeuses: a larger file is read from the old offset, an unchanged one not at all, a smaller one from its start, as after a Clear. The offset is forgotten only inwatchForFile, when the file is actually gone, so what appears at the path later is still read whole, as agrunt cleanand rebuild expects. This is the decision the second finding asked for, and it is the one the module's own comment already made for a same-length rewrite: replaying the file on every such event duplicates it into the pane, which is worse than missing a replacement that happens to be no smaller.Nothing on screen changes shape. The renderer's
backlogflag and its counting are untouched.How to test this
Platforms: any for the pane; the
renamepath is where the platforms differ in which eventsfs.watchsends, so a pass on Windows is worth more than a second one on macOS. Build: the current head, or the Buildkite artifact for it once it exists.The journey carries the editor's save. From the repository root:
It is red on
trunkat the new step: the footer says 3 unseen lines where 1 is right, because the whole file was replayed and counted. I checked by puttingtrunk's two source files back under the new tests. The duplicate from the first finding is a race between a stat and a stream's first read, which a person cannot stage by hand;node --test tests/unit/log-tail.test.cjsreproduces it on a real file (also red ontrunk), and the two new tests intests/unit/ipc-wiring.test.cjsreach therenamedecision directly, with the file present and with it gone.What the journey cannot reach, for a pass by hand against a real site with a built
wordpress-developand the dev server started:Starting state: a site whose dev server is running, with the Logs tray open on the Debug.log tab and at least one line in the pane.
build/wp-content/debug.logunder the site is the file; the pane names its path.echo "PHP Notice: by hand" >> build/wp-content/debug.log. Expected: it arrives in the pane without anything being clicked. This is the tail on the new file.What must not have happened: no line in the pane appears twice; the badge after the save counts the added line, not the file's line count; the marker line about an earlier run appears only once, under the backlog the start replayed, and not after the save.
Risks and limitations
statSyncand itsfs.watchattaching, two synchronous calls apart, now waits for the nextchangeevent instead of arriving at once and then again. WordPress logs in bursts, so the next line brings it.debug.logcopied over it, is read from the old offset and its head is not shown. The same trade-offplanTailReadalready makes for a same-length rewrite on achange; a smaller one is replayed from its start, as a Clear is.renamepath's events were checked by script on macOS (onerename, file present, old watcher dead) and not by hand on Windows, wherefs.watchwatches the directory and may send achangeas well; every ordering I could construct reads each byte once, the wiring tests pin the decision without a real watcher, and the journey runs on Windows in CI.renamearrives after the new file exists is taken for the old one: with the first write longer than the old file, its first bytes up to the old size are skipped. The events are asynchronous and a few milliseconds behind, so the window exists; nothing reproduces it in practice, and the inode would not tell the cases apart either, since an editor's save is a new inode too.redesign/wpds; that branch merged intotrunkas Redesign the interface with the WordPress Design System #591 on 2026-10-05 with Count unseen debug.log lines on the footer's Logs button #614 in it, so this change edits the badge version directly and there is nothing left to merge it into.Related
Follow-up to #217 (the debug.log tail and its read planner), #558 (the logs tray) and #614 (the unseen count, which is what the second finding miscounts).
Design decisions and alternatives considered
Why
endrather than reordering the stat and the watcher. Attachingfs.watchbefore thestatSyncwould also close the gap in the first risk above, but a stat that fails after the watcher is attached leaves a watcher to close on a failure path, and the duplicate was the user-facing bug. The bound is one field, and the plan is what the tests read.Why the decision lives in
attachFileWatcherand not in a third planner. The two planners already cover both answers; the only new fact is whether the tail had a file before, which islastSize > 0, and the place that knows the file is gone iswatchForFile. AplanReattachRead(lastSize, size)would be a one-line ternary with its own tests and nothing the wiring tests do not already pin.Why the file found after a
renameis not always treated as new. It is new in the sense of being another inode, but the app cannot tell an editor's save from agrunt cleanthat way; the size can, as far as a size can, and the pane's own comment already chose missing a same-length rewrite over duplicating the file. The case this gets wrong, a larger unrelated file placed at the path, is in Risks.Review outcome (required — see AGENTS.md)
1 [fix here] · 0 [follow-up] — fixed. Pre-PR review per
.github/instructions/code-review.instructions.md; CodeRabbit not yet requested.d18513a673e034beecc8e769d10ea4f12723dbf8/ base0cf005f86417f786397a792b290f6748b21adbcb(origin/trunk);npm run lintandnpm testgreen on that head (1961 tests, 0 failures), the two touched unit files re-run by the reviewer, the journey read and not run. Finding, tests 🟡 [fix here]: the wiring test for a file removed and brought back could not go red, because a 5-byte file after a 20-byte one is read from its start by either rule. Fixed ince9fb0fby bringing the file back at 25 bytes; confirmed red with the reset removed and green with it. Two style notes taken: the comment inattachFileWatcherno longer says the offset is 0 only when there was no file (a Clear zeroes it too), and the remove-and-recreate window is now in Risks. Verified and not findings: no range the planners produce can makefs.createReadStreamthrow; two in-flight streams read disjoint ranges; every path throughwatchForFileis right; Windows may deliver tworenameevents for a replace and the second reads nothing; the journey's new matches are scoped to the tray and run after the exact byte stream was asserted.d18513a→ce9fb0f3d1da8ad4623777209c21394f725c9d2dchecked: one commit, the test fix above plus the comment, lint and the threewp-debug:startwiring tests green; no other file touched.Implementation notes
src/log-tail.js:end: size - 1on every range; header comment says why. A one-byte file is the edge the new unit test pins ({ start: 0, end: 0 }).src/main.js,startWpDebugTail:attachFileWatcherchoosesplanTailReadwhenstate.lastSize > 0,planInitialReadotherwise;watchForFilezeroeslastSizewhen the file is absent;reattachAfterLossno longer zeroes it. ThefromBeforeflag and the marker are as they were, so a file found after arenameis told as news without the marker.tests/unit/log-tail.test.cjs: ranges updated, a range-end test, and a real-file test that opens a stream from a plan, appends before it reads, and asserts the stream carried only what the plan saw.tests/unit/ipc-wiring.test.cjs:fakeTailedFilestands in forexistsSync,statSync,createReadStreamandwatchon the log path only, falling through to the realfselsewhere, so a watcher's event is delivered with the file in the state the test says. One test for arenamewith the file present (continued from the offset, old watcher closed, one new watcher, no marker, nothing read for an unchanged size), one for arenamewith the file gone (folder watched, file read whole when it comes back).tests/e2e/journeys/logs.spec.js: the "first appears" test gains an editor's save over the file and an append after it, asserting the exact text the window was told and the count on the footer.{ start: 0 }on a 14-byte file, appended to before it read, delivered 21 bytes, and a re-read from 14 delivered the same 7 again;fs.watchon a file renamed over on macOS delivered onerenamewith the path present at its new size and nothing for a later append.Screenshots or recording
Nothing on screen changed shape: the same pane shows fewer lines in two cases where it showed too many.
🤖 Generated with Claude Code