Skip to content

wait: print a failed task's output - #2686

Merged
berendt merged 1 commit into
mainfrom
fix/wait-print-failed-task-output
Sep 10, 2026
Merged

wait: print a failed task's output#2686
berendt merged 1 commit into
mainfrom
fix/wait-print-failed-task-output

Conversation

@ideaship

Copy link
Copy Markdown
Contributor

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 wrapping shell task's stderr was empty and its msg was non-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 use result.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 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. A failed role's full output is still sitting there; it is simply never looked at.

What this does

tail_task_output performs the same non-destructive xrevrange read 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, because xrevrange answers newest-first and a play printed backwards is no diagnosis at all. peek_task_output could not be reused as-is: it takes count=1 and keeps only the last line. Draining would have been wrong — fetch_task_output xdels what it reads and would steal the output from --live and from the operator.

_report_failure_output calls it from the FAILURE/REVOKED branch, gated on --output so the flag governs the payload exactly as it does for SUCCESS, and the healthy path reads no Redis at all.

Only stdout records count. finish_task_output appends an rc and an action: quit record 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 — 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 line look like it produced two, 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. 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.

Failure modes kept cosmetic

A read failure must not turn a reporting feature into a new fault: 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. One warning, then the peek disables itself for the run — the same contract _report_stall uses. 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

  • 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.
  • This does not cover a task that never completes. Such a task never reaches the FAILURE branch, so the hang shape still needs its own reporting from the STARTED path. The two are complementary, not one fix.
  • The REVOKED state 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, flake8 clean; mypy unchanged from main (21 pre-existing missing-stub errors before and after).

The tests carry fixtures derived from the producer (_stdout() / _control_pair() mirroring push_task_output / finish_task_output) rather than invented record shapes — an earlier revision of this branch used {b"content": ...} with no type key, which is a record the producer never writes, and every test passed over a stream that cannot exist.

🤖 Generated with Claude Code

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>
@ideaship
ideaship marked this pull request as ready for review September 10, 2026 05:16

@sourcery-ai sourcery-ai Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hey - I've reviewed your changes and they look great!

Sourcery assessment

Approved.


Sourcery is free for open source - if you like our reviews please consider sharing them ✨

@ideaship ideaship self-assigned this Sep 10, 2026
@berendt
berendt merged commit 5659a5b into main Sep 10, 2026
4 checks passed
@berendt
berendt deleted the fix/wait-print-failed-task-output branch September 10, 2026 07:21
@github-project-automation github-project-automation Bot moved this from New to Done in Human Board Sep 10, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: Done

Development

Successfully merging this pull request may close these issues.

3 participants