cmoriarty/braid
1
0
Fork 0
Code Issues 15 Pull requests Projects Releases Packages 1 Wiki Activity Actions

A scripted step's output pumps are cancelled before they drain: the transcript loses the tail, and so can an effect marker #123

New issue
Closed
opened 2026-10-02 11:19:31 -04:00 by cmoriarty · 1 comment
cmoriarty commented 2026-10-02 11:19:31 -04:00
Owner
Copy link

What happens

ScriptedExecutor.start (src/osf/engine/executors.py) cancels both output pumps (_pump, one per stream) the moment proc.wait() returns. A pump can still be holding output at that point, and the cancel drops it: it never becomes a script.output event, and an ::osf:effect:: marker in it is never scanned, so no osf.effect.recorded row is written. The step then records script.exit and carries on as if nothing were missing.

It surfaced as a flaky test, tests/unit/test_scheduler.py::test_a_scripted_step_streams_its_output_and_its_exit_code (assert 'script.output' in [...], line 1210): one failure in a -n auto run, 2 of 15 isolated runs with one busy loop per core, 0 of 15 on an idle machine. The test is right and the executor is wrong. The flake is the smallest case of a bigger loss.

Three ways the output is lost

Each reproduced on demand, with no CPU load, by holding one thing back:

  1. The pump has not run yet. If the child has already exited when proc.wait() is first awaited, wait() returns without suspending and the pumps are cancelled before their first step. Reproduced by delaying the osf.step.deadline write by 0.5 s: no output, no marker.
  2. The pump is behind. It reads 4 KiB and does one DB write per chunk while the child writes at full speed, so when the process exits the StreamReader still holds up to about 100 KB that the pump never read. None of it is chunked, and none of it is scanned for markers.
  3. The pump is mid-flush. The cancel lands inside await emit(...). The chunk has already left the buffer, and Database.write awaits a concurrent.futures.Future for the writer thread: cancelling the awaiting task cancels that future, and the writer skips a job it has not started. Reproduced by parking the writer thread on a gate job: both the script.output event and the marker are missing.

Measured on current main, no extra load

script what is lost
seq 1 500 (1.9 KB) nothing
seq 1 2000 (8.9 KB) 54% of the bytes
seq 1 10000 (49 KB) 41%
seq 1 40000 (229 KB) 36%; the last line is missing in 40 of 40 runs
seq 1 100000 (589 KB) 17%
sleep 0.3; echo '::osf:effect::{...}' the marker line is missing from the transcript in 38-39 of 40 runs (the effect row survives here, and does not when the writer thread is held)
seq 1 40000; echo '::osf:effect::{...}' the effect is not recorded in 20 of 20 runs

Why it matters beyond the test

  • The end of a script's output is where its error is (npm ci, a test run's summary, a refused push), and it is the part the console loses.
  • pr-exists and pr-merged read the external_effect rows that markers write, and the scripts in forgejo.py, plan.py and gitflow.py print their marker as they finish. A marker lost this way fails a step whose pull request was in fact opened, and a redo cannot show the effect.

Expected

Once the process is gone, its pumps read to EOF and flush before they are cancelled. The cancel stays for the stuck case, a pipe a grandchild still holds open, and for the stop path, and it is bounded so a step cannot hang on a drain. A deterministic regression test holds the write back, or has the child exit first, instead of relying on load.

## What happens `ScriptedExecutor.start` (`src/osf/engine/executors.py`) cancels both output pumps (`_pump`, one per stream) the moment `proc.wait()` returns. A pump can still be holding output at that point, and the cancel drops it: it never becomes a `script.output` event, and an `::osf:effect::` marker in it is never scanned, so no `osf.effect.recorded` row is written. The step then records `script.exit` and carries on as if nothing were missing. It surfaced as a flaky test, `tests/unit/test_scheduler.py::test_a_scripted_step_streams_its_output_and_its_exit_code` (`assert 'script.output' in [...]`, line 1210): one failure in a `-n auto` run, 2 of 15 isolated runs with one busy loop per core, 0 of 15 on an idle machine. The test is right and the executor is wrong. The flake is the smallest case of a bigger loss. ## Three ways the output is lost Each reproduced on demand, with no CPU load, by holding one thing back: 1. **The pump has not run yet.** If the child has already exited when `proc.wait()` is first awaited, `wait()` returns without suspending and the pumps are cancelled before their first step. Reproduced by delaying the `osf.step.deadline` write by 0.5 s: no output, no marker. 2. **The pump is behind.** It reads 4 KiB and does one DB write per chunk while the child writes at full speed, so when the process exits the `StreamReader` still holds up to about 100 KB that the pump never read. None of it is chunked, and none of it is scanned for markers. 3. **The pump is mid-flush.** The cancel lands inside `await emit(...)`. The chunk has already left the buffer, and `Database.write` awaits a `concurrent.futures.Future` for the writer thread: cancelling the awaiting task cancels that future, and the writer skips a job it has not started. Reproduced by parking the writer thread on a gate job: both the `script.output` event and the marker are missing. ## Measured on current main, no extra load | script | what is lost | | --- | --- | | `seq 1 500` (1.9 KB) | nothing | | `seq 1 2000` (8.9 KB) | 54% of the bytes | | `seq 1 10000` (49 KB) | 41% | | `seq 1 40000` (229 KB) | 36%; the last line is missing in 40 of 40 runs | | `seq 1 100000` (589 KB) | 17% | | `sleep 0.3; echo '::osf:effect::{...}'` | the marker line is missing from the transcript in 38-39 of 40 runs (the effect row survives here, and does not when the writer thread is held) | | `seq 1 40000; echo '::osf:effect::{...}'` | the effect is not recorded in 20 of 20 runs | ## Why it matters beyond the test - The end of a script's output is where its error is (`npm ci`, a test run's summary, a refused push), and it is the part the console loses. - `pr-exists` and `pr-merged` read the `external_effect` rows that markers write, and the scripts in `forgejo.py`, `plan.py` and `gitflow.py` print their marker as they finish. A marker lost this way fails a step whose pull request was in fact opened, and a redo cannot show the effect. ## Expected Once the process is gone, its pumps read to EOF and flush before they are cancelled. The cancel stays for the stuck case, a pipe a grandchild still holds open, and for the stop path, and it is bounded so a step cannot hang on a drain. A deterministic regression test holds the write back, or has the child exit first, instead of relying on load.
cmoriarty commented 2026-10-02 13:14:07 -04:00
Author
Owner
Copy link

Shipped in 7dfd2e4 (deploy run #90, production restarted on it at 17:02 UTC) and archived in 53abd8d. The change is openspec/changes/archive/2026-10-02-script-output-drain, and its spec is now openspec/specs/script-output/spec.md.

What was wrong. ScriptedExecutor cancelled both output pumps the moment proc.wait() returned. A pump can still be holding output then, in one of three states, and each lost the output and any ::osf:effect:: marker in it:

  1. Not started. The child had exited during the step's first write, so wait() returned at once and the pumps were cancelled before they ran. This was the flaky test: 11 of 11 failures in 160 separate pytest processes under load, with no write cancelled in any of them.
  2. Behind. About 100 KB sat unread in the stream's buffer.
  3. Mid-write. The cancel dropped a write the writer had not started.

A marker with no newline after it was also never scanned (0 of 10 recorded).

What changed. Once the process is gone, its pumps are waited for. A stream is waited for while it makes progress, and given up on after 5 s of silence, or 60 s after the process ended, with a log warning and a transcript line saying which. A step cancelled by the engine is unchanged.

Verified.

  • The flaky test passed 100 of 100 under two busy loops per core. It failed 10 of 100 before.
  • 12 regression tests force each state by holding something back, and each fails on main for the reason it names. They passed 20 runs under the same load.
  • Fast lane 2,286 passed. Full lane green: backend 2,294, UI unit 515, browser 149 passed and 3 @live skipped.
  • On a local osfd, a step that printed 229 KB and then an effect marker succeeded on pr-exists, and its transcript was byte-identical.
  • On production after the deploy, a quick-fix run on soundcheck#71 recorded complete transcripts for git.clone, script.brief, script.agents-md and script.deps, with no notices and a clean journal. The run itself is still going.

Left alone, not filed.

  • The console's script block is a preview by design (the first 40 lines of each chunk, about 8,000 characters), so the tail of a long output is only in the log and the API.
  • A pump flushes only when a read returns, so a line printed within 100 ms of a flush shows at the next output or at exit. That is a delay, not a loss.
Shipped in 7dfd2e4 (deploy run #90, production restarted on it at 17:02 UTC) and archived in 53abd8d. The change is `openspec/changes/archive/2026-10-02-script-output-drain`, and its spec is now `openspec/specs/script-output/spec.md`. **What was wrong.** `ScriptedExecutor` cancelled both output pumps the moment `proc.wait()` returned. A pump can still be holding output then, in one of three states, and each lost the output and any `::osf:effect::` marker in it: 1. **Not started.** The child had exited during the step's first write, so `wait()` returned at once and the pumps were cancelled before they ran. This was the flaky test: 11 of 11 failures in 160 separate pytest processes under load, with no write cancelled in any of them. 2. **Behind.** About 100 KB sat unread in the stream's buffer. 3. **Mid-write.** The cancel dropped a write the writer had not started. A marker with no newline after it was also never scanned (0 of 10 recorded). **What changed.** Once the process is gone, its pumps are waited for. A stream is waited for while it makes progress, and given up on after 5 s of silence, or 60 s after the process ended, with a log warning and a transcript line saying which. A step cancelled by the engine is unchanged. **Verified.** - The flaky test passed 100 of 100 under two busy loops per core. It failed 10 of 100 before. - 12 regression tests force each state by holding something back, and each fails on `main` for the reason it names. They passed 20 runs under the same load. - Fast lane 2,286 passed. Full lane green: backend 2,294, UI unit 515, browser 149 passed and 3 `@live` skipped. - On a local osfd, a step that printed 229 KB and then an effect marker succeeded on `pr-exists`, and its transcript was byte-identical. - On production after the deploy, a `quick-fix` run on soundcheck#71 recorded complete transcripts for `git.clone`, `script.brief`, `script.agents-md` and `script.deps`, with no notices and a clean journal. The run itself is still going. **Left alone, not filed.** - The console's script block is a preview by design (the first 40 lines of each chunk, about 8,000 characters), so the tail of a long output is only in the log and the API. - A pump flushes only when a read returns, so a line printed within 100 ms of a flush shows at the next output or at exit. That is a delay, not a loss.
Sign in to join this conversation.
No Branch/Tag specified
Branches Tags
main
archive/prefect-kestra-experiments
Labels
Clear labels
No items
No labels
Milestone
Clear milestone
No items
No milestone
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
cmoriarty/braid#123
No description provided.