wait: print a failed task's output - #2686
Merged
Merged
Conversation
A task that ends in FAILURE prints its state line and nothing else, so a failed role is exactly as opaque as a hung one. That is how the 2026-09-10 midnight testbed runs came out undiagnosable: `osism apply nutshell` aborted at keystone, five roles reached FAILURE, and neither the job log nor job-output.json recorded a single line of why -- no play, no recap, no `fatal:`. The FAILURE branch cannot use `result.get()`: Celery re-raises the task's exception from it, which would replace the exit code with a traceback. That is why the branch has had no output since #2630 added it to fix `rc` staying 0. But the result backend is not the only copy of the output. The producer pushes every line to a Redis stream keyed by task id as Ansible emits it, and on the collection path nothing ever drains it -- `_handle_collection` calls `apply_async()` and returns -- so a failed role's full output is still there, and simply never looked at. Read it. `tail_task_output` is the same non-destructive `xrevrange` read `peek_task_output` performs for stall reporting, widened from the newest line to the last `FAILED_TASK_OUTPUT_LINES` and reversed back into emit order, because `xrevrange` answers newest first and a play printed backwards is no diagnosis at all. `peek_task_output` itself could not be reused: it takes `count=1` and keeps only the last line. Draining would have been wrong -- `fetch_task_output` `xdel`s what it reads and would steal the output from `--live` and from the operator. Only `stdout` records count. A stream also carries the `rc` and `action: quit` records `finish_task_output` appends, and it appends them before `run_ansible_in_environment` raises `AnsibleFailure`, so every failed play's stream ends with two records that are not output. `peek_task_output` can ignore them because it only ever reads a task still in flight, which is before they exist; this helper reads after completion, which is exactly when they do. Taken as output they would append a bare rc and `quit` to the tail, spend two slots of the line budget, and make a role that failed before writing a single line look like it produced two lines -- losing the one distinction the empty-stream case exists to draw. So the read allowlists `stdout`, over-reads by `STREAM_CONTROL_RECORDS` so filtering does not shorten the tail, and reports counts in `stdout` records rather than stream records. Every Celery task calls `run_ansible_in_environment` at most once, so there is at most one such pair and it is always at the end of the stream, which makes the subtraction exact rather than an estimate. Like `peek_task_output`, the helper derives everything the caller needs from the reply -- the line count and how much of it the tail omits -- rather than returning raw values for the caller to compute on. That keeps every computation over Redis data inside whatever guard wraps the call, so a reply that reads fine but does not behave like an integer cannot raise past it, and `_report_failure_output` needs no guard wider than the one `_report_stall` already uses. Gated on `--output`, so the flag governs the payload exactly as it does for SUCCESS, and the healthy path reads no Redis at all. A read failure stays cosmetic: the non-`--live` path never needed Redis, so it must not become a hard dependency, and a task that has already failed cleanly with rc 1 must not acquire a traceback on top. The empty-stream case is reported as such rather than silently printing nothing; it distinguishes a role that died mid-play from one that died before its first line. The 50-line cap keeps a nutshell run legible where several roles can fail at once, at the price of truncating a long play; the header says how many earlier lines it left out. Left for later: the same treatment for a task that never completes at all, which never reaches this branch and needs the stall path to report instead (ci/nutshell-task-silent-hang). Assisted-by: Claude:claude-opus-5 Signed-off-by: Roger Luethi <luethi@osism.tech>
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
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.
A task that ends in FAILURE prints its state line and nothing else, so a failed role is exactly as opaque as a hung one.
That is how the 2026-09-10 midnight testbed runs came out undiagnosable.
osism apply nutshellaborted at keystone, five roles reached FAILURE, and neither the job log norjob-output.jsonrecorded a single line of why — no play, no recap, nofatal:. The wrapping shell task's stderr was empty and itsmsgwasnon-zero return code. Which role failed had to be reconstructed by dispatch accounting (the roles never scheduled are the failed one's subtree).Why the branch is silent today
osism wait's FAILURE branch cannot useresult.get()— Celery re-raises the task's exception from it, which would replace the exit code with a traceback. That is deliberate, and it is why the branch has printed nothing since it was added to fixrcstaying 0:But the result backend is not the only copy of the output. The producer pushes every line to a Redis stream keyed by task id as Ansible emits it, and on the collection path nothing ever drains it —
_handle_collectioncallsapply_async()and returns. A failed role's full output is still sitting there; it is simply never looked at.What this does
tail_task_outputperforms the same non-destructivexrevrangeread that stall reporting already relies on:widened from the newest line to the last
FAILED_TASK_OUTPUT_LINES(50) and reversed back into emit order, becausexrevrangeanswers newest-first and a play printed backwards is no diagnosis at all.peek_task_outputcould not be reused as-is: it takescount=1and keeps only the last line. Draining would have been wrong —fetch_task_outputxdels what it reads and would steal the output from--liveand from the operator._report_failure_outputcalls it from the FAILURE/REVOKED branch, gated on--outputso the flag governs the payload exactly as it does for SUCCESS, and the healthy path reads no Redis at all.Only
stdoutrecords count.finish_task_outputappends anrcand anaction: quitrecord beforerun_ansible_in_environmentraisesAnsibleFailure, so every failed play's stream ends with two records that are not output.peek_task_outputcan ignore them because it only ever reads a task still in flight — before they exist; this helper reads after completion, which is exactly when they do. Taken as output they would append a bare rc andquitto the tail, spend two slots of the line budget, and make a role that failed before writing a line look like it produced two, losing the one distinction the empty-stream case exists to draw. So the read allowlistsstdout, over-reads bySTREAM_CONTROL_RECORDSso filtering does not shorten the tail, and reports counts in stdout records. Every Celery task callsrun_ansible_in_environmentat most once, so there is at most one such pair and it is always at the end of the stream — which makes the subtraction exact rather than an estimate.Failure modes kept cosmetic
A read failure must not turn a reporting feature into a new fault: the non-
--livepath never needed Redis, so it must not become a hard dependency, and a task that has already failed cleanly with rc 1 must not acquire a traceback on top. One warning, then the peek disables itself for the run — the same contract_report_stalluses. Everything computed from the reply is derived inside the helper, so a reply that reads fine but does not behave like an integer cannot raise past the guard.The empty-stream case is reported explicitly rather than silently printing nothing; it separates a role that died mid-play from one that died before its first line.
Limitations
STARTEDpath. The two are complementary, not one fix.REVOKEDstate shares the branch and therefore the behaviour, though it does not occur anywhere in the CI archive I checked.Testing
10 new unit tests in
tests/unit/commands/test_wait.py, each watched failing first. Full suite 3291 passed / 3 xfailed;black,flake8clean;mypyunchanged frommain(21 pre-existing missing-stub errors before and after).The tests carry fixtures derived from the producer (
_stdout()/_control_pair()mirroringpush_task_output/finish_task_output) rather than invented record shapes — an earlier revision of this branch used{b"content": ...}with notypekey, which is a record the producer never writes, and every test passed over a stream that cannot exist.🤖 Generated with Claude Code