Clean work directories on disconnect by chrisstaite-menlo · Pull Request #247 · TraceMachina/nativelink

chrisstaite-menlo · 2023-09-07T09:53:08Z

When a worker disconnects it may have jobs that aren't cleaned up.

This change is

When a worker disconnects it may have jobs that aren't cleaned up.

allada

Reviewable status: 0 of 7 files reviewed, 1 unresolved discussion (waiting on @chrisstaite-menlo)

a discussion (no related file):
Before landing this I'd like to take some time to investigate what is causing it. I believe I have an idea that I want to flesh out.

allada

Reviewable status: 0 of 7 files reviewed, 1 unresolved discussion (waiting on @chrisstaite-menlo)

a discussion (no related file):

Previously, allada (Nathan (Blaise) Bruer) wrote…

Before landing this I'd like to take some time to investigate what is causing it. I believe I have an idea that I want to flesh out.

I added some better logging and a potential fix: #266

If you are ok with it, i'd like to see if this fixes it.

…ommit `FilesystemStore::finalize_holding` (filesystem_store.rs:1571-1577) renamed `<digest>.holding` → canonical CAS path but never inserted the resulting `FileEntry` into `evicting_map`. Result: file on disk, invisible to `has_with_results` (which consults the in-memory index only — never stats the disk) until the next process startup walked `add_files_to_cache` over `content_path/d/`. Production symptom (2026-05-04 ~10:30-11:00 UTC): `FastSlowStore:: run_producer` saw `head_result = None` for ~seconds after a fresh chunked commit, fell through to peer-fetch via `WorkerProxyStore`, peers replied partial bytes, Bazel hashed the partial bytes and declared `OutputDigestMismatchException`. Builds wedged. Logs showed ~4012 "not found in either fast or slow store" + 80 chunked-mismatch warnings per 30 min. Root cause: cross-layer contract gap. `commit_chunked` doc-comment at filesystem_store.rs:1545-1550 deferred the `evicting_map` insert to "the driver"; the chunked driver's `commit_and_verify` didn't do it either. NO PARTY OWNED THE INSERT. Seven prior review passes (212- phase{2.1,2.2-3,2.4,2.5-2.6-2.7}, 218 M2/M3, 245) all asked about writer-termination, eviction codes, and registry — none asked "what does the in-process index see after this rename?" Fix: in `finalize_holding`, after `chunked_finalize_holding` succeeds (rename has landed), construct a `FileEntry` pointing at the canonical CAS path and insert it into `evicting_map`. Mirrors the `add_files_to_cache` startup-walk emplace (filesystem_store.rs:550-591) rather than `emplace_file` (which would attempt a redundant Temp → Content rename — the chunked path already did its own rename). CAS-immutable shortcut: if the key already exists in the map, skip the insert (digest = content; existing entry already points at the same on-disk path that the rename overwrote with byte-identical content). Mirrors `emplace_file`'s short-circuit at filesystem_store. rs:1217-1223. Lock ordering: the partial-map removal happens INSIDE `chunked_finalize_holding` (chunked_filesystem.rs:694), which runs BEFORE this insert. There is no window where the file is on disk and indexed in NEITHER structure. Test: nativelink-store/tests/filesystem_store_247_chunked_commit_ immediately_visible_test.rs - Production composition: real `ChunkedDriver` + real `FilesystemStore` + real Sha256 digest match → drives the success path of `commit_and_verify`, then immediately calls `has_with_results` (the call `FastSlowStore::run_producer` makes via `head_result`). - 5 s `tokio::time::timeout` deadlock detector + bespoke assertion message: "FilesystemStore::has() must return Some(size) immediately after chunked commit — file on disk but evicting_map not updated (TraceMachina#247)". - 5/5 stability runs at ~0.13-0.16s each. - Mutation step: comment out `evicting_map.insert` → test FAILS in 0.11s with `left: None, right: Some(12288)` and the bespoke message. Restore the insert → 5/5 still pass. Also adds CLAUDE.md "Index-visibility contract" rule (commit f2182705) so future reviewers ask the same question on every rename- into-canonical-path change. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

…a background_spawn! Distributed-systems reviewer flagged a MAJOR on TraceMachina#247 (`46c5c2d5`): the post-rename `evicting_map.insert` was a separate `.await` from `chunked_finalize_holding`. If the spawned `212_chunked_driver` task were aborted between those two awaits (server shutdown, panic, caller-cancellation), the file would land on disk without an `evicting_map` entry — a narrower-window re-introduction of TraceMachina#247 itself, not collected by `prune_holding_partials` (which only cleans `.holding` files, not canonical-path files). The legacy `emplace_file` (filesystem_store.rs:1208) defends against exactly this with a `background_spawn!` wrapper, citing TraceMachina#495. Mirror that pattern here: - Move the post-rename portion (CAS-immutable shortcut, FileEntry construction, `evicting_map.insert`) into a `background_spawn!` task. Spawned tasks run to completion regardless of caller-future drop. - Between `chunked_finalize_holding.await?` resolving Ok and the `background_spawn!` invocation there is no `.await` — only sync variable captures — so the rename → spawn pair is atomic w.r.t. caller-cancellation. (Cancellation can only happen at await points; the spawn's `tokio::spawn` is sync.) - Await the spawned `JoinHandle` to surface the result to the caller. If the caller's future is cancelled WHILE awaiting the JoinHandle, the spawned task continues to completion — the JoinHandle is just dropped. - A `JoinError` from the spawn now surfaces as `Code::Internal`. Cleaner failure mode than silently leaving the index unupdated. Cancellation-safety properties: - Cancelled before rename completes: file remains in `.holding`, `prune_holding_partials` GCs at next startup. OK. - Cancelled after rename, during spawn: spawn-call is sync; the rename → spawn-call pair is atomic. The window doesn't exist. - Cancelled while awaiting JoinHandle (after spawn): spawned task continues to completion, file is indexed. OK. - Spawned task panics: surfaces as JoinError → Code::Internal Err to caller. The caller sees the failure; downstream logging / metrics / retry can act on it. The file is still on disk unindexed, which is the same risk as a process kill mid-insert — addressed only by the existing `add_files_to_cache` startup walk. Acceptable. Test (`chunked_commit_makes_blob_visible_to_has_immediately`) unchanged — still passes 5/5 stability at ~0.13-0.42s. Mutation step re-verified: comment out `evicting_map.insert` inside the spawn → test FAILS in 0.78s with the same bespoke `TraceMachina#247` message. Restored insert → green again. Mirrors `emplace_file`'s pattern faithfully (variable-capture preamble, single spawn block, `JoinError` → Internal). Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

Addresses findings from the 4-reviewer pass on the 5-commit salvage bundle (TraceMachina#247, TraceMachina#244, TraceMachina#246, FIXME(TraceMachina#218), TraceMachina#247-cancellation-safety): **testing-czar MAJOR-1** — `27498447`'s cancellation-safety property was structurally untested. Adds `finalize_holding_uses_background_spawn_for_cancellation_safety_247`, a structural test that scans `filesystem_store.rs::finalize_holding` for `background_spawn!`. Behavioral tests for this property are fundamentally racy (the rename→insert window is microseconds; abort either wins the race against the rename or loses to the inline insert — see test doc-comment for details). The structural test catches the specific regression direction the reviewer named ("simplifying the spawn back to `.await`") with zero timing dependency. Mutation step verified: replace `background_spawn!` with `tokio::spawn` in the source → test red-fails with bespoke `TraceMachina#247 cancellation-safety` message. **testing-czar MINOR-2** — FIXME(TraceMachina#218) zero-byte test bypassed the `has_with_results` index-visibility contract (used `tokio::fs::read` + `tokio::fs::metadata` on the kernel-view). Adds the missing post-`finalize_holding` `has_with_results` assertion. CLAUDE.md "Index-visibility contract" rule explicitly forbids the substitution this test was making. **testing-czar MINOR-4** — adds `chunked_commit_visible_through_existence_cache_store_247` which wraps the FilesystemStore in `ExistenceCacheStore` to lock in the production-composition contract. Today this is functionally equivalent to the FilesystemStore-only test (because ExistenceCacheStore does not cache negatives), but the equivalence is fragile to a future "negative caching" change. **testing-czar MINOR-1** — adds `forward_racer_does_not_abort_racer_task_on_bind_buffered_ok_244` positive-control test for TraceMachina#244. Doc-comment is honest about the mutation-step limitation: hoisting `handle.abort()` outside the `if let Err` arm does NOT trip the test, because the racer task has already completed (its tx-drop is what triggered bind_buffered's EOF) by the time the abort lands — `abort()` on a completed task is a no-op. The test still has value as positive coverage of the peer-winner success path. **testing-czar MINOR-3** — DEFERRED. The dropped TraceMachina#246 mid-stream send-Err test would require a coordination mechanism (`tokio::sync::Notify`) rather than just a buffer-overflow body to reliably fire `verify_store.rs:188`'s `tx_guard.fail` arm. Tracker to follow. **code-reviewer M1** — drops precise line numbers in `writer_termination_245_drop_fallback_test.rs` doc-comments (`compression_store.rs:334` etc.) in favor of identifier-based references (`compression_store.rs CompressionStore::update write_fut WriteHalfGuard wrap`). Survives future doc-only line drift. **perf-optimizer MINOR-3** — cross-references the `write_chunk_at_ offset` empty-chunk no-op (`chunked_filesystem.rs:423`) to the FIXME(TraceMachina#218) zero-byte fast-path so a future change to that early- return doesn't silently flip the fast-path's `!has_entry` predicate. **Verified post-fix:** - 5/5 affected test binaries pass (3 in TraceMachina#247-test, 2 in TraceMachina#244-test, 5 in TraceMachina#218-test, 6 in verify_store_245-test, 2 in writer_term-test — 18 tests, all green). - MAJOR-1 mutation step (replace `background_spawn!` → `tokio::spawn` in finalize_holding) red-fails the new structural test with the bespoke `TraceMachina#247 cancellation-safety` message. **NIT-1 + NIT-2 deferred** — pure NITs; defer to a follow-up cleanup or never. No behavior risk. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

…-steals-canonical Production trace 2026-05-05 (PID 570543, deployed binary ace7aba with TraceMachina#247 + 2749844 cancellation-safety follow-up): 575 PHANTOM BLOB warns at FastSlowStore::run_producer between 06:23 and 08:59 PDT. 89% (483/543) of unique phantom digests had >=2 chunked-commit log lines preceding the phantom; modal commit count was 3 commits/digest. Root cause: FilesystemStore::finalize_holding's post-rename evicting_map.insert(key, new_arc) flow was unsafe for the duplicate- commit case (two chunked writers commit the same digest). The bug chain: 1. Commit TraceMachina#1 finalize_holding renames .holding -> canonical CAS path, spawns insert -> evicting_map[key] = Arc#1 pointing at PathType:: Content (canonical). 2. Commit TraceMachina#2 finalize_holding renames .holding -> canonical (overwrites in place; byte-identical per CAS), spawns insert. 3. The spawned insert calls MokaEvictingMap::insert(key, Arc#2): - cache.get(key) captures Arc#1 as `existing`. - cache.insert(key, Arc#2) replaces in-place. - returns Arc#1 to caller; caller calls Arc#1.unref().await. 4. FileEntryImpl::unref on Arc#1 (path_type=Content, key=digest) renames canonical CAS path -> tmp_path-cas/d/XX/<temp-key> (an orphan path with a counter-mangled hash). EncodedFilePath::Drop then background_spawn!s remove_file on the temp path. 5. evicting_map[key] = Arc#2 still claims path_type: Content at the canonical path -- but the file is gone. Subsequent has_with_results(key) returns Some(size) (entry in map); subsequent get_part(key) opens canonical -> ENOENT -> "Stale filesystem cache entry" -> FastSlowStore::run_producer PHANTOM BLOB warn -> WorkerProxyStore peer fetch -> partial bytes -> Bazel OutputDigestMismatchException -> build wedge. Why the existing CAS-immutable shortcut at filesystem_store.rs:1657 (pre-TraceMachina#256) didn't fire: production deploys (`buildcache-native.json5`) do NOT set `content_is_immutable: true` on the slow FilesystemStore. The default at nativelink-config/src/stores.rs:717 is `false`. The shortcut gated `size_for_key.is_some()` -> skip-insert behind `content_is_immutable`. The chunked path is intrinsically content- addressable (commit_chunked takes &DigestInfo only -- there's no String-key path through chunked code), so the content_is_immutable flag was the wrong gate for THIS code path. Fix: add a TraceMachina#256 duplicate-commit guard at the START of finalize_ holding (BEFORE the .holding -> canonical rename). If evicting_map.size_for_key(key) is Some, the canonical CAS file is already on disk and indexed; the .holding file is byte-identical (CAS invariant). Just unlink the .holding file + drop the in-flight partial entry + return Ok WITHOUT renaming or inserting. This prevents the rename from overwriting + the insert+old-Arc-unref chain entirely. Also generalize the in-spawn shortcut (line 1656-1660 pre-TraceMachina#256) to drop the content_is_immutable gate -- as a race-window second check, it is correct unconditionally for the chunked path (digest = content; either Arc indexes a canonical file with byte-identical content). The pre-rename gate handles the common case; the in-spawn re-check covers the case where two callers both pass the pre-rename gate simultaneously. Sibling-bug audit (CLAUDE.md): the only other evicting_map.insert site at runtime is emplace_file (filesystem_store.rs:1226). It is NOT vulnerable to the same bug because it inserts BEFORE renaming temp -> canonical; each emplace_file call has a UNIQUE temp_path (make_temp_key uses a per-call counter), so the OLD-Arc unref renames the OLD entry's unique temp -> trash temp, never touching the NEW entry's temp -> canonical staging. Test: nativelink-store/tests/filesystem_store_256_duplicate_chunked_ commit_test.rs (production composition: real ChunkedDriver x2 against real FilesystemStore; 5s deadlock detector; bespoke TraceMachina#256 message). - Pre-fix: test FAILS in 0.11s with "FilesystemStore::get_part must succeed after a duplicate chunked commit ..." -- exact production log signature: "Evicted blob from filesystem cache (unref)" -> "filesystem_delete_file" -> "Stale filesystem cache entry" -> get_part NotFound. - Post-fix: PASSES in 0.12s. - Mutation step (CLAUDE.md TDD): comment out the pre-rename guard AND the in-spawn re-check -> test FAILS with the bespoke message. Restore -> green. - The TraceMachina#247 + TraceMachina#247-followup test family (filesystem_store_247_chunked_commit_immediately_visible_test) all 3 tests still pass post-fix (the new TraceMachina#256 logic does not regress the single-commit visibility property the TraceMachina#247 fix introduced). Production-trace evidence sample (digest eb235413...-2014838): 06:38:35.761 chunked driver commit TraceMachina#1 06:38:35.801 chunked driver commit TraceMachina#2 (40ms later, same digest) 08:58:35.454 ByteStream::inner_read (2h20m later) has() Ok size=2014838 io_uring open canonical -> ENOENT "Stale filesystem cache entry" unref tries canonical -> tmp -> ENOENT (file already gone) PHANTOM BLOB warn fires Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

…teHalfGuard + gate fast_slow Err OOM-pressure mitigation per `.claude/audits/186-verifystore-noise-investigation.md`. Server emergency-restarted at 09:05 PDT (RSS hit 75 GB / 80 GB cap); the audit identified these two log classes as the dominant noise feeding mimalloc allocator pressure during phantom-blob bursts. Production rate (2026-05-04 20:37 → 2026-05-05 05:59, ~9h21m): - streaming_blob warn: 7,365 events; ~13K events / 6-min burst at 22:37–22:42. - WriteHalfGuard Drop error: 6,227 events; same burst window, 1.18:1 ratio with the streaming_blob warn — both reports of the SAME upstream NotFound from different layers (populator-side `send_error` vs outer-guard Drop). Per-site reasoning: 1. `streaming_blob.rs::StreamingBlobWriter::send_error` — demote `warn!` → `debug!` when `err.code == Code::NotFound`. NotFound is ALWAYS upstream-caused (slow_store NotFound + EC stale-positive cleanup; TraceMachina#247-class FilesystemStore disk/index divergence). The streaming_blob buffer itself isn't the suspect; logging the same fact 7K times drowns the actual phantom-blob signal. Other codes (Internal, Aborted, Unavailable) still warn — those are genuine producer wedges where the streaming buffer IS the suspect. Folds into the existing benign-vs-suspect split in the Drop arm (full-byte cancellation → debug, partial → warn). 2. `buf_channel.rs::WriteHalfGuard::Drop` — demote `error!` → `debug!` unconditionally. The composability harness (`writer_termination_245_drop_fallback_test.rs`, `waiter_explicit_termination_test.rs`, `fast_slow_store_test.rs::write_half_guard_drop_fallback_*`) is now the load-bearing detector for genuine writer-termination contract violations — production logs are not. Wire-side `Error` message ("buf_channel: writer dropped without commit") is preserved unchanged so remote clients still see a unique, greppable identifier; only the operator-side log level changes. 3. `fast_slow_store.rs::get_part` outer-guard NotFound exit paths — already gated via `commit_with_inner_miss_gate` in committed code (commits `009feab6` TraceMachina#171 sibling-bug audit, `ce468b18` parallel-path coverage, `9c02ce41` TraceMachina#171 fix, `b19a2ccf` TraceMachina#245). Verified all 9 NotFound exit paths in `get_part` (mirror_blobs size mismatch, in_flight size mismatch, local_only_reads, slow-store fallback, populator terminal-state NotFound branch, populate-then-fast-evicted retry, sliding-window-evicted fallback, populator-caller streaming-reader Err NotFound, waiter streaming-reader Err) — each routes through `commit_with_inner_miss_gate` or honors the `INNER_MISS_NO_TERMINATE` task-local explicitly. No code changes needed for site TraceMachina#3 in this commit. NOT covered here (out of audit scope, follow-up needed): - The new `Code::Unavailable` early-return at `fast_slow_store.rs:4143` (commit `ace7aba6` TraceMachina#252 chunked-pin partial-miss) does NOT terminate the outer guard. Drop fires + synthesizes an Internal error to the paired buf_channel reader, masking the Unavailable signal at the channel level. The function caller still observes Unavailable; the channel reader observes Internal. Noise impact is small now that TraceMachina#2 is debug, but the code-mismatch is a TraceMachina#252 contract gap to follow up separately. Tests: no existing test asserts on the WARN/ERROR level of either log; `waiter_explicit_termination_test.rs:308` asserts on the message body (`!logs_contain("WriteHalfGuard fired Drop fallback")`) and continues to guard correctly because the gate suppresses the Drop entirely (regardless of log level). Build: `cargo build --release --features quic,pprof,chunked_fast_slow` — 3m23s cold, no errors. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

…c from debug! to info!/warn! `release_max_level_info` (workspace Cargo.toml:101) strips debug! in release builds, so the existing BLOCK-B emissions at fast_slow_store.rs:6050,6072,6079 produced ZERO journal output in prod. Operators (and design reviewers) could not answer "is BLOCK-B firing today?" — a load-bearing input to the Option-C run_producer wait design that mirrors this Notify wait in the update path. This commit: - Promotes the BLOCK-B subscription entry `debug!` → `info!`. - Adds a slow-wait threshold (`BLOCK_B_SLOW_WAIT_THRESHOLD = 1 s`) that escalates the exit log from `info!` to `warn!` when commit- side contention extends the wait. Picked at 1 s (vs `SOFT_WARN_SECS / 2 = 15 s`) so operators see commit anomalies earlier; the deeper soft-warn at 30 s already covers the multi-MiB / commit-watchdog cases. - Leaves the "drained between lock-drop and notify enable" branch as `debug!` (no `.await` taken; would fire at line rate; entry-`info!` already provides the journalable signal). Three log lines MAX per BLOCK-B wait (entry / Ok exit / slow-wait warn). Volume bounded by chunked-commit fan-in (single-digit concurrent in production); no hot-loop emissions added. Behavior of the wait itself is unchanged — this is observability-only. Test follows in next commit.

…OCK-B entry promotion Production-composition test (real FastSlowStore wrapping a real MemoryStore fast tier and a real on-disk FilesystemStore slow tier) that: - Manually inserts a digest into chunked_in_flight_digests with a per-digest Notify (mirroring InFlightChunkedGuard::new without taking the cross-crate dep on nativelink-service). - Spawns a reader; yields enough times to park it on `notified.await`. - Drains the map and fires `notify_waiters()` (mirroring InFlightChunkedGuard::Drop). - Asserts the reader returns the slow-tier bytes within a 5 s deadlock-detector window. - Asserts the tracing-test buffer contains the BLOCK-B entry log at INFO level (specifically filtering on " INFO " prefix, per the `ac_pin_registry::cap_exceeded_emits_rate_limited_warn` pattern, so a regression to `debug!` does NOT satisfy the assertion via substring match in test builds where `release_max_level_info` is inactive). Mutation step (verified): revert the BLOCK-B entry `info!` back to `debug!`; the assertion red-fails with the bespoke message "BLOCK-B entry must emit at INFO level — regression to debug! would be stripped by release_max_level_info". Synchronization is a `tokio::sync::Barrier(2)` rendezvous between the test body and the drainer task (CLAUDE.md "No `sleep` as synchronization in tests").

…in_flight (1/64) Invariant violated: two high-volume INFO log sites fire on every read and every chunked blob admission (~302/10m and ~708/10m respectively), increasing log overhead without providing signal beyond what the closed TraceMachina#147 investigation needed and without a volume bound on the durability path log. Mechanism that violates it: (a) grpc_store.rs:read_internal emitted "channel acquired (TraceMachina#147 trace)" at info! on every read — 4 arms (TCP / QUIC / Dual-TCP / Dual-QUIC); TraceMachina#147 was fixed in 5adf34a and f47a7bd, so this is leftover instrumentation with no open follow-up. (b) chunked_write_handler.rs:bazel_facing_v1_dispatcher reaper inline code emitted "chunked_in_flight removed" (outcome=reaper_decrement) at info! on every chunked blob admission — the other two paired sites (registered + Drop-removal) were already demoted to debug! by the dafcf8b sweep and compile out in prod (release_max_level_info); this site was added post-sweep and missed it. Mechanism that re-establishes it after the fix: (a) remove all 4 read_internal info! calls and the sole-purpose resource_for_log local binding; ep_idx/conn_idx/post_conn are retained (used in map_err and return tuples). (b) gate the reaper_decrement info! behind chunked_inflight_log_sampled(&dig): a deterministic pure function that folds the first 8 bytes of the digest packed hash into a u64 key and tests key % 64 == 0 — same digest always yields the same bool so the (already-debug) registered and removed lines remain paired if the other sites are ever restored; volume drops from ~708/10m to ~11/10m. Composite invariants this fix interacts with: - FL-688 durability path: the "chunked_in_flight removed" signal distinguishes writer paths (TraceMachina#247/TraceMachina#477 DS disambiguation). Preserved at 1/64 sampling — enough for journal diagnosis, not per-blob. - release_max_level_info compile-out: debug! sites compile out; the remaining info! at the reaper site now has bounded volume. - refcount bookkeeping logic: unchanged; only the info! emission is gated — the map lock, decrement, per-digest wakeup, and FSS-wide notify are unconditional. - No per-RPC timeouts on internal paths: unchanged. Test that proves the fix re-establishes the invariant: - sampling_tests::sample_period_constant_is_64: numeric-constant discipline — literal 64 at declaration site. - sampling_tests::sampling_is_deterministic_per_digest: same digest → same bool across 5 repeated calls (register/remove pair safety). - sampling_tests::sampling_rate_is_approximately_1_in_64: 6400 distinct synthetic digests → 50–150 true (expected 100); bespoke messages for mutation A (% 1 → 6400) and mutation B (false → 0). Behavior changes: - grpc_store.rs read_internal: 4 info! removed entirely (~302/10m → 0). No data-path change; ep_idx/conn_idx/post_conn retained for error-path tuple. Verified in: nativelink-store --lib 98/98 pass. - chunked_write_handler.rs reaper_decrement: info! sampled 1/64 (~708/10m → ~11/10m). Refcount bookkeeping, wakeup logic, and registry semantics: NO change. Verified in: nativelink-service --lib sampling_tests 3/3 pass + mutation A/B red-verified. Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>

…construct_latency gossip Reduce hot-path per-request `info!` volume that, under a 140-executor build burst, multiplies into thousands/min and lands in the write-burst-stall regime (241 tokio threads in `__futex_wait`). The two WriteChunkedV2 lifecycle logs carry load-bearing TraceMachina#247/TraceMachina#477 wire-shape attribution, so they are SAMPLED (not blanket-demoted to `debug!`, which `release_max_level_info` would strip from the release binary) with an always-incremented counter that keeps the true rate scrapeable. The `worker_construct_latency` gossip is INERT (feeds no gate), so it is demoted to `debug!`. Per-site before/after emission: - chunked_write_handler_v2.rs "WriteChunkedV2 RPC entry": 1/RPC (777/15min observed) -> first + every 64th (~1/64) + `cumulative` field carrying the true count. peer_addr SocketAddr->String alloc now skipped on the suppressed path. - chunked_write_handler_v2.rs "WriteChunkedV2: session opened": 1/session -> first + every 64th (~1/64) + `cumulative` field. - simple_scheduler.rs worker_construct_latency: 1/worker/15s (1,796/15min) -> 0 in release binary (info! -> debug!, compiled out). Value still computed each cycle via construct_latency_snapshot() and recorded via update_worker_construct_latency (gossip mechanism untouched); recoverable in a debug build or once a hold-gate consumer lands. Invariant being violated: hot-path per-request `info!` lines emit unconditionally, so a build burst multiplies them into the write-burst-stall regime; and an inert per-worker gossip `info!` adds ~1,796 lines/15min for a signal that is consumed by nothing. Mechanism that violates it: chunked_write_handler_v2.rs:166 + :307 emit one `info!` each per chunked write unconditionally; simple_scheduler.rs:2936 emits one `info!` per worker per 15s interval for the inert worker_construct_latency gossip. Mechanism that re-establishes it after the fix: the two v2 lifecycle logs are gated by `v2_lifecycle_log_decision` (emit first + every 64th; an always-incremented AtomicU64 exposes the true rate as a `cumulative` field), cutting emission ~64x while keeping the TraceMachina#247/TraceMachina#477 signal measurable; the inert gossip is demoted to `debug!` while its value stays computed each cycle. Composite invariants this fix interacts with: (a) TraceMachina#247/TraceMachina#477 wire-shape attribution -- preserved via sampling + cumulative counter, NOT deleted; (b) release_max_level_info (debug!/trace! stripped in release) -- the load-bearing lifecycle logs are SAMPLED not demoted (kept at info!); the inert gossip is DELIBERATELY demoted because it feeds nothing; (c) the T_SETUP hold gate -- untouched; update_worker_construct_latency still records the gossiped value so the mechanism is intact. Test that proves the fix re-establishes the invariant: chunked_write_handler_v2::v2_lifecycle_log_sampling_tests::counter_increments_every_call_while_log_samples (+ gate_emits_first_then_every_period, sample_period_actually_throttles, sample_period_constant_is_64). Behavior changes: - chunked_write_handler_v2.rs "WriteChunkedV2 RPC entry" info!: unconditional (1/RPC) -> sampled (first + every 64th) + `cumulative` field; peer_addr resolved only on the emitted path. Verified safe in composition: reached only from CasExtensions/WriteChunkedV2 (worker->server upload); change is emission-rate-only -- no control-flow, no data-shape, no ack-timing change. - chunked_write_handler_v2.rs "WriteChunkedV2: session opened" info!: unconditional (1/session) -> sampled (first + every 64th) + `cumulative` field. Same composition; emission-rate-only. - simple_scheduler.rs worker_construct_latency info! -> debug!: per-worker per-15s emission removed from the release binary. Verified safe in composition: SimpleScheduler's periodic hold-counters-log task; the value is inert (not consumed by any gate), still computed each cycle and recorded via update_worker_construct_latency. No scheduling/control-flow change. - No new buffering fields, channels, sync-write primitives, or per-RPC timeouts introduced. Out-of-scope drift (reported to parent, not touched -- outside owned crates): - "Client connected" per-connection info! is at src/bin/nativelink.rs:2529 (top-level `nativelink` bin), NOT bytestream_server.rs/worker_api_server.rs as the dispatch stated -- outside nativelink-service/nativelink-scheduler. - BLOCK-B read enter/exit info! is at nativelink-store/src/fast_slow_store.rs :7571 (entry) / :7618 (Ok exit) in FastSlowStore::get_part -- nativelink-store, which the dispatch instructed to leave and note. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> (cherry picked from commit 2278b8c2fddb5ca6175801df78614ef3a6228d84)

Clean work directories on disconnect

299c023

When a worker disconnects it may have jobs that aren't cleaned up.

chrisstaite-menlo requested a review from allada September 7, 2023 09:53

allada suggested changes Sep 8, 2023

View reviewed changes

allada suggested changes Sep 11, 2023

View reviewed changes

chrisstaite-menlo closed this Sep 11, 2023

Navigation Menu

Repository navigation

Clean work directories on disconnect - #247

Clean work directories on disconnect#247
chrisstaite-menlo wants to merge 1 commit into
TraceMachina:mainfrom
chrisstaite-menlo:clean_work_directories_on_disconnect

chrisstaite-menlo commented Sep 7, 2023 •

edited by allada

Loading

Uh oh!

allada left a comment

Uh oh!

allada left a comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Conversation

chrisstaite-menlo commented Sep 7, 2023 • edited by allada Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

allada left a comment

Choose a reason for hiding this comment

Uh oh!

allada left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

chrisstaite-menlo commented Sep 7, 2023 •

edited by allada

Loading