node/run: a job's end reads its state from a store that has let it go: a fix's outputs end store_io, a cargo job loses its workspace #60

New issue

Open

opened 2026-11-13 15:42:55 +00:00 by xemmerling · 0 comments

xemmerling commented

2026-11-13 15:42:55 +00:00

Owner

Seen. 15:33:00Z 11-13 on production (123aaf58). Not from that promote: job_history has one store_io a day since 11-11, each a person's job that leaves outputs ("fix sdk-types" 11-11, cargo build ... wasm-split on 11-12 and at 01:29Z 11-13, "fix fmt" today).

Job j558-54892, check "fix fmt", run r5a5abfe724 on state 6ee880154aae, launched 15:31:40Z, ran 79 s. Worker: ERROR t::node::run::end: storing the job's outputs: state 6ee880154aae unknown: blob 6ee880154aae7050... missing. The server ends it error, cause store_io. The check ran again (j558-54921) and was told pass at 15:34:00Z: no error reached the person, their answer came 85 s late.
Job j558-54891, a cargo driver of the same session (run rd56113f3d5, state c5486f4bc669), launched 15:31:36Z. At its end, 15:32:51Z, twice: WARN t::node::run::left: the job's workspace, whose packages own what cargo looked up: state c5486f4bc669 unknown: blob c5486f4bc669bb53... missing. In 26 minutes of worker log: 4 such lines, and 2 of parse crates/collab/actions/Cargo.toml: blob ... missing from the same place.
The node's freer was freeing 20 to 210 GB a minute then (15:26 to 15:33Z). A pass that freed 403 units, 77 GB, is logged at 15:32:50.47Z; the first warning at 15:32:51.03Z.

Cause, read from the code (main 123aaf58). Before a job starts, OnStore::choose (src/node/prepare.rs:167) fetches and holds the job's state and its workspace's manifests, "held while the choice reads them" (cas.ensure(&[state]), cas.ensure(&workspace)): the holds drop with the choice. While the job runs its source is held as a made layer (layers.hold(&LayerId::source(&state))), which does not hold the state's manifest blob in the node's blobs. At the end, src/node/run/left.rs reads the state again with no fetch and no hold:

line 171, cas.manifest(&spec.state)?, the base of a fix's tree: an error here ends the job store_io;
line 247, the same read for a cargo driver's workspace, and line 248 its Cargo files through cargo::files::reader: an error here is the warning, and what cargo looked up stays beside its units.

Cas::manifest answers only while the blob is there (self.has(id)). Between a job's start and its end nothing holds its state, so the freer may free the pack it lies in.

Fix proposed. The end's reads follow the store's own rule (Cas::ensure: fetch what is missing, hold it while it is read), as line 175 already does for the .gitignore files: the state's manifest, and for a cargo driver the files workspace::files_read names, are ensured and held while the end reads them. Not a hold for the job's whole life: some 150 jobs share a head's state, and a pinned manifest makes its pack one the freer has to move. A test frees the job's state from the node's blobs between start and end and expects the fix's tree stored and the workspace read.

Fixed on main: 9faf6c61 (16:10Z 11-13, on top of 65bf0d9b), "node/run: a job's end fetches and holds what it reads of its state". fix_tree and workspace_of in src/node/run/left.rs are free functions now; each ensures and holds the state's manifest, and the .gitignore files or the files files_read names, while it reads them. A blob the server lacks too is still the fix's store error and still only the driver's warning. Three tests free the state from the node's blobs between start and end; they fail on main before it. No other unheld read of a job's state was found in src/node/run. The whole check set passed on testing, forced (run rc1445209bc, 8 of 8). On production since 16:32Z 11-13 (my promote of 9faf6c61, which also carries 65bf0d9b).

Say here if you would rather have the job hold its state for its life.

Before the promote, on testing: a real t fix fmt on a clone with one formatting error came back fixed with no store error (16:20Z). The forward upgrade to node protocol 71 kept 8 of 8 running test/t jobs (16:01Z). A rollback from 9faf6c61 to 123aaf58 under a running check set kept 15 of 15 running jobs, with no unknown-field or parse error on the old server or worker, and the run ended 8 of 8 passed (16:25Z). On production: the worker re-attached 70 jobs at 16:32:56Z, none lost. To read from here: store_io in job_history, and the two warning lines in the worker's log, which should stop.

One hour on production (9faf6c61, 16:32Z to 17:33Z 11-13): kept. The worker logged none of the two lines (0 "the job's workspace ... state ... unknown", 0 "storing the job's outputs") against 6 in 26 minutes before; no job of 8,358 ended store_io; the freer went on freeing throughout (the node's free disk moved between 1,144 and 1,329 GB). What remains is the once-a-day store_io not coming back over the next days.

**Seen.** 15:33:00Z 11-13 on production (123aaf58). Not from that promote: `job_history` has one `store_io` a day since 11-11, each a person's job that leaves outputs ("fix sdk-types" 11-11, `cargo build ... wasm-split` on 11-12 and at 01:29Z 11-13, "fix fmt" today). - Job j558-54892, check "fix fmt", run r5a5abfe724 on state 6ee880154aae, launched 15:31:40Z, ran 79 s. Worker: `ERROR t::node::run::end: storing the job's outputs: state 6ee880154aae unknown: blob 6ee880154aae7050... missing`. The server ends it `error`, cause `store_io`. The check ran again (j558-54921) and was told pass at 15:34:00Z: no error reached the person, their answer came 85 s late. - Job j558-54891, a cargo driver of the same session (run rd56113f3d5, state c5486f4bc669), launched 15:31:36Z. At its end, 15:32:51Z, twice: `WARN t::node::run::left: the job's workspace, whose packages own what cargo looked up: state c5486f4bc669 unknown: blob c5486f4bc669bb53... missing`. In 26 minutes of worker log: 4 such lines, and 2 of `parse crates/collab/actions/Cargo.toml: blob ... missing` from the same place. - The node's freer was freeing 20 to 210 GB a minute then (15:26 to 15:33Z). A pass that freed 403 units, 77 GB, is logged at 15:32:50.47Z; the first warning at 15:32:51.03Z. **Cause, read from the code (main 123aaf58).** Before a job starts, `OnStore::choose` (src/node/prepare.rs:167) fetches and holds the job's state and its workspace's manifests, "held while the choice reads them" (`cas.ensure(&[state])`, `cas.ensure(&workspace)`): the holds drop with the choice. While the job runs its source is held as a made layer (`layers.hold(&LayerId::source(&state))`), which does not hold the state's manifest blob in the node's blobs. At the end, src/node/run/left.rs reads the state again with no fetch and no hold: - line 171, `cas.manifest(&spec.state)?`, the base of a fix's tree: an error here ends the job `store_io`; - line 247, the same read for a cargo driver's workspace, and line 248 its Cargo files through `cargo::files::reader`: an error here is the warning, and what cargo looked up stays beside its units. `Cas::manifest` answers only while the blob is there (`self.has(id)`). Between a job's start and its end nothing holds its state, so the freer may free the pack it lies in. **Fix proposed.** The end's reads follow the store's own rule (`Cas::ensure`: fetch what is missing, hold it while it is read), as line 175 already does for the `.gitignore` files: the state's manifest, and for a cargo driver the files `workspace::files_read` names, are ensured and held while the end reads them. Not a hold for the job's whole life: some 150 jobs share a head's state, and a pinned manifest makes its pack one the freer has to move. A test frees the job's state from the node's blobs between start and end and expects the fix's tree stored and the workspace read. **Fixed on main: 9faf6c61** (16:10Z 11-13, on top of 65bf0d9b), "node/run: a job's end fetches and holds what it reads of its state". `fix_tree` and `workspace_of` in src/node/run/left.rs are free functions now; each ensures and holds the state's manifest, and the `.gitignore` files or the files `files_read` names, while it reads them. A blob the server lacks too is still the fix's store error and still only the driver's warning. Three tests free the state from the node's blobs between start and end; they fail on main before it. No other unheld read of a job's state was found in src/node/run. The whole check set passed on testing, forced (run rc1445209bc, 8 of 8). On production since 16:32Z 11-13 (my promote of 9faf6c61, which also carries 65bf0d9b). Say here if you would rather have the job hold its state for its life. **Before the promote, on testing:** a real `t fix fmt` on a clone with one formatting error came back fixed with no store error (16:20Z). The forward upgrade to node protocol 71 kept 8 of 8 running test/t jobs (16:01Z). A rollback from 9faf6c61 to 123aaf58 under a running check set kept 15 of 15 running jobs, with no unknown-field or parse error on the old server or worker, and the run ended 8 of 8 passed (16:25Z). **On production:** the worker re-attached 70 jobs at 16:32:56Z, none lost. To read from here: `store_io` in `job_history`, and the two warning lines in the worker's log, which should stop. **One hour on production (9faf6c61, 16:32Z to 17:33Z 11-13): kept.** The worker logged none of the two lines (0 "the job's workspace ... state ... unknown", 0 "storing the job's outputs") against 6 in 26 minutes before; no job of 8,358 ended `store_io`; the freer went on freeing throughout (the node's free disk moved between 1,144 and 1,329 GB). What remains is the once-a-day `store_io` not coming back over the next days.

xemmerling referenced this issue from a commit

2026-11-13 16:10:00 +00:00

node/run: a job's end fetches and holds what it reads of its state

xemmerling referenced this issue

2026-11-13 16:17:32 +00:00

declared_builds takes 0.86 GB an hour since f06bfdc3: each row repeats its closure's units' reads, and the database volume has about a day and a half left #59