feat(wait): report what a stalled task last did

[ideaship]

Problem

A task dispatched by osism apply <collection> (e.g. nutshell) streams its Ansible output into a Redis stream line by line — but nothing ever reads it back:

• the collection path returns right after apply_async() and never calls handle_task() (osism/commands/apply.py), unlike the single-role path;
• osism wait without --live only prints result.get() from the Celery result backend, never touching the stream.

So when such a task hangs mid-play it stays STARTED for hours while the job log shows nothing but the poll loop — even though its partial output is sitting in Redis the whole time. job-output.json is no help either: a play's output is written there when the task completes, so a task that never completes contributes nothing to it.

Builds that would have benefited

Five builds have been individually verified as this shape — in each, the roles that produced no play output are exactly the tasks that never completed. All ran in periodic-midnight and all were killed at the 4h30m job timeout, each burning a 6-node testbed for the full duration:

Date	Job	Build	Duration	Silent task(s)
2026-04-03	testbed-deploy-next-in-a-nutshell-with-tempest-ubuntu-24.04	d362501b	4h30m	kubernetes
2026-06-15	testbed-deploy-stable-in-a-nutshell-with-tempest-ubuntu-24.04	eb40d017	4h32m	kubernetes
2026-08-13	testbed-deploy-current-in-a-nutshell-with-tempest-ubuntu-24.04	e5f6fb91	4h31m	kubernetes
2026-08-13	testbed-deploy-stable-in-a-nutshell-with-tempest-ubuntu-24.04	9839c6ef	4h31m	kubernetes
2026-08-23	testbed-deploy-current-in-a-nutshell-with-tempest-ubuntu-24.04	967e4b11	4h31m	loadbalancer, openvswitch

The victim role varies, so this is not specific to k3s: in 967e4b11 the kubernetes task ran and succeeded at 00:59:16 while two A [1] roles went silent instead. In e5f6fb91 the last completed work is octavia at 01:20, and from then until the 04:30 kill the log is nothing but the 3-second poll loop.

Identifying the silent task today takes an accounting argument across the whole console log, because the dispatcher never names task IDs. This change would have printed it directly, while the job was still running.

More broadly, 23 timed-out in-a-nutshell builds between 2025-12-30 and 2026-08-23 carry no cause signature at all — only the informational kolla-collection-celery-task-stuck, which merely records that the poll loop ran. Every one of them had at least one task sitting in STARTED with its output unread, so every one would have gained a diagnosis. (That set and the five above overlap but neither contains the other: 9839c6ef also carries an unrelated github-download signature.)

What this does

In the STARTED branch, peek at the task's stream with xrevrange/xlen and log the line count, how long the task has been silent, and the last line it emitted.

The peek never consumes: fetch_task_output() xdels every entry it reads, which would steal output from the --live path and from the operator. The last entry's stream ID doubles as the timestamp of that line, so no extra bookkeeping is needed to measure silence.

Guards:

• Reporting starts only once a task has been silent past OSISM_WAIT_STALL_REPORT (default 600s), so runs whose tasks are making progress stay exactly as quiet as before.
• Reports are rate-limited per task. Suppression is keyed on the last line rather than time alone, so a task that emits something and then wedges again is reported immediately, while a standing stall is restated once per interval instead of once per second.
• An empty stream is reported separately — "no output at all" distinguishes a task that hung before its first line from one that hung mid-play.
• The path without --live never needed Redis, so any peek error is logged once and disables further peeking rather than propagating.
• --format script output is unchanged.

Verified against a live cluster

Measured on a running OSISM manager before writing the code:

Question	Result
Anything drains these streams in the background?	No — a synthetic stream held len=2 untouched; xdel exists only inside fetch_task_output
Is XREVRANGE non-destructive?	Yes — XLEN 30 before and after
Do stream IDs give emit wall-clock?	Yes — ID 1787674011181 matched the 16:06:51 inside that line's own content
Is output pushed incrementally or flushed at the end?	Incrementally — 30 entries over 22.73s, 25 over 22.58s

That last row is the point: the job log is a single flush at completion, Redis is a live stream. The data was never destroyed, just never read.

Testing

• 8 new unit tests in tests/unit/commands/test_wait.py (21 total in that file, all passing).
• Full unit suite: 3 failed, 1883 passed, 1261 errors vs 3 failed, 1875 passed, 1261 errors on main — exactly the 8 new tests, nothing else moved. Those 3 failures and 1261 errors are pre-existing (fakeredis/lupa in test_init_semaphore, plus unrelated env gaps) and are not addressed here.
• black and flake8 clean.

Limitations

This makes the hang self-explaining while the job is still running. It does not bound the hang — a wedged nutshell still holds its nodes until the caller or CI times out. Choosing a safe abort threshold needs the data this change will now produce.

🤖 Generated with Claude Code

[sourcery-ai]

Hey - I've found 2 issues

Prompt for AI Agents

Please address the comments from this code review:

## Individual Comments

### Comment 1
<location path="osism/commands/wait.py" line_range="14" />
<code_context>
+# How long a STARTED task may go without emitting output before ``wait``
+# starts reporting what it was last doing. Healthy tasks emit more or less
+# continuously, so this only fires on a task that is genuinely wedged.
+STALL_REPORT_SECONDS = int(os.environ.get("OSISM_WAIT_STALL_REPORT", 600))
+
+
</code_context>
<issue_to_address>
**issue (bug_risk):** A non-integer `OSISM_WAIT_STALL_REPORT` value raises `ValueError` while importing `osism.commands.wait`, so the `osism wait` command fails before it can run. A zero or negative value also disables the intended rate limiting and causes every poll of a stalled task to emit another warning.

**Triggers:** When the new environment variable is set to an invalid, zero, or negative value.

**Suggested fix:** Parse and validate the setting, falling back to the default or rejecting non-positive values with a clear configuration error.

```suggestion
try:
    STALL_REPORT_SECONDS = int(os.environ.get("OSISM_WAIT_STALL_REPORT", 600))
except ValueError:
    STALL_REPORT_SECONDS = 600

if STALL_REPORT_SECONDS <= 0:
    raise ValueError("OSISM_WAIT_STALL_REPORT must be a positive integer")
```
</issue_to_address>

### Comment 2
<location path="osism/commands/wait.py" line_range="132" />
<code_context>
+        except Exception as exc:
+            # The non-``--live`` path never needed Redis, so a peek
+            # failure must stay cosmetic. Report once, then stop trying.
+            logger.debug(f"Cannot read the output stream of task {task_id}: {exc}")
+            self._peek_disabled = True
+            return
</code_context>
<issue_to_address>
**issue (bug_risk):** A Redis peek failure is recorded only with `logger.debug`, so the normal `osism wait` log gives no visible indication that stall reporting has been disabled. The command then continues without the diagnosis this feature is intended to provide.

**Triggers:** When Redis is unavailable or a stream read fails during a non-live wait.

**Suggested fix:** Log the one-time disablement at warning or info level, while continuing to suppress repeated attempts.

```suggestion
            logger.warning(f"Cannot read the output stream of task {task_id}: {exc}")
```
</issue_to_address>

Sourcery assessment

Approval pending. 2 findings to address first.

Blocking findings: osism/commands/wait.py:14, osism/commands/wait.py:132

---

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

• X
• Mastodon
• LinkedIn
• Facebook

_{Help me be more useful! Please click 👍 or 👎 on each comment and I'll use the feedback to improve your reviews.}

[sourcery-ai]

Hey - I've found 1 issue

Prompt for AI Agents

Please address the comments from this code review:

## Individual Comments

### Comment 1
<location path="osism/commands/wait.py" line_range="62-70" />
<code_context>
+    if now is None:
+        now = time.time()
+
+    entries = redis_conn.xrevrange(task_id, "+", "-", count=1)
+    if not entries:
+        return SimpleNamespace(lines=0, last_line=None, stalled_for=None, last_id=None)
+
+    entry_id, fields = entries[0]
+    last_ms = int(entry_id.decode().split("-")[0])
+
+    return SimpleNamespace(
+        lines=redis_conn.xlen(task_id),
+        last_line=fields.get(b"content", b"").decode().rstrip("\n"),
+        stalled_for=now - last_ms / 1000.0,
</code_context>
<issue_to_address>
**issue (bug_risk):** `xrevrange` and `xlen` are separate Redis calls, so a producer that appends a line between them makes the helper pair the new line count with the previous last line and its older timestamp. `wait` then reports a stall even though the task emitted output during the peek.

**Triggers:** When a STARTED task emits output between the `xrevrange` and `xlen` calls, especially near the stall threshold.

**Suggested fix:** Read the latest entry and count from one atomic Redis operation, or re-check the latest entry after `xlen` and discard the sample if its ID advanced.
</issue_to_address>

Sourcery assessment

Needs a human reviewer. 1 finding to address first, and this adds Redis reads and persists the last task-output line in the wait log, so an incorrect or overly sensitive report can outlive a revert and require log cleanup. The behavior is otherwise bounded and cosmetic: reverting stops future reports, and it does not alter task execution or stored task data.

Blocking findings: osism/commands/wait.py:70

---

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

• X
• Mastodon
• LinkedIn
• Facebook

_{Help me be more useful! Please click 👍 or 👎 on each comment and I'll use the feedback to improve your reviews.}

[sourcery-ai]

issue (bug_risk): xrevrange and xlen are separate Redis calls, so a producer that appends a line between them makes the helper pair the new line count with the previous last line and its older timestamp. wait then reports a stall even though the task emitted output during the peek.

Triggers: When a STARTED task emits output between the xrevrange and xlen calls, especially near the stall threshold.

Suggested fix: Read the latest entry and count from one atomic Redis operation, or re-check the latest entry after xlen and discard the sample if its ID advanced.