Repository navigation
Conversation
The test gave the forked trigger runner a fixed budget of thirty _service_subprocess(0.1) calls before asserting on the status log lines. _service_subprocess returns as soon as any I/O arrives, so on a loaded CI runner that budget can be spent before the runner process has reached its status log, which made the test fail intermittently on unrelated PRs. Poll until both lines have arrived, the same way test_trigger_logger_fd_closed_when_removed already does, and always kill the supervisor even when the assertion fails.
Eason09053360
left a comment
Eason09053360
left a comment
There was a problem hiding this comment.
I am not sure which are suitable here.
I found #72919 proposed the same fix on Sep 11 (poll up to 300 iterations with an early break, and kill() in finally). It was closed by the one-time open PR limit sweep, not after a review. Its description might goes a bit further on the root cause: the test patches time.monotonic with itertools.count(step=60), the runner is started with os.fork() and inherits that patch, and its "async thread was blocked" watchdog then logs nonstop ahead of the status lines. It also links five more failing runs.
Didn't notice this one, thanks for pointing out! |
| (FileDeleteTrigger("/tmp/foo.txt", poke_interval=1), 1, 0), | ||
| ], | ||
| ) | ||
| @patch("time.monotonic", side_effect=itertools.count(start=1, step=60)) |
There was a problem hiding this comment.
If watchdog lines are the only real problem, and status lines are the ones we want, cant we just put a very large threshold, as watchdog logs only when time_elapsed > blocked_main_thread_warning_threshold?
| @conf_vars({("triggerer", "blocked_main_thread_warning_threshold"): "1e12"}) | |
| @patch("time.monotonic", side_effect=itertools.count(start=1, step=60)) |
That would stop the flood at the source
There was a problem hiding this comment.
Thanks for the suggestion. I checked it against the two failure messages we see on CI, and the threshold would only fix one of them.
assert '0 triggers currently running' in ''(https://github.com/apache/airflow/actions/runs/34639425288/job/103404354117): stdout is still empty at the 30th call because the runner has not started logging yet. The watchdog has not logged anything at that point either, so a higher threshold does not help here.- stdout that only has "blocked for 300.00 seconds" lines (https://github.com/apache/airflow/actions/runs/33582219324/job/100101874765): the threshold would help here, because the watchdog lines would no longer sit ahead of the status lines.
The threshold would make the logs quieter, but it would not change whether the test passes. I'd prefer to keep this PR as it is.
4 participants
related: #73397
This PR fixes the flaky test test_trigger_log: the loop now breaks as soon as both status lines arrive, and the upper bound is raised to 300 attempts (30 seconds) so a slow CI runner has enough headroom.
AI Summary
`test_trigger_log` gave the forked trigger runner a fixed budget of thirty `_service_subprocess(0.1)` calls before asserting on the "triggers currently running" / "watchers currently running" log lines. `_service_subprocess` returns as soon as any I/O arrives, so on a loaded CI runner that budget can be spent before the runner process has reached its status log. Example failure on an unrelated PR: https://github.com/apache/airflow/actions/runs/36232920075/job/108381612308This polls until both lines have arrived (up to 300 iterations), mirroring the approach already used by
test_trigger_logger_fd_closed_when_removed, and moves the supervisorkill()into afinallyblock so a failing assertion no longer leaks the runner process.Follow-up to #73397, which fixed the same class of flakiness in
test_trigger_lifecycle.Verified locally:
test_trigger_logpasses on repeated runs;prek run --from-ref upstream/main --stage pre-commitpasses.Was generative AI tooling used to co-author this PR?
Generated-by: Claude Code (Fable 5.1) following the guidelines