Skip to content

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) - #265

Merged
brettheap merged 10 commits into
mainfrom
fix/suite-wrapper-prints-timings-77
Oct 20, 2026
Merged

brettheap merged 10 commits into
mainfrom
fix/suite-wrapper-prints-timings-77

Conversation

@brettheap

@brettheap brettheap commented Oct 19, 2026 •

Copy link
Copy Markdown
Contributor

Part of #77 (step 1b). Step 1a (#261) times each section of tests/test_lane_helpers.sh and its exit-trap teardown; this step makes a PASSING run's numbers readable in CI's log.

Review status: lane 5's delta review of 458f831..b752cd2 is LAND (nothing blocking); the polish round below takes its findings 1, 2, 3 and 5.

What was wrong

Step 1a prints its per-section table on the suite's stdout and its teardown line on stderr, and appends both to $GITHUB_STEP_SUMMARY. On a pass, the wrapper tests/test_lane_helpers_suite.py captures both streams (run_in_own_group, since #217) and drops them: it prints the transcript only inside the assertion message of a failure. So on a green run 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.

Pytest captures at the file descriptor, so print and even sys.__stdout__ inside a passing test are discarded as well (checked on pytest 9.1.1: of print, sys.__stdout__.write and capsys.disabled(), only the last reached the terminal).

What changed (the wrapper, and two comments)

After both of test_the_lane_helper_suite_passes' assertions have passed, show_timings(proc) prints, through capsys.disabled(), a one-line lead, the suite's timing table (the line starting wall time per section, longest first, with its rows) and its teardown: rm -rf of the sandbox ... line.

  • A suite that printed no table, or no teardown line, is said to have printed none ((no timing table: ...)); it never fails the run, which is step 1a's own rule. The same rule covers the write: the block is cut down to what stdout's own encoding can say (\uXXXX for the rest; the real headings carry em dashes) and an OSError is let go (both are tested).
  • A failing run is untouched, and prints nothing extra: its whole transcript is already in the assertion message, so nothing is said twice.
  • Why capsys.disabled() and not a pytest_terminal_summary hook in conftest.py (which already has one, for the test roots): it needs no state shared with a file every test uses, and it stays in the wrapper. The cost 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.
  • capsys is reached through an autouse fixture, not a parameter on the test: tests/test_lane_helpers_suite_timeout.py (Make the shell suite's wrapper stop the suite's process group on a timeout, interrupt, TERM or hangup, pin the launcher precedence of lane <name> with launchers the suite names, and say what the pty driver comment counts #217) calls test_the_lane_helper_suite_passes() itself, with no arguments, at six call sites, and a capsys parameter would make every one a TypeError. Called from there the fixture is not in play (it is this module's), _past_capture stays contextlib.nullcontext, and the block goes into the capture that call discards. The fixture asks for capsys with request.getfixturevalue and falls back to the no-op on pytest.FixtureLookupError only, so -p no:capture does not turn every test in the module into an error.
  • run_in_own_group, stop_group, the timeout and the signal handling are not touched. In tests/test_lane_helpers.sh only two comments in step 1a's header block change (they said the wrapper throws a passing run's output away).

Functions and regions edited:

  • tests/test_lane_helpers_suite.py: module docstring (one paragraph); import sys; new TIMING_HEADER, TEARDOWN_PREFIX, _TIMING_ROW, suite_timings, _past_capture, _speak_past_capture (autouse fixture), show_timings; test_the_lane_helper_suite_passes (one added line, after its last assertion); nine new tests at the foot, with their stand-in and helpers (_STAND_IN, _STAND_IN_TABLE, _CHILD_PLUGIN, _CHILD_NOT_INHERITED, _RUNNER_SETS, run_wrapper_over, lines_ending).
  • tests/test_lane_helpers.sh: two comment paragraphs in the step 1a header block (no code).

Tests

Nine new test functions (fourteen cases) in tests/test_lane_helpers_suite.py:

  • test_a_passing_suite_shows_its_timings_in_pytests_own_output, test_a_failing_suite_prints_no_timings_block_beside_its_transcript (six cases, one per thing a runner may set), test_a_passing_suite_that_printed_no_clock_is_said_to_have_none, test_a_stdout_that_cannot_spell_the_table_does_not_fail_a_pass and test_a_run_without_pytests_capture_plugin_still_runs_and_shows_the_block: each runs the wrapper's REAL test in a child pytest (pytest -q, no -s) over a stand-in suite script that prints a table, a footer and a teardown line, and reads the child's own output.
  • test_the_timings_are_the_table_and_the_teardown_line_and_nothing_else and test_a_row_of_negative_seconds_does_not_end_the_table: the parser, on strings.
  • test_a_stream_that_cannot_be_written_to_does_not_fail_a_pass: in process; writes the block into a stream that raises OSError (ENOSPC) and asks that the write was attempted and the call returned. Nothing else in the file reaches the suppress(OSError) in show_timings.
  • test_the_wrapper_looks_for_what_the_suite_prints: holds the wrapper's strings, both teardown wordings among them, to the printf lines of tests/test_lane_helpers.sh, so step 1a's output cannot change shape unnoticed.

Fail-before / pass-after of the first round (direct pytest under the shared flock, every LANES_*, TMUX*, WORKBENCHES_* unset; only these tests, never the full suite):

  • main's unchanged wrapper plus only the new tests: 4 failed (the pass test shows no table; the no-clock test shows no note; the parser and the drift test with NameError), 1 passed (the failing-suite test, which is a guard against printing before asserting).
  • with the change: all pass, together with test_the_liveness_fixture_outlives_the_suite_timeout.
  • isolated real-format check: step 1a's real section, section_report and teardown_report sourced from the suite and run under bash, their stdout and stderr fed to suite_timings: the table (header, four rows including an em dash heading, the whole-run row) and the one teardown line come back whole.

Fix round (independent review of 458f831: CHANGES, one blocking finding)

Blocking:

  1. The child pytest of run_wrapper_over inherited the runner's colour settings. With FORCE_COLOR=1 or PY_COLORS=1 its E lines end in an escape sequence, lines_ending counted nothing and the failing-suite test was red. The child now gets PY_COLORS=0 (pytest reads it 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 on a runner. The failing-suite test is parametrized over what a runner may set (FORCE_COLOR=1, PY_COLORS=1, CI=true, both, BUILD_NUMBER=7, nothing) and pins that no escape sequence reaches the child's output.

Smaller, all taken:
2. show_timings no longer raises UnicodeEncodeError on a non-UTF-8 stdout (it cuts the block to the stream's encoding with backslashreplace and lets an OSError go). New case under PYTHONIOENCODING=ascii, with an em dash in the stand-in's table.
3. The autouse fixture asks for capsys through request.getfixturevalue and falls back to the no-op when it is missing. New case runs the real test and a pure one under -p no:capture.
4. The drift test holds both teardown wordings (took and FAILED after) to the suite's printf lines.
5. The row pattern takes negative seconds (^\s*-?\d+ s\s: bash's SECONDS can step back), so such a row no longer ends the table and loses the whole-run row. New parser case.
6. The two stale comments at the head of tests/test_lane_helpers.sh now say what the wrapper prints. Nothing else in that file changes.

Evidence at b752cd2 (direct pytest under the shared flock, every lane variable unset; the "new tests" are the eight functions of that round, selected with the liveness test, so 14 cases and the real shell-suite test deselected):

  • Before, on a snapshot of 458f831, pytest 9.1.1 and 8.3.4 alike (the earlier six tests): clean env, CI=true, CI=true FORCE_COLOR=1 and BUILD_NUMBER=7 NO_COLOR=1 pass, FORCE_COLOR=1 gives 1 failed, 5 passed and PY_COLORS=1 gives 1 failed, 5 passed.
  • The new cases against the OLD production code (458f831's wrapper with only the new tests): 3 failed, 11 passed: the ASCII case with UnicodeEncodeError: 'ascii' codec can't encode character '—', the -p no:capture case with fixture 'capsys' not found, and the negative-row case with a two-line table where five were expected.
  • The drift test against a copy of the suite whose took printf alone is reworded: fails with the teardown line's took wording moved; the previous single-prefix assertion stayed green on it.
  • After, on this branch: the new tests and the liveness test pass (14 passed, 1 deselected) under pytest 9.1.1 and under CI's 8.3.4, each in a clean env, FORCE_COLOR=1, PY_COLORS=1, CI=true, CI=true FORCE_COLOR=1, NO_COLOR=1 BUILD_NUMBER=7 and an outer PYTHONIOENCODING=ascii.
  • tests/test_repo_hygiene.py, tests/test_test_roots.py and tests/test_lane_helpers_suite_timeout.py (the files that read the suite file or call the wrapper's test): 287 passed.

Polish round (lane 5's delta review of 458f831..b752cd2: LAND)

Non-blocking findings of that review, taken here (finding 4 needs no action):

  1. Nothing reached the 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, above. Fail-before, on a scratch copy of b752cd2 that carries this polish, with only that with removed: 1 failed, 14 passed, 1 deselected, the failure OSError: [Errno 28] No space left on device, on pytest 9.1.1 and on CI's 8.3.4. Pass-after: the module with tests/test_lane_helpers_suite_timeout.py gives 27 passed, 1 deselected on both, and the new test alone 1 passed.
  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 there now says so; no code changes.
  3. The fixture's except LookupError is now except pytest.FixtureLookupError, so a fault of another kind is not read as "no capture plugin". pytest.FixtureLookupError is _pytest.fixtures.FixtureLookupError, a LookupError, on both versions, and with -p no:capture the module gives 15 passed, 1 deselected on both.
  4. This body: the CI section below gives each job its own figures.

Run with every LANES_*, TMUX* and WORKBENCHES_* variable unset, CI and the colour variables unset, under the shared flock, and with -k 'not test_the_lane_helper_suite_passes'; never tests/run.sh and never the full suite.

CI

First run (d14e482): the real suite passed in the tests job and its block is in that job's log (test_lane_helpers.sh passed; its own clock ..., the 29-row table, teardown: rm -rf of the sandbox took 0 s); one failure, mine: the failing-suite test counted the row twice, because the child pytest inherits CI=true and pytest then prints the whole assertion message in its short summary. Fixed in 458f831.

Second run (458f831): green in every job; the tests job log carries the block (1958 passed, 51 skipped).

Third run (b752cd2: the fix round plus a merge of main at 00d52ae, run https://github.com/opensoft/openRepoTools/actions/runs/39321564950): green in every job, read by each job's completedAt. Each job printed its own block:

  • tests (job 118296641385): success at 21:51:23Z, 2010 passed, 51 skipped in 4113.27s. Block: the lead line, 29 section rows, 1815 s 100% the whole run, from the top of this file to this table, teardown: rm -rf of the sandbox took 0 s.
  • tests-no-submodule (job 118296641607): success at 21:32:34Z, 1661 passed, 400 skipped in 2985.97s. Block: the lead line, 29 section rows, 1358 s 100% the whole run, from the top of this file to this table, teardown: rm -rf of the sandbox took 1 s.
  • guard-launch-mode success at 20:42:57Z; SonarCloud pass.
    The tests job was slow because the runners were shared with several queue builds.

Fourth run (300e63d: this polish round plus a merge of main at 21e0829, run https://github.com/opensoft/openRepoTools/actions/runs/39337757910): green in every job, read by each job's completedAt. Each job printed its own block:

  • tests (job 118351416207): success at 23:45:39Z, 2033 passed, 70 skipped in 3271.18s. Block: the lead line, 29 section rows, 1430 s 100% the whole run, from the top of this file to this table, teardown: rm -rf of the sandbox took 1 s.
  • tests-no-submodule (job 118351416114): success at 23:47:00Z, 1684 passed, 419 skipped in 3355.02s. Block: the lead line, 29 section rows, 1531 s 100% the whole run, from the top of this file to this table, teardown: rm -rf of the sandbox took 0 s.
  • guard-launch-mode (job 118351415776) success at 22:51:21Z; SonarCloud pass.
    Neither log has a FAILED or ERROR line. The 19 extra skips (70 against 51, and 419 against 400) are tests/test_handoff_skill_80_85.py, which came in from main with The handoff skill's two PAUSED writes carry the why it computed, sanitized as lane-handoff's sanitize does, and a why carrying a line break is refused before step 1 (#80 item 7, #85) #264: its zsh cases skip where there is no zsh.

🤖 Generated with Claude Code

Brett Heap and others added 5 commits October 18, 2026 20:37
…, 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 <noreply@anthropic.com>
…emoval 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 <noreply@anthropic.com>
…n 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 <noreply@anthropic.com>
@sourcery-ai

sourcery-ai Bot commented Oct 19, 2026

Copy link
Copy Markdown

Reviewer's Guide

The wrapper now makes a passing shell suite's timing table and teardown line visible in pytest/CI output by parsing the captured streams and writing through capsys.disabled(), while leaving failing-run transcripts unchanged; comprehensive child-process, parser, and format-drift tests validate the behavior.

File-Level Changes

Change Details Files
Expose timing information from passing suite runs without duplicating failing-run diagnostics.
  • Parse the suite's stdout timing table and stderr teardown line using anchored format markers.
  • Print parsed timing output through a pytest capture-disabled context only after all pass assertions succeed.
  • Emit non-failing notices when either expected timing component is absent, while preserving the existing failure transcript behavior.
tests/test_lane_helpers_suite.py
Add end-to-end and parser-level coverage for timing visibility and output-shape compatibility.
  • Run the real wrapper test in child pytest processes over configurable stand-in suites to verify pass, fail, and missing-table behavior.
  • Verify extracted output contains only timing/teardown data on pass and appears only once on failure.
  • Test parsing boundaries and enforce that wrapper markers remain synchronized with the shell suite's printf formats.
tests/test_lane_helpers_suite.py

Tips and commands

Interacting with Sourcery

  • Trigger a new review: Comment @sourcery-ai review on the pull request.
  • Continue discussions: Reply directly to Sourcery's review comments.
  • Generate a GitHub issue from a review comment: Ask Sourcery to create an
    issue from a review comment by replying to it. You can also reply to a
    review comment with @sourcery-ai issue to create an issue from it.
  • Generate a pull request title: Write @sourcery-ai anywhere in the pull
    request title to generate a title at any time. You can also comment
    @sourcery-ai title on the pull request to (re-)generate the title at any time.
  • Generate a pull request summary: Write @sourcery-ai summary anywhere in
    the pull request body to generate a PR summary at any time exactly where you
    want it. You can also comment @sourcery-ai summary on the pull request to
    (re-)generate the summary at any time.
  • Generate reviewer's guide: Comment @sourcery-ai guide on the pull
    request to (re-)generate the reviewer's guide at any time.
  • Resolve all Sourcery comments: Comment @sourcery-ai resolve on the
    pull request to resolve all Sourcery comments. Useful if you've already
    addressed all the comments and don't want to see them anymore.
  • Dismiss all Sourcery reviews: Comment @sourcery-ai dismiss on the pull
    request to dismiss all existing Sourcery reviews. Especially useful if you
    want to start fresh with a new review - don't forget to comment
    @sourcery-ai review to trigger a new review!

Customizing Your Experience

Access your dashboard to:

  • Enable or disable review features such as the Sourcery-generated pull request
    summary, the reviewer's guide, and others.
  • Change the review language.
  • Add, remove or edit custom review instructions.
  • Adjust other review settings.

Getting Help

…peats 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 <noreply@anthropic.com>
Brett Heap and others added 2 commits October 19, 2026 18:34
…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 <noreply@anthropic.com>
Brett Heap and others added 2 commits October 19, 2026 22:50
…rror, 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 <noreply@anthropic.com>
@sonarqubecloud

Copy link
Copy Markdown

@brettheap
brettheap marked this pull request as ready for review October 20, 2026 11:48
@sourcery-ai

sourcery-ai Bot commented Oct 20, 2026

Copy link
Copy Markdown

Sorry @brettheap, you've used your own review budget of 250,000 diff characters for the last 7 days.

You can request another review in 1 day and 7 hours by commenting @sourcery-ai review. Upgrade to get a review now.

@brettheap
brettheap merged commit a42946e into main Oct 20, 2026
5 checks passed
brettheap pushed a commit that referenced this pull request Oct 20, 2026
Main moved from this branch's base 21e0829 by nine commits: lane-handoff's
lifecycle read (677acc0), #228's release series (c82578f to 234b670), #271
(f18b818), #284 (90eed74) and #265 (a42946e). Of this PR's files, only
lanes-edit.sh (lane_reconcile's leg sweep) and docs/README-lanes.md (the
triad section) changed there, away from its hunks, and the merge is clean.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant