Repository navigation
logkeeper asks a refused volume again and gives the file the boot it missed - #1190
Conversation
4594e85 to
cd47061
Compare
Review r1 of #1190 (head
|
…d catches up a part at a time Review r1 of #1190 found five blockers in the volume's bookkeeping. 1. The note for what the replay let go was counted into the file's durable length and the next part's start, but never appended to the replay, so every later reopen asked the replay from bytes past where the file stood. Now `Volume` keeps the file's bytes (`size`, `durable`) and the replay's offsets (`from`, `through`, `durable_through`) separately. A note moves the first and not the second. A gap resumes at the replay's own line start. 2. `reopen` called `set_len(durable)` without asking the file's length, so a missing or short part was padded with zeros. Now a part shorter than its last sync left it is rebuilt whole from its own start in the replay, and says so. The one hazard left, a swapped stick carrying a file under the same name, is named in the record. 3. `a_refused_file_is_given_back_the_boot_the_replay_holds` drives a real `Volume` in a scratch directory through: - an unsynced write with bytes torn past it; - a refusal long enough for the replay to let go of what the file was owed; - a continuation whose create is refused; - a part cut to nothing behind its back. After each step, the parts on disk are the boot with one note where the gap was, and no part exceeds its bound by more than a line. Negative controls, each applied and restored: - counting the note into the replay's offset (blocker 1) fails it "across the gap"; - padding a short part (blocker 2) fails it "after the part was cut"; - writing the rewrite past a part's room fails it on a part's size. 4. The rewrite went into the current part in one write of up to 16 MiB. Now `Volume::catch_up` takes what is owed from the replay (`Hub::owed`) through the same part-sized writes and continuations as any round, each part synced as it fills, at most `MAX_LOG_BYTES` a round. The round's own text waits in the replay until the file has caught up. 5. `policy::RETRY_*`'s comment claimed a quick recovery loses less. The wait trades how often a dead volume is asked against how soon a live one is written; nothing is lost while the replay holds it. Also: the storage track states FUA by its specifications instead of by another implementation, and the retry paragraph is said once, at `store::Volume`. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
r2 at
|
8523f43 to
f3a8caa
Compare
…d catches up a part at a time Review r1 of #1190 found five blockers in the volume's bookkeeping. 1. The note for what the replay let go was counted into the file's durable length and the next part's start, but never appended to the replay, so every later reopen asked the replay from bytes past where the file stood. Now `Volume` keeps the file's bytes (`size`, `durable`) and the replay's offsets (`from`, `through`, `durable_through`) separately. A note moves the first and not the second. A gap resumes at the replay's own line start. 2. `reopen` called `set_len(durable)` without asking the file's length, so a missing or short part was padded with zeros. Now a part shorter than its last sync left it is rebuilt whole from its own start in the replay, and says so. The one hazard left, a swapped stick carrying a file under the same name, is named in the record. 3. `a_refused_file_is_given_back_the_boot_the_replay_holds` drives a real `Volume` in a scratch directory through: - an unsynced write with bytes torn past it; - a refusal long enough for the replay to let go of what the file was owed; - a continuation whose create is refused; - a part cut to nothing behind its back. After each step, the parts on disk are the boot with one note where the gap was, and no part exceeds its bound by more than a line. Negative controls, each applied and restored: - counting the note into the replay's offset (blocker 1) fails it "across the gap"; - padding a short part (blocker 2) fails it "after the part was cut"; - writing the rewrite past a part's room fails it on a part's size. 4. The rewrite went into the current part in one write of up to 16 MiB. Now `Volume::catch_up` takes what is owed from the replay (`Hub::owed`) through the same part-sized writes and continuations as any round, each part synced as it fills, at most `MAX_LOG_BYTES` a round. The round's own text waits in the replay until the file has caught up. 5. `policy::RETRY_*`'s comment claimed a quick recovery loses less. The wait trades how often a dead volume is asked against how soon a live one is written; nothing is lost while the replay holds it. Also: the storage track states FUA by its specifications instead of by another implementation, and the retry paragraph is said once, at `store::Volume`. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Review r2 of #1190 (head
|
f3a8caa to
a99667b
Compare
…d catches up a part at a time Review r1 of #1190 found five blockers in the volume's bookkeeping. 1. The note for what the replay let go was counted into the file's durable length and the next part's start, but never appended to the replay, so every later reopen asked the replay from bytes past where the file stood. Now `Volume` keeps the file's bytes (`size`, `durable`) and the replay's offsets (`from`, `through`, `durable_through`) separately. A note moves the first and not the second. A gap resumes at the replay's own line start. 2. `reopen` called `set_len(durable)` without asking the file's length, so a missing or short part was padded with zeros. Now a part shorter than its last sync left it is rebuilt whole from its own start in the replay, and says so. The one hazard left, a swapped stick carrying a file under the same name, is named in the record. 3. `a_refused_file_is_given_back_the_boot_the_replay_holds` drives a real `Volume` in a scratch directory through: - an unsynced write with bytes torn past it; - a refusal long enough for the replay to let go of what the file was owed; - a continuation whose create is refused; - a part cut to nothing behind its back. After each step, the parts on disk are the boot with one note where the gap was, and no part exceeds its bound by more than a line. Negative controls, each applied and restored: - counting the note into the replay's offset (blocker 1) fails it "across the gap"; - padding a short part (blocker 2) fails it "after the part was cut"; - writing the rewrite past a part's room fails it on a part's size. 4. The rewrite went into the current part in one write of up to 16 MiB. Now `Volume::catch_up` takes what is owed from the replay (`Hub::owed`) through the same part-sized writes and continuations as any round, each part synced as it fills, at most `MAX_LOG_BYTES` a round. The round's own text waits in the replay until the file has caught up. 5. `policy::RETRY_*`'s comment claimed a quick recovery loses less. The wait trades how often a dead volume is asked against how soon a live one is written; nothing is lost while the replay holds it. Also: the storage track states FUA by its specifications instead of by another implementation, and the retry paragraph is said once, at `store::Volume`. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
…he row's fill holds and it checks the boot Review r2 of #1190: three blockers, and one host case. A. The stop's flush caught up at most one part, left it unsynced and answered FLUSHED in silence. `Volume::finish` now does the stop: - it catches up a part at a time while there is time; - it makes durable what it wrote; - where the replay holds bytes the file does not, it says so in the file, and logkeeper says so on the console; - a continuation refused during that catch-up ends it the same way, the last part synced by its rotation. The time is `STOP_CATCH_UP`, half the supervisor's bound on the whole flush (`toyos_quiesce::FLUSH_MS`, 5 s): the rest drains the rings, makes the final sync and answers. A time bound rather than a byte count, because how much a stick takes in it is the device's. FLUSHED now means "done", which `toyos_logstream::FLUSH`'s doc says. Host test: `a_stop_with_more_owed_than_its_time_syncs_and_says_the_shortfall`. A volume is refused while 38 lines arrive, then stopped with no time and with time: the first is synced and ends with the shortfall, the second is whole. Controls, each applied and restored: no shortfall line, no sync, and no catching up while there is time, each fail it. B. The new row was red: the loader deletes and recreates `loader.log` at every boot, so the 256 KiB kept for it was free again by the time logkeeper wrote. `fill_log_volume` now fills every cluster and keeps nothing. The loader's own files are refused that boot, which it says and boots on, and logkeeper's first write is refused. C. The row now checks the boot it claims, against the console, which is the independent account: - the stick's first line is the boot's first kernel record; - each CPU's kernel records on the stick are the console's, in order; - no gap note or shortfall is in the file. Also the record's own case: `a_first_part_refused_at_open_is_made_and_given_the_boot` has the first part's create refused (a directory nothing may be created in) and the part made at the first catch-up, given the boot from its start. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
r3 at
|
fe5641f to
1728915
Compare
|
The row is green on the guest runner at Two harness-only fixes got it there:
Evidence: https://github.com/ToyOSOrg/evidence/tree/dfba7eb32340a5793c7da5054a7dc6514e2b571b/r4. Host CI at |
Review r3 of #1190 at
|
…ounds `flushed` adopts first: an opener that answered while the flush's rounds ran left the file empty and had the stop say /log never opened, though LOG_OPENED was already on the console. The comments that said the replay and its readers trail the file now say so only once the file is open; the header drops the supervisor's sequencing, and the residual's record names its exit's shape and #1190 as its vehicle. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
… dead stop parameter Review r3 of #1190: 1. `Volume::lost` left `through` at what had been written, not at what its last sync had made durable, so a stop whose reopen was refused after an unsynced write told the console it was short by less than it was. `lost` now rolls `size` and `through` back to the last sync, which a reopen did anyway, and the stop does the same on any refusal before it counts. Host case: `a_stop_refused_after_an_unsynced_write_counts_from_the_last_sync`. It writes unsynced, refuses the volume, and puts a directory where the part was, so the reopen is refused whoever runs it. Control: without the rollback it fails "the shortfall counts from the last sync". 2. `caught_up`'s `at_stop` was dead once the stop went through `Volume::finish`, and its doc claimed the stop. Both are gone. The first-part test now refuses the create with a directory at the part's path, which refuses root too. `ours` lists files alone, since a directory is no log part, and takes no part number. Control: listing directories again fails that test (the part opens at the next number). Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
r4 at
|
|
Guest run 42071298691 at |
Review r4 of #1190 at
|
…finish loses the part on its own refusal Review r4 of #1190: - `ours` listing files alone (7011568) let a directory under a part's name hand that number to the boot, whose create and every reopen then failed for good: any program that writes `/log` could keep the boot's log off it. Reverted: an entry under a part's name takes the number, whatever it is, and the boot writes the next part. - The first-part test stays root-safe without it: the volume is opened on a log directory not made yet, so the create is refused (NotFound) whoever runs it, and the directory is made before the second round. - S1, taken: `Volume::finish` marks the part lost on its own refusal, so its doc's "the file as its last sync left it" is its own contract and not the caller's; the stop no longer calls `lost` itself. A refused write or sync to an open part has no root-safe host staging, so that path is held by inspection. `cargo test` in `system/logkeeper`: 27 passed. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
r5 at
|
Review r5 of #1190 at
|
|
The evidence branch
|
…om the replay #1190's logkeeper rounds r1 to r5 (1815b94, 7d45162, a99667b, 7011568, bc12850), rebased onto #1195's opener thread and #1196's stop mark as #1195's reviewer planned. - A refused create, append, sync or continuation is asked again (`policy::Retry`, 1 s doubling to 64 s). `Volume` keeps the file's bytes (`size`, `durable`) apart from the replay's offsets (`from`, `through`, `durable_through`). `catch_up` opens the part again, cut to its last sync, or rebuilds it whole where it is shorter, and gives it what it is owed from the replay (`Hub::owed(at, max)` → `store::Owed`), a part's worth a round, through the ordinary part-sized writes and continuations. A gap the replay let go of is said in the file only. - The stop (`Volume::finish`) catches up within `STOP_CATCH_UP`, half the supervisor's flush bound, syncs what it wrote, and says any shortfall in the file and on the console; a refusal there leaves the part lost and the count from the last sync. - #1195: its opener thread stays; `adopt` only takes the volume, whose file stands at the replay's start, so the next round's catch-up gives it the boot so far; #1195's own catch-up loop, `Hub::owed(&mut u64)` and `serve::Owed` go. A volume still opening at the stop is waited for within the same `STOP_CATCH_UP`, then given the boot by `finish`, or said not to have opened. - #1196: the stop mark is written only over a part that is open, since a refused volume's file is not the boot's whole log. Host tests in `store.rs` (27 in all): the bookkeeping through an unsynced write, a replay gap, a refused continuation and a part cut behind its back; a refused first create; a stop with and without time; a stop whose reopen is refused after an unsynced write. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
bc12850 to
3d7e965
Compare
#1190's row (5809592, a99667b, 0939e4e, 6405def), rebased. `BootOptions::full_log` fills the stick's log volume (`toyos_build::image::fill_log_volume`). `a_refused_log_is_written_whole_once_the_volume_takes_it` waits for the refusal, runs `log_unfill`, waits for the volume to answer, stops, and reads the stick back. It checks that the stick begins at the boot's first kernel record, that each CPU's kernel records are the console's in order, and that there is no gap note or shortfall. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
…ng rulings #1190's records (1e70db4, 1728915), rebased: - logkeeper-ends-the-boots-log-on-one-refused-create-and-nothing-durable-says-so closes. Its amended exit is the row, green on the guest runner at the pre-rebase head (run 42040641298). - a-file-held-across-a-file-servers-restart-answers-gone is narrowed to DATA reopen by inode number, waiting on a volume identity, and names the swapped-stick hazard of reopening by path. - std-file-lock-answers-ok-and-locks-nothing stays with M4. - The storage track records the DATA commit's two flushes and FUA missing end to end. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
…lings #1190's records (1e70db4, 1728915), rebased: - logkeeper-ends-the-boots-log-on-one-refused-create-and-nothing-durable-says-so stays open, rewritten to what is built. Its exit is the row, which was green before #1196 (run 42040641298). The row frees the full volume with a test job, and #1196 made `/log` read-only to every row but the log keeper's, so the row now stalls there and needs another way to free it. - a-file-held-across-a-file-servers-restart-answers-gone is narrowed to DATA reopen by inode number, waiting on a volume identity, and names the swapped-stick hazard of reopening by path. - std-file-lock-answers-ok-and-locks-nothing stays with M4. - The storage track records the DATA commit's two flushes and FUA missing end to end. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
3d7e965 to
76fd342
Compare
…ng rulings #1190's records (1e70db4, 1728915), rebased: - logkeeper-ends-the-boots-log-on-one-refused-create-and-nothing-durable-says-so closes on the host tests, by the coordinator's ruling (option 3). `store.rs`'s tests cover each case: - a refused first create; - an unsynced write with bytes torn past it; - a gap the replay let go of; - a refused continuation; - a part cut short behind the volume's back; - a stop with and without time; - a stop whose reopen is refused after an unsynced write. End to end, `a_refused_log_is_written_whole_once_the_volume_takes_it` was green on the guest runner before #1196 (run 42040641298 at `6405def8d`): the stick read back held the boot from its first kernel record, each CPU's records as the console carried them. That row is not carried here. It freed its full log volume with a test job, and #1196 leaves `/log` writable to the log keeper alone. Filling the volume with logkeeper's own old parts instead does not heal it either: retention sweeps only at open, before the first write, and at a rotation, which a refused part never reaches. - a-file-held-across-a-file-servers-restart-answers-gone is narrowed to DATA reopen by inode number, waiting on a volume identity, and names the swapped-stick hazard of reopening by path. - std-file-lock-answers-ok-and-locks-nothing stays with M4. - The storage track records the DATA commit's two flushes and FUA missing end to end. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
76fd342 to
6760114
Compare
Review r7 of #1190 at
|
…om the replay #1190's logkeeper rounds r1 to r5 (1815b94, 7d45162, a99667b, 7011568, bc12850), rebased onto #1195's opener thread and #1196's stop mark as #1195's reviewer planned. - A refused create, append, sync or continuation is asked again (`policy::Retry`, 1 s doubling to 64 s). `Volume` keeps the file's bytes (`size`, `durable`) apart from the replay's offsets (`from`, `through`, `durable_through`). `catch_up` opens the part again, cut to its last sync, or rebuilds it whole where it is shorter, and gives it what it is owed from the replay (`Hub::owed(at, max)` → `store::Owed`), a part's worth a round, through the ordinary part-sized writes and continuations. A gap the replay let go of is said in the file only. - The stop (`Volume::finish`) catches up within `STOP_CATCH_UP`, half the supervisor's flush bound, syncs what it wrote, and says any shortfall in the file and on the console; a refusal there leaves the part lost and the count from the last sync. - #1195: its opener thread stays; `adopt` only takes the volume, whose file stands at the replay's start, so the next round's catch-up gives it the boot so far; #1195's own catch-up loop, `Hub::owed(&mut u64)` and `serve::Owed` go. A volume still opening at the stop is waited for within the same `STOP_CATCH_UP`, then given the boot by `finish`, or said not to have opened. - #1196: the stop mark is written only over a part that is open, since a refused volume's file is not the boot's whole log. Host tests in `store.rs` (27 in all): the bookkeeping through an unsynced write, a replay gap, a refused continuation and a part cut behind its back; a refused first create; a stop with and without time; a stop whose reopen is refused after an unsynced write. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
…ng rulings #1190's records (1e70db4, 1728915), rebased: - logkeeper-ends-the-boots-log-on-one-refused-create-and-nothing-durable-says-so closes on the host tests, by the coordinator's ruling (option 3). `store.rs`'s tests cover each case: - a refused first create; - an unsynced write with bytes torn past it; - a gap the replay let go of; - a refused continuation; - a part cut short behind the volume's back; - a stop with and without time; - a stop whose reopen is refused after an unsynced write. End to end, `a_refused_log_is_written_whole_once_the_volume_takes_it` was green on the guest runner before #1196 (last at run 42071298691, `701156896`): the stick read back held the boot from its first kernel record, each CPU's records as the console carried them. That row is not carried here. It freed its full log volume with a test job, and #1196 leaves `/log` writable to the log keeper alone. Filling the volume with logkeeper's own old parts instead does not heal it either: retention sweeps only at open, before the first write, and at a rotation, which a refused part never reaches. - a-file-held-across-a-file-servers-restart-answers-gone is narrowed to DATA reopen by inode number, waiting on a volume identity, and names the swapped-stick hazard of reopening by path. - std-file-lock-answers-ok-and-locks-nothing stays with M4. - The storage track records the DATA commit's two flushes and FUA missing end to end. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
…ments and records say what the code does Code: - `adopt` calls `caught_up`, so a volume whose opener answers is given a part's worth of the boot then, not at the next round that reads a line. - The stop's flush no longer goes through `adopt`: `recv_timeout` takes an answer already queued, and `finish` alone writes the file there, inside the stop's deadline. An opener that ended without answering is the same panic in both places. - A withheld stop mark says so in one line. - The `None` arm of the startup report no longer says there is no /log: `Volume::open` has said the reason, which is a name or a part number. Comments: the replay leads the file while the part is refused or catching up; the stop's flush waits for the opener within `STOP_CATCH_UP`; `Degraded` is also a refused part; `mark` says why it asks `is_open`. Records: - the-console-waits-on-logkeepers-file-writes lists the loop's blocking calls as they are now and says the offset and the stop's catch-up are in the tree, and the move to a thread is what is left. - a-machine-without-an-iommu-refuses-every-claim quotes the line logkeeper now says where /log is absent. - New finding: a log volume full with fewer than sixteen of logkeeper's files is never written again, since retention sweeps only at open and at a rotation. Co-Authored-By: Claude Fable 5.2 <noreply@anthropic.com>
6760114 to
46a355a
Compare
Response to review r7 (head
|
Review r8 of #1190 at
|
Review r8 of #1190: the sweep retires only as many files as the count is over by, so it frees what those held and no more, and the boot is refused once it has written past that. Co-Authored-By: Claude Fable 5.2 <noreply@anthropic.com>
|
Orchestrator verification of the r8 fix (46a355a..7e9ed63), which is record-only: one issue file, +7/-2. The false sentence about sixteen or more files is replaced with what the code does: the sweep frees only what the retired files held, so the boot is refused once it has written past that. The r8 review (#1190 (comment)) found the code correct, and the checks at 46a355a stand. Landing. |
Problem
One refused create, append or sync on
/logended the boot's log file for the rest of the boot, and nothing durable said so (logkeeper-ends-the-boots-log-on-one-refused-create-and-nothing-durable-says-so).Resulting behavior
STOP_CATCH_UP(half the supervisor's flush bound), syncs what it wrote, and says in the file and on the console how many bytes short the file ends.adoptgives it a part's worth when its opener answers, and each round after gives it another.Decisions
Volume::catch_up/finishover a per-file offset. logkeeper: the console no longer waits for /log to open #1195's catch-up loop,Hub::owed(&mut u64)andserve::Owedare gone; its opener thread stays./logafter Memory overwrite on every boot; the black box goes, and a clean stop proves an image #1196. The record closes onstore.rs's host cases; the row's last green was run 42071298691 at701156896, before Memory overwrite on every boot; the black box goes, and a clean stop proves an image #1196.docs/does not describe logkeeper's refusal handling.Records
logkeeper-ends-the-boots-log-….a-log-volume-full-of-logkeepers-own-parts-is-never-written-again. Retention sweeps only at open and at a rotation, and counts files, not bytes. A full volume holding fewer than sixteen of logkeeper's files is never healed; with sixteen or more, the sweep frees only what the retired files held, and the boot is refused once it has written past that.the-console-waits-on-logkeepers-file-writesnow lists the loop's blocking calls as they are and says what is left: moving the volume to its own thread.a-machine-without-an-iommu-refuses-every-claimquotes the line logkeeper now says where/logis absent.a-file-held-across-…is narrowed to DATA reopen;std-file-lock-…stays with M4; the storage track records FUA missing end to end.Checks at
46a355afb(rebased onto mainf9b5d7f12)cargo testinsystem/logkeeper: exit 0, 27 passed.cargo run -- --ci host: exit 1, 1 of 110 steps red. The red isthe build system: cargo test --lib, inllvm::tests::the_caller_s_environment_reaches_neither_the_build_nor_the_key, which breaks macOS's git wrapper; it is recorded on main asthe-llvm-environment-test-breaks-git-on-macos, and this branch changes nothing underbuild/. The other 109 steps are green,system/logkeeper's among them.the_log_lands_on_the_boot_stick: 6 files, 2,539,693 bytes. It needs a guest because it reads back a stick a real boot wrote through the late-adopted catch-up and rotation.a_clean_stop_proves_its_image: the loader's proof over the mark of an open part.acpi_mediated_access.store.rsfrom r2 to r5 still apply:store.rsis unchanged since.r1tor7-rebaseon the same branch)Risks
acpi_mediated_accesspassed, but its guest stops on the probe's own sleep type and its capture shows no logkeeper line from that path. The path stands on inspection, as in review r7.adopt's catch-up has no test of its own.Logis not host-testable, and no row asserts when a just-adopted file first holds bytes.the_log_lands_on_the_boot_stickshows the late-adopted file whole./logopens stops up to 2.5 s later.Earlier rounds' responses and evidence are in the comments above.
🤖 Generated with Claude Code