[benweru]

What and why

i2c_sensor_nack wrote a dmesg.txt that held 0 or 1 lines and differed between runs of the same seeds (found in #11). Brief: docs/tasks/sprint4-i2c-dmesg-window.md.

Cause. The window was cut by line count (_dmesg()[len(before):]). The kernel log is a fixed-size ring buffer, so once it is full, old lines are evicted as new ones arrive and a count slice drops lines. A WSL2 VM shares one log with Docker Desktop, so it fills in a long session.

Fix. dmesg_new_lines(before, after) in src/orbitlog/faults/linux.py cuts the window by the monotonic [seconds.microseconds] timestamp. It handles equal timestamps and continuation lines. The live test now asserts that dmesg.txt holds the i2c-stub: Virtual chip at <decoy> line, which would have caught this.

Also in this PR: the Sprint 4 title is marked approved in docs/plan.md, and docs/linux-fault-hosts.md records a second finding. WSL2 mounts its own modules disk over /lib/modules/<kernel> on start, so the copied i2c-*.ko files vanish after a WSL restart and the copy and depmod -a step must be repeated. This also corrects the setup I documented in #11.

How it was verified (real output)

Host: Linux Benweru 6.6.87.2-microsoft-standard-WSL2 #1 SMP PREEMPT_DYNAMIC Thu Jun 5 18:30:46 UTC 2025 x86_64.

Cause reproduced with a probe that takes both slices from the same before/after snapshots, using 4000 labelled test lines to fill the ring (oldest kept: line 1816). Count slice versus timestamp slice, after the flood:

iter 0: n_before=2184 n_after=2185 by_count=1 by_ts=2 | by_ts last: [26118.717294] i2c-stub: Virtual chip at 0x50
iter 1: n_before=2185 n_after=2186 by_count=1 by_ts=2 | by_ts last: [26118.790085] i2c-stub: Virtual chip at 0x50
iter 2: n_before=2186 n_after=2187 by_count=1 by_ts=2 | by_ts last: [26118.861936] i2c-stub: Virtual chip at 0x50

On a fresh VM (548 lines) the two methods agreed (by_count=2 by_ts=2), so the bug needs a full ring.

Real fault, ring full and churning (a thread writes labelled test lines to /dev/kmsg while the fault runs, as other host activity would), 8 seeds each, as root with ORBITLOG_ENABLE_I2C_STUB=1:

old code (a9b93f6 lineage):  SUMMARY: seeds missing the 'Virtual chip' line = 8 of 8     (dmesg_lines: 2,2,2,1,2,2,2,2)
this branch (cb57927):       SUMMARY: seeds missing the 'Virtual chip' line = 0 of 8     (dmesg_lines: 12,11,10,11,12,11,11,11)

The extra lines in the second run are the test noise: the window is a time slice and keeps whatever else the kernel logged.

pytest -m linux_i2c with the stronger assertion, in WSL2: 1 passed, 90 deselected in 0.37s.

make test: Windows 72 passed, 4 skipped, 15 deselected in 4.97s. WSL2: 75 passed, 1 skipped, 15 deselected in 2.52s. The new tests cover normal growth, eviction at constant length, equal timestamps, continuation lines, and empty input.

Known issues

• An earlier live run of the old code on a full ring passed all 8 seeds by luck. Whether the count slice fails depends on line sizes and on other activity, which is why it looked flaky. The churning run above is the reliable reproduction.
• The test noise was written to the WSL VM's kernel log. It is labelled orbitlog-test-flood or orbitlog-test-churn, only exists until the VM restarts, and never enters a dataset.
• The errno and missing NACK line differences from the article (Errno 19 vs 121) are unchanged and out of scope.