fix(observability): let a long task say it is still working - #1177
Merged
Conversation
A composite action — an explore grid, a baseline pair, a profile and its roofline — is one task row that internally completes many units over hours. Between dispatch and return it emitted nothing durable, so a healthy 80-minute run and a wedged one left identical evidence. Field sessions read that as "orchestration silent 8097s" while the run was in fact progressing normally, and as a health probe demanding a restart of a server no phase had booted yet. Executors now report each unit through an ambient reporter the runner binds to the task, landing on the row as a heartbeat that moves ``updated_at``. Stall detection consults it and withholds the accusation while dispatched work is still moving; the server probe holds its fire when no server process is up. Emitters: per variant in the grid runner, after the baseline warmup round, and per roofline sub-step. Refs #1145, #1168 Co-authored-by: Cursor <cursoragent@cursor.com>
This was referenced Aug 13, 2026
5 tasks
Collaborator
|
Blocking items only, verified at PR head. 1. The heartbeat cadence is ~10x coarser than the window it feeds, so the cited incident still alertsThe suppression window is the existing global work_idle_s = _in_flight_work_idle_s(data.local_task_progress, now_unix=ctx.now_unix)
if work_idle_s is not None and work_idle_s < cfg.stall_timeout_s:
# Dispatched work reported a unit more recently than the threshold: the
# session is progressing and quiet agents are waiting on it, not stuck.
return []The baseline executor emits one heartbeat, after the warmup round returns ( The issue's proposed fix #2 was a dedicated 60–90 minute threshold for profiling/TraceLens. The heartbeat and the threshold it gates were never sized against each other. No test can surface this: every stall test injects Worth separating from the fix itself — the diagnosis in the PR body ("8097s is exactly the length of PRELUDE; the silence was the design") is correct, and the reporting mechanism is sound. It is the sizing that does not land. 2.
|
The heartbeat's consumer suppressed too much. A single running task that had reported recently returned no symptoms at all, before the per-agent loop ever ran: one busy explore grid vouched for the Coordinator, the critic and the kernel agent alike, and a genuinely hung agent went unreported for as long as anything on the box kept moving. Nothing was logged, so the near-miss left no trace an operator could read afterwards. Freshness also came from ``MAX(updated_at)`` over running rows, which a task merely entering ``running`` advances — the suppression could fire without a single heartbeat behind it. Progress notes now name their owning agent, the probe reads them out of the task history instead of trusting a column that moves for other reasons, and the judgement moved into the per-agent branch: only an agent's own work speaks for it. Work buys time, not immunity — past ``severity_high_after_s`` the accusation fires regardless of how busy the machine looks — and a withheld accusation is downgraded to LOW with its counter-evidence attached rather than discarded, so "we would have accused X, but its work reported Ns ago" is visible in the session. Attribution is as narrow as the data supports: the ``tasks`` table has no requester column and every row is dispatched by the Coordinator's orchestration loop, so a heartbeat is stamped for that agent alone. Refs #1145 Co-authored-by: Cursor <cursoragent@cursor.com>
CI E2E report — ✅ Succeeded
|
The completion reports only fire once a unit has landed, so the very failure this heartbeat targets - a first variant or a warmup round that hangs for tens of minutes - still produced no evidence at all. Announce each unit on entry, before the launch that can block, and keep the completion reports as they were. Entry reporting also covers the branches that reach neither the completion report nor a finally, so `_after_variant` is left alone rather than moved into a finally that would double-report. Co-authored-by: Cursor <cursoragent@cursor.com>
Three of the five sub-step call sites were bare: the N26 re-analysis and both halves of the multi-node compute-bound re-profile ran silently, and each of them can take tens of minutes. Rather than paste the same report block at each site, funnel every call through a single closure next to the local imports, so a site added later cannot be the silent one. Each call site keeps its own try/except and fail-soft semantics unchanged; only the await is wrapped. Co-authored-by: Cursor <cursoragent@cursor.com>
``ray::IDLE`` is the name of a parked worker only; once a worker starts running a serving actor Ray renames it after the actor class, so ``ray::ServingActor`` matched no pattern and the process disappeared from the probe entirely. Presence still says nothing about busy-versus-hung — it only stops the probe reporting an empty machine while work is on it. Co-authored-by: Cursor <cursoragent@cursor.com>
…utput A start-of-unit report covers the first 300 seconds and nothing after, so the 55-minute TraceLens analysis - one await, no units - still went stale halfway through. A timer would have "fixed" it by vouching for wedged processes, which is the exact failure the stall signal exists to catch. Drive the heartbeat from the child's own output instead: the subprocess reader already walks stdout/stderr line by line, so it now tallies what it reads, and a driver on the loop reports once per interval in which that tally moved. A silent child produces no heartbeat and stays accusable. The kernel-tool child is unbuffered so its lines arrive while it works rather than in eight-kilobyte lumps. Covers the TraceLens analysis (via every kernel tool subprocess) and the profile / baseline benchmark round. The Ray-managed round runs its child in a remote worker with no channel back for the callback, and is left on the ceiling from the first commit in this series. Co-authored-by: Cursor <cursoragent@cursor.com>
``updated_at`` marks when a task entered ``running``, and three consumers measure elapsed runtime from it: the R6 lease watchdog turned into an inactivity timeout that a heartbeating task could never trip, the ``extend_lease`` remaining-budget math read time-since-last-note as time-already-spent and handed lanes and GPUs more than the budget allowed, and the Coordinator's own "Tasks in flight" line rendered an 80-minute task as seconds old — this PR's goal running backwards in the one surface the Coordinator reads. ``running()`` gets its least-recently-updated-first meaning back for free. The write had no reader left: the probe already reads freshness from the progress notes on ``history`` rather than from the column. The docstring argued for the behaviour and is rewritten to state the invariant instead, matching the one ``extend_lease`` documents a few lines below. Removing the bump restores the pre-PR reaper behaviour rather than changing it. It does not close the pre-existing gap between the catalogue's ``lease_ttl_sec`` and observed composite runtimes (roofline 2700s vs a 3106s TraceLens step, baseline 4200s vs a 3941s warmup round plus its measured round); that needs a TTL or extension policy decision and is reported on the PR rather than papered over here. Refs #1145 Co-authored-by: Cursor <cursoragent@cursor.com>
…still merges The hook grew a progress report, so "pulse" stopped describing all of it and it was renamed to match. But the name is a merge surface: #1171 adds a call site of its own, in the branch that records a variant reaped by the session budget as skipped rather than failed. Renaming here deletes the definition that call site resolves to, in a region #1171 never touches, so git reports no conflict and the merge lands a NameError on the reaped-variant path -- found only by lint or by running it. Keep the name and say what it does in the docstring instead. Costs an imprecise word; buys a merge that cannot break silently in either order. Co-authored-by: Cursor <cursoragent@cursor.com>
![github-advanced-security[bot]](https://avatars.githubusercontent.com/in/57789?s=60&v=4){kind=small}
Contributor
Author
|
Both blocking items are fixed. The second one was the more serious of the two and your reading of it was exactly right. 1. The cadence now matches the window it feeds —
|
![github-code-quality[bot]](https://avatars.githubusercontent.com/u/9919?s=60&v=4){kind=small}
``asyncio.CancelledError`` derives from ``BaseException``, so the ``except Exception`` guard around ``transaction()`` never saw it: a cancel landing on one of the ``to_thread`` hops after ``BEGIN IMMEDIATE`` had already run left the shared connection inside a transaction for the rest of the session, and every later registry write failed with "cannot start a transaction within a transaction". The heartbeat this branch adds is the first path that routinely cancels a coroutine mid-write, once per long subprocess step. Catch ``BaseException``, and roll back inline rather than on a worker thread — the exception being handled is usually this task's own cancellation, and an ``await`` there can be cancelled in turn. A rollback that itself fails is logged, never allowed to mask the original exception. Co-authored-by: Cursor <cursoragent@cursor.com>
Teardown used to hard-cancel the driver and swallow the result. Both halves were wrong. The cancel could land while the driver was inside a ``tasks`` row write, which is exactly the case that leaves the coordinator's connection wedged. The driver now polls a stop flag between ticks, so teardown asks it to finish the note it is in and only cancels if it overruns a bounded grace — a wedged sink costs the executor the grace window and nothing more. ``suppress(CancelledError)`` around the await could not tell the driver's own cancellation from the enclosing task being cancelled during teardown, so an outer cancel was absorbed and the step returned as though it had finished. Nothing catches ``CancelledError`` on that path any more. ``interval_s`` now resolves its default at call time so the timescale can be compressed under test. Co-authored-by: Cursor <cursoragent@cursor.com>
…issing it ``_run_magpie`` is the longest single block in a session — up to a 7800s variant timeout against a 300s suppression window — and it ran the benchmark with no liveness callback, so a grid announced each variant on entry and then went dark. Same shape in the baseline's discarded multi-node warmup pass. Both now run under the same output-driven heartbeat the measured baseline round already uses. In the grid all three Magpie passes (auto-warmup, multi-node warmup, benchmark) go through one helper, so a pass added later cannot be the one that reports nothing. The Ray serving-lease branch is left as an explicit gap in both files: the round executes inside an actor in another process and only its final ``(rc, stdout, stderr)`` crosses back, so there is no local per-line event to hang a callback on. A Ray-backed round reports on entry and stays quiet until it returns. Co-authored-by: Cursor <cursoragent@cursor.com>
The suite asserted that notes are emitted, never that consecutive notes on a path stay closer together than the window a consumer waits before calling the owning agent silent — which is how a benchmark with no liveness callback survived a change whose whole purpose was to close that gap. ``ProgressCadence`` records each note against a compressed clock, so a test second stands for ten production minutes and the assertions still read in the numbers the window is configured with. Every long path now has a test that fails if its callback is dropped: the grid variant benchmark, the baseline round, the multi-node warmup pass and the kernel tool subprocess. Two existing tests could not fail for the reason they existed: ``test_run_subprocess_counts_the_lines_its_child_emits`` counted nothing, only that a callable had been passed, and now asserts one call per line the child emits; ``test_a_variant_reports_before_it_blocks`` covered the entry marker and nothing after it, so a cadence test now sits beside it. Co-authored-by: Cursor <cursoragent@cursor.com>
…ver is ``is_server`` was computed against the module constant while the match list came from ``config.server_process_patterns``, so a framework an operator added to the documented knob was matched as a process yet flagged as not-a-server — which silently disabled ``local_server_unreachable`` for exactly the deployment that configured it. The probe config now carries the server subset and the flag follows it. An empty process list was also doing double duty: "nothing is running" and "we could not find out". ``_sample_processes`` returns ``None`` for the second and ``SourceData`` carries ``local_processes_known``, so a missing or wedged ``ps`` no longer mutes an unrelated finding. Co-authored-by: Cursor <cursoragent@cursor.com>
Unbuffering a kernel tool keeps the heartbeat above it honest, but assigning PYTHONUNBUFFERED overrode an operator who had set it deliberately. The three launcher sites in multi_node/scripts already use setdefault; match them. Co-authored-by: Cursor <cursoragent@cursor.com>
_json_loads_or_none caught the decode errors but not RecursionError, so a deeply nested history blob written by another process aborted the entire probe tick instead of costing only the sub-probe that read it. Co-authored-by: Cursor <cursoragent@cursor.com>
The symptom table described agent_stall as medium/high only; a stall whose dispatched work is still reporting is LOW and routes to send_message (observation), which the ladder test now locks in. Co-authored-by: Cursor <cursoragent@cursor.com>
…he clock The 900s ceiling on a withheld agent_stall assumed a suppressed accusation should eventually fire anyway. Measured work units break that assumption: a single warmup runs 3941s and a TraceLens pass 3106s, so every healthy long phase crossed the ceiling and alerted exactly as if nothing had reported. Suppression now lasts as long as the counter-evidence stays fresh — the tick after the work stops reporting accuses at full severity. Long waits are still visible: the withheld note itself rises from LOW to MEDIUM past the threshold, which is now operator-configurable via agent_stall_high_after_s. Co-authored-by: Cursor <cursoragent@cursor.com>
…e wall The four cadence assertions compressed a 300s suppression window into 0.5s of real time and then compared a real wall-clock gap against it, so every scheduling delay in the test was multiplied by 600 and charged to the path under test. The dominant term was not the heartbeat at all but the run-up before the first note -- fixture setup, imports, the fake magpie workspace -- which on two cores under eight-way contention grew to 753/888/1035 production seconds against a 300 budget. Advance the clock only when the simulated child does a chunk of the work it stands in for, so the timeline is a pure function of the lines emitted. The run-up and the tail collapse to what they represent, the steady-state spacing stays at the production ratio, and the assertion keeps failing when a liveness callback is dropped or the tick is widened past the window. Fake the kernel tool's child with the same helper the other three use: with a real subprocess there is nothing in the test that can advance the simulated clock. The real pump's line counting keeps its own coverage in test_run_subprocess_counts_the_lines_its_child_emits. Co-authored-by: Cursor <cursoragent@cursor.com>
The process guard read "probed successfully, saw no server process" as "no server was supposed to be running", which is true of the gap between two variants and false of a server that crashed while its own load generator was still sending requests into the closed port. That second snapshot is exactly the one worth alerting on, and it was the one being suppressed: all targets unreachable plus one is_server=False benchmark_serving process produced no symptoms at all where base emitted a HIGH local_server_unreachable. Suppress only when the probe answered, no server process is up and no benchmark client is running. The client patterns are deliberately narrower than the harness patterns the process probe matches -- the outer Magpie/InferenceX harness is up across server launch and teardown too, so it stays evidence of nothing, which is what keeps the idle-stretch guard intact. Record benchmark_client_seen next to server_process_seen so the branch that decided is legible in the alert, and give the suppressed case its own row in the symptom table, which still promised that any target down always alerts. Co-authored-by: Cursor <cursoragent@cursor.com>
…clock Four of these tests asserted a note count reached after sleeping a few tick intervals, which only holds if the loop was scheduled during that sleep. On the 2-vCPU CI runner, with two xdist workers and coverage tracing, it is not: under comparable oversubscription three of them failed in every run, because the driver had not yet taken the tick the assertion assumed. Wait for the driver's own notes instead. A note is proof the driver got that tick, so the wait is as long as the machine needs and the counts become exact rather than lower bounds. A driver that is supposed to stay silent — the one watching a child that went quiet, and the one whose step already returned — is paced by a second heartbeat kept deliberately noisy, so the window it would have reported in is intervals it actually got rather than intervals the test hoped had gone by, and the assertion becomes the ordered sequence of who spoke. Every wait is bounded so a driver that stops reporting fails in seconds. Also drop ``assert elapsed < 1.0`` from the wedged-sink test: a teardown that waited on the sink instead of cancelling it would still be inside the ``async with``, never reaching the assertion, so the measured interval was carrying no coverage that ``events == ["cancelled"]`` does not. Co-authored-by: Cursor <cursoragent@cursor.com>
``asyncio.shield`` protects the rollback, not the wait on it. A cancel landing on that wait raised straight through the ``except BaseException`` written to keep the caller's exception, and ``transaction()`` then ran on to its ``raise`` and released ``_async_lock`` with the rollback still queued on ``_sync_lock`` behind the worker the first cancel abandoned -- fire and forget with the lock already gone, which is the shape this rollback was moved off the loop to avoid rather than to adopt. The next writer finds the connection inside a transaction nobody will close and every write in the session fails with "cannot start a transaction within a transaction". The same handler lost the cancellation outright. One cancel is enough: a ``record_progress`` body raises on its own -- a ``BEGIN IMMEDIATE`` past ``busy_timeout``, a ``history`` column that will not parse -- and the swallowed cancel left the caller with the body's exception, which ``report_progress`` drops. An action cancelled by the stop path then runs on as though nothing had happened while the dispatcher's ``gather`` waits for it. Keep the shielded future and resume the wait after every cancel, so the connection is always clean before ``_async_lock`` is released, then re-raise the cancel that arrived. Narrow the ``except`` to what a rollback can actually fail with -- a statement error, or an executor refusing work during teardown -- so control flow is no longer swallowed as though it were a database error. Co-authored-by: Cursor <cursoragent@cursor.com>
…rver's log ``grew`` means "one of the resolved logs got longer", from any writer, and feeding it to the liveness callback made the heartbeat the bare timer ``heartbeat_while_output_flows`` documents itself as never being. A child that printed nothing for 3s was reported alive 5 times by a ``server.log`` an unrelated thread appended to. In a real round that writer is the inference server, which keeps logging while the benchmark client is wedged, and both vLLM and sglang write an access line per request -- including the health probe the robustness agent issues every standalone tick against the server it is monitoring. That closes a loop where the monitor's own probe manufactures the evidence suppressing its own stall accusation, and the wall-clock ceiling that used to backstop the case is gone. Report liveness on evidence about the round instead: a generation-progress marker, which says tokens were flowing whoever logged them, or growth in the benchmark body's own redirected stderr, which is output of this very child that never reaches its pipe. Keeping the second is what stops the narrowing from silencing a working round: the scriptable and bypass paths redirect the body's stderr to ``benchmark_stderr.log``, so for a whole round the pipe is empty and that file is all there is. The stall watchdog keeps the broad "any new bytes" signal, which is the right one for a gate that kills. The scan now returns a named tuple rather than a fourth positional bool nobody could read, which is also how the throwaway ``_saw_progress`` binding at the call site goes away. Co-authored-by: Cursor <cursoragent@cursor.com>
``_pulse_after_variant`` inferred which variant it was reporting from the tail of ``results`` rather than from the index it was handed. A stop cause that ends the batch records the round it stopped and then a not-run row for every later variant, so the tail is the last variant in the grid and the terminal note for variant 1 of 3 reads ``label='c2', index=1, total=3``. The log line one frame away is right and the ledger is right; only the progress note -- the artefact this heartbeat exists to make honest, and the one a stall signal reads -- is wrong. Locate the row by index instead, in a helper that says why the tail is not it, and take the label from the grid entry where it cannot disagree. Extracting the note also takes it out of a ``run_grid`` that is already far past the length worth reading, and leaves ``_pulse_after_variant``'s signature alone so no call site has to change. Co-authored-by: Cursor <cursoragent@cursor.com>
…, not hangs The sink sleeps for an hour, so a teardown that waited on it instead of cancelling it never leaves the ``async with`` and never reaches an assertion. With no timeout plugin in this suite that blocks until the CI job is killed -- the failure mode the grace window under test was added to prevent, which the test for it should be the last place to reproduce. Run the step under ``asyncio.wait_for``: the regression now fails in ten seconds where it previously hung indefinitely. Co-authored-by: Cursor <cursoragent@cursor.com>
Narrowing the liveness callback to generation-progress markers left one writer still able to vouch for a wedged child: some vLLM builds print ``Avg generation throughput: 0.0 tokens/s`` on an idle engine, and an engine goes idle precisely when the client driving it wedges. The most likely production shape of the defect therefore survived the fix -- a server logging zeros suppresses the stall accusation its own client has earned. Read the value instead of the marker, reusing the parse the post-mortem throughput estimate already runs over the same two frameworks' lines: the third copy of that knowledge goes away, and a framework added to one parser can no longer drift from the other. A line whose rate cannot be read counts as no progress -- this evidence only ever suppresses an accusation, and one suppressed by mistake is invisible, where a missing one is visible and still answerable from the child's own redirected stderr. Co-authored-by: Cursor <cursoragent@cursor.com>
Every variant outcome reports a terminal note except one: a multi-node round whose server never came back recorded its row and left, so the row a stall signal reads stayed at ``started`` for the rest of the session while the variant was already over. Two behaviour-lock tests pinned that omission as though it were a rule, which is how it outlived the boundary the other thirteen paths share -- and unlike a reaped round, nothing moves the task afterwards to make the stale row harmless. Reach the boundary like every sibling does, so the note comes from ``_variant_progress_note`` and names the variant that ended rather than the tail of the batch, and the failed restart gets the same bounded robustness tick as every other variant boundary. The loop's 27 early exits were enumerated to confirm this was the only gap: the one remaining exit that reports nothing is the session-budget skip, which breaks before the variant is announced and so has no row to close. Co-authored-by: Cursor <cursoragent@cursor.com>
The withheld note rose to MEDIUM once the agent had been silent past severity_high_after_s, which is the wall-clock ceiling the previous commit set out to remove, one rung lower: MEDIUM routes to alert(medium), so the measured healthy runs it cited -- a 3941s warmup, a 3106s TraceLens pass -- alerted while reporting a unit every tick. Elapsed silence now grades only the accusation. A phase whose work keeps reporting stays on the observation tier however long it runs, and the tick after the reports stop accuses at full severity, which is what "bounded by evidence freshness" was supposed to mean. The withheld case gets its own symptom name so RCA can tell a healthy long phase from an agent that really went quiet, and the evidence records the freshness window that holds the accusation back. The ladder tier a withheld note must not reach is pinned by a test of its own. Co-authored-by: Cursor <cursoragent@cursor.com>
The shipped test inserted the quiet unit first, so the freshest note always arrived second and the branch that records the quiet end never ran: deleting it left the whole suite green. Which order the rows arrived in was also SQLite's choice, the running-task select having no ORDER BY, so the assertion rested on unspecified behaviour either way. Order the select by task_id and let the test choose which unit's note is folded in first, so both directions of the fold are covered by the same case. Co-authored-by: Cursor <cursoragent@cursor.com>
Every note re-read the whole history blob, appended to it and rewrote it inside a BEGIN IMMEDIATE on the connection every other writer serialises behind, with no cap. 720 notes -- 12 hours at the 60s heartbeat -- left a blob north of 100 KB and tens of MB of cumulative row rewrites, and the robustness probe re-parses that blob for every running task on every tick. The cost scaled with session length, which is what the heartbeat exists for. Retain the newest 120 notes, two hours of trail at that cadence and longer than the longest measured work unit. Transitions are never dropped: consumers read those positionally -- the last entry for a failure class, the newest queued -> cancelled for a policy denial -- so only progress notes are retired. Measured on this branch, 720 notes: blob 103 KB -> 17 KB, cumulative rewrites 35.6 MiB -> 10.9 MiB, and flat per note from there instead of growing. Co-authored-by: Cursor <cursoragent@cursor.com>
The client that overrides "no server process, so none was wanted" was found in a whole-host ps snapshot, so on a shared node a co-tenant's benchmark_serving vouched that this session's port should be answering, and an idle stretch came back as a HIGH alert on somebody else's traffic. The process probe now records each matched process's working directory, which is the anchor a session already has: the harness is launched with its cwd inside the session directory and its children inherit it. A client counts as this session's when its cwd is under that directory, or when it names a path there on its command line, for the launch paths that chdir elsewhere. With no session directory configured there is nothing to compare against and the check stays host-wide as before. Co-authored-by: Cursor <cursoragent@cursor.com>
The escalation knob was described as operator-configurable, but discover() reads a fixed list of deployment-shape variables and this is not one of them, so it is set in code like every other threshold on Config -- gpu_temp_warn_c, the disk and shm percentages, its own sibling agent_stall_timeout_s. Correct the claim rather than wire these two into discover(): none of the ~60 thresholds is environment-settable, and making the stall pair the exception would buy one deployment knob at the price of an env variable per threshold and a doc table that has to keep up. Where the boundary runs is now written down next to the thresholds and under the environment table. Co-authored-by: Cursor <cursoragent@cursor.com>
A benchmark client only overrides "no server process, so none was wanted" when it can be tied to this session, and the tie is the working directory the harness's whole subtree inherits. The baseline arm anchors Magpie to its own output dir for that reason; the grid runner defaulted to the system temp directory, so an explore / sweep / conc_sweep / integrate_patch client carried no anchor of its own and a server that died mid-variant read as the idle gap between two variants -- the one snapshot the vouching rule exists to catch. Grid variants are where a server most often dies mid-benchmark. Each pass now runs from output_root, the per-task workspace under the session, exactly as the baseline does. Nothing that reads a benchmark's results depended on that directory being /tmp: Magpie re-roots the server itself, and workspace selection scans the per-variant output dir while the leak harvest scans /workspace plus $INFERENCE_OPTIMIZER_LEAK_ROOTS -- never the cwd. A relative result_dir now resolves under the task workspace, which is where the baseline already resolves one and where the salvage path can find what it produced. The cwd override goes with it. No caller set it, and an override is the one knob that could let the anchor drift back out of the session. Co-authored-by: Cursor <cursoragent@cursor.com>
The cwd reading guarded the directory boundary; the command-line reading on the next line was a bare substring test. A co-tenant benchmarking out of <session>-retry -- a retry, a backup, or any sibling an operator names after ours -- contains this session's path, so it still vouched that this session's port should be answering. That is the false alarm the previous fix set out to remove, narrowed from host-wide to prefix-wide rather than eliminated, and it is reachable whenever the session directory is operator-supplied. Both readings now go through one helper that compares a path a component at a time, so the two cannot drift apart again, and the command line is read as tokens (plus the value of a key=value token, so --result-dir=<path> still counts) rather than searched for a substring, which is what makes a boundary applicable to it at all. The launch-path matrix now also holds the case that hid the missing grid anchor: a client with neither cwd nor command line under the session is indistinguishable from a co-tenant's and must not vouch. Co-authored-by: Cursor <cursoragent@cursor.com>
…boundary Co-authored-by: Cursor <cursoragent@cursor.com>
Co-authored-by: Cursor <cursoragent@cursor.com>
…ibility Co-authored-by: Cursor <cursoragent@cursor.com>
CodeQL read `await cancelled_task` inside pytest.raises as a statement with no effect, and the log assertions after a raise it did not model as unreachable. Catch CancelledError and ValueError explicitly so the control flow is the test. Co-authored-by: Cursor <cursoragent@cursor.com>
The previous try/except/else left an unreachable else, and a bare `except CancelledError: pass` is an empty handler. One helper now documents the success path, and the rollback-failure test goes back to pytest.raises with the log assertions inside that block. Co-authored-by: Cursor <cursoragent@cursor.com>
pytest.raises is not modelled as catching the raise, so the log assertions after it were unreachable. Catch ValueError by assignment instead, with no else-clause and no context manager for CodeQL to misread. Co-authored-by: Cursor <cursoragent@cursor.com>
xiaofei-zheng
pushed a commit
that referenced
this pull request
Aug 25, 2026
* fix(observability): let a long task say it is still working A composite action — an explore grid, a baseline pair, a profile and its roofline — is one task row that internally completes many units over hours. Between dispatch and return it emitted nothing durable, so a healthy 80-minute run and a wedged one left identical evidence. Field sessions read that as "orchestration silent 8097s" while the run was in fact progressing normally, and as a health probe demanding a restart of a server no phase had booted yet. Executors now report each unit through an ambient reporter the runner binds to the task, landing on the row as a heartbeat that moves ``updated_at``. Stall detection consults it and withholds the accusation while dispatched work is still moving; the server probe holds its fire when no server process is up. Emitters: per variant in the grid runner, after the baseline warmup round, and per roofline sub-step. Refs #1145, #1168 Co-authored-by: Cursor <cursoragent@cursor.com> * fix(observability): bound and attribute the progress suppression The heartbeat's consumer suppressed too much. A single running task that had reported recently returned no symptoms at all, before the per-agent loop ever ran: one busy explore grid vouched for the Coordinator, the critic and the kernel agent alike, and a genuinely hung agent went unreported for as long as anything on the box kept moving. Nothing was logged, so the near-miss left no trace an operator could read afterwards. Freshness also came from ``MAX(updated_at)`` over running rows, which a task merely entering ``running`` advances — the suppression could fire without a single heartbeat behind it. Progress notes now name their owning agent, the probe reads them out of the task history instead of trusting a column that moves for other reasons, and the judgement moved into the per-agent branch: only an agent's own work speaks for it. Work buys time, not immunity — past ``severity_high_after_s`` the accusation fires regardless of how busy the machine looks — and a withheld accusation is downgraded to LOW with its counter-evidence attached rather than discarded, so "we would have accused X, but its work reported Ns ago" is visible in the session. Attribution is as narrow as the data supports: the ``tasks`` table has no requester column and every row is dispatched by the Coordinator's orchestration loop, so a heartbeat is stamped for that agent alone. Refs #1145 Co-authored-by: Cursor <cursoragent@cursor.com> * fix(observability): report grid and baseline units before they block The completion reports only fire once a unit has landed, so the very failure this heartbeat targets - a first variant or a warmup round that hangs for tens of minutes - still produced no evidence at all. Announce each unit on entry, before the launch that can block, and keep the completion reports as they were. Entry reporting also covers the branches that reach neither the completion report nor a finally, so `_after_variant` is left alone rather than moved into a finally that would double-report. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(observability): route every roofline sub-step through one reporter Three of the five sub-step call sites were bare: the N26 re-analysis and both halves of the multi-node compute-bound re-profile ran silently, and each of them can take tens of minutes. Rather than paste the same report block at each site, funnel every call through a single closure next to the local imports, so a site added later cannot be the silent one. Each call site keeps its own try/except and fail-soft semantics unchanged; only the await is wrapped. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(observability): let the probe see a busy ray worker ``ray::IDLE`` is the name of a parked worker only; once a worker starts running a serving actor Ray renames it after the actor class, so ``ray::ServingActor`` matched no pattern and the process disappeared from the probe entirely. Presence still says nothing about busy-versus-hung — it only stops the probe reporting an empty machine while work is on it. Co-authored-by: Cursor <cursoragent@cursor.com> * feat(observability): let a long step prove it is alive from its own output A start-of-unit report covers the first 300 seconds and nothing after, so the 55-minute TraceLens analysis - one await, no units - still went stale halfway through. A timer would have "fixed" it by vouching for wedged processes, which is the exact failure the stall signal exists to catch. Drive the heartbeat from the child's own output instead: the subprocess reader already walks stdout/stderr line by line, so it now tallies what it reads, and a driver on the loop reports once per interval in which that tally moved. A silent child produces no heartbeat and stays accusable. The kernel-tool child is unbuffered so its lines arrive while it works rather than in eight-kilobyte lumps. Covers the TraceLens analysis (via every kernel tool subprocess) and the profile / baseline benchmark round. The Ray-managed round runs its child in a remote worker with no channel back for the callback, and is left on the ceiling from the first commit in this series. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(observability): stop the progress note from moving updated_at ``updated_at`` marks when a task entered ``running``, and three consumers measure elapsed runtime from it: the R6 lease watchdog turned into an inactivity timeout that a heartbeating task could never trip, the ``extend_lease`` remaining-budget math read time-since-last-note as time-already-spent and handed lanes and GPUs more than the budget allowed, and the Coordinator's own "Tasks in flight" line rendered an 80-minute task as seconds old — this PR's goal running backwards in the one surface the Coordinator reads. ``running()`` gets its least-recently-updated-first meaning back for free. The write had no reader left: the probe already reads freshness from the progress notes on ``history`` rather than from the column. The docstring argued for the behaviour and is rewritten to state the invariant instead, matching the one ``extend_lease`` documents a few lines below. Removing the bump restores the pre-PR reaper behaviour rather than changing it. It does not close the pre-existing gap between the catalogue's ``lease_ttl_sec`` and observed composite runtimes (roofline 2700s vs a 3106s TraceLens step, baseline 4200s vs a 3941s warmup round plus its measured round); that needs a TTL or extension policy decision and is reported on the PR rather than papered over here. Refs #1145 Co-authored-by: Cursor <cursoragent@cursor.com> * fix(observability): keep the variant hook's name so a sibling change still merges The hook grew a progress report, so "pulse" stopped describing all of it and it was renamed to match. But the name is a merge surface: #1171 adds a call site of its own, in the branch that records a variant reaped by the session budget as skipped rather than failed. Renaming here deletes the definition that call site resolves to, in a region #1171 never touches, so git reports no conflict and the merge lands a NameError on the reaped-variant path -- found only by lint or by running it. Keep the name and say what it does in the docstring instead. Costs an imprecise word; buys a merge that cannot break silently in either order. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(storage): roll back a transaction the caller was cancelled out of ``asyncio.CancelledError`` derives from ``BaseException``, so the ``except Exception`` guard around ``transaction()`` never saw it: a cancel landing on one of the ``to_thread`` hops after ``BEGIN IMMEDIATE`` had already run left the shared connection inside a transaction for the rest of the session, and every later registry write failed with "cannot start a transaction within a transaction". The heartbeat this branch adds is the first path that routinely cancels a coroutine mid-write, once per long subprocess step. Catch ``BaseException``, and roll back inline rather than on a worker thread — the exception being handled is usually this task's own cancellation, and an ``await`` there can be cancelled in turn. A rollback that itself fails is logged, never allowed to mask the original exception. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(observability): stop the heartbeat driver cooperatively Teardown used to hard-cancel the driver and swallow the result. Both halves were wrong. The cancel could land while the driver was inside a ``tasks`` row write, which is exactly the case that leaves the coordinator's connection wedged. The driver now polls a stop flag between ticks, so teardown asks it to finish the note it is in and only cancels if it overruns a bounded grace — a wedged sink costs the executor the grace window and nothing more. ``suppress(CancelledError)`` around the await could not tell the driver's own cancellation from the enclosing task being cancelled during teardown, so an outer cancel was absorbed and the step returned as though it had finished. Nothing catches ``CancelledError`` on that path any more. ``interval_s`` now resolves its default at call time so the timescale can be compressed under test. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(observability): report liveness from the three long paths still missing it ``_run_magpie`` is the longest single block in a session — up to a 7800s variant timeout against a 300s suppression window — and it ran the benchmark with no liveness callback, so a grid announced each variant on entry and then went dark. Same shape in the baseline's discarded multi-node warmup pass. Both now run under the same output-driven heartbeat the measured baseline round already uses. In the grid all three Magpie passes (auto-warmup, multi-node warmup, benchmark) go through one helper, so a pass added later cannot be the one that reports nothing. The Ray serving-lease branch is left as an explicit gap in both files: the round executes inside an actor in another process and only its final ``(rc, stdout, stderr)`` crosses back, so there is no local per-line event to hang a callback on. A Ray-backed round reports on entry and stays quiet until it returns. Co-authored-by: Cursor <cursoragent@cursor.com> * test(observability): bound how long a path may go unreported The suite asserted that notes are emitted, never that consecutive notes on a path stay closer together than the window a consumer waits before calling the owning agent silent — which is how a benchmark with no liveness callback survived a change whose whole purpose was to close that gap. ``ProgressCadence`` records each note against a compressed clock, so a test second stands for ten production minutes and the assertions still read in the numbers the window is configured with. Every long path now has a test that fails if its callback is dropped: the grid variant benchmark, the baseline round, the multi-node warmup pass and the kernel tool subprocess. Two existing tests could not fail for the reason they existed: ``test_run_subprocess_counts_the_lines_its_child_emits`` counted nothing, only that a callable had been passed, and now asserts one call per line the child emits; ``test_a_variant_reports_before_it_blocks`` covered the entry marker and nothing after it, so a cadence test now sits beside it. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(robustness): let the configured server patterns decide what a server is ``is_server`` was computed against the module constant while the match list came from ``config.server_process_patterns``, so a framework an operator added to the documented knob was matched as a process yet flagged as not-a-server — which silently disabled ``local_server_unreachable`` for exactly the deployment that configured it. The probe config now carries the server subset and the flag follows it. An empty process list was also doing double duty: "nothing is running" and "we could not find out". ``_sample_processes`` returns ``None`` for the second and ``SourceData`` carries ``local_processes_known``, so a missing or wedged ``ps`` no longer mutes an unrelated finding. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(kernel): default the child's buffering instead of dictating it Unbuffering a kernel tool keeps the heartbeat above it honest, but assigning PYTHONUNBUFFERED overrode an operator who had set it deliberately. The three launcher sites in multi_node/scripts already use setdefault; match them. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(robustness): keep a pathological JSON blob inside its own sub-probe _json_loads_or_none caught the decode errors but not RecursionError, so a deeply nested history blob written by another process aborted the entire probe tick instead of costing only the sub-probe that read it. Co-authored-by: Cursor <cursoragent@cursor.com> * docs(robustness): document the withheld agent_stall as its own row The symptom table described agent_stall as medium/high only; a stall whose dispatched work is still reporting is LOW and routes to send_message (observation), which the ladder test now locks in. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(robustness): bound stall suppression by evidence freshness, not the clock The 900s ceiling on a withheld agent_stall assumed a suppressed accusation should eventually fire anyway. Measured work units break that assumption: a single warmup runs 3941s and a TraceLens pass 3106s, so every healthy long phase crossed the ceiling and alerted exactly as if nothing had reported. Suppression now lasts as long as the counter-evidence stays fresh — the tick after the work stops reporting accuses at full severity. Long waits are still visible: the withheld note itself rises from LOW to MEDIUM past the threshold, which is now operator-configurable via agent_stall_high_after_s. Co-authored-by: Cursor <cursoragent@cursor.com> * test(observability): measure the cadence on a simulated clock, not the wall The four cadence assertions compressed a 300s suppression window into 0.5s of real time and then compared a real wall-clock gap against it, so every scheduling delay in the test was multiplied by 600 and charged to the path under test. The dominant term was not the heartbeat at all but the run-up before the first note -- fixture setup, imports, the fake magpie workspace -- which on two cores under eight-way contention grew to 753/888/1035 production seconds against a 300 budget. Advance the clock only when the simulated child does a chunk of the work it stands in for, so the timeline is a pure function of the lines emitted. The run-up and the tail collapse to what they represent, the steady-state spacing stays at the production ratio, and the assertion keeps failing when a liveness callback is dropped or the tick is widened past the window. Fake the kernel tool's child with the same helper the other three use: with a real subprocess there is nothing in the test that can advance the simulated clock. The real pump's line counting keeps its own coverage in test_run_subprocess_counts_the_lines_its_child_emits. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(robustness): let a benchmark client vouch that a server was wanted The process guard read "probed successfully, saw no server process" as "no server was supposed to be running", which is true of the gap between two variants and false of a server that crashed while its own load generator was still sending requests into the closed port. That second snapshot is exactly the one worth alerting on, and it was the one being suppressed: all targets unreachable plus one is_server=False benchmark_serving process produced no symptoms at all where base emitted a HIGH local_server_unreachable. Suppress only when the probe answered, no server process is up and no benchmark client is running. The client patterns are deliberately narrower than the harness patterns the process probe matches -- the outer Magpie/InferenceX harness is up across server launch and teardown too, so it stays evidence of nothing, which is what keeps the idle-stretch guard intact. Record benchmark_client_seen next to server_process_seen so the branch that decided is legible in the alert, and give the suppressed case its own row in the symptom table, which still promised that any target down always alerts. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(robustness): keep the in-flight unit a fresher sibling was hiding The snapshot kept only the newest heartbeat per agent, so with two units dispatched concurrently -- one reporting, one quiet for hours -- the quiet one left no trace at all and the withheld accusation rested entirely on the healthy sibling. Only ``running`` hinted that a second unit existed, and nothing read it. Keep both ends of the range and name the quiet one in the evidence. Not the oldest alone, and not "decline to withhold when some unit is quiet": a quiet unit is not an agent fault, and quiet units are expected today -- a Ray-backed baseline round has no local process to call a liveness callback from, so it reports on entry and then not again until it returns, which either of those readings would turn into an accusation on a healthy run. The stuck unit's own backstop is the lease watchdog. What was missing was visibility, not severity. Co-authored-by: Cursor <cursoragent@cursor.com> * test(robustness): cover the quiet fallback's admission that nothing looked Deleting local_processes_known=False from _QuietFallback left test_factory fully green, which made the one line standing between "nothing looked" and "nothing is running" the only unprotected decision in the module. Assert it through the consumer it defends -- the guard that suppresses local_server_unreachable when the process probe saw no server -- so the test says why the flag exists rather than restating the assignment. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(storage): keep the loop running while a cancelled write rolls back The rollback added for cancelled ``transaction()`` bodies took ``_sync_lock`` on the event-loop thread, and in the cancellation case it queued behind the very worker the cancel had abandoned: that worker is parked inside its own ``BEGIN IMMEDIATE``, holding the lock, for as long as another writer holds the database — up to ``PRAGMA busy_timeout = 30000``. With a 3s external writer, the whole orchestrator stopped for 2.55s, and it stopped during the shutdown or budget-exhaustion window that issued the cancel, so a stalled loop ate the cooperative-stop window it was supposed to be spending. Run the rollback on a worker thread under ``asyncio.shield``. The worker queues behind the abandoned one on ``_sync_lock``, which is the ordering the rollback already relied on, and the shield keeps it uncancellable — a bare ``await`` in a handler for this task's own cancellation is exactly how the connection stayed wedged in a transaction. Awaited, not fired and forgotten: ``_async_lock`` stays held until the connection is clean, so no later ``BEGIN IMMEDIATE`` can find a transaction still open. Anything that goes wrong with the rollback itself — a failing statement, a shut-down executor during teardown, a second cancel landing on the wait — is logged and never masks the caller's original exception. Co-authored-by: Cursor <cursoragent@cursor.com> * test(observability): pace the heartbeat tests on the driver, not the clock Four of these tests asserted a note count reached after sleeping a few tick intervals, which only holds if the loop was scheduled during that sleep. On the 2-vCPU CI runner, with two xdist workers and coverage tracing, it is not: under comparable oversubscription three of them failed in every run, because the driver had not yet taken the tick the assertion assumed. Wait for the driver's own notes instead. A note is proof the driver got that tick, so the wait is as long as the machine needs and the counts become exact rather than lower bounds. A driver that is supposed to stay silent — the one watching a child that went quiet, and the one whose step already returned — is paced by a second heartbeat kept deliberately noisy, so the window it would have reported in is intervals it actually got rather than intervals the test hoped had gone by, and the assertion becomes the ordered sequence of who spoke. Every wait is bounded so a driver that stops reporting fails in seconds. Also drop ``assert elapsed < 1.0`` from the wedged-sink test: a teardown that waited on the sink instead of cancelling it would still be inside the ``async with``, never reaching the assertion, so the measured interval was carrying no coverage that ``events == ["cancelled"]`` does not. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(storage): wait out the rollback a second cancel used to abandon ``asyncio.shield`` protects the rollback, not the wait on it. A cancel landing on that wait raised straight through the ``except BaseException`` written to keep the caller's exception, and ``transaction()`` then ran on to its ``raise`` and released ``_async_lock`` with the rollback still queued on ``_sync_lock`` behind the worker the first cancel abandoned -- fire and forget with the lock already gone, which is the shape this rollback was moved off the loop to avoid rather than to adopt. The next writer finds the connection inside a transaction nobody will close and every write in the session fails with "cannot start a transaction within a transaction". The same handler lost the cancellation outright. One cancel is enough: a ``record_progress`` body raises on its own -- a ``BEGIN IMMEDIATE`` past ``busy_timeout``, a ``history`` column that will not parse -- and the swallowed cancel left the caller with the body's exception, which ``report_progress`` drops. An action cancelled by the stop path then runs on as though nothing had happened while the dispatcher's ``gather`` waits for it. Keep the shielded future and resume the wait after every cancel, so the connection is always clean before ``_async_lock`` is released, then re-raise the cancel that arrived. Narrow the ``except`` to what a rollback can actually fail with -- a statement error, or an executor refusing work during teardown -- so control flow is no longer swallowed as though it were a database error. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(observability): report a step alive on its own output, not the server's log ``grew`` means "one of the resolved logs got longer", from any writer, and feeding it to the liveness callback made the heartbeat the bare timer ``heartbeat_while_output_flows`` documents itself as never being. A child that printed nothing for 3s was reported alive 5 times by a ``server.log`` an unrelated thread appended to. In a real round that writer is the inference server, which keeps logging while the benchmark client is wedged, and both vLLM and sglang write an access line per request -- including the health probe the robustness agent issues every standalone tick against the server it is monitoring. That closes a loop where the monitor's own probe manufactures the evidence suppressing its own stall accusation, and the wall-clock ceiling that used to backstop the case is gone. Report liveness on evidence about the round instead: a generation-progress marker, which says tokens were flowing whoever logged them, or growth in the benchmark body's own redirected stderr, which is output of this very child that never reaches its pipe. Keeping the second is what stops the narrowing from silencing a working round: the scriptable and bypass paths redirect the body's stderr to ``benchmark_stderr.log``, so for a whole round the pipe is empty and that file is all there is. The stall watchdog keeps the broad "any new bytes" signal, which is the right one for a gate that kills. The scan now returns a named tuple rather than a fourth positional bool nobody could read, which is also how the throwaway ``_saw_progress`` binding at the call site goes away. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(observability): name the variant that ran in its own progress note ``_pulse_after_variant`` inferred which variant it was reporting from the tail of ``results`` rather than from the index it was handed. A stop cause that ends the batch records the round it stopped and then a not-run row for every later variant, so the tail is the last variant in the grid and the terminal note for variant 1 of 3 reads ``label='c2', index=1, total=3``. The log line one frame away is right and the ledger is right; only the progress note -- the artefact this heartbeat exists to make honest, and the one a stall signal reads -- is wrong. Locate the row by index instead, in a helper that says why the tail is not it, and take the label from the grid entry where it cannot disagree. Extracting the note also takes it out of a ``run_grid`` that is already far past the length worth reading, and leaves ``_pulse_after_variant``'s signature alone so no call site has to change. Co-authored-by: Cursor <cursoragent@cursor.com> * test(observability): bound the wedged-sink step so a regression fails, not hangs The sink sleeps for an hour, so a teardown that waited on it instead of cancelling it never leaves the ``async with`` and never reaches an assertion. With no timeout plugin in this suite that blocks until the CI job is killed -- the failure mode the grace window under test was added to prevent, which the test for it should be the last place to reproduce. Run the step under ``asyncio.wait_for``: the regression now fails in ten seconds where it previously hung indefinitely. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(observability): take the rate, not the line, as proof of tokens Narrowing the liveness callback to generation-progress markers left one writer still able to vouch for a wedged child: some vLLM builds print ``Avg generation throughput: 0.0 tokens/s`` on an idle engine, and an engine goes idle precisely when the client driving it wedges. The most likely production shape of the defect therefore survived the fix -- a server logging zeros suppresses the stall accusation its own client has earned. Read the value instead of the marker, reusing the parse the post-mortem throughput estimate already runs over the same two frameworks' lines: the third copy of that knowledge goes away, and a framework added to one parser can no longer drift from the other. A line whose rate cannot be read counts as no progress -- this evidence only ever suppresses an accusation, and one suppressed by mistake is invisible, where a missing one is visible and still answerable from the child's own redirected stderr. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(observability): end the variant a failed remote restart abandoned Every variant outcome reports a terminal note except one: a multi-node round whose server never came back recorded its row and left, so the row a stall signal reads stayed at ``started`` for the rest of the session while the variant was already over. Two behaviour-lock tests pinned that omission as though it were a rule, which is how it outlived the boundary the other thirteen paths share -- and unlike a reaped round, nothing moves the task afterwards to make the stale row harmless. Reach the boundary like every sibling does, so the note comes from ``_variant_progress_note`` and names the variant that ended rather than the tail of the batch, and the failed restart gets the same bounded robustness tick as every other variant boundary. The loop's 27 early exits were enumerated to confirm this was the only gap: the one remaining exit that reports nothing is the session-budget skip, which breaks before the variant is announced and so has no row to close. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(robustness): let the evidence, not the wait, grade a withheld stall The withheld note rose to MEDIUM once the agent had been silent past severity_high_after_s, which is the wall-clock ceiling the previous commit set out to remove, one rung lower: MEDIUM routes to alert(medium), so the measured healthy runs it cited -- a 3941s warmup, a 3106s TraceLens pass -- alerted while reporting a unit every tick. Elapsed silence now grades only the accusation. A phase whose work keeps reporting stays on the observation tier however long it runs, and the tick after the reports stop accuses at full severity, which is what "bounded by evidence freshness" was supposed to mean. The withheld case gets its own symptom name so RCA can tell a healthy long phase from an agent that really went quiet, and the evidence records the freshness window that holds the accusation back. The ladder tier a withheld note must not reach is pinned by a test of its own. Co-authored-by: Cursor <cursoragent@cursor.com> * test(robustness): visit the progress rows in both orders The shipped test inserted the quiet unit first, so the freshest note always arrived second and the branch that records the quiet end never ran: deleting it left the whole suite green. Which order the rows arrived in was also SQLite's choice, the running-task select having no ORDER BY, so the assertion rested on unspecified behaviour either way. Order the select by task_id and let the test choose which unit's note is folded in first, so both directions of the fold are covered by the same case. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(state): bound the progress notes a task's history retains Every note re-read the whole history blob, appended to it and rewrote it inside a BEGIN IMMEDIATE on the connection every other writer serialises behind, with no cap. 720 notes -- 12 hours at the 60s heartbeat -- left a blob north of 100 KB and tens of MB of cumulative row rewrites, and the robustness probe re-parses that blob for every running task on every tick. The cost scaled with session length, which is what the heartbeat exists for. Retain the newest 120 notes, two hours of trail at that cadence and longer than the longest measured work unit. Transitions are never dropped: consumers read those positionally -- the last entry for a failure class, the newest queued -> cancelled for a policy denial -- so only progress notes are retired. Measured on this branch, 720 notes: blob 103 KB -> 17 KB, cumulative rewrites 35.6 MiB -> 10.9 MiB, and flat per note from there instead of growing. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(robustness): tie a vouching benchmark client to this session The client that overrides "no server process, so none was wanted" was found in a whole-host ps snapshot, so on a shared node a co-tenant's benchmark_serving vouched that this session's port should be answering, and an idle stretch came back as a HIGH alert on somebody else's traffic. The process probe now records each matched process's working directory, which is the anchor a session already has: the harness is launched with its cwd inside the session directory and its children inherit it. A client counts as this session's when its cwd is under that directory, or when it names a path there on its command line, for the launch paths that chdir elsewhere. With no session directory configured there is nothing to compare against and the check stays host-wide as before. Co-authored-by: Cursor <cursoragent@cursor.com> * docs(robustness): say where the stall thresholds are actually set The escalation knob was described as operator-configurable, but discover() reads a fixed list of deployment-shape variables and this is not one of them, so it is set in code like every other threshold on Config -- gpu_temp_warn_c, the disk and shm percentages, its own sibling agent_stall_timeout_s. Correct the claim rather than wire these two into discover(): none of the ~60 thresholds is environment-settable, and making the stall pair the exception would buy one deployment knob at the price of an env variable per threshold and a doc table that has to keep up. Where the boundary runs is now written down next to the thresholds and under the environment table. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(robustness): run a grid variant inside the session that owns it A benchmark client only overrides "no server process, so none was wanted" when it can be tied to this session, and the tie is the working directory the harness's whole subtree inherits. The baseline arm anchors Magpie to its own output dir for that reason; the grid runner defaulted to the system temp directory, so an explore / sweep / conc_sweep / integrate_patch client carried no anchor of its own and a server that died mid-variant read as the idle gap between two variants -- the one snapshot the vouching rule exists to catch. Grid variants are where a server most often dies mid-benchmark. Each pass now runs from output_root, the per-task workspace under the session, exactly as the baseline does. Nothing that reads a benchmark's results depended on that directory being /tmp: Magpie re-roots the server itself, and workspace selection scans the per-variant output dir while the leak harvest scans /workspace plus $INFERENCE_OPTIMIZER_LEAK_ROOTS -- never the cwd. A relative result_dir now resolves under the task workspace, which is where the baseline already resolves one and where the salvage path can find what it produced. The cwd override goes with it. No caller set it, and an override is the one knob that could let the anchor drift back out of the session. Co-authored-by: Cursor <cursoragent@cursor.com> * fix(robustness): tie a client to the session by directory, not by prefix The cwd reading guarded the directory boundary; the command-line reading on the next line was a bare substring test. A co-tenant benchmarking out of <session>-retry -- a retry, a backup, or any sibling an operator names after ours -- contains this session's path, so it still vouched that this session's port should be answering. That is the false alarm the previous fix set out to remove, narrowed from host-wide to prefix-wide rather than eliminated, and it is reachable whenever the session directory is operator-supplied. Both readings now go through one helper that compares a path a component at a time, so the two cannot drift apart again, and the command line is read as tokens (plus the value of a key=value token, so --result-dir=<path> still counts) rather than searched for a substring, which is what makes a boundary applicable to it at all. The launch-path matrix now also holds the case that hid the missing grid anchor: a client with neither cwd nor command line under the session is indistinguishable from a co-tenant's and must not vouch. Co-authored-by: Cursor <cursoragent@cursor.com> * test(robustness): hold both spellings of --result-dir to the session boundary Co-authored-by: Cursor <cursoragent@cursor.com> * docs(grid): say why the session-rooted cwd is created up front Co-authored-by: Cursor <cursoragent@cursor.com> * Make the heartbeat cancel tests name the exception they wait for CodeQL read `await cancelled_task` inside pytest.raises as a statement with no effect, and the log assertions after a raise it did not model as unreachable. Catch CancelledError and ValueError explicitly so the control flow is the test. Co-authored-by: Cursor <cursoragent@cursor.com> * Satisfy CodeQL on the heartbeat cancel tests without empty excepts The previous try/except/else left an unreachable else, and a bare `except CancelledError: pass` is an empty handler. One helper now documents the success path, and the rollback-failure test goes back to pytest.raises with the log assertions inside that block. Co-authored-by: Cursor <cursoragent@cursor.com> * Stop CodeQL treating the rollback-failure asserts as dead pytest.raises is not modelled as catching the raise, so the log assertions after it were unreachable. Catch ValueError by assignment instead, with no else-clause and no context manager for CodeQL to misread. Co-authored-by: Cursor <cursoragent@cursor.com> --------- Co-authored-by: Cursor <cursoragent@cursor.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
4 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Refs #1145, #1168.
A composite action -- an explore grid, a double-round baseline, a profile plus a
roofline -- is a single task row in the database, yet inside it a dozen units run
one after another for hours. Between dispatch and return it writes nothing
durable, so an analysis that has been working for eighty minutes and one that
hung in its first minute leave identical evidence behind.
In the field session that blind spot surfaced as two false accusations:
orchestration silent 8097s-- 8097s is exactly the length of PRELUDE, astretch with no LLM turn to take. The silence was the design, not a fault
(Improve visibility on long phases #1145).
:8888/healthconnection-refused alert recommending an inference serverrestart, raised in a phase where nothing had started a server yet.
Separately, everything EXPLORE learns about a batch of variants is released in
one lump when the task reaches a terminal state, so a running grid shows no
progress at all (#1168).
Producing a heartbeat
orchestrator/trace/task_progress.pypublishes an ambient reporter through aContextVar.SubAgentRunnerbinds a sink that writes back to the task row itis executing, so code deep in an executor calls
report_progress(...)without acallback threaded through the call chain -- the emission points sit eight frames
down and there are a dozen entry points. The scope propagates across
asyncio.create_taskandto_thread, and concurrent tasks do not cross intoeach other. Outside a scope -- unit tests, direct CLI calls -- it is a no-op.
Recording it
TaskRegistry.record_progress()appends a timestamped progress note to thetask's
history. Freshness is read from those notes, not fromupdated_at:that column marks when the task entered
running, and the R6 lease watchdog,extend_leaseremaining-budget math and the "Tasks in flight" projection allmeasure elapsed runtime from it -- moving it would turn a cumulative budget into
an inactivity timeout.
local_probetherefore scans running tasks for thenewest attributed progress note when answering "when did something last happen".
Emission points
Every variant boundary in the grid runner (reusing the existing
variant-boundary hook), the end of each baseline warmup round, and each roofline
sub-step -- reported on entry, because the attempt that never returns is
precisely the case a heartbeat has to be able to show. Subprocess-backed work
also emits on streamed stdout (
PYTHONUNBUFFERED=1on the kernel tool path) soTraceLens and similar long captures do not stay silent until exit.
Consumers
local_probegains alocal_task_progresssource.still reporting units on time, and when it does accuse, the in-flight evidence
goes into the alert.
local_server_unreachableonly when the processprobe succeeded and saw neither a server process nor a benchmark client tied
to this session -- a refused port with nothing behind it is the expected
reading during teardown or pre-boot. If a load generator for this session is
still running, or the process probe could not answer, the alert still fires.
Process patterns are split into server and non-server groups, and samples carry
is_server.Scope with respect to #1168
A running EXPLORE now shows each variant's name, index, state and throughput on
the task row and in the logs. Journal rows still land at the task's terminal
state: KEEP / REVERT / dedup / gain are decided in the comparison step after the
whole grid finishes, and moving journal rows to variant granularity means moving
that decision logic with them. That is a separate change, not one to fold in
here.
Test plan
test_task_progress_heartbeat.py(new): a heartbeat lands on its own row,updated_atstays at the running-entry timestamp while progress notesaccumulate, a reaped row or a throwing sink never takes down the work
being observed, the scope does not leak, and the log counter format.
test_grid_runner_behavior_lock.py: per-variant reporting, failedvariants included.
test_stall.py: the accusation is suppressed while work reports, raisedwhen the work goes quiet too, and falls back to the original rule for a
running task that has never reported.
test_signals_local_health.py: a refused connection with no serverprocess is not a fault; the existing cases gain the "a server process
exists" precondition.
test_sources_local_probe.py: the probe takes the most recent runningheartbeat, returns empty with nothing running, and degrades to "no
evidence" rather than raising on a heterogeneous schema.
Made with Cursor