From 6335ca8e4bbebaa7320ee9dd007716e725e3aa01 Mon Sep 17 00:00:00 2001 From: Brett Heap Date: Sun, 18 Oct 2026 20:37:53 +0000 Subject: [PATCH 1/6] The shell suite times each of its sections and its exit-trap teardown, and prints both in its transcript and in CI's step summary (#77, step 1a) Lane 1 measured one run on WSL and put 56% of the wall in the exit trap's rm -rf of the sandbox and 57% of the rest in two sections, but no CI runner's own split was ever printed, and the pytest wrapper prints the suite's transcript only when it fails. A new section helper prints each == heading exactly as echo did and clocks it with SECONDS; section_report prints the rows longest first just before the footer, which stays the last stdout line; cleanup times its rm -rf and says so on stderr. Where GITHUB_STEP_SUMMARY is set both tables are appended there, because a passing run's stdout and stderr are discarded. Two assertions keep a bare echo heading from joining the section before it. Nothing is skipped or changed in the teardown: the numbers come first. Part of #77. Co-Authored-By: Claude Sonnet 5.5 --- tests/test_lane_helpers.sh | 196 +++++++++++++++++++++++++++++++------ 1 file changed, 167 insertions(+), 29 deletions(-) diff --git a/tests/test_lane_helpers.sh b/tests/test_lane_helpers.sh index 05be68c8..4bfe2f78 100755 --- a/tests/test_lane_helpers.sh +++ b/tests/test_lane_helpers.sh @@ -62,6 +62,110 @@ for f in lane-start lane-end lanes-edit.sh link-estates lane lanes lane-rename l done [ -f "$SRC_DIR/repos.tsv" ] || { echo "missing: $SRC_DIR/repos.tsv" >&2; exit 1; } +# WHERE THE TIME GOES, MEASURED BEFORE ANYTHING IS CHANGED (opensoft/openRepoTools#77, +# step 1a). The nightly runs this file for about 45 minutes and the only number +# anybody has is the whole of it: lane 1's one instrumented run on WSL put 56% of +# the wall in the exit trap's `rm -rf "$SANDBOX"` and 57% of the rest in two +# sections, from ONE run, under contention, on one workstation. Nothing about a +# CI runner's own split was ever printed, and the pytest wrapper prints this +# file's transcript only when the suite FAILS, so a green run said nothing at +# all. Three things, all of them reading and none of them changing what is run: +# +# `section "== … =="` prints a heading exactly as `echo` did and stamps the +# clock beside it, so each section's whole-second wall +# time is a row by the time the footer is reached; +# `section_report` prints those rows, longest first, just before the +# footer — which stays the LAST line on stdout, because +# the wrapper looks for ` passed, 0 failed` there; +# `cleanup` times its own `rm -rf` and says so on stderr. +# +# AND BOTH GO TO THE JOB'S STEP SUMMARY where CI names one. A passing run's +# stdout and stderr are both captured by the wrapper and thrown away, so a +# table that only reached them would be one nobody reads on the runs that +# matter. `$GITHUB_STEP_SUMMARY` is a file the runner reads after the step, it +# is an absolute path and survives the `HOME` and `TMPDIR` this suite moves +# below, and a write to it that fails is a note on stderr and never a failed +# assertion: a timing table is not a reason to turn a green run red. +# +# `$SECONDS` AND NOT `date +%s` OR `$EPOCHREALTIME`: it is bash's own clock, so +# a heading costs no process (this file spawns enough of them), and it is in the +# bash 3.2 this file is written for, which `$EPOCHREALTIME` (5.0) is not. The price +# is whole seconds, so a row is good to one second either way — which is nothing +# beside the sections and the teardown this is here to find. It is read as a +# DIFFERENCE from `SUITE_T0`, because bash takes a `SECONDS` from the +# environment as its starting value and an absolute read would carry it. +# +# Rows are kept as `` lines in one string, not in an +# array: `"${rows[@]}"` on an empty array is an unbound variable under `set -u` +# in the bash 3.2 above. The first row, `(preamble …)`, is everything before the +# first heading — the fakes and the fixtures — and the rows add up to the clock +# at the table exactly, because each heading closes the last one at the very +# reading it opens its own with. +SUITE_T0=$SECONDS +SECTION_TAB=$'\t' +SECTION_NAME="(preamble, before the first heading)" +SECTION_T0=$SUITE_T0 +SECTION_ROWS="" + +section_close() { # — the open section's row, once + [ -n "$SECTION_NAME" ] || return 0 + SECTION_ROWS="${SECTION_ROWS}$(($1 - SECTION_T0))${SECTION_TAB}${SECTION_NAME}"$'\n' + SECTION_NAME="" +} + +section() { # <== heading ==> — printed as `echo` printed it, and clocked + local sc_now=$SECONDS + section_close "$sc_now" + echo "$1" + SECTION_NAME="${1#== }" + SECTION_NAME="${SECTION_NAME% ==}" + SECTION_T0=$sc_now +} + +step_summary() { # — appended to the job's step summary, when CI names one + [ -n "${GITHUB_STEP_SUMMARY:-}" ] || return 0 + printf '%s\n' "$1" >> "$GITHUB_STEP_SUMMARY" || + echo "note: could not append to GITHUB_STEP_SUMMARY ($GITHUB_STEP_SUMMARY)" >&2 + return 0 +} + +section_report() { + local sr_now=$SECONDS sr_total sr_sorted sr_secs sr_name sr_pct sr_text="" sr_md="" + section_close "$sr_now" + sr_total=$((sr_now - SUITE_T0)) + # Longest first, and by name within a second, so two runs of one suite print + # their ties in one order. `LC_ALL=C` because the headings carry em dashes and + # a locale's collation is not what a table of seconds is for. + sr_sorted="$(printf '%s' "$SECTION_ROWS" | LC_ALL=C sort -t "$SECTION_TAB" -k1,1nr -k2,2)" + while IFS="$SECTION_TAB" read -r sr_secs sr_name; do + [ -n "$sr_name" ] || continue + sr_pct=$(( sr_total > 0 ? sr_secs * 100 / sr_total : 0 )) + sr_text="${sr_text}$(printf '%6s s %3s%% %s' "$sr_secs" "$sr_pct" "$sr_name")"$'\n' + # No heading holds a `|`, which would split its cell; none ever has. + sr_md="${sr_md}| ${sr_secs} | ${sr_pct}% | ${sr_name} |"$'\n' + done < — stderr, because the footer is stdout's last line + printf 'teardown: rm -rf of the sandbox took %s s\n' "$1" >&2 + step_summary "### Shell suite: sandbox teardown + +The exit trap's \`rm -rf\` of the suite's sandbox took **$1 s** (whole seconds). It runs after the footer, so it is in none of the rows above." +} + SANDBOX="$(mktemp -d)" # Set before the traps below, so `cleanup` never reads an inherited value. A11T_ROOT="" @@ -109,10 +213,19 @@ cleanup() { [ -n "${PART_CHILD_B:-}" ] && kill -KILL "$PART_CHILD_B" 2>/dev/null [ -n "${GD_DUP:-}" ] && kill "$GD_DUP" 2>/dev/null [ -n "${TH73_PID:-}" ] && kill "$TH73_PID" 2>/dev/null + # opensoft/openRepoTools#77, step 1a: THE TEARDOWN IS TIMED, both removals + # together, and said once. It is said only where the sandbox was really + # there to remove: the INT and TERM handlers below call this and then `exit`, + # which runs the EXIT trap and so this function a second time, and a second + # "took 0 s" would be a number about nothing. + local cl_t0=$SECONDS # #180's short checkout root for the clause (c) TAIL case, which is outside # `$SANDBOX` wherever the run root is long. [ -n "${A11T_ROOT:-}" ] && [ -d "$A11T_ROOT" ] && rm -rf -- "$A11T_ROOT" - [ -n "${SANDBOX:-}" ] && [ -d "$SANDBOX" ] && rm -rf -- "$SANDBOX" + if [ -n "${SANDBOX:-}" ] && [ -d "$SANDBOX" ]; then + rm -rf -- "$SANDBOX" + teardown_report "$((SECONDS - cl_t0))" + fi return 0 } # AND A SIGNAL HANDLER THAT CLEANS UP MUST ALSO EXIT. `tests/run.sh` states @@ -1042,7 +1155,7 @@ git -C "$WIP" add -- lanes/log git -C "$WIP" commit -q -m "seed two object logs" git -C "$WIP" push -q origin main -echo "== lane-start ==" +section "== lane-start ==" run "$START" --help is "lane-start --help exits 0" "$rc" 0 @@ -1168,7 +1281,7 @@ run "$START" repoA 6 --no-launch -- --dangerously-skip-permissions is "arguments after -- reach claude" "$(launch_of "$out")" "claude --name repoA-6 --dangerously-skip-permissions" has "…alongside the minted --session-id" "$out" "--session-id " -echo "== lane-start: Amendment 6 — resume the row's recorded session ==" +section "== lane-start: Amendment 6 — resume the row's recorded session ==" # The fallback, unchanged in shape: the row names an id this directory has no # transcript for, so the title is all that is left — and lane-start says so. @@ -1233,7 +1346,7 @@ is "--dry-run writes no register commit" "$(git -C "$WIP" rev-parse HEAD)" "$b is "--dry-run leaves LANES.md byte-identical" "$(cksum < "$LANES")" "$before_sum" has "--dry-run plans the exact resume" "$err" "PLAN exec claude --name repoA-12 --resume $NEW12_ID" -echo "== lane-end ==" +section "== lane-end ==" run "$END" --help is "lane-end --help exits 0" "$rc" 0 @@ -1275,7 +1388,7 @@ is "a lane named before the - rule can still be ended" "$rc" 0 has "…verbatim, and retired" "$(grep '^| `browser-ui-repair`' "$LANES")" "| RETIRED · 20" -echo "== Amendment 7: the per-lane object log ==" +section "== Amendment 7: the per-lane object log ==" E="$OPENREPOTOOLS_BIN_DIR/lanes-edit.sh" WS_S="${LANES_WORKSTATION:-$(hostname -s)}" @@ -2327,7 +2440,7 @@ is "…and that fallback still refuses an open LANDING" "$rc" 2 has "…saying it is the pre-cutover scan" "$err" "has no object log yet (pre-cutover)" -echo "== Addendum 5: R17–R23 ==" +section "== Addendum 5: R17–R23 ==" # ------------------- R17: a LANDED closes the LANDING it answers, by (lane, PR) # @@ -2588,7 +2701,7 @@ run "$E" who "opensoft/repoG#11" has "a claim past the threshold says WHICH of Rule 1's discharges left it not stale" "$out" "has since written an OPENED naming it" hasnt "…rather than two true halves that read as a contradiction" "$out" "old, threshold ${STALE_H}h" -echo "== Addendum 6: R24–R26, and the lifecycle reads ==" +section "== Addendum 6: R24–R26, and the lifecycle reads ==" # ------- R24: a LANDED that NAMES a repository prefers a LANDING on that one # @@ -2745,7 +2858,7 @@ is "lane-end refuses a merge hold that only the PUBLISHED row shows" "$rc" 2 has "…naming the row it read it from" "$err" "the published row on origin/main" has "…and it is Rule 6's word that stopped it" "$err" "the last LANDING in its state cell" -echo "== Addendum 7: R29–R30 ==" +section "== Addendum 7: R29–R30 ==" # ---------------- R29: the Rule 6 pairing resolves spellings through repos.tsv # @@ -2948,7 +3061,7 @@ run env LANES_LANE=repoZR-1 LANES_SESSION="$ZR_ID" "$E" claim "#3" --no-github is "…while the claim itself uses the home the peer recorded" "$rc" 0 has "…expanding '#3' against it" "$(cat "$LOGD/repoZR-1.md")" ", opensoft/repoZR#3" -echo "== Addendum 8: R33–R35 ==" +section "== Addendum 8: R33–R35 ==" # ---------- R33: the resume target and the RESUMED uuid are the PUBLISHED cell's # @@ -3054,7 +3167,7 @@ is "…the fragment still lists both under ## Open" \ "$(printf '%s\n' "$out" | sed -n '/^## Open/,$p' | grep -c '^- ')" 2 -echo "== Amendment 8: swap and restart ==" +section "== Amendment 8: swap and restart ==" # ------------------------------------------------------------------ swapped # @@ -3290,7 +3403,7 @@ is "…and the launch resumes the id the cell now ends on" "$out" "claude --n unset FAKE_TMUX_WINDOW rm -f "$sessions_dir/live-harness2.json" -echo "== Amendment 11 hotfix: R-A11-1, --name on every branch, unknown refused ==" +section "== Amendment 11 hotfix: R-A11-1, --name on every branch, unknown refused ==" # ---- R-A11-1: A LIVE SESSION THAT BELONGS TO ANOTHER ROW IS NEVER TAKEN ---- # @@ -4675,7 +4788,7 @@ cp -- "$WS_YAML_SAVED" "$WS_YAML" is "the sandbox's own pointer file is restored for the guards below" \ "$(sed -n 's/^path:[[:space:]]*//p' "$WS_YAML" | head -n1)" "$WIP" -echo "== Amendment 11: the record's fields, and clause (h)'s reads ==" +section "== Amendment 11: the record's fields, and clause (h)'s reads ==" # THE SHAPE EVERY CASE BELOW IS ABOUT, in one place: a lane whose log carries # clause (c)'s three sub-fields, and a live window table for the reads that @@ -6211,7 +6324,7 @@ is "…with the path that was named once" "$out" "$HOME/projects/xFactory/xFac run "$START" --dry-run opsXfactory 5 has "…and the next start takes it from the LOG rather than from any rung" "$err" "from the lane's log" -echo "== Amendment 11: the cross-lane write clause (d) rule 1 forbids ==" +section "== Amendment 11: the cross-lane write clause (d) rule 1 forbids ==" # # THE TEST THAT WOULD HAVE CAUGHT EVIDENCE 2(b), written here and owed to the # `opensoft/brett-wip` hotfix that `openRepoTools#24` — act 3, merged as @@ -6336,7 +6449,7 @@ rm -f "$sessions_dir/live-vt2.json" rm -f "$sessions_dir/live-vt.json" unset FAKE_TMUX_WINDOWS -echo "== Amendment 11 decision 7, as Amendment 18 Addendum 2 leaves it: \`lane \` ==" +section "== Amendment 11 decision 7, as Amendment 18 Addendum 2 leaves it: \`lane \` ==" # # THE TWO SURFACES BRETT HEAP'S DIRECTION NAMES, and the count they met before # this word existed. Measured on Eagle on 2026-09-13, after the tmux server was @@ -6622,7 +6735,7 @@ is "…launching nothing, which is what --dry-run means" "$(cat "$FAKE_PCLAUD run env -u TMUX "$LANE" --dry-run repoA11-7 \` kept as the PERSON's door and not as this one" \ "$hfsk" "IS STILL A PERSON'S DOOR AND IS NO LONGER THIS ONE" hasnt "…which is never \`restart \`" "$hfsk" 'respawn-pane -k -t "$pane" "restart' -echo "== Amendment 18 Addendum 1: the word \`lane\`, the numbered pick, the three branches ==" +section "== Amendment 18 Addendum 1: the word \`lane\`, the numbered pick, the three branches ==" # # AMENDMENT 18 ADDENDUM 1, RATIFIED 2026-09-14T14:05:54Z verbatim "ratify the # addendum", out of Brett Heap's two messages that morning — *"i dont understand @@ -12672,7 +12785,7 @@ hasnt "…and never rendering the listing instead" "$out" "AVAILABLE" run env -C "$PICK_DIR" PATH="$LANEBIN_PATH" "$LANE" --all "" "$WIP/.gitignore"; else git -C "$WIP" checkout -q -- .gitignore 2>/dev/null || : # ========================================================================= -echo "== opensoft/openRepoTools#163: lane-end's close-out gate, and lane-worktrees add ==" +section "== opensoft/openRepoTools#163: lane-end's close-out gate, and lane-worktrees add ==" # # WORKSPACE CREATION OUTPACES WORKSPACE CLOSEOUT, and #163 is both ends of it. # `lane-worktrees add` makes a lane's worktree AND records it in the lane's #97 @@ -17171,6 +17284,24 @@ has "…by name" "$err" "--inventory-only is the door past ONE lane's close-ou if [ -n "$cg_had_lsr" ]; then export LANES_LANE_STATE_ROOT="$cg_lsr"; else unset LANES_LANE_STATE_ROOT; fi +# ----------------------------------------- the section clock reads every heading +# +# opensoft/openRepoTools#77, step 1a. A heading printed with a bare `echo` +# prints exactly as it always did and is NOT clocked, so its seconds would +# silently join the section before it and the table at the foot would blame +# the wrong one. Two readings of this file's own text hold that: no `echo "== ` +# is left, and by the time the last heading has opened, the clock holds one row +# for each `section` heading in the file — the preamble's, plus every heading's +# but the open one's — which is also the proof that none of them sits in a +# branch this run skipped. `grep -c` reads a FILE here, which always exists: +# it prints `0` and exits 1 on no match, so the `|| :` only keeps the status +# quiet. +is "every == heading in this suite goes through section, so each is clocked" \ + "$(grep -c '^echo "== ' "$SELF" || :)" 0 +is "…and the clock holds one row per heading by the last heading's start" \ + "$(printf '%s' "$SECTION_ROWS" | awk 'END { print NR + 0 }')" \ + "$(grep -c '^section "== ' "$SELF" || :)" + # ------------------------------------------------------- nothing real touched # # The check is that the suite CREATED nothing here, which is not the same as @@ -17212,6 +17343,13 @@ is "…and every log it did create is inside the sandbox workspace" \ is "the liveness fixture was still running when the run ended" \ "$(kill -0 "$LIVE_PID" 2>/dev/null && printf alive || printf gone)" alive +# THE TABLE OF opensoft/openRepoTools#77, step 1a: every section's wall time, +# longest first, and the same table in the job's step summary. It is printed +# HERE, above the rule, because the footer below must stay the LAST line on +# stdout — the pytest wrapper looks for ` passed, 0 failed` in the transcript +# and its failure message quotes the last line — and the teardown, which +# happens after the footer by nature, is said on stderr by `cleanup`. +section_report echo "----" if [ "$pending_n" != 0 ]; then printf '%s PENDING — owed to a commit landing in another repository, not a failure:\n' "$pending_n" From d05dc0b88c7a50e8a9614acde9814a14fd7a3d99 Mon Sep 17 00:00:00 2001 From: Brett Heap Date: Mon, 19 Oct 2026 11:31:58 +0000 Subject: [PATCH 2/6] The shell suite's teardown line is said once by a flag and a failed removal is said to have failed, and its clock check moves to the foot and also catches an indented or single-quoted echo heading (#77, step 1a fix round) The teardown guard read whether the sandbox still existed, so a rm -rf that failed (a directory inside it that was not writable) reported twice under TERM or INT, and a plain exit said took N s though the removal had failed. cleanup now sets TEARDOWN_SAID after the first report, still retries the removal on the second call without saying anything, and teardown_report words a failed removal as FAILED after N s. The two clock assertions moved from above the guards to just before section_report, because a section added where the next one naturally goes would have been counted in the file and not yet in the clock. The first assertion's pattern now matches an echo heading at any indent and in either quote. Part of #77. Co-Authored-By: Claude Sonnet 5.5 --- tests/test_lane_helpers.sh | 82 ++++++++++++++++++++++++-------------- 1 file changed, 53 insertions(+), 29 deletions(-) diff --git a/tests/test_lane_helpers.sh b/tests/test_lane_helpers.sh index 4bfe2f78..cb284c59 100755 --- a/tests/test_lane_helpers.sh +++ b/tests/test_lane_helpers.sh @@ -106,6 +106,7 @@ SECTION_TAB=$'\t' SECTION_NAME="(preamble, before the first heading)" SECTION_T0=$SUITE_T0 SECTION_ROWS="" +TEARDOWN_SAID="" section_close() { # — the open section's row, once [ -n "$SECTION_NAME" ] || return 0 @@ -159,11 +160,18 @@ ${sr_md}| **${sr_total}** | 100% | **the whole run, from the top of the suite to " } -teardown_report() { # — stderr, because the footer is stdout's last line - printf 'teardown: rm -rf of the sandbox took %s s\n' "$1" >&2 - step_summary "### Shell suite: sandbox teardown +teardown_report() { # — stderr, because the footer is stdout's last line + if [ "$2" = took ]; then + printf 'teardown: rm -rf of the sandbox took %s s\n' "$1" >&2 + step_summary "### Shell suite: sandbox teardown The exit trap's \`rm -rf\` of the suite's sandbox took **$1 s** (whole seconds). It runs after the footer, so it is in none of the rows above." + else + printf 'teardown: rm -rf of the sandbox FAILED after %s s, so part of it is left behind\n' "$1" >&2 + step_summary "### Shell suite: sandbox teardown + +The exit trap's \`rm -rf\` of the suite's sandbox **FAILED after $1 s** (whole seconds), so part of it is left behind. It runs after the footer, so it is in none of the rows above." + fi } SANDBOX="$(mktemp -d)" @@ -214,17 +222,29 @@ cleanup() { [ -n "${GD_DUP:-}" ] && kill "$GD_DUP" 2>/dev/null [ -n "${TH73_PID:-}" ] && kill "$TH73_PID" 2>/dev/null # opensoft/openRepoTools#77, step 1a: THE TEARDOWN IS TIMED, both removals - # together, and said once. It is said only where the sandbox was really - # there to remove: the INT and TERM handlers below call this and then `exit`, - # which runs the EXIT trap and so this function a second time, and a second - # "took 0 s" would be a number about nothing. - local cl_t0=$SECONDS + # together, and said ONCE, by a flag. The INT and TERM handlers below call + # this and then `exit`, which runs the EXIT trap and so this function a second + # time; a second line would repeat the first, or say "took 0 s" about nothing. + # The flag is not "is the sandbox still there": a removal that FAILED (a + # directory inside it that is not writable) leaves it there, and a guard that + # reads that said it twice. The second call still tries the removal again, + # as it always did, and says nothing. And a removal that failed is said to + # have failed, with the seconds it took to do so, not "took": a number that + # reads as a teardown that finished is the one thing this line must not be. + local cl_t0=$SECONDS cl_ok=1 # #180's short checkout root for the clause (c) TAIL case, which is outside # `$SANDBOX` wherever the run root is long. - [ -n "${A11T_ROOT:-}" ] && [ -d "$A11T_ROOT" ] && rm -rf -- "$A11T_ROOT" + [ -n "${A11T_ROOT:-}" ] && [ -d "$A11T_ROOT" ] && { rm -rf -- "$A11T_ROOT" || cl_ok=0; } if [ -n "${SANDBOX:-}" ] && [ -d "$SANDBOX" ]; then - rm -rf -- "$SANDBOX" - teardown_report "$((SECONDS - cl_t0))" + rm -rf -- "$SANDBOX" || cl_ok=0 + if [ -z "${TEARDOWN_SAID:-}" ]; then + TEARDOWN_SAID=1 + if [ "$cl_ok" = 1 ]; then + teardown_report "$((SECONDS - cl_t0))" took + else + teardown_report "$((SECONDS - cl_t0))" failed + fi + fi fi return 0 } @@ -17284,24 +17304,6 @@ has "…by name" "$err" "--inventory-only is the door past ONE lane's close-ou if [ -n "$cg_had_lsr" ]; then export LANES_LANE_STATE_ROOT="$cg_lsr"; else unset LANES_LANE_STATE_ROOT; fi -# ----------------------------------------- the section clock reads every heading -# -# opensoft/openRepoTools#77, step 1a. A heading printed with a bare `echo` -# prints exactly as it always did and is NOT clocked, so its seconds would -# silently join the section before it and the table at the foot would blame -# the wrong one. Two readings of this file's own text hold that: no `echo "== ` -# is left, and by the time the last heading has opened, the clock holds one row -# for each `section` heading in the file — the preamble's, plus every heading's -# but the open one's — which is also the proof that none of them sits in a -# branch this run skipped. `grep -c` reads a FILE here, which always exists: -# it prints `0` and exits 1 on no match, so the `|| :` only keeps the status -# quiet. -is "every == heading in this suite goes through section, so each is clocked" \ - "$(grep -c '^echo "== ' "$SELF" || :)" 0 -is "…and the clock holds one row per heading by the last heading's start" \ - "$(printf '%s' "$SECTION_ROWS" | awk 'END { print NR + 0 }')" \ - "$(grep -c '^section "== ' "$SELF" || :)" - # ------------------------------------------------------- nothing real touched # # The check is that the suite CREATED nothing here, which is not the same as @@ -17343,6 +17345,28 @@ is "…and every log it did create is inside the sandbox workspace" \ is "the liveness fixture was still running when the run ended" \ "$(kill -0 "$LIVE_PID" 2>/dev/null && printf alive || printf gone)" alive +# THE SECTION CLOCK READS EVERY HEADING, asserted HERE, at the foot, and not +# above the guards: it must run after the last section has opened, or a section +# added where the next one naturally goes (just above `nothing real touched`) +# would be counted in the file and not yet in the clock, and turn this red for +# nothing. It is two readings, and it reads this file and its clock, not a +# fixture, so the liveness assertion above is still the last one about the RUN. +# opensoft/openRepoTools#77, step 1a. A heading printed with a bare `echo` +# prints exactly as it always did and is NOT clocked, so its seconds would +# silently join the section before it and the table below would blame the +# wrong one. First, no heading is spelled with `echo` any more, at any indent +# and in either quote. Second, by the last heading's start the clock holds one +# row for each `section` heading in the file — the preamble's, plus every +# heading's but the open one's — which also proves none of them sits in a +# branch this run skipped. `grep -c` reads a FILE here, which always exists: it +# prints `0` and exits 1 on no match, so the `|| :` only keeps the status quiet. +sc_bare_re="^[[:space:]]*echo[[:space:]]+[\"']== " +is "every == heading in this suite goes through section, so each is clocked" \ + "$(grep -cE "$sc_bare_re" "$SELF" || :)" 0 +is "…and the clock holds one row per heading by the last heading's start" \ + "$(printf '%s' "$SECTION_ROWS" | awk 'END { print NR + 0 }')" \ + "$(grep -c '^section "== ' "$SELF" || :)" + # THE TABLE OF opensoft/openRepoTools#77, step 1a: every section's wall time, # longest first, and the same table in the job's step summary. It is printed # HERE, above the rule, because the footer below must stay the LAST line on From bd494dd4c59d229f2dc4e407e7d61cbd0d6d505b Mon Sep 17 00:00:00 2001 From: Brett Heap Date: Mon, 19 Oct 2026 14:12:11 +0000 Subject: [PATCH 3/6] The shell suite's wrapper prints the suite's timing table and teardown line on a pass, where CI's log can read them (#77, step 1b) Step 1a made tests/test_lane_helpers.sh time each of its sections and its sandbox teardown, but the numbers went only to the suite's own stdout/stderr and to $GITHUB_STEP_SUMMARY. On a PASS the wrapper (tests/test_lane_helpers_suite.py) captures both streams and throws them away, so the table is in no log that `gh run view --log` returns, and the step summary is open only to someone signed in to the web UI. #77 needs the numbers readable. The wrapper now, after both of its assertions have passed, prints the table (the line starting "wall time per section, longest first" and its rows) and the teardown line to pytest's real output through capsys.disabled(), under a one-line lead. A suite that printed no table or no teardown line is said to have printed none, and never fails the run. A failing run is untouched: its whole transcript is already in the assertion message and is not printed twice. capsys.disabled() is reached through an autouse fixture, not a parameter on test_the_lane_helper_suite_passes: tests/test_lane_helpers_suite_timeout.py calls that function with no arguments at six call sites. run_in_own_group, stop_group and the timeout and signal handling are not touched. Five tests: three run the wrapper's real test in a child pytest over a stand-in suite (a pass shows its table once, a failure says its transcript once with no second table, a pass with no clock gets the note), one holds the parser to the table and the teardown line, and one holds the wrapper's strings to the printf lines of the suite itself. Part of #77. Co-Authored-By: Claude Sonnet 5.5 --- tests/test_lane_helpers_suite.py | 237 ++++++++++++++++++++++++++++++- 1 file changed, 236 insertions(+), 1 deletion(-) diff --git a/tests/test_lane_helpers_suite.py b/tests/test_lane_helpers_suite.py index 8c22aab5..7bc36091 100644 --- a/tests/test_lane_helpers_suite.py +++ b/tests/test_lane_helpers_suite.py @@ -15,7 +15,10 @@ implementation of the suite's own reporting and a second thing to keep right. What pytest needs to know is one bit: did every assertion pass? So this runs the file, and on failure prints the WHOLE transcript into the assertion -message, which is what a person reading a red CI job actually needs. +message, which is what a person reading a red CI job actually needs. A PASS +prints only the suite's own account of where its time went (`show_timings`, +opensoft/openRepoTools#77), because a green job is where nobody reads the +transcript and where that one account is wanted. IT TOUCHES NOTHING REAL. The suite redirects `$HOME`, `$TMPDIR`, `$AGENT_PROTOCOL_ROOT` and `$OPENREPOTOOLS_BIN_DIR` into a `mktemp -d` sandbox @@ -33,6 +36,7 @@ import shutil import signal import subprocess +import sys import threading import time from pathlib import Path @@ -282,6 +286,93 @@ def note(signum, _frame): os.kill(os.getpid(), pending[0]) +#: WHAT THE SUITE SAYS ABOUT ITS OWN CLOCK (opensoft/openRepoTools#77, step 1a +#: put it in the suite; step 1b is this file carrying it out). The two strings +#: are the ones `tests/test_lane_helpers.sh` prints, and +#: `test_the_wrapper_looks_for_what_the_suite_prints` reads that file to hold +#: them to it: the table's first line on STDOUT, whose rows follow it up to the +#: rule that precedes the footer, and the teardown line on STDERR, said by the +#: exit trap after the footer by nature. +TIMING_HEADER = "wall time per section, longest first" +TEARDOWN_PREFIX = "teardown: rm -rf of the sandbox" + +#: A row of that table: `%6s s %3s%% `. +_TIMING_ROW = re.compile(r"^\s*\d+ s\s") + + +def suite_timings(stdout: str, stderr: str) -> tuple[list[str], list[str]]: + """The suite's timing table and its teardown line, each as lines, or as an + empty list where the suite printed none. Reads text only and cannot fail: + what to do about a missing one is `show_timings`' to say.""" + table: list[str] = [] + lines = stdout.splitlines() + for at, line in enumerate(lines): + if line.startswith(TIMING_HEADER): + table = [line] + for row in lines[at + 1:]: + if not _TIMING_ROW.match(row): + break + table.append(row) + break + teardown = [ln for ln in stderr.splitlines() if ln.startswith(TEARDOWN_PREFIX)] + return table, teardown + + +#: HOW `show_timings` SPEAKS PAST PYTEST'S CAPTURE: a context manager that +#: suspends it. It is `capsys.disabled` while one of THIS module's tests runs, +#: put there by the fixture below, and a no-op anywhere else. +_past_capture = contextlib.nullcontext + + +@pytest.fixture(autouse=True) +def _speak_past_capture(capsys, monkeypatch): + """Give `show_timings` the one fixture it needs WITHOUT A PARAMETER ON THE + TEST. `tests/test_lane_helpers_suite_timeout.py` calls + `test_the_lane_helper_suite_passes()` itself, with no arguments, at six call + sites, so that the call site and not a copy of it is what it proves; a + `capsys` parameter would make every one a TypeError. Called from there the + fixture is not in play (it is this module's, and autouse only reaches this + module's tests), `_past_capture` stays a no-op, and the block goes into the + capture a passing test discards: nothing there reads it.""" + monkeypatch.setitem(globals(), "_past_capture", capsys.disabled) + + +def show_timings(proc) -> None: + """Print a PASSING suite's timings to pytest's real output. + + WHY THIS EXISTS (opensoft/openRepoTools#77). A passing run's stdout and + stderr were both captured here and dropped, so the numbers step 1a added + reached no log `gh run view --log` returns, and a step summary only a + person signed in to the web UI can open. + + `capsys.disabled()` AND NOT A PRINT: pytest captures at the file + descriptor, so `print` and even `sys.__stdout__` land in the capture + buffer, which a passing test throws away. The fixture is the supported way + to speak past it, and it keeps the data inside this file. A + `pytest_terminal_summary` hook in `conftest.py` (there is one, for the test + roots) would print at the foot of the log instead, but it needs this test to + leave the numbers somewhere for the hook to find, in a file every other + test shares. What the fixture costs is the block's place: it lands in + `-q`'s row of dots, at the moment the test passes, so it opens and closes + with a newline. + + A MISSING TABLE OR TEARDOWN LINE IS SAID, AND NEVER FAILS THE RUN: a suite + that stopped printing its clock is a regression `gh run view` would + otherwise hide for ever, and a timing table is not a reason to turn a green + run red. THE CALLER PRINTS ONLY AFTER ITS ASSERTIONS HAVE PASSED, so a + failing run says its transcript once, in the assertion message, and not + again here.""" + table, teardown = suite_timings(proc.stdout, proc.stderr) + block = [f"{SUITE.name} passed; its own clock, which a pass would otherwise " + "discard (opensoft/openRepoTools#77):"] + block += table or [f"(no timing table: no line of its stdout starts " + f"{TIMING_HEADER!r})"] + block += teardown or [f"(no teardown line: no line of its stderr starts " + f"{TEARDOWN_PREFIX!r})"] + with _past_capture(): + print("\n" + "\n".join(block) + "\n", flush=True) + + @WINDOWS_SKIP @pytest.mark.skipif(shutil.which("bash") is None, reason="the lane helpers and their suite are bash") @@ -321,3 +412,147 @@ def test_the_lane_helper_suite_passes(): # The footer, read rather than assumed: a suite that exited 0 having run # nothing at all would otherwise pass this. assert " passed, 0 failed" in proc.stdout, proc.stdout[-2000:] + show_timings(proc) + + +# --- the timings a pass prints (opensoft/openRepoTools#77, step 1b) --------- + +#: A STAND-IN FOR THE SUITE, in the shape step 1a gave its output: a heading, +#: a case, the table of its sections with its rule, the footer, and the +#: teardown line on stderr after it. `table=False` is a suite that prints no +#: clock; `failing` is one whose footer counts a failure and which exits 1. +_STAND_IN = """#!/usr/bin/env bash +echo "== a heading ==" +echo "ok a case" +{table}echo "----" +echo "{footer}" +echo "teardown: rm -rf of the sandbox took 3 s" >&2 +exit {status} +""" +_STAND_IN_TABLE = """echo 'wall time per section, longest first (whole seconds; opensoft/openRepoTools#77):' +echo ' 12 s 60% the slow section' +echo ' 8 s 40% the quick section' +echo ' 20 s 100% the whole run, from the top of this file to this table' +""" + +#: THE REAL TEST, RUN BY A CHILD PYTEST over this very file, with its own +#: fixtures and signature, and with the suite it runs swapped for a stand-in by +#: this plugin. A copy of its body here would prove the copy; and a child and +#: not this process, because what is under test is what pytest's REAL output +#: holds, which `capsys` and `capfd` in a test that is itself captured cannot +#: say. +_CHILD_PLUGIN = '''\ +import os +from pathlib import Path + +import pytest + + +@pytest.fixture(autouse=True) +def stand_in_suite(monkeypatch): + import test_lane_helpers_suite as wrapper + monkeypatch.setattr(wrapper, "SUITE", Path(os.environ["STAND_IN_SUITE"])) +''' + + +def run_wrapper_over(tmp_path, *, table=True, failing=False): + """Run the wrapper's own test, as `pytest tests -q` runs it, over a + stand-in suite. Returns that run's output split into lines.""" + stand_in = tmp_path / "stand-in-suite.sh" + stand_in.write_text(_STAND_IN.format( + table=_STAND_IN_TABLE if table else "", + footer="1 passed, 1 failed, 0 skipped, 0 pending" if failing + else "2 passed, 0 failed, 0 skipped, 0 pending", + status=1 if failing else 0), encoding="utf-8") + (tmp_path / "stand_in_plugin.py").write_text(_CHILD_PLUGIN, encoding="utf-8") + env = dict(os.environ, STAND_IN_SUITE=str(stand_in), + PYTHONPATH=os.pathsep.join( + [str(tmp_path), *filter(None, [os.environ.get("PYTHONPATH")])]), + PYTHONDONTWRITEBYTECODE="1") + for name in ("PYTEST_ADDOPTS", "PYTEST_PLUGINS", "PYTEST_CURRENT_TEST"): + env.pop(name, None) + proc = run_in_own_group( + [sys.executable, "-m", "pytest", "-q", "-p", "no:cacheprovider", + "-p", "stand_in_plugin", + f"{Path(__file__).resolve()}::test_the_lane_helper_suite_passes"], + timeout=600, cwd=str(tmp_path), env=env) + return proc, (proc.stdout + proc.stderr).splitlines() + + +def lines_ending(lines, text): + """How many lines of the output end in `text`: a row of the stand-in's + table, whether bare (a pass) or after pytest's `E ` (a failure's message). + A failure's assertion explanation holds the whole `CompletedProcess` as one + escaped line, which ends in something else and so is not counted.""" + return sum(1 for ln in lines if ln.rstrip().endswith(text)) + + +@WINDOWS_SKIP +@pytest.mark.skipif(shutil.which("bash") is None, + reason="the lane helpers and their suite are bash") +def test_a_passing_suite_shows_its_timings_in_pytests_own_output(tmp_path): + proc, lines = run_wrapper_over(tmp_path) + assert proc.returncode == 0, "\n".join(lines) + assert lines_ending(lines, "the slow section") == 1, "\n".join(lines) + assert lines_ending(lines, "the quick section") == 1, "\n".join(lines) + assert lines_ending(lines, "to this table") == 1, "\n".join(lines) + assert lines_ending(lines, "teardown: rm -rf of the sandbox took 3 s") == 1, ( + "\n".join(lines)) + assert lines_ending(lines, "opensoft/openRepoTools#77):") == 2, ( + "the table's own header and the lead line over it, once each:\n" + + "\n".join(lines)) + # What the suite printed that is NOT its clock stays out of a green log. + assert lines_ending(lines, "ok a case") == 0, "\n".join(lines) + + +@WINDOWS_SKIP +@pytest.mark.skipif(shutil.which("bash") is None, + reason="the lane helpers and their suite are bash") +def test_a_failing_suite_says_its_transcript_once_and_no_second_table(tmp_path): + proc, lines = run_wrapper_over(tmp_path, failing=True) + assert proc.returncode != 0, "\n".join(lines) + # In the assertion message, which holds the whole transcript: once. + assert lines_ending(lines, "the slow section") == 1, "\n".join(lines) + assert lines_ending(lines, "teardown: rm -rf of the sandbox took 3 s") == 1, ( + "\n".join(lines)) + assert not any("its own clock" in ln for ln in lines), ( + "a failing run printed the passing run's lead line:\n" + "\n".join(lines)) + + +@WINDOWS_SKIP +@pytest.mark.skipif(shutil.which("bash") is None, + reason="the lane helpers and their suite are bash") +def test_a_passing_suite_that_printed_no_clock_is_said_to_have_none(tmp_path): + proc, lines = run_wrapper_over(tmp_path, table=False) + assert proc.returncode == 0, "\n".join(lines) + assert any(ln.startswith("(no timing table: ") for ln in lines), "\n".join(lines) + + +def test_the_timings_are_the_table_and_the_teardown_line_and_nothing_else(): + stdout = ("== a heading ==\nok a case\n" + "wall time per section, longest first (whole seconds; x):\n" + " 12 s 60% the slow section\n" + " 20 s 100% the whole run\n" + "----\n" + "2 passed, 0 failed, 0 skipped, 0 pending\n") + stderr = ("a note\nteardown: rm -rf of the sandbox took 3 s\n" + "teardown: rm -rf of the sandbox FAILED after 4 s, so part of it is left\n") + table, teardown = suite_timings(stdout, stderr) + assert table == [ + "wall time per section, longest first (whole seconds; x):", + " 12 s 60% the slow section", + " 20 s 100% the whole run"] + assert teardown == [ + "teardown: rm -rf of the sandbox took 3 s", + "teardown: rm -rf of the sandbox FAILED after 4 s, so part of it is left"] + assert suite_timings("no table here\n", "") == ([], []) + + +def test_the_wrapper_looks_for_what_the_suite_prints(): + """The strings above are copies, and a copy nobody holds to its original + reads as a pass that silently prints nothing. Hold them to the suite's + own `printf`s.""" + text = SUITE.read_text(encoding="utf-8") + assert f"printf '{TIMING_HEADER}" in text, "the table's header moved" + assert f"printf '{TEARDOWN_PREFIX}" in text, "the teardown line moved" + assert "'%6s s %3s%% %s'" in text, "a row of the table changed shape" From 458f8314e5ede13c2abf800c7f8d18f4ab2310f9 Mon Sep 17 00:00:00 2001 From: Brett Heap Date: Mon, 19 Oct 2026 15:18:12 +0000 Subject: [PATCH 4/6] The wrapper's failing-suite test no longer counts how often pytest repeats a failure message, which CI's environment changes (#77, step 1b fix round) On the first CI run of this PR the real suite passed and its timing block was in the tests job's log, but test_a_failing_suite_says_its_transcript_once_and_ no_second_table failed in tests and tests-no-submodule with "assert 2 == 1". Its child pytest inherits CI=true from the runner, and pytest prints the whole assertion message in its short summary when CI is set (the first line only elsewhere), so the stand-in's table row appeared twice there and once on a workstation. The count was never what the test is about. The test is now test_a_failing_suite_prints_no_timings_block_beside_its_ transcript: the transcript must be in the child's output at least once, and the lead line that every block show_timings prints opens with must not be, so a wrapper that printed on a failure still fails it. Part of #77. Co-Authored-By: Claude Sonnet 5.5 --- tests/test_lane_helpers_suite.py | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) diff --git a/tests/test_lane_helpers_suite.py b/tests/test_lane_helpers_suite.py index 7bc36091..b4321578 100644 --- a/tests/test_lane_helpers_suite.py +++ b/tests/test_lane_helpers_suite.py @@ -508,13 +508,21 @@ def test_a_passing_suite_shows_its_timings_in_pytests_own_output(tmp_path): @WINDOWS_SKIP @pytest.mark.skipif(shutil.which("bash") is None, reason="the lane helpers and their suite are bash") -def test_a_failing_suite_says_its_transcript_once_and_no_second_table(tmp_path): +def test_a_failing_suite_prints_no_timings_block_beside_its_transcript(tmp_path): proc, lines = run_wrapper_over(tmp_path, failing=True) assert proc.returncode != 0, "\n".join(lines) - # In the assertion message, which holds the whole transcript: once. - assert lines_ending(lines, "the slow section") == 1, "\n".join(lines) - assert lines_ending(lines, "teardown: rm -rf of the sandbox took 3 s") == 1, ( + # The transcript is in the assertion message, and that it is THERE is all + # that is counted: how many times pytest repeats the message is not this + # file's to pin. Its short summary prints the whole message where `CI` is + # set in the environment (GitHub's runners set it, and the child inherits + # it) and the first line anywhere else, so a count of one held on a + # workstation and read two on the runner. + assert lines_ending(lines, "the slow section") >= 1, "\n".join(lines) + assert lines_ending(lines, "teardown: rm -rf of the sandbox took 3 s") >= 1, ( "\n".join(lines)) + # What is pinned is that the wrapper said nothing of its own: every block + # `show_timings` prints opens with its lead line, which names the run a + # PASS. assert not any("its own clock" in ln for ln in lines), ( "a failing run printed the passing run's lead line:\n" + "\n".join(lines)) From 0bf05e44a2e4dd8355fb83c62a84333136fafc89 Mon Sep 17 00:00:00 2001 From: Brett Heap Date: Mon, 19 Oct 2026 18:34:24 +0000 Subject: [PATCH 5/6] The wrapper's child pytest no longer inherits colour or CI settings, a pass prints its block on any stdout and without pytest's capture plugin, and a negative row no longer ends the table (#77, step 1b, review round) Independent review of #265 found one blocking and five smaller faults. Blocking: run_wrapper_over's child pytest inherited the runner's environment. With FORCE_COLOR=1 or PY_COLORS=1 its `E` lines end in an escape sequence, so lines_ending counted nothing and the failing-suite test went red (1 failed, 5 passed, under each, on pytest 9.1.1 and 8.3.4). The child now gets PY_COLORS=0, which pytest reads before NO_COLOR, FORCE_COLOR and the tty, and loses CI, BUILD_NUMBER, NO_COLOR and FORCE_COLOR, so its output is the same on a workstation and a runner. The failing-suite test is parametrized over what a runner may set and also pins that no escape sequence appears. Smaller: - show_timings cuts the block to what stdout's own encoding can say, with \uXXXX for the rest, and lets an OSError go: the real table carries em dashes and a plain print raised UnicodeEncodeError under PYTHONIOENCODING= ascii, after the test had passed. New case with PYTHONIOENCODING=ascii. - the autouse fixture asks for capsys through request.getfixturevalue and falls back to the no-op when it is missing, so `-p no:capture` no longer turns every test in the module into an error. New case runs the real test and a pure one under it. - the drift test holds BOTH teardown wordings ("took" and "FAILED after") to the suite's printf lines, so rewording only one fails it. - the row pattern accepts negative seconds (bash's SECONDS can step back), so such a row no longer ends the table and loses the whole-run row. New parser case. - two comments at the head of tests/test_lane_helpers.sh still said the wrapper throws a passing run's output away; they now say what it prints. Nothing else in that file changes. Part of #77. Co-Authored-By: Claude Sonnet 5.5 --- tests/test_lane_helpers.sh | 15 +-- tests/test_lane_helpers_suite.py | 164 ++++++++++++++++++++++++++----- 2 files changed, 148 insertions(+), 31 deletions(-) diff --git a/tests/test_lane_helpers.sh b/tests/test_lane_helpers.sh index 27c09c3e..9d166e8b 100755 --- a/tests/test_lane_helpers.sh +++ b/tests/test_lane_helpers.sh @@ -67,9 +67,11 @@ done # anybody has is the whole of it: lane 1's one instrumented run on WSL put 56% of # the wall in the exit trap's `rm -rf "$SANDBOX"` and 57% of the rest in two # sections, from ONE run, under contention, on one workstation. Nothing about a -# CI runner's own split was ever printed, and the pytest wrapper prints this -# file's transcript only when the suite FAILS, so a green run said nothing at -# all. Three things, all of them reading and none of them changing what is run: +# CI runner's own split was ever printed, and the pytest wrapper printed this +# file's transcript only when the suite FAILED, so a green run said nothing at +# all (step 1b: the wrapper now prints the table and the teardown line below on +# a pass too). Three things, all of them reading and none of them changing what +# is run: # # `section "== … =="` prints a heading exactly as `echo` did and stamps the # clock beside it, so each section's whole-second wall @@ -80,9 +82,10 @@ done # `cleanup` times its own `rm -rf` and says so on stderr. # # AND BOTH GO TO THE JOB'S STEP SUMMARY where CI names one. A passing run's -# stdout and stderr are both captured by the wrapper and thrown away, so a -# table that only reached them would be one nobody reads on the runs that -# matter. `$GITHUB_STEP_SUMMARY` is a file the runner reads after the step, it +# stdout and stderr are both captured by the wrapper, which prints from them +# only the table and the teardown line (step 1b) and drops the rest. The step +# summary is the formatted copy, for a person signed in to the web UI. +# `$GITHUB_STEP_SUMMARY` is a file the runner reads after the step, it # is an absolute path and survives the `HOME` and `TMPDIR` this suite moves # below, and a write to it that fails is a note on stderr and never a failed # assertion: a timing table is not a reason to turn a green run red. diff --git a/tests/test_lane_helpers_suite.py b/tests/test_lane_helpers_suite.py index b4321578..698857c9 100644 --- a/tests/test_lane_helpers_suite.py +++ b/tests/test_lane_helpers_suite.py @@ -296,8 +296,11 @@ def note(signum, _frame): TIMING_HEADER = "wall time per section, longest first" TEARDOWN_PREFIX = "teardown: rm -rf of the sandbox" -#: A row of that table: `%6s s %3s%% `. -_TIMING_ROW = re.compile(r"^\s*\d+ s\s") +#: A row of that table: `%6s s %3s%% `. The seconds may be NEGATIVE: +#: they are differences of bash's `SECONDS`, which a clock step can send +#: backwards, and a row the pattern did not know would end the table there and +#: lose every row after it, the whole-run row among them. +_TIMING_ROW = re.compile(r"^\s*-?\d+ s\s") def suite_timings(stdout: str, stderr: str) -> tuple[list[str], list[str]]: @@ -325,7 +328,7 @@ def suite_timings(stdout: str, stderr: str) -> tuple[list[str], list[str]]: @pytest.fixture(autouse=True) -def _speak_past_capture(capsys, monkeypatch): +def _speak_past_capture(request, monkeypatch): """Give `show_timings` the one fixture it needs WITHOUT A PARAMETER ON THE TEST. `tests/test_lane_helpers_suite_timeout.py` calls `test_the_lane_helper_suite_passes()` itself, with no arguments, at six call @@ -333,7 +336,16 @@ def _speak_past_capture(capsys, monkeypatch): `capsys` parameter would make every one a TypeError. Called from there the fixture is not in play (it is this module's, and autouse only reaches this module's tests), `_past_capture` stays a no-op, and the block goes into the - capture a passing test discards: nothing there reads it.""" + capture a passing test discards: nothing there reads it. + + `capsys` IS ASKED FOR, NOT REQUIRED. Under `-p no:capture` the fixture does + not exist, and a parameter named `capsys` on an AUTOUSE fixture would make + every test in this file, the liveness test among them, an ERROR for it. + Nothing captures there, so nothing needs suspending, and the no-op serves.""" + try: + capsys = request.getfixturevalue("capsys") + except LookupError: # pytest's FixtureLookupError is one + return monkeypatch.setitem(globals(), "_past_capture", capsys.disabled) @@ -361,7 +373,15 @@ def show_timings(proc) -> None: otherwise hide for ever, and a timing table is not a reason to turn a green run red. THE CALLER PRINTS ONLY AFTER ITS ASSERTIONS HAVE PASSED, so a failing run says its transcript once, in the assertion message, and not - again here.""" + again here. + + THE SAME RULE MAKES THE WRITE ITSELF SAFE. The suite's headings carry em + dashes, and a stdout that cannot spell one (`PYTHONIOENCODING=ascii`, a + stray `LANG`) would raise `UnicodeEncodeError` from a plain `print`, in a + test that had already passed. So the block is cut down to what the stream's + own encoding can say, with `\\uXXXX` for the rest, and a stream that cannot + be written to at all (an `OSError`) is let go: the numbers are lost and the + run is not.""" table, teardown = suite_timings(proc.stdout, proc.stderr) block = [f"{SUITE.name} passed; its own clock, which a pass would otherwise " "discard (opensoft/openRepoTools#77):"] @@ -369,8 +389,12 @@ def show_timings(proc) -> None: f"{TIMING_HEADER!r})"] block += teardown or [f"(no teardown line: no line of its stderr starts " f"{TEARDOWN_PREFIX!r})"] + text = "\n" + "\n".join(block) + "\n" with _past_capture(): - print("\n" + "\n".join(block) + "\n", flush=True) + encoding = getattr(sys.stdout, "encoding", None) or "ascii" + text = text.encode(encoding, "backslashreplace").decode(encoding) + with contextlib.suppress(OSError): + print(text, flush=True) @WINDOWS_SKIP @@ -429,9 +453,11 @@ def test_the_lane_helper_suite_passes(): echo "teardown: rm -rf of the sandbox took 3 s" >&2 exit {status} """ +#: The third row carries an em dash, as the real suite's headings do. _STAND_IN_TABLE = """echo 'wall time per section, longest first (whole seconds; opensoft/openRepoTools#77):' echo ' 12 s 60% the slow section' echo ' 8 s 40% the quick section' +echo ' 0 s 0% a row with a dash \u2014 in it' echo ' 20 s 100% the whole run, from the top of this file to this table' """ @@ -441,7 +467,7 @@ def test_the_lane_helper_suite_passes(): #: not this process, because what is under test is what pytest's REAL output #: holds, which `capsys` and `capfd` in a test that is itself captured cannot #: say. -_CHILD_PLUGIN = '''\ +_CHILD_PLUGIN = """\ import os from pathlib import Path @@ -452,12 +478,32 @@ def test_the_lane_helper_suite_passes(): def stand_in_suite(monkeypatch): import test_lane_helpers_suite as wrapper monkeypatch.setattr(wrapper, "SUITE", Path(os.environ["STAND_IN_SUITE"])) -''' +""" + +#: WHAT THE CHILD IS NOT TO INHERIT. Each of these changes how pytest WRITES, +#: not what it says, and a test that reads its output line by line must not +#: depend on which of them the runner set. `CI` and `BUILD_NUMBER` make pytest +#: print a whole failure message in its short summary where it prints the first +#: line elsewhere; `NO_COLOR` and `FORCE_COLOR` are two of the four things that +#: decide whether it colours. The fourth is the terminal, which a pipe is not, +#: and the first, `PY_COLORS`, is read before the rest, so it is SET to "0" +#: below rather than only removed: a runner that exports `FORCE_COLOR=1` and a +#: `PY_COLORS=1` ends every `E` line in an escape sequence, and `lines_ending` +#: then counts nothing. +_CHILD_NOT_INHERITED = ("PYTEST_ADDOPTS", "PYTEST_PLUGINS", "PYTEST_CURRENT_TEST", + "CI", "BUILD_NUMBER", "NO_COLOR", "FORCE_COLOR") +_REAL_TEST = "test_the_lane_helper_suite_passes" -def run_wrapper_over(tmp_path, *, table=True, failing=False): + +def run_wrapper_over(tmp_path, *, table=True, failing=False, inherited=None, + env_extra=None, args=(), tests=(_REAL_TEST,)): """Run the wrapper's own test, as `pytest tests -q` runs it, over a - stand-in suite. Returns that run's output split into lines.""" + stand-in suite. Returns the child's process and its output as lines. + + `inherited` is what the CHILD'S PARENT is imagined to have set, which the + child must not see; `env_extra` is what it IS to see; `args` are more + pytest options and `tests` the names, in this file, it is to run.""" stand_in = tmp_path / "stand-in-suite.sh" stand_in.write_text(_STAND_IN.format( table=_STAND_IN_TABLE if table else "", @@ -465,16 +511,18 @@ def run_wrapper_over(tmp_path, *, table=True, failing=False): else "2 passed, 0 failed, 0 skipped, 0 pending", status=1 if failing else 0), encoding="utf-8") (tmp_path / "stand_in_plugin.py").write_text(_CHILD_PLUGIN, encoding="utf-8") - env = dict(os.environ, STAND_IN_SUITE=str(stand_in), - PYTHONPATH=os.pathsep.join( - [str(tmp_path), *filter(None, [os.environ.get("PYTHONPATH")])]), - PYTHONDONTWRITEBYTECODE="1") - for name in ("PYTEST_ADDOPTS", "PYTEST_PLUGINS", "PYTEST_CURRENT_TEST"): + env = dict(os.environ, **(inherited or {})) + for name in _CHILD_NOT_INHERITED: env.pop(name, None) + env.update( + STAND_IN_SUITE=str(stand_in), PY_COLORS="0", PYTHONDONTWRITEBYTECODE="1", + PYTHONPATH=os.pathsep.join( + [str(tmp_path), *filter(None, [os.environ.get("PYTHONPATH")])]), + **(env_extra or {})) proc = run_in_own_group( [sys.executable, "-m", "pytest", "-q", "-p", "no:cacheprovider", - "-p", "stand_in_plugin", - f"{Path(__file__).resolve()}::test_the_lane_helper_suite_passes"], + "-p", "stand_in_plugin", *args, + *(f"{Path(__file__).resolve()}::{name}" for name in tests)], timeout=600, cwd=str(tmp_path), env=env) return proc, (proc.stdout + proc.stderr).splitlines() @@ -505,18 +553,34 @@ def test_a_passing_suite_shows_its_timings_in_pytests_own_output(tmp_path): assert lines_ending(lines, "ok a case") == 0, "\n".join(lines) +#: What a runner may have set that the child is not to see: the colour +#: variables and `CI`, alone and together. +_RUNNER_SETS = [ + pytest.param({"FORCE_COLOR": "1"}, id="FORCE_COLOR=1"), + pytest.param({"PY_COLORS": "1"}, id="PY_COLORS=1"), + pytest.param({"CI": "true"}, id="CI=true"), + pytest.param({"CI": "true", "FORCE_COLOR": "1"}, id="CI=true+FORCE_COLOR=1"), + pytest.param({"BUILD_NUMBER": "7"}, id="BUILD_NUMBER=7"), + pytest.param({}, id="nothing"), +] + + @WINDOWS_SKIP @pytest.mark.skipif(shutil.which("bash") is None, reason="the lane helpers and their suite are bash") -def test_a_failing_suite_prints_no_timings_block_beside_its_transcript(tmp_path): - proc, lines = run_wrapper_over(tmp_path, failing=True) +@pytest.mark.parametrize("inherited", _RUNNER_SETS) +def test_a_failing_suite_prints_no_timings_block_beside_its_transcript( + tmp_path, inherited): + proc, lines = run_wrapper_over(tmp_path, failing=True, inherited=inherited) assert proc.returncode != 0, "\n".join(lines) + # The child's output is the same whatever the runner set: no escape + # sequence ends a row (the lines below are counted by how they END), and + # the same message is printed the same number of times. + assert not any("\x1b[" in ln for ln in lines), ( + "the child coloured its output:\n" + "\n".join(lines)) # The transcript is in the assertion message, and that it is THERE is all # that is counted: how many times pytest repeats the message is not this - # file's to pin. Its short summary prints the whole message where `CI` is - # set in the environment (GitHub's runners set it, and the child inherits - # it) and the first line anywhere else, so a count of one held on a - # workstation and read two on the runner. + # file's to pin. assert lines_ending(lines, "the slow section") >= 1, "\n".join(lines) assert lines_ending(lines, "teardown: rm -rf of the sandbox took 3 s") >= 1, ( "\n".join(lines)) @@ -536,6 +600,37 @@ def test_a_passing_suite_that_printed_no_clock_is_said_to_have_none(tmp_path): assert any(ln.startswith("(no timing table: ") for ln in lines), "\n".join(lines) +@WINDOWS_SKIP +@pytest.mark.skipif(shutil.which("bash") is None, + reason="the lane helpers and their suite are bash") +def test_a_stdout_that_cannot_spell_the_table_does_not_fail_a_pass(tmp_path): + """The real suite's headings carry em dashes. On an ASCII stdout the block + is written with `\\uXXXX` in their place, and the run stays green.""" + proc, lines = run_wrapper_over(tmp_path, env_extra={"PYTHONIOENCODING": "ascii"}) + assert proc.returncode == 0, "\n".join(lines) + assert any(ln.endswith("a row with a dash \\u2014 in it") for ln in lines), ( + "\n".join(lines)) + assert not any("UnicodeEncodeError" in ln for ln in lines), "\n".join(lines) + + +@WINDOWS_SKIP +@pytest.mark.skipif(shutil.which("bash") is None, + reason="the lane helpers and their suite are bash") +def test_a_run_without_pytests_capture_plugin_still_runs_and_shows_the_block(tmp_path): + """`-p no:capture` removes the `capsys` fixture. The fixture that asks for + it must not turn every test in this file into an ERROR (here the real test + and a pure one, both of them this file's), and with nothing capturing, the + block is on the output as it is.""" + proc, lines = run_wrapper_over( + tmp_path, args=("-p", "no:capture"), + tests=(_REAL_TEST, + "test_the_timings_are_the_table_and_the_teardown_line_and_nothing_else")) + assert proc.returncode == 0, "\n".join(lines) + assert not any("capsys" in ln for ln in lines), "\n".join(lines) + assert any("2 passed" in ln for ln in lines), "\n".join(lines) + assert lines_ending(lines, "the slow section") == 1, "\n".join(lines) + + def test_the_timings_are_the_table_and_the_teardown_line_and_nothing_else(): stdout = ("== a heading ==\nok a case\n" "wall time per section, longest first (whole seconds; x):\n" @@ -556,11 +651,30 @@ def test_the_timings_are_the_table_and_the_teardown_line_and_nothing_else(): assert suite_timings("no table here\n", "") == ([], []) +def test_a_row_of_negative_seconds_does_not_end_the_table(): + """bash's `SECONDS` can step backwards, and the suite prints the difference + as it is: ` -9 s -300% `.""" + stdout = ("wall time per section, longest first (whole seconds; x):\n" + " 12 s 400% the slow section\n" + " -9 s -300% a section the clock stepped back over\n" + " 0 s 0% (preamble, before the first heading)\n" + " 3 s 100% the whole run, from the top of this file to this table\n" + "----\n" + "2 passed, 0 failed, 0 skipped, 0 pending\n") + table, _ = suite_timings(stdout, "") + assert len(table) == 5, table + assert table[-1].endswith("to this table"), table + + def test_the_wrapper_looks_for_what_the_suite_prints(): """The strings above are copies, and a copy nobody holds to its original reads as a pass that silently prints nothing. Hold them to the suite's - own `printf`s.""" + own `printf`s: BOTH teardown wordings, because the wrapper takes either by + its prefix and rewording only one of them would otherwise go unseen.""" text = SUITE.read_text(encoding="utf-8") assert f"printf '{TIMING_HEADER}" in text, "the table's header moved" - assert f"printf '{TEARDOWN_PREFIX}" in text, "the teardown line moved" + assert f"printf '{TEARDOWN_PREFIX} took " in text, ( + "the teardown line's `took` wording moved") + assert f"printf '{TEARDOWN_PREFIX} FAILED after " in text, ( + "the teardown line's `FAILED after` wording moved") assert "'%6s s %3s%% %s'" in text, "a row of the table changed shape" From 4f3b18cfb03c1ce918736418625536cfd3ea5c7c Mon Sep 17 00:00:00 2001 From: Brett Heap Date: Mon, 19 Oct 2026 22:50:39 +0000 Subject: [PATCH 6/6] The wrapper's timing block is tested against a stdout that raises OSError, its capsys fallback lets go of pytest's own FixtureLookupError only, and the child's env pops say which colour guard is pinned (#77, step 1b, polish round) Lane 5's delta review of 458f831..b752cd2 is LAND with five non-blocking findings. This takes its findings 1, 2 and 3 (finding 5 is the PR body only). 1. Nothing reached `contextlib.suppress(OSError)` in show_timings: with it removed, every test in the module still passed. New test test_a_stream_that_cannot_be_written_to_does_not_fail_a_pass writes the block into a stream that raises ENOSPC (put where sys.stdout is only for the write, by a stand-in for capsys.disabled()) and asks that the write was attempted and the call returned. With only the suppress removed it fails with `OSError: [Errno 28] No space left on device` and the other fourteen still pass, on pytest 9.1.1 and on CI's 8.3.4. 2. The pops of CI, BUILD_NUMBER, NO_COLOR and FORCE_COLOR in run_wrapper_over are belt and braces: only PY_COLORS="0" and the escape-sequence assertion are pinned. A comment now says so. No code changes there. 3. The autouse fixture caught LookupError, which is wider than what pytest raises when `capsys` is missing under `-p no:capture`: it now catches pytest.FixtureLookupError, so a fault of another kind is not read as "no capture plugin". The `-p no:capture` cases pass on both pytest versions. Part of #77. Co-Authored-By: Claude Sonnet 5.5 --- tests/test_lane_helpers_suite.py | 44 ++++++++++++++++++++++++++++++-- 1 file changed, 42 insertions(+), 2 deletions(-) diff --git a/tests/test_lane_helpers_suite.py b/tests/test_lane_helpers_suite.py index 698857c9..ad98b0e5 100644 --- a/tests/test_lane_helpers_suite.py +++ b/tests/test_lane_helpers_suite.py @@ -341,10 +341,12 @@ def _speak_past_capture(request, monkeypatch): `capsys` IS ASKED FOR, NOT REQUIRED. Under `-p no:capture` the fixture does not exist, and a parameter named `capsys` on an AUTOUSE fixture would make every test in this file, the liveness test among them, an ERROR for it. - Nothing captures there, so nothing needs suspending, and the no-op serves.""" + Nothing captures there, so nothing needs suspending, and the no-op serves. + Only pytest's own `FixtureLookupError` is let go: a wider clause would read + a fault of some other kind as "no capture plugin" and hide it.""" try: capsys = request.getfixturevalue("capsys") - except LookupError: # pytest's FixtureLookupError is one + except pytest.FixtureLookupError: # the capture plugin is off return monkeypatch.setitem(globals(), "_past_capture", capsys.disabled) @@ -512,6 +514,8 @@ def run_wrapper_over(tmp_path, *, table=True, failing=False, inherited=None, status=1 if failing else 0), encoding="utf-8") (tmp_path / "stand_in_plugin.py").write_text(_CHILD_PLUGIN, encoding="utf-8") env = dict(os.environ, **(inherited or {})) + # THE COLOUR TESTS PIN `PY_COLORS="0"`, set below, and the escape-sequence + # assertion; these pops only keep a runner's own settings out of the child. for name in _CHILD_NOT_INHERITED: env.pop(name, None) env.update( @@ -613,6 +617,42 @@ def test_a_stdout_that_cannot_spell_the_table_does_not_fail_a_pass(tmp_path): assert not any("UnicodeEncodeError" in ln for ln in lines), "\n".join(lines) +def test_a_stream_that_cannot_be_written_to_does_not_fail_a_pass(monkeypatch): + """`show_timings` lets an `OSError` from its write go (a full disk, a pipe + nobody reads): the numbers are lost and the run is not. NOTHING ELSE IN THIS + FILE REACHES THAT `suppress`, and with it removed every other test here + still passes, so this one writes into a stream that raises ENOSPC and asks + that the write was ATTEMPTED and that the call RETURNED. + + The stream is put where `sys.stdout` is by a stand-in for `capsys.disabled()` + (the autouse fixture's own would hand the real stdout back), and only for the + write, so nothing is left behind for the fixtures that tear down after this + test.""" + class Unwritable: + encoding = "utf-8" + attempts = 0 + + def write(self, text): + Unwritable.attempts += 1 + raise OSError(28, "No space left on device") + + def flush(self): + raise OSError(28, "No space left on device") + + @contextlib.contextmanager + def unwritable_stdout(): + with contextlib.redirect_stdout(Unwritable()): + yield + + monkeypatch.setitem(globals(), "_past_capture", unwritable_stdout) + show_timings(subprocess.CompletedProcess( + ["bash", "suite.sh"], 0, + stdout=f"{TIMING_HEADER} (whole seconds):\n 3 s 100% the whole run\n", + stderr="teardown: rm -rf of the sandbox took 0 s\n")) + assert Unwritable.attempts >= 1, ( + "the block was never written to the stream, so nothing was tested") + + @WINDOWS_SKIP @pytest.mark.skipif(shutil.which("bash") is None, reason="the lane helpers and their suite are bash")