Skip to content

Make sure logging output isn't erased by progress display - #501

Merged
rgushchin merged 7 commits into
sashiko-dev:mainfrom
kees:fix/logging-scroll
Sep 18, 2026
Merged

rgushchin merged 7 commits into
sashiko-dev:mainfrom
kees:fix/logging-scroll

Conversation

@kees

@kees kees commented Sep 10, 2026

Copy link
Copy Markdown
Contributor

Insashiko review, the progress bars actively repaint the bottom of the screen region, but that means they clobber any logging lines in the process, and they become unreadable. Fix this by making it a distinct screen area and leave the scrollable area above for logging output.

@rgushchin

Copy link
Copy Markdown
Member

Note

This review was produced by an AI agent (Gemini, driven by a human
reviewer). The findings marked "verified" below were checked by running code,
not just by reading it; the reproductions are included so you can confirm them
yourself. Everything else is a reading of the diff and may be wrong — please
push back where it is.

Summary

The problem statement and the overall shape look right, and commits 1–3 are
clean wins on their own. Commit 4 (the DECSTBM reserved region) is where the
risk is: it makes correct screen geometry load-bearing for the first time, and
the geometry it relies on is never actually obtained.

Suggestion: land 1–3, hold 4 until the row count and the release paths are
sorted.

Three of the issues below can leave the user's terminal in a broken state that
survives the process exiting (scrolling region clamped; needs reset).


Blocking

B1. terminal_rows is always 24 — stty size can never succeed

get_terminal_size() shells out to stty size, but
std::process::Command::output() gives the child Stdio::null() for stdin, and
stty reads the window size from its own stdin. It fails 100% of the time,
including under a real pty:

let o = std::process::Command::new("stty").arg("size").output().unwrap();
println!("status={:?}", o.status);
println!("stdout={:?}", String::from_utf8_lossy(&o.stdout));
println!("stderr={:?}", String::from_utf8_lossy(&o.stderr));
$ script -qc ./sttytest /dev/null
status=ExitStatus(unix_wait_status(256))
stdout=""
stderr="stty: 'standard input': Inappropriate ioctl for device\n"

So get_terminal_size() always returns the (24, get_terminal_width())
fallback, and there is no LINES fallback the way there is a COLUMNS one.
terminal_rows == 24 unconditionally.

This was harmless before the PR — a wrong width only mis-truncates a line — but
it is now the basis of both the DECSTBM split and every absolute cursor address.

Concretely, 3 patches (wanted = 4) on a 50-row terminal:

computed actual effect
split 24 - 4 = 20 \x1b[1;20r confines all scrolling to the top 20 rows of 50
frame top 21 progress painted at rows 21–24, i.e. the middle of the screen
rows 25–50 dead zone, stale content, never touched again

On a terminal shorter than 24 rows it inverts: wanted + 1 > 24 is false so it
still reserves, the bottom margin clamps to the screen, every \x1b[{21..24};1H
clamps to the last row, so all progress lines collide on one line and logs
scroll over it anyway — which is the bug this PR is fixing.

Suggested fix: query TIOCGWINSZ on the stderr fd (libc is already in
the tree transitively; the terminal_size crate also works), falling back to
LINES/COLUMNS then (24, 80). Querying stderr is also more correct than
stty-on-stdin now that the display has been moved to stderr. If the subprocess
is worth keeping, .stdin(Stdio::inherit()) makes it work — but it is still the
wrong descriptor and still a fork per call.

B2. The region is leaked on every non-happy path

release_progress_region is called after run_git_review(...).await?. The
commit message reasons carefully about std::process::exit and dismisses
SIGKILL, but skips the cases in between:

  • Err from the review — the ? returns straight past the release. Review
    failures are not exotic (git apply failure, provider error, bad baseline).
  • Ctrl-C — there is no SIGINT handler on the review path (the existing one
    belongs to serve), and interrupting a long review is the normal way to stop
    one.
  • Panic in the review path, and progress_state.lock().unwrap() itself
    panicking if a worker poisoned the mutex.

In all of these the user's shell inherits a terminal with the scrolling region
clamped. It survives the exit and survives clear; only reset / tput csr
fixes it. That is a worse outcome than the clobbered log lines being fixed here.

Suggested fix: capture the result, release, then propagate:

let result = run_git_review(...).await;
release_progress_region(&mut progress_state.lock().unwrap());
let result = result?;

plus a SIGINT/SIGTERM handler on this path that releases and re-raises. A guard
type would express this better than hand-placed calls — the process::exit
argument against Drop is fair, but that only means the exits need an explicit
release too, not that every other path should go without one.

B3. cargo test corrupts the developer's terminal

test_a_frame_taller_than_the_screen_reserves_nothing calls the real
reserve_progress_region with a real BufferWriter::stderr.
BufferWriter::print writes to io::stderr() directly (termcolor 1.4.1,
lib.rs:1145), and libtest's capture only intercepts the print!/eprint!
macros — direct writes go to fd 2. Verified:

#[test]
fn direct_write_escapes_capture() {
    use std::io::Write;
    eprintln!("VIA_EPRINTLN_SHOULD_BE_CAPTURED");
    let _ = std::io::stderr().write_all(b"VIA_DIRECT_WRITE_NOT_CAPTURED\n");
}
eprintln!(...)               -> captured     (0 occurrences in output)
io::stderr().write_all(...)  -> NOT captured (1 occurrence in output)

With terminal_rows = 4, wanted = 3 the test emits, to the real terminal:

\x1b[r \x1b[4;1H \n\n\n \x1b[1;1r \x1b[1;1H

\x1b[1;1r sets the scrolling region to a single line. The compensating
release_progress_region uses eprintln!, which is captured — so the reset is
swallowed and the damage is not. Running the unit tests in a terminal leaves it
hosed.

Suggested fix: have reserve_progress_region / release_progress_region
write to a &mut impl WriteColor (or &mut Buffer) supplied by the caller.
Tests then assert on the emitted bytes in memory, which is also much better
coverage than the current assert_eq!(state.reserved, ...) — nothing today
checks that the escape sequences are the ones intended.


Should fix

M1. Large series lose the progress display entirely

reserve_progress_region sets reserved = 0 when the frame does not fit, and
render_progress then returns having printed nothing. With terminal_rows
pinned at 24 (B1), any series of ≥23 patches silently loses all progress
output — a regression against main, which rendered something. Even with B1
fixed, a 40-patch series on a 30-row terminal hits it. render_progress_plain
looks like the natural fallback.

M2. No SIGWINCH handling, and the stale value is now structural

Rows and columns are sampled once. Terminals reset DECSTBM on resize, so after a
resize the region is gone, the frame paints at stale absolute rows, and ordinary
output scrolls over it — back to the original bug, permanently, for the rest of
the run. On main a resize only mis-truncated a line. Re-querying on SIGWINCH
(cheap once B1 uses an ioctl) and re-reserving would close this.

M3. "May not carry colour" and "may not carry cursor movement" are conflated

render_progress branches on color_choice == ColorChoice::Never. Two
consequences:

  • --color never or NO_COLOR on a real terminal drops the in-place display
    and falls back to appending. Neither flag says anything about cursor movement;
    a user who wants monochrome should not lose the live display.
  • Inversely, TERM=dumb on a tty yields ColorChoice::Auto (since ansi_choice
    only consults is_terminal). termcolor suppresses the colours, but the
    hand-written \x1b7 / \x1b[H / DECSTBM escapes bypass termcolor and go out
    anyway.

A distinct DisplayMode::{Repaint, Append}, decided by stderr().is_terminal()
(and TERM) and kept separate from the ColorChoice, would cover both.


Nits

  • The explicit stderr lock is mostly redundant. BufferWriter::print already
    takes io::stderr().lock() and issues one write_all under it, so the frame
    is atomic against other stderr writers without help. The outer
    let _stderr = std::io::stderr().lock(); only buys atomicity between the
    reservation print and the frame print — worth either scoping it to that or
    saying so in the comment, since as written it also holds the lock across all
    the format!/repeat work and blocks every logging thread for the duration.
  • IgnoreBrokenPipeWriter does not override write_all. The default impl
    loops on write, taking and releasing the stderr lock per iteration, so a
    large log record can be split around a repaint. Records are small today, so
    this is theoretical — but the PR's atomicity argument rests on "one write, one
    lock", and this is the one place that is not. One-line fix in logging.rs.
  • printed_lines is now write-only in the repaint path (the erase loop it
    drove is gone); last_status is only meaningful in the append path. Two
    mode-specific fields on one struct — an enum over the two display modes would
    make the invalid combinations unrepresentable.
  • /dev/ptmx in a unit test. It passes in CI today, but it allocates a pty
    per run and will fail in any sandbox without devpts. If ansi_choice took a
    plain bool (the caller does the is_terminal() call), the test needs no
    device at all.
  • reserve_progress_region scrolls unconditionally. It prints wanted
    newlines from the bottom row even when the screen has blank space below the
    cursor, discarding that many lines off the top, then parks the cursor at the
    bottom of the new region — leaving a visible gap between the last log line and
    whatever prints next.
  • Lock ordering is now load-bearing: progress_state → stderr. Any future
    code that logs while holding stderr and then touches progress state
    deadlocks. Worth a comment on ProgressState.
  • get_terminal_width() no longer consults stty after the split; its only
    remaining caller is the get_terminal_size fallback. Fine, just noting the
    name now overstates what it does.

What is good

  • Commit 1 (per-descriptor ColorChoice) is a genuine bug fix: sashiko review > out.txt
    previously went colourless on a display that was still a terminal, and
    --color always could not override it. The three-line ansi_choice is the
    right shape.
  • Commit 2 fixes a real corruption: on main the erase escapes were hardcoded
    and emitted regardless of color_choice, so 2> log wrote a frame's worth of
    escapes into the file per progress event. The append path is the right answer.
  • Commit 3 (48 syscalls → 1 per frame) is clearly correct and well evidenced by
    the strace counts.
  • Extracting status_label with a with_turns flag removes a real duplication
    and is exactly what the append path needed.
  • The commit messages are unusually good — they explain the reasoning, not the
    diff.

@kees
kees force-pushed the fix/logging-scroll branch from 3aab349 to cafcd0b Compare September 17, 2026 03:00
@kees

kees commented Sep 17, 2026

Copy link
Copy Markdown
Contributor Author

Thanks for the notes! I think I've addressed everything in this new set of patches. SIGWINCH took a fair bit of plumbing, but I think it's not too bad. The terminal capability detection logic does make the Sashiko build now explicitly Linux-only, though, which I can change, but would require more crates to generalize. Let me know if you want to go that way.

@kees
kees force-pushed the fix/logging-scroll branch from cafcd0b to bcf9a41 Compare September 17, 2026 03:15
@kees

kees commented Sep 17, 2026

Copy link
Copy Markdown
Contributor Author

Aaand rebased. :)

A progress bar update frame reaches stderr a piece at a
time. TruncatingWriter opens a fresh handle on stderr for every
colored segment, and termcolor writes the color, the text and the reset
separately; StandardStream is unbuffered, as std::io::Stderr is, so each
of those is a write of its own, every line end one more, and the erase
before them one per line erased.

Gather the frame instead: TruncatingWriter writes into a writer, the
erase joins it, and render_progress paints the whole string into a
termcolor Buffer and prints that once.

One repaint of a frame of two patches, under strace (349 bytes either
way), before and after:

  write(2) syscalls for the frame: 47
      write(2, "\33[F\33[2K", 7)             = 7
      ...
      write(2, "\33[0m", 4)                  = 4
      write(2, "      [Patch 1] ", 16)       = 16
      ...

  write(2) syscalls for the frame: 1
      write(2, "\33[F\33[2K...\33[0m      [Patch 1] "..., 349) = 349

This also assists testing so that writes can be captured instead of
leaking to stderr to corrupt the terminal running "cargo test".

Signed-off-by: Kees Cook <kees@kernel.org>
Running "sashiko review" writes to both streams: the report to stdout, the
progress display to stderr. One ColorChoice was computed from stdout alone
and used for both, so redirecting stdout painted the display colorless
even though its own stream was still a terminal, and "--color always"
could not put the color back.

Split the detection and use a common object to hold the results, as we
will be adding more detected details in subsequent patches.

Using "--color" for "always" and "never" should control the process,
so it overrides both streams.

Signed-off-by: Kees Cook <kees@kernel.org>
Checking isatty doesn't say anything about color capability: vt100 and
xterm-mono are terminals with no color at all, and a review painting
color codes at them makes things unreadable.

TERM names the terminal and terminfo describes it. Require a color count
of at least eight, and a string that selects one. A TERM terminfo does
not know describes nothing and is treated as having nothing. The database
is read once and both streams are asked against it, which makes testing
easier as well.

Being a terminal still matters, and is still asked: a stream redirected
to a file has no terminal behind it, whatever TERM says about the screen
its reader may also have.

A database that cannot be read is not an answer of no. Plenty of
containers ship no terminfo at all, and the terminal on the other end of
the descriptor is a terminal regardless, so where there is no terminfo to
check, TERM naming something other than a dumb terminal is taken as color.

Signed-off-by: Kees Cook <kees@kernel.org>
The progress bar display repaints in place: it walks the cursor up one
line per line it last drew, erases each, and paints the frame again. That
requires two things of the terminal, cursor_up and clr_eol, and a terminal
may not have them.

Ask terminfo, as the color question already does. When not available,
append a line per patch as its status changes.

Avoid update spam by removing the turn counter associated with a given
stage. The status text moves into a function the old and new update
display paths share, which is where the turn counter becomes conditional.

Signed-off-by: Kees Cook <kees@kernel.org>
The width came from running "stty size", which reports the size of its own
standard input. Stdin is not the stream the progress display writes to, and
it is not necessarily a terminal at all.

Ask the stream, with the TIOCGWINSZ ioctl that stty itself uses, and
store the result in the per-stream object. Use 24x80 as fallback when
no other details are available.

As Sashiko is expected to run on Linux, so this is not intended to be
a portable solution.

Signed-off-by: Kees Cook <kees@kernel.org>
Update the width when catching SIGWINCH so that subsequent progress bar
output will be correctly sized. Skipped when stderr lacks a size.

Signed-off-by: Kees Cook <kees@kernel.org>
The display repaints by walking the cursor back up over its own frame,
which assumes nothing else has written to stderr since. Logging output
breaks that assumption, and the erase takes the log away instead of the
frame.

Give the progress display lines of its own instead. DECSTBM confines
scrolling to everything above the last few lines, so ordinary output can
never reach them, and a frame saves the cursor, addresses those lines
outright, and puts it back. Logging carries on above, where it left off,
with no coordination beyond the implicit std stream locking (which,
now that progress bar updates are a single write) which stops any
tearing.

That asks four things of the terminal: change_scroll_region, save_cursor,
restore_cursor, and cursor_address, so reservation_capable replaces the
cursor_capable that gated the repainting before.

The reservation is one line per patch and one for the overall bar, set when
the patches become known and again when that count changes, or when a
resize moves the foot of the screen, which SIGWINCH now asks the rows for
as well as the width. The room for those lines is made with newlines from
wherever the output has reached, so a full screen scrolls a line away per
line taken and a screen with space below uses what is already there, and
either way nothing on screen is written over.

Require 3/4 of a screen to display patch status in, otherwise don't do
any of this. Process exit or interruption resets the scrolling region.

Signed-off-by: Kees Cook <kees@kernel.org>
@kees
kees force-pushed the fix/logging-scroll branch from bcf9a41 to a7df8c5 Compare September 17, 2026 23:53
@kees

kees commented Sep 17, 2026

Copy link
Copy Markdown
Contributor Author

Rebased again. :)

@sashiko-bot

sashiko-bot Bot commented Sep 18, 2026

Copy link
Copy Markdown

Sashiko review — v2

Commit 2/7 — ae609343 cli: split output stream capability detection

  • [LOW] In the commit message, the first two lines of the body are 74
    characters long, which exceeds the strict 72-character limit for patch
    submission formatting.

Commit 3/7 — 08e8d61f cli: take the color answer from terminfo rather than from isatty

  • [MEDIUM] In src/main.rs (OutputStream::detect), the fallback logic for
    missing terminfo databases relies directly on the global environment state
    (std::env::var) to determine color capability. This leaves the fallback
    behavior untestable in a concurrent test runner and without unit test
    coverage.

  • [LOW] The commit message body contains lines that exceed the strict
    72-character limit required by the repository standards (e.g., measuring 73
    and 74 characters). This degrades git log hygiene and formatting.

Commit 4/7 — c179ecb6 cli: append a line per patch where the terminal cannot be drawn over

  • [MEDIUM] In src/main.rs
    (test_drawing_over_the_frame_is_the_terminals_answer_too), the test
    hardcodes an absolute path to open /dev/ptmx. Relying on host-specific
    global state violates test isolation rules and will deterministically
    panic the test suite on non-Unix operating systems or locked-down CI
    environments where /dev/ptmx is unavailable.

  • [LOW] In the commit message, the third paragraph of the body contains lines
    that exceed the 72-character limit (up to 74 characters). This violates
    the repository's strict formatting standards.

Commit 5/7 — a6c3af9f cli: ask the terminal its size with an ioctl

  • [LOW] Commit message body contains text exceeding 72 characters, reaching
    74 and 75 characters in the first paragraph.

Commit 6/7 — eb01c650 cli: follow the terminal size across a resize

  • [HIGH] In src/main.rs (watch_for_resize) and Cargo.toml, the unconditional
    import of tokio::signal::unix and the rustix process feature break
    cross-platform compilation on non-Unix systems like Windows.

  • [MEDIUM] In COMMIT_MESSAGE, the patch lacks required validation data or a
    test procedure description demonstrating that the terminal resizing feature
    functions correctly for users in practice.

  • [MEDIUM] In src/main.rs (test_a_resize_is_followed_while_the_review_runs),
    the test broadcasts a process-global SIGWINCH signal. This breaks strict
    test isolation guidelines and can cause unpredictable cross-test
    interference when cargo test executes tests concurrently.

  • [MEDIUM] In src/main.rs (test_a_resize_is_followed_while_the_review_runs),
    the test uses an arbitrary wall-clock sleep to wait for non-action.
    Asserting a negative event using fixed delays is non-deterministic and
    makes the test suite flaky under heavy CI load.

  • [MEDIUM] In src/main.rs (multiple tests including
    test_a_resize_is_followed_while_the_review_runs), tests depend on the
    global system path /dev/ptmx outside of an isolated temporary directory.
    This violates isolation guidelines and causes failures in sandboxed
    environments.

Commit 7/7 — a7df8c5f cli: keep the progress display in a reserved screen region

  • [MEDIUM] In src/main.rs (watch_for_resize), the gap-closing check fails to
    inspect or update terminal_rows. It only checks and updates terminal_width,
    causing terminal height changes in this narrow window to be permanently lost
    and leading to incorrect progress region reservations based on stale height.

  • [LOW] The commit message body contains lines that exceed the 72-character
    limit, violating project formatting rules.

Full review and stage logs on sashiko.sashiko.dev

@rgushchin
rgushchin merged commit 3deefac into sashiko-dev:main Sep 18, 2026
3 checks passed
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.

2 participants