diff --git a/lane-handoff b/lane-handoff index 3c09e0b1..3505e726 100755 --- a/lane-handoff +++ b/lane-handoff @@ -1486,15 +1486,25 @@ lc_on=""; lc_gen=""; lc_op=""; lc_state=""; lc_inventory_missed="" lifecycle_begin() { lc_on=""; lc_gen=""; lc_op=""; lc_state="" - lcb_now=""; lcb_rc=0 - lcb_now="$(LANES_NO_FETCH=1 "$LANES_EDIT" lane-state "$lane" 2>/dev/null \ - | awk -F"\t" '$1 == "state" { print $2; exit }')" || lcb_rc=$? + lcb_now=""; lcb_raw=""; lcb_rc=0 + # READ WHOLE, THEN PARSE (opensoft/openRepoTools#280). This read was + # `lane-state | awk '… { print $2; exit }'` under `pipefail`, and that `awk` + # exits at the line it wants: a `lane-state` that wrote once more after it + # — its builtin `printf` hands a multi-line snapshot to the pipe in pieces — + # died of SIGPIPE, the substitution's status was 141, and the `case` below + # took that for a read that FAILED: "could not be read", no fence, no + # inventory and no RUNNING -> SWAPPING -> SWAPPED, on timing alone (CI run + # 39322387035). The reader had stopped listening; the read had not failed. + # So the status below is `lane-state`'s own, from a command nothing can end + # early, and the state is parsed out of what it printed afterwards. + lcb_raw="$(LANES_NO_FETCH=1 "$LANES_EDIT" lane-state "$lane" 2>/dev/null)" || lcb_rc=$? case "$lcb_rc" in 0 | 8) : ;; *) note "the lane lifecycle could not be read (\`$LANES_EDIT lane-state $lane\` exited $lcb_rc), so this handoff records no RUNNING -> SWAPPING -> SWAPPED transition. The swap itself goes on (\`R-A11-11\`) and the PAUSED record below is unaffected." return 0 ;; esac + lcb_now="$(printf '%s\n' "$lcb_raw" | awk -F"\t" '$1 == "state" { print $2; exit }')" [ -n "$lcb_now" ] || lcb_now=none # AN INTERRUPTED SWAP IS TAKEN OVER, NOT COMPETED WITH. A lane still # reading `SWAPPING` when a new handoff starts is one whose previous @@ -1502,8 +1512,10 @@ lifecycle_begin() { # which is precisely what refuses the old finalizer if it ever wakes up. # The old operation id is named rather than lost. if [ "$lcb_now" = SWAPPING ]; then - lcb_old="$(LANES_NO_FETCH=1 "$LANES_EDIT" lane-state "$lane" 2>/dev/null \ - | awk -F"\t" '$1 == "operation" { print $2; exit }')" + # Read whole, then parsed, for the reason given above (#280); its status + # was never read, and the operation is only named in the note below. + lcb_old_raw="$(LANES_NO_FETCH=1 "$LANES_EDIT" lane-state "$lane" 2>/dev/null)" + lcb_old="$(printf '%s\n' "$lcb_old_raw" | awk -F"\t" '$1 == "operation" { print $2; exit }')" note "lane $lane is still recorded SWAPPING from operation ${lcb_old:-unknown}, which never finished: this handoff SUPERSEDES it with a new generation, and that is what refuses the old finalizer if it ever returns. Nothing of that operation is undone here." fi lcb_out=""; lcb_src=0 diff --git a/tests/test_triad_lane_tooling_handoff.py b/tests/test_triad_lane_tooling_handoff.py index 0dbdfad0..eee65abd 100644 --- a/tests/test_triad_lane_tooling_handoff.py +++ b/tests/test_triad_lane_tooling_handoff.py @@ -96,9 +96,9 @@ def field(out: str, key: str) -> list: def handoff(b: Bench, lane: str, cwd: Path, why: str = "t018 handoff", - *flags: str) -> subprocess.CompletedProcess: + *flags: str, env: dict | None = None) -> subprocess.CompletedProcess: return b.tool("lane-handoff", "--lane", lane, "--transcript", "none", "--agent", "claude", - *flags, why, cwd=cwd) + *flags, why, cwd=cwd, env=env) def writers_file(b: Bench, lane: str, rows: dict) -> Path: @@ -789,6 +789,138 @@ def test_t018_a_leg_tree_add_made_is_withheld_where_the_legs_git_is_an_empty_dir assert inventory(b, "triad-1") == want +# ===================================================================== #280 + +#: A `lanes-edit.sh` that is the bench's own for every verb but `lane-state`, and +#: answers that one in PIECES - the `state` line, 1.5 MiB of padding, then the +#: rest of the snapshot - so that its reader has gone before it has finished, +#: WHATEVER THE TIMING AND WHATEVER THE AWK. A pipe holds 64 KiB, so a producer +#: with 1.5 MiB to write is still writing when a reader that stops at the first +#: line closes; its next write gets SIGPIPE and the wrapper dies of it, as the +#: real one can when a reader is quick enough to leave between its writes (its +#: builtin `printf` writes a multi-line snapshot a line at a time). A pause +#: instead of the padding was a race of its own: an awk that stalled for longer +#: than the pause read it all. mawk reads ahead until its buffer is full - the +#: review of fc061fe measured the end of input at 255 KiB or less and an early +#: stop at 320 KiB or more - so the padding stays far above that. Its key, `pad`, +#: is no field `lane-state` prints, so nothing in `lane-handoff` takes it for +#: one. `real` is the bench's copy, `calls` the file each `lane-state` call is +#: logged to, `pad` one padding line (a real TAB) and `pad_lines` how many. +SLOW_LANE_STATE = """#!/bin/sh +real='{real}' +if [ "$1" = lane-state ]; then + printf '%s\\n' "$*" >> '{calls}' + out="$("$real" "$@")" + rc=$? + if [ "$rc" != 0 ]; then + [ -z "$out" ] || printf '%s\\n' "$out" + exit "$rc" + fi + first="$(printf '%s\\n' "$out" | sed -n 1p)" + rest="$(printf '%s\\n' "$out" | sed 1d)" + printf '%s\\n' "$first" + yes '{pad}' | head -n {pad_lines} + printf '%s\\n' "$rest" + exit 0 +fi +exec "$real" "$@" +""" +#: One line of padding, and how many: 32768 lines of 48 bytes are 1.5 MiB. +PAD_LINE = "pad\tno lifecycle field is spelled like this one" +PAD_LINES = 32768 + +#: `lane-handoff`'s lifecycle read as it was written before #280: the producer +#: piped into an `awk` that exits at its first match, under `pipefail`. +OLD_LIFECYCLE_READ = r'''set -uo pipefail +rc=0 +now="$(LANES_NO_FETCH=1 "$1" lane-state "$2" 2>/dev/null | awk -F"\t" '$1 == "state" { print $2; exit }')" || rc=$? +printf '%s %s\n' "$now" "$rc" +''' + + +def slow_lane_state(b: Bench) -> tuple: + """THE PRODUCER THAT OUTLIVES ITS READER: the wrapper (a `$LANES_EDIT`), and + the file it logs each `lane-state` call to.""" + wrapper = b.root / "slow-lane-state" / "lanes-edit.sh" + wrapper.parent.mkdir() + calls = wrapper.parent / "calls" + wrapper.write_text(SLOW_LANE_STATE.format(real=b.bin / "lanes-edit.sh", calls=calls, + pad=PAD_LINE, pad_lines=PAD_LINES)) + wrapper.chmod(0o755) + return wrapper, calls + + +def lane_state(b: Bench, lane: str) -> dict: + proc = b.tool("lanes-edit.sh", "lane-state", lane) + assert proc.returncode == 0, proc.stderr + return dict(ln.split("\t", 1) for ln in proc.stdout.splitlines() if "\t" in ln) + + +@NEEDS_UPSTREAM +def test_280_a_lifecycle_read_whose_producer_writes_after_the_filter_exits_is_still_a_read(triad): + """#280: `lane-handoff` read the lane's lifecycle as `lane-state | awk '$1 == + "state" { print $2; exit }'` under `set -o pipefail`, and that `awk` exits at + the first line. A producer that writes once more after that dies of SIGPIPE - + the real one's builtin `printf` hands a multi-line snapshot to the pipe in + pieces, and a reader quick enough sees the first before the last is written - + so the substitution's status was 141, the handoff said "the lane lifecycle + could not be read" and recorded no RUNNING -> SWAPPING -> SWAPPED transition + (CI run 39322387035, which passed one prefix down and in every run before + it). The race is held here EVERY time, by a `lane-state` that prints its + `state` line, 1.5 MiB of padding and then the rest: a pipe holds 64 KiB, so + that producer is still writing when a reader that stops at the first line + has closed, whatever the timing and whatever the awk. THE PREMISE FIRST: the + old shape of the read, run on that producer, gives `RUNNING 141`. Then the + handoff reads the snapshot whole and takes the status from `lane-state` + alone, so it records the transition as it does when the producer is quick.""" + b, t = triad + a = t["assembly"] + wrapper, calls = slow_lane_state(b) + old = b.run("bash", "-c", OLD_LIFECYCLE_READ, "_", wrapper, "triad-1") + assert (old.returncode, old.stdout) == (0, "RUNNING 141\n"), (old.stdout, old.stderr) + calls.write_text("") # the premise logged a call of its own + + proc = handoff(b, "triad-1", a, "t280 handoff", env={"LANES_EDIT": str(wrapper)}) + assert proc.returncode == 0, proc.stdout + proc.stderr + assert "lane-state triad-1" in calls.read_text().splitlines(), \ + "the handoff never read the lifecycle through the wrapper" + assert "the lane lifecycle could not be read" not in proc.stderr, proc.stderr + assert "exited 141" not in proc.stderr, proc.stderr + assert "lifecycle: RUNNING -> SWAPPING (generation " in proc.stderr, proc.stderr + assert "lifecycle: SWAPPING -> SWAPPED (generation " in proc.stderr, proc.stderr + assert "lifecycle: SWAPPED" in proc.stdout, proc.stdout + assert lane_state(b, "triad-1")["state"] == "SWAPPED" + + +@NEEDS_UPSTREAM +def test_280_a_swapping_lane_read_the_same_way_still_names_the_operation_it_supersedes(triad): + """#280, a lane left SWAPPING: the FIRST read - the state - goes through the + same producer and must still see SWAPPING, so the handoff takes the lane + over, and its note names the operation that never finished. THAT IS WHAT + THIS PINS: the note's content, and the first read on a SWAPPING lane. It + cannot pin the SECOND read's own fix, the operation read once more for that + note: its status was never read, so reverting that site alone still passes.""" + b, t = triad + a = t["assembly"] + wrapper, calls = slow_lane_state(b) + took = b.tool("lanes-edit.sh", "set-lane-state", "triad-1", "SWAPPING", "--expect", "RUNNING", + "--operation", "op-stuck-280") + assert took.returncode == 0, took.stderr + assert lane_state(b, "triad-1")["operation"] == "op-stuck-280" + + proc = handoff(b, "triad-1", a, "t280 handoff", env={"LANES_EDIT": str(wrapper)}) + assert proc.returncode == 0, proc.stdout + proc.stderr + assert "lane-state triad-1" in calls.read_text().splitlines(), \ + "the handoff never read the lifecycle through the wrapper" + assert "the lane lifecycle could not be read" not in proc.stderr, proc.stderr + assert ("lane triad-1 is still recorded SWAPPING from operation op-stuck-280, which never " + "finished") in proc.stderr, proc.stderr + assert "lifecycle: SWAPPING -> SWAPPING (generation " in proc.stderr, proc.stderr + assert "lifecycle: SWAPPING -> SWAPPED (generation " in proc.stderr, proc.stderr + after = lane_state(b, "triad-1") + assert after["state"] == "SWAPPED" and after["operation"] != "op-stuck-280", after + + # ===================================================== the single repository def single_repository_decoys(bench: Bench) -> list: