Stdout buffering defeats poll.py's "alive, mid-sweep" corroboration, so a healthy long sweep reads as an outage nf-uiy ← Beads

Twinned from https://github.com/cfsh/ninefold/issues/621 by tools/beads/import_github.py's reconcile pass.

poll.py's corroboration branch — the one that tells *"alive, mid-sweep"* from *"dead"* — is defeated by Python's stdout buffering, and it fails in the direction #461 was filed to stop.

The mechanism

dispatch_health reads dispatch.log's mtime as evidence the dispatcher is working when the heartbeat is stale. From tools/reviewer/README.md:

| heartbeat | dispatch.log | digest says | |---|---|---| | stale | touched recently | ⓘ alive, mid-sweep — does not hold the cron | | stale | quiet | ⚠ STALE-DISPATCH — real outage, holds the cron at 30m |

But the dispatcher's progress goes to stdout, and Python block-buffers stdout when it is a file — which it always is, for a cron or schtasks job that redirects into a log. So nothing reaches the log until the tick exits.

Measured on the Linux dispatcher host, with nflib imported exactly as every tool imports it:

``` print("line one") # t=0 time.sleep(6) print("line two") # t=6 ```

``` after 3s, log holds 0 bytes after 8s (process exited), log holds 58 bytes ```

nflib.force_utf8() reconfigures encoding and newline but leaves line_buffering=False — proc.py's own docstring already notes stdout is "BLOCK-buffered whenever stdout is not a Windows console", which is the same fact from the other side.

Why that inverts the check

The log's mtime advances when a tick ends, not while it runs. So during a long sweep — the exact condition corroboration exists for — the log is quiet, and "quiet" is the branch that declares a real outage.

Live on this box as I write, with a review genuinely in flight:

``` heartbeat age: 68m (tick 17, ok=true) dispatch.log mtime age: 69m pr-613.lock empty, 08:32 → a review IS running ```

dispatch_health is silent only because 68m is under the 90m threshold (3 × 30m). Past that it reaches:

> ⚠ STALE-DISPATCH: last good dispatcher tick was 91m ago … and dispatch.log has been quiet for 92m. Reviews and label reconciliation have stopped — this is the #352 shape, which ran undetected for 38 hours.

…about a dispatcher that is fine. That is #461's false alarm, restored by a mechanism nobody suspected, and it holds every session's cron at 30m.

Why it has not obviously bitten before

• stderr is line-buffered, so *warnings* do land promptly. A tick that warns looks alive; a tick that is merely slow and healthy looks dead. The corroboration effectively only works when something is going wrong.
• Sweeps used to finish inside one interval. With five dev sessions and ~10 open PRs, they no longer do — a tick doing several synchronous xhigh reviews now routinely exceeds 90 minutes.
• It affects the Windows host too: the same buffering applies to >> from Git Bash.

Fix

python3 -u (or PYTHONUNBUFFERED=1) in the invocation makes the mtime mean what the reader assumes. I have applied that to this box's crontab as an operational mitigation, with the reasoning in a comment — but the deployed invocation lives in tools/reviewer/README.md, and that is what a new host gets set up from, so the repo change is: add -u to the documented command and say why, on both the Windows and Linux forms.

Worth considering alongside: write_heartbeat is the tick's *last* action by design, and a mid-sweep progress signal is what corroboration actually wants. An explicit "sweeping" touch would be a stronger signal than a log mtime that happens to move — but the one-character fix restores the documented behaviour, and the rest is a design question.

Filed unclaimed while working #576; not claiming it.