[Bug]: test_run_timeout_during_metrics_drain_interrupts is flaky in CI: timeout hits service startup #553

Bug Description

test_run_timeout_during_metrics_drain_interrupts fails in about 1 in 6 CI test jobs with AssertionError: aggregator must still write a final snapshot. The docstring describes a fast session, after which the 2.5 s run_timeout_s watchdog fires while the aggregator drains a large tokenization backlog. In every CI failure, the watchdog instead fires before the services are ready. The metrics aggregator gets SIGTERM during its own startup and exits without writing final_snapshot.json.

Why it fails

1. confirmed: The 2.5 s budget includes setup and service startup.

   • run_benchmark sets the deadline before setup_benchmark runs (execute.py#L1294-L1300).
   • A comment in the sibling test says the budget "must comfortably exceed service + worker startup" (test_run_timeout.py#L120-L124).
   • This test sets 2.5 s (L162).

2. confirmed (CI logs): Aggregator startup takes up almost all of the budget. The watchdog fires 2.32–2.40 s after the aggregator is spawned. Two slow steps run before the aggregator installs its SIGTERM handler (__main__.py#L331-L339) and sends its ready signal (L353-L356):

   Step	Code	On the runner
   Load the tokenizer	token_metrics.py#L274	Done 1.21–1.40 s after spawn (all 30 failures)
   Spawn and warm up a spawn-context shard process	token_metrics.py#L321-L398	Not finished when the watchdog fired in 29/30. In the 30th it logged setup 1.2s and finished 2.40 s after spawn.

3. confirmed: This is the abort path when the watchdog fires before a session exists.

   • RunWatchdog._fire cancels the orchestration task (watchdog.py#L155-L162).
   • launch()'s except Exception does not catch the CancelledError (launcher.py#L127-L151).
   • MetricsPipeline.start catches it as BaseException and runs terminate_all (pipeline.py#L371-L377, launcher.py#L153-L180), which sends SIGTERM to both services.
   • The event logger already has a handler and logs the signal. The aggregator has not installed its handler yet, so the default SIGTERM action kills it. In 29/30 failures it was still in shard setup at that point. In all 30, fixture teardown starts 0.21–0.28 s after the watchdog fires, well before the 5 s SIGKILL escalation.
   • _run_benchmark_async then raises ExecutionError("Run timeout … aborted before a report could be produced") (execute.py#L1045-L1049). That message satisfies pytest.raises, so the test continues to the snapshot assertion and fails there.

4. confirmed (CI logs):

   • All 30 failures lack All 2 services ready and metrics aggregator received SIGTERM.
   • 29 of 30 also lack BatchTokenizer: N shards and the aggregator's ev_pub subscription.
   • In the 30th failure, shard setup finished at 51,115, the aggregator subscribed at 51,116, and the watchdog fired at 51,117.
   • The session never started, so the 100 large prompts (test_helpers.py#L37-L43) were loaded but never sent.

5. confirmed (code): The scenario in the docstring cannot pass on main.

   • final_snapshot.json gets state == "interrupted" in only two ways. One is the session's INTERRUPTED marker before ENDED, which session.run publishes in its finally only if stop() already ran (session.py#L486-L492). The other is the aggregator's SIGTERM handler (__main__.py#L50-L111).
   • If the watchdog fires after a normal ENDED, neither happens. The parent waits interrupted_teardown_grace_s (30 s) and then sends SIGKILL (pipeline.py#L409-L425), so the snapshot is either complete or missing.
   • A pass therefore needs the abort to land after the aggregator installs its SIGTERM handler and before a normal ENDED.

6. suspected: Whether the test passes depends on runner load, which the test does not control.

   • Passing runs capture no output, so they have no timeline.
   • Time between consecutive result lines is 3.21–3.32 s for passes and 2.82–2.96 s for failures.
   • The failure rate rose from September to October. The cause is unknown.

7. confirmed (local macOS only): After the aggregator is killed during shard setup, its shard worker and the multiprocessing resource tracker stay alive, reparented to PID 1.

Steps to Reproduce

1. In CI, run the test job (uv run pytest -xv -m "not slow and not performance" --cov=src …). Failing examples:

   Date	Trigger	Run / job
   2026-10-26	push to main (4b385eb)	40344725100
   2026-10-27	PR feat(provenance): resolve source git SHA via a validated multi-channel chain #491	40433891117
   2026-10-28	PRs Add validation module to serve as backend for submission checker and policies enforcement #544, fix: reject calls without declared tools #547, fix: save datasets selected by run mode #548, fix: decode SGLang streaming responses #550	40705033572, 40721937559, 40721994833, 40722576277
   2026-09-29	push to main (0543413)	36644804123 (shard setup finished 2 ms before the watchdog fired)

   Green runs for comparison: 40722319572, 40344804818.

2. On Linux, run uv run pytest -xvs "tests/integration/commands/test_run_timeout.py::test_run_timeout_during_metrics_drain_interrupts". Given the mechanism above, it should fail whenever the aggregator has not installed its SIGTERM handler by the time the watchdog fires. This has not been tried on Linux outside CI.

3. On macOS the test cannot run unmodified, because pin_loadgen() requires Linux. With enable_cpu_affinity=False added to _make_config's BenchmarkConfig, it failed 3 of 3 times locally with the same signature.

Environment

Relevant Logs

Excerpt from run 40344725100. Runner timestamps are removed and long lines are trimmed.

15:03:32,101 - ...cpu_affinity - INFO - CPU affinity: 2 physical cores across 1 NUMA nodes, requesting 5 for loadgen, 1 workers
15:03:32,271 - ...benchmark.execute - INFO - Loaded 100 samples
15:03:32,275 - ...services.launcher - INFO - Launching service: ...metrics_aggregator (id=0)
15:03:32,275 - ...services.launcher - INFO - Launching service: ...event_logger (id=1)
15:03:32,609 - ...zmq.pubsub - INFO - Subscriber connected to ipc:///dev/shm/zmq_0ocxk4jx/ev_pub_a037df9b
15:03:33,524 - ...metrics_aggregator.token_metrics - ERROR - Failed to compute chat-template baseline for .../tokenizers/char; ...
15:03:34,602 - ...benchmark.watchdog - ERROR - Run timeout reached; aborting run
15:03:34,603 - __main__ - WARNING - event logger received SIGTERM — flushing writers
.../tokenizers/char (Streaming: False):   0%|          | 0/100 [00:02<?, ?it/s]
E       AssertionError: aggregator must still write a final snapshot
!!!!!!!!!!!!!!!!!!!!!!!!!! stopping after 1 failures !!!!!!!!!!!!!!!!!!!!!!!!!!!
==== 1 failed, 33 passed, 157 deselected, 16 warnings in 278.93s (0:04:38) =====

# job 109665184403 (main push, 2026-09-29)
23:26:48,716 - ...services.launcher - INFO - Launching service: ...metrics_aggregator (id=0)
23:26:51,115 - ...token_metrics - INFO - BatchTokenizer: 1 shards across 2 CPUs (setup 1.2s)
23:26:51,116 - ...zmq.pubsub - INFO - Subscriber connected to ipc:///dev/shm/zmq_so7uvv_n/ev_pub_f9c7d40f
23:26:51,117 - ...benchmark.watchdog - ERROR - Run timeout reached; aborting run

The chat-template ERROR is expected, because the char tokenizer has no chat template. Here it only marks the end of tokenizer load. All 2 services ready (launcher.py#L128) is missing from every failure.

Impact

• Unit tests are skipped. CI runs with -x and collects tests/integration before tests/unit. This one failure ends the job early: the main-push run stopped after 279 s with 1 failed, 33 passed. A green job reports 2684 passed, 8 skipped. About 2,650 tests never run until someone re-runs the job, and about 2,570 of them are unit tests.

• Frequency, 2026-09-01 to 10-30: this test failed in 30 of the 191 test jobs that reached it (16%).

  Period	Failed / reached
  September	18 / 145
  October	12 / 46
  Pushes to main	7 / 26

• Recent failures:

  • PRs feat: block hardcoded secrets with gitleaks at commit, push, and CI #541 (Oct 21), feat(provenance): resolve source git SHA via a validated multi-channel chain #491 (Oct 27), and Add validation module to serve as backend for submission checker and policies enforcement #544, fix: reject calls without declared tools #547, fix: save datasets selected by run mode #548, fix: decode SGLang streaming responses #550 (Oct 28)
  • Pushes to main on Oct 22 and Oct 26

Possible fixes

1. Re-budget the test (test-only change).
   • Set run_timeout_s well above service and worker startup, as test_run_timeout_produces_interrupted_report does (6.0 s with a ~120 s workload, test_run_timeout.py#L119-L126).
   • Make the session long enough that the watchdog always fires mid-session.
   • Re-document the test as "abort mid-session with a large tokenization backlog", because point 5 shows the drain case cannot pass.
   • Only test_run_timeout.py#L152-L163 changes.
2. Make the documented drain scenario real, if that is the intended contract.
   • When an abort lands during the drain, have drain_and_build_report send SIGTERM (terminate_all) before it falls back to kill_all (pipeline.py#L415-L425). The aggregator's handler would then write an INTERRUPTED snapshot (__main__.py#L50-L111).
   • The test would also need a deterministic trigger, such as aborting when the aggregator reaches DRAINING, instead of a wall-clock deadline that includes startup.
3. Close the aggregator's pre-handler SIGTERM window.
   • Install a SIGTERM handler before tokenizer and shard setup (__main__.py#L253-L270, token_metrics.py#L360-L382). A SIGTERM during startup would then exit cleanly and terminate the shard workers, which would also avoid the orphaned worker in point 7.
   • This only makes this test pass if the handler also writes an INTERRUPTED snapshot. That conflicts with the sibling test's comment that a fire before the session exists leaves no mid-run artifacts (test_run_timeout.py#L120-L124), so it needs a design decision.