Repository navigation
Conversation
|
The latest updates on your projects. Learn more about Vercel for GitHub.
|
|
|
b7r6
left a comment
b7r6
left a comment
There was a problem hiding this comment.
The diagnosis is exactly right, and the writeup makes it easy to trust: the assignment-vs-command-start clock skew is real, the requeue → AlreadyExists → stray-result → disconnect cascade is real, and the failing-on-main test plus deployment evidence pin it. This is a good fix to the right bug.
The concern is that removing the scheduler-side deadline for Alive/Unknown workers gives away more than the bug requires. There are supported configurations and reachable failure modes where "a live worker enforces it itself" doesn't hold, and in those the removed check was the only enforcement anywhere (details inline).
An alternative shape that keeps the win without the regressions: enforce in every arm, but at action_timeout + grace, where grace covers the worker's later clock start — e.g. no_event_action_timeout, measured from max(last_transition, last_worker_updated) so it only has to cover "time since the worker last showed signs of life" rather than an unbounded input fetch. A live worker then always wins the race by construction, the scheduler stays a true backstop for wedged fetch / unkillable children / external-timeout configs / orphans, and no liveness special-casing is needed. Smaller diff than the arm restructuring: one grace term on the existing check.
The liveness-gated shape is also workable — but then the inline gaps (Unknown arm, Stale-arm coverage, the error message) each need addressing individually.
One small pre-existing thing surfaced by the restructuring, fine to punt: when the Stale arm fires via Action.timeout, the client-facing message (timeout_operation_id, ~line 900) still reads "Operation timed out after {no_event_action_timeout} seconds" — the number and cause come from the liveness config rather than the RBE deadline that actually fired. Since this change routes a new cause through that arm, it'd be a nice moment to thread the real one into the message, but it doesn't need to block anything.
Worth saying in passing: every option here, this PR included, is a heuristic around the same missing piece — the scheduler never learns when the command actually started, so it's timing a deadline against an event it can't observe. The eventual fix is for the worker to report command-start as an explicit operation transition (it already has the timestamp locally; ExecutedActionMetadata carries it, but only in the final result — one message too late), and for the scheduler to anchor the deadline to its own receipt of that event. No cross-machine clock comparison, no grace term, and every liveness arm collapses into one rule with a fallback for "the event never came." That's a worker_api.proto change and too big for this PR — but it's the direction, and whichever heuristic lands here should land as the acknowledged interim. A tracking issue will follow.
| // the Bazel client's --test_timeout, which surfaces as TIMEOUT/NO | ||
| // STATUS instead of a backend signal pointing at the worker. | ||
| // The per-action `Action.timeout` from the RBE protocol, as a backend | ||
| // backstop. A live worker enforces it itself and reports a completed |
There was a problem hiding this comment.
Three reachable cases where the premise "a live worker enforces Action.timeout itself" doesn't hold, and this arm then has no deadline (with max_action_executing_timeout_s defaulting to 0/disabled):
timeout_handled_externally: true(cas_server.rs:1052, the documented docker-wrapper pattern) — the worker deliberately substitutesmax_action_timeout(running_actions_manager.rs:3712, default 20 min). A broken wrapper turns a 30 s action into a 20-minute one with no backendDEADLINE_EXCEEDED.- The worker's timer starts in
execute()(running_actions_manager.rs:2211), after input fetch. A hung CAS fetch on a heartbeating worker is bounded by nothing. - An unkillable child (D-state, NFS/fuse hang): the worker's kill fails, it parks on
wait(), never reports a result, and keeps heartbeating.
Pre-PR all three were eventually surfaced by the check this removes. The +grace shape in the review summary covers all three without re-introducing the race.
| // action is requeued (onto the worker still running it, which refuses | ||
| // with AlreadyExists) and the worker's own result then evicts it and | ||
| // every other action it holds. So the backstop applies only to a | ||
| // worker of ours that has gone quiet; a peer instance's worker |
There was a problem hiding this comment.
The comment says "a peer instance's worker enforces the timeout itself", but this arm's own pre-existing comment notes Unknown is also "an orphan no instance will ever reap" — and an orphan has no worker enforcing anything. Concretely: after a replica restart/scale-down, an orphaned action with Action.timeout = 60s previously got DEADLINE_EXCEEDED at ~60 s; now it waits up to ORPHANED_ACTION_TIMEOUT (1 h). And in the two-replica case the ceiling is measured from last_worker_updated_timestamp, which a live-but-stuck worker on the peer keeps advancing — so the 1 h ceiling can be postponed indefinitely and no instance enforces the deadline.
| .unwrap_or(now); | ||
|
|
||
| worker_should_update_before < now | ||
| past_action_deadline || worker_should_update_before < now |
There was a problem hiding this comment.
The cascade this PR fixes is still reachable through this arm. Registry heartbeats are refreshed only by keepalives (refresh_worker via worker_keep_alive_received), not by operation updates (update_action doesn't touch the registry) — so a worker with a lagging keepalive channel but a live, progressing action reads Stale, and past_action_deadline fires on the assignment-relative clock: requeue onto the still-running worker, AlreadyExists, same eviction chain. Requiring action-update staleness before the OR fires (e.g. measuring from max(last_transition, last_worker_updated)) closes it — or the grace shape makes it moot.
| /// here as well would requeue every action that runs to its timeout onto the | ||
| /// worker still running it, and the worker's own result would then evict it. | ||
| #[nativelink_test] | ||
| async fn leaves_action_timeout_to_a_live_worker() -> Result<(), Error> { |
There was a problem hiding this comment.
Good test — and it fails on main, which is the standard that matters. Two arms whose behavior this PR changes have no equivalent though: delete past_action_deadline || from the Stale arm and the suite stays green (the existing Stale test uses timeout ZERO), and the Unknown arm's loss of Action.timeout is asserted nowhere. Both changed behaviors need a test that fails without them, or the next refactor reverts this silently.
|
Tracking issue for the event-anchored fix described in the review: #2827. |
should_timeout_operation ended an Executing action once Action.timeout had passed since it was assigned. The worker enforces the same timeout, but its clock starts when the command starts, after input fetch, so the scheduler always fired first. The action was requeued onto the worker still running it, which refused with AlreadyExists; the retries ran out, and when the worker's own DEADLINE_EXCEEDED result arrived it was treated as a stray and the worker was disconnected, taking every other action on it down too. The scheduler now enforces Action.timeout in every liveness case, at Action.timeout plus no_event_action_timeout, measured from the later of the assignment and the worker's last update on the action. A live worker reports first, so no liveness special-casing is needed, and the scheduler still ends an action whose worker never reports: a hung input fetch, an unkillable child, a broken timeout_handled_externally wrapper, or an orphan no instance reaps. The client's DEADLINE_EXCEEDED message now names the deadline that fired, instead of always citing no_event_action_timeout. This is the interim: the scheduler cannot observe when the command starts. TraceMachina#2827 tracks the worker reporting command start as an operation transition, so the deadline can be anchored to that event.
cfbf664 to
d4b4b15
Compare
b7r6
left a comment
b7r6
left a comment
There was a problem hiding this comment.
This is the shape hoped for, executed better than the review asked. timeout_cause returning a typed cause fixes the misattributed client message at both call sites and flushed out a drifted duplicate of the rule along the way; the max(assignment, last-update) anchor means the grace only covers time since the worker last showed life, so every case in the earlier round — wedged fetch, unkillable child, broken external-timeout wrapper, orphans, the lagging-keepalive Stale worker — lands in a test with a named cause. The arm collapse into silent_for is the structural payoff: the liveness special-casing the first version added is gone, and the interim/#2827 relationship is stated honestly in the commit. Nice work.
rohnnyjoy
changed the title
|
Thanks, agreed on all of it. I've reshaped it the way you suggested: Action.timeout is enforced in every arm at timeout + no_event_action_timeout, measured from max(last_transition, last_worker_updated), with no liveness special-casing. That covers the external-timeout, hung-fetch and unkillable-child cases, orphans on the Unknown arm, and the Stale-arm cascade. Each has a test that fails without the change (details in the description). The client message now names the deadline that actually fired. The commit body calls this the interim fix until #2827. |
|
Triage of the red Underlying issue (lane hard-fails on a momentary endpoint outage) is addressed in #2897: |
#2897) A transient connection-refused from the staging CAS during Bazel's remote-capabilities query fails the build outright (2026-10-01, run 36815211094: the Redis store tester went red on the #2826 merge push and green on the next 14 main runs — pure endpoint blip, unrelated change blamed). Two gaps closed: - tools/bazel-retry.sh: the transient pattern now also matches 'Connection refused', 'Failed to query remote execution capabilities', and gRPC 'UNAVAILABLE:' (still gated on ^ERROR: lines, max 3 attempts). - native-bazel.yaml: the Linux/macOS test arms and the three Redis store tester invocations go through bazel-retry instead of raw bazel. The Windows arm is left raw for now (different startup-flag shape).
This branch was successfully deployed
4 participants
What and why
should_timeout_operationtimes an Executing action out onceAction.timeouthas elapsed since it was assigned. The worker enforces the same timeout itself, but its clock starts when the command starts (after input fetch), so the scheduler always fires first. The action is then requeued onto the worker still running it, which refuses with AlreadyExists; the retries exhaust ("attempted to execute too many times 3 > 2"), and when the worker's own DEADLINE_EXCEEDED result arrives the scheduler treats it as a stray and disconnects the worker, taking every other action on it down too.This keeps the scheduler's
Action.timeoutcheck in every liveness case (Alive, Stale, Unknown) and gives it a grace: it fires atAction.timeout + no_event_action_timeout, measured frommax(last_transition_timestamp, last_worker_updated_timestamp). A live worker therefore reports its own result first, with no liveness special-casing, and the scheduler is still the backstop for an action whose worker never reports: a hung input fetch, an unkillable child, a brokentimeout_handled_externallywrapper, or an orphan no instance reaps.It also threads the cause into the client-facing error:
timeout_operation_idused to say "timed out after {no_event_action_timeout} seconds" even whenAction.timeoutfired. A smallTimeoutCause(returned by a newtimeout_cause, whichshould_timeout_operationwraps) now names the deadline that fired, in both the client message and the scheduler's log.This is an interim heuristic. The lasting fix is the worker reporting command start as an operation transition (#2827), so the deadline is anchored to an event the scheduler observes.
How was this verified?
cargo test -p nativelink-scheduler: all pass.cargo clippy -p nativelink-scheduler --all-targets, nightlycargo fmt --checkandtyposare clean.simple_scheduler_state_manager_test.rs:gives_a_live_worker_the_grace_to_report_its_own_timeout(Alive),gives_a_stale_worker_with_a_recent_update_the_grace(Stale, the keepalive-lag case from the review),gives_a_peer_instances_worker_the_grace(Unknown), andmeasures_the_grace_from_the_workers_last_update(themax(...)anchor).times_out_a_live_but_wedged_worker_past_the_grace(Alive, also checks the client message),times_out_a_stale_worker_on_action_timeout_past_the_grace(Stale, asserts the cause is Action.timeout),times_out_an_orphan_on_action_timeout_past_the_grace(Unknown, instead of waiting forORPHANED_ACTION_TIMEOUT).action_timeout_is_enforced_backend_side_testinsimple_scheduler_test.rsnow asserts both: not timed out inside the grace, timed out with cause Action.timeout past it.main(4fe0a27) with only the tests applied: the four grace tests andaction_timeout_is_enforced_backend_side_testfail. (The three "past the grace" tests pass onmain, which enforces earlier.)Action.timeoutcheck removed: the three "past the grace" tests, the anchor test andaction_timeout_is_enforced_backend_side_testfail.last_transition_timestampalone:measures_the_grace_from_the_workers_last_updatefails.NO STATUSwith "Job cancelled because it attempted to execute too many times 3 > 2", and the scheduler logged "timed out after 60 seconds issuing a retry", "Timing out operation", then closed the worker's connection, which also dropped three unrelated in-flight actions. With this revision applied to v1.7.1 (the same diff, rebased) and deployed: the same test ends as TIMEOUT in 60.0 s and 60.3 s on our two worker pools, reported by the worker, with no "Timing out operation", retry or worker disconnect in the scheduler log and no worker restart. The first revision had been running on that deployment since 2026-09-29.Risk
Low. Nothing changes for an action with no
Action.timeout. For one with a timeout, the scheduler now ends itno_event_action_timeoutlater than before (measured from the worker's last update if that is later than the assignment), in every liveness case; a worker that reports its own timeout in that window is never pre-empted. The residual race: a worker whose input fetch plus kill and report take longer thanno_event_action_timeoutpast the timeout is still pre-empted, as today. The client-facing DEADLINE_EXCEEDED message text changes.AI assistance
An agent (Claude) found the bug from our scheduler and worker logs, wrote the patch and the tests, reshaped both to the review, and ran the verification above, on our deployment too. I review each revision; this one stays a draft until I have.
This change is