[Japabu]

Problem

acpi_press_is_one_sci stalled on every run since #1175 (three of three, main included). Its console carried nothing after the UART's hand-over: no supervisor line, no program line.

Cause, read off the guest

A diagnostic run of the row on main's code, plus QEMU's 16550 trace and QMP on the stall, showed:

• The UART driver never served its line. After the kernel's last inline byte, the driver's only register access was one IER write of 0x01, its Machine::open. No LSR or IIR read followed, so Line::serve never ran. The driver was parked before its loop, in logkeeper_api::carry, waiting for logkeeper's answer.
• The guest was idle, not wedged. Both vCPUs were halted with interrupts open (HLT=1, RFL=0x246, CR3 the kernel's), twice, 2 s apart.

The code explains why carry was never answered. logkeeper runs Volume::open → read_dir("/log") before its loop, its carriers and its log port. A request on a role's port waits for that role's server. The supervisor starts the LOG file server only with storage, and storage waits for the root bridges' memory to be declared, for at most declaration::BOUND = 30 s. The press probe holds the acpi claim and declares nothing, so every console channel stood silent for the bound, past the harness's 17 s. The other acpicase rows looked fine only because their boots end within a second and the stop's replay covers the gap. Before #1175 the kernel's klogd carried the console without logkeeper.

Severity: hang, not data loss. Nothing a channel took was lost: the lines waited in the rings and the replay. By the code, they would reach the console once the bound expired and the supervisor closed LOG's ports. That was not observed: the harness gives up at 17 s. For a LOG server that takes the request and never answers, the wait had no bound at all.

Change

logkeeper opens the volume on a thread of its own:

• The loop, the carriers and the log port run from the start.
• The loop adopts the volume once the thread answers, outside a stop, and at the stop's flush. The file then takes the boot whole from the replay, in whole lines (Hub::owed), before each round after. A gap the replay let go of is said in the file.
• A stop that comes first says /log had not opened. inspect reports volume.state = opening meanwhile.

The closed record's durable rule now lives in logkeeper's module header: nothing waits for the volume to open.

Residual, recorded rather than fixed: the loop's own file writes and syncs still block on the LOG server. A server that is alive but wedged would silence the console the same way, with no failure bound. It is read from the code, not reproduced: issues/the-console-waits-on-logkeepers-file-writes.md.

Overlap with #1190 (draft, dataloss-followup). #1190 reworks the same volume code: the file keeps its own offset into the replay and is asked again after a refusal. It still opens the volume before the loop, so it does not fix this stall. Whichever lands second should adopt the other's mechanism: #1190's caught_up subsumes this branch's adopt catch-up loop, and this branch's opener thread is what #1190's first open needs. Both add a Hub::owed.

Metal

The T14 has no 16550 (its loopback reads 0xFF), so the UART driver exits and the UART path does not exist there. The same wait did apply to the panel console, which reads the log through logkeeper's log port, served only after the volume opened. On a normal boot that hold-back lasts for the declaration and the LOG mount, about a second by declaration::BOUND's note. A LOG server that hangs would make it indefinite. This is inferred from the code; no metal run was made. No metal row isolates the wait, and the press row needs QEMU's power button.

Checks

All guest runs are guest-rows.yml, x86-64 KVM. Evidence is on pr-1195, with the runner's home and hostname masked.

check	revision	result
diagnosis: the row, QEMU -trace serial_* and QMP on the stall (patch, never for landing)	main 0f085b1 + patch	STALL; trace and registers as above (log)
acpi_press_is_one_sci	883809d	PASS (2 s), four of four: 42038000569, 42039351255, 42039919410, 42040934202
the other four acpicase rows, the_log_lands_on_the_boot_stick, nvme_disk_boots	883809d	6 passed (log). The stick's log volume holds a whole boot's log, so the late-opened file took the early boot from the replay
cargo run -- --ci host (macOS aarch64)	883809d	exit 0, 108 steps green (log), incl. the new a_late_file_is_owed_the_boot_whole_and_what_was_let_go

Negative control: the change reverted onto its base. The row stalled three of three without it: 42010705757 and 42016111039 at #1187's head 0383550, and 42025888487 at main b27dd3e. 0383550's tree differs from this branch's base 6755d1d only in issues/ and instruction files. The row at 6755d1d itself, this branch's base without the change, stalls the same way: STALL at 17 s, the console ending at Boot: complete (42049438240).

Review round 1 at 1131a5a (flushed adopts a volume that opened during the stop's rounds; comments corrected): acpi_press_is_one_sci and the_log_lands_on_the_boot_stick, 2 passed (42068104021). cargo test -p logkeeper 23 passed. Earlier results stand for what this round did not touch: the round changed only flushed's start, comments and the record.

No aarch64 guest run: the change is userland logkeeper code, which is architecture-independent and touches no shared kernel code.

🤖 Generated with Claude Code

[Japabu]

Review of #1195 at 883809d

I read the commit, the full diff against its base 6755d1d, all of system/logkeeper/src/main.rs and serve.rs, Replay in lib/logstream, store.rs's open and rotation, the LOG_OPENED consumers (build/bootlog.rs, tests/toyos.rs), the handoff, and #1190's logkeeper diff. I checked the six cited guest runs with gh run view. The press row at 883809d succeeded in 42038000569, 42039351255, 42039919410 and 42040934202. The six-row batch at 883809d succeeded in 42038076347. The control at 6755d1d failed in 42049438240 with STALLED: waiting for the probe to arm the power button.

Architectural assessment

The diagnosis holds up. Before this change, logkeeper's main called Volume::open → read_dir("/log") before it started the hub, the carriers or the loop. The LOG server's start therefore gated every console channel. Moving the open off the loop is the right first step, and logkeeper is the right owner. The other option would be the supervisor reordering LOG ahead of storage, which only moves the dependency.

Threading. The volume thread shares one sync_channel(1) with the loop and nothing else. Its startup lines go through logkeeper's own ring like any other say!. The loop thread is still the only thing that appends to the replay: append, append_stopping and resume all run on it, and own_line only renders. adopt runs on that same thread between rounds, so the catch-up reads a replay nothing else can grow at that moment. Nothing is duplicated, lost or reordered when the file catches up. The resume path holds too. to_volume is a no-op while the volume is closed, and hub.resume appends the held text, so a later adopt writes it exactly once. The gap note goes to the file only, which is right because the console and readers already had those bytes. Memory while the file is closed is the existing REPLAY_BYTES (16 MiB), which was already allocated by design. STOPPING_BYTES still bounds the stop's hold-back. Nothing new grows.

Should the console depend on the file at all? It should not. After this PR the dependency is indirect: the loop is both the replay's only appender and the file's synchronous writer. The clean final shape makes the file a consumer of the replay with its own offset, on its own thread, like the readers and carriers. The opener thread becomes the file's writer, and the stop asks it to reach hub.end(), sync and answer within a bound. That shape removes the residual hang, this PR's adopt catch-up, and the "file first" ordering that the stop protocol now has to reason about. It needs exactly the per-file offset and bounded stop catch-up that #1190 builds (Volume::through, catch_up, finish with STOP_CATCH_UP). Doing it here would build that mechanism a second time and deepen the conflict. Recording the residual is acceptable for this PR. Its exit should be taken up together with #1190, not left as an unheld finding.

#1190. I recommend landing #1195 first. It is small, self-contained and fixes a red row that #1175 introduced. #1190 is a large draft that also spans fat32, fileserver, nvme and shell. #1190 then rebases onto it like this:

• Keep the opener thread.
• Reduce adopt to taking the volume. With Data-loss follow-up: recovery finishes a half-done FAT rename; logkeeper asks a refused volume again #1190's Volume::through() at 0, caught_up already gives a late file the boot from the replay a part at a time.
• Delete this branch's catch-up loop and its Hub::owed(&mut u64) / serve::Owed in favour of Data-loss follow-up: recovery finishes a half-done FAT rename; logkeeper asks a refused volume again #1190's owed(at, max) / store::Owed.
• Give Data-loss follow-up: recovery finishes a half-done FAT rename; logkeeper asks a refused volume again #1190's flushed, which runs finish against a deadline, a case for a volume still opening.

The next step after both is the writer-thread move above. #1190's own description should stop implying it settles the volume path while the loop still blocks on /log.

Net production change: about +75 lines of logkeeper code, +16 of test, and +26/-45 in issues. Proportionate.

Findings

BLOCKER 1. system/logkeeper/src/main.rs:687-690. flushed can falsely say /log never opened, and the boot's file can lose all its content.

adopt runs only at the top of the loop. flushed runs later in the same iteration, after the flush's rounds (round repeated until the rings drain), which can take a while. If the opener answers in that window, opening is still Some, so flushed logs "/log had not opened by the stop". By then the volume thread has already put LOG_OPENED <path> on the console. Volume::open created the file (store.rs create), but it never receives a byte, because adopt skips while stopping is set. So a short boot that stops about when LOG mounts leaves an empty /log file and two contradictory lines. That is exactly the timing of the acpicase-style boots this PR is about.

The fix is one line: call self.adopt() at the start of flushed, while stopping is still None. Its catch-up writes skip the per-round sync, and flushed's own sync then makes them durable. The "had not opened" message is then true whenever it appears.

BLOCKER 2. system/logkeeper/src/main.rs:47-48 and system/logkeeper/src/serve.rs:5-8. Comments that are now false.

"each is a thread with an offset into what the file already has" and "appends each round's lines to one Replay after the file has them" no longer hold while the file is closed. The paragraph added at main.rs:50-54 says the opposite in the next sentence. Change both to say that readers and carriers hold an offset into the replay, and that the replay follows the file once it is open. Or delete the clauses.

SUGGESTION. main.rs:50-54. "which can wait for the root bridges' memory to be declared" is the supervisor's and storage's current sequencing, and it will go stale. The durable rule is the bold sentence plus "its file server may start late". The story belongs in the commit, which already has it.

SUGGESTION. main.rs:600-602. In the adopt doc, "which holds it whole for this, and each round after" is hard to parse, and "whole" is not guaranteed: the code handles Owed::Gap. "The volume, once its opener answers outside a stop: the file first takes the boot so far from the replay" says it.

SUGGESTION. issues/the-console-waits-on-logkeepers-file-writes.md. Name the exit's shape: the file as a replay consumer on its own thread with a bounded stop catch-up. Also note that #1190's per-file offset is its vehicle, so whoever reconciles #1190 picks it up. The finding is otherwise accurate. I confirmed from the code that LOG_WRITE_BUDGET is judged only after write/sync return (main.rs:594).

Evidence. The runs, revisions and control are as claimed, and the control is the change reverted onto its own base. Host CI at 883809d is claimed green with a log. No metal run was made. I accept that, because the changed logic is hardware-independent and the_log_lands_on_the_boot_stick exercises the late-adopt catch-up path end to end on QEMU. The fix for blocker 1 changes the stop path. After it, compile and rerun acpi_press_is_one_sci and the_log_lands_on_the_boot_stick once at the new head, because both end in a stop. The new host test mostly exercises Replay::next through a thin wrapper, but it does pin the offset advance and the non-waiting Nothing. That is acceptable.

The issue close is correct. The deleted record's exit (cause named and fixed, row green) is met, its slug is cited nowhere outside issues/, and its durable rule moved to the module header.

SEND BACK

[Japabu]

Review r2 of #1195: 883809d3d..1131a5acf

I read the round's diff and then, at 1131a5a, adopt, flushed, resume, to_volume, answered, the stop branch of round, Hub::{owed, own_line, append_stopping, resume, end} and the supervisor's flush. gh run view 42068104021 shows head 1131a5a with rows succeeding, and its title names acpi_press_is_one_sci and the_log_lands_on_the_boot_stick. This PR's checks run reports every job as skipped, so the host evidence (logkeeper 23/23, clippy clean) is the implementer's claim. The code change is three statements, so I accept that.

Architectural assessment

Unchanged from r1. The open moving off the loop is right. The residual dependency of the console on file writes is recorded, and the record now names its exit and its vehicle (#1190).

Previous blockers

Blocker 1 is resolved. flushed now calls self.adopt() first (system/logkeeper/src/main.rs:688). stopping is still None at that point, so the adopt runs. "had not opened by the stop" is printed only when try_recv found nothing, which makes it true from the loop's side.

Blocker 2 is resolved. main.rs:48 and serve.rs:5-8 now say that readers and carriers hold an offset into the replay, and that the replay follows the file once it is open.

Does adopting inside the stop introduce problems?

• Ordering and duplication: none. adopt writes the replay from 0 to its end. After the flush's rounds that end is the whole log up to the flush. own_line only renders and never appends, so hub.end() handed to carriers.stop is unchanged by the catch-up. stopping is set after the adopt, so lines from then on go only to Stopping.text and append_stopping. If the stop is refused, resume writes the held text to the now-open volume once and hub.resume appends it, past the offset the adopt reached. If the opener answers only after flushed, adopt is skipped for the stop's duration. A refused stop then reaches the next iteration's adopt, which takes the whole replay once, resumed text included. Neither path writes a byte twice.
• Time bound: no new class. The catch-up is at most REPLAY_BYTES written in CHUNK (64 KiB) pieces with one sync. That is the same work the loop-top adopt already does when the opener answers one iteration earlier, just before the flush. If it outruns FLUSH_BOUND, the supervisor's existing bound handles it: it warns, stops anyway, and the console has carried every line regardless. The exit of issues/the-console-waits-on-logkeepers-file-writes.md (a bounded stop catch-up) covers this residual. In practice the replay is small here, because an opener answering during a stop means a short boot.
• Failure: correct. If adopt's sync is refused, answered drops the volume. flushed's own sync then returns Ok with no volume, and answered returns early. The message is said once.

Suggestion edits

• The adopt doc (main.rs:599-600) and the module header paragraph (main.rs:50-53) are concise and true. The sequencing story is gone from the header.
• The finding's exit (issues/the-console-waits-on-logkeepers-file-writes.md:23-28) is now concrete and testable. The file becomes a replay consumer on its own thread, and the stop asks it to reach the end and sync within a bound. It hands off to whoever reconciles Data-loss follow-up: recovery finishes a half-done FAT rename; logkeeper asks a refused volume again #1190. The record matches the code: LOG_WRITE_BUDGET is still judged only after write or sync returns. The frontmatter and owner line are unchanged and valid.

Findings

SUGGESTION. system/logkeeper/src/main.rs:686-688. The new comment says the sync below makes the catch-up durable. adopt already ends with its own sync and answered, so after an adopt the sync in flushed is a second, empty sync. The comment is not false, but it describes the wrong sync. Two fixes would work. One is to delete the comment, since self.adopt() followed by the opening check reads clearly enough. The other is to say only "An opener that answered during the flush's rounds is adopted before the stop." I don't require the redundant sync to be removed: it costs one call on a path that has just written the whole file.

No blockers remain.

LAND