Skip to content

Commit 1dab3b2

Browse files
pluskymimi1vx
authored andcommitted
fix(cli): render mid-spin log lines flush-left, coordinating spinner and logging
Log records emitted while the TTY spinner was painting rendered with phantom leading padding (e.g. 19 blank columns after a '[|] set_repo remove' frame during update/prepare), or -- with colours disabled on a TTY -- glued straight onto the leftover frame text. ColorFormatter prepended ESC[2K (erase entire line) to the levelname, which blanks the frame but leaves the cursor at the frame's end column, so the record started mid-line; with colours off there was no erase at all. Move screen management out of the formatter into a shared seam: * mtui/support/spinner.py: serialize frame painting through a module-level RLock, register active spinners, and expose spinner_suspended() -- it erases the visible frame with CR + ESC[K (homing the cursor to column 0) and pauses repainting while held. stop() erases under the lock and _spin re-checks the stop flag under the lock so a frame is never repainted after stop erased it. * mtui/cli/colors/formatter.py: emit every record from a SpinnerAwareStreamHandler that wraps super().emit() in spinner_suspended(), and drop the ESC[2K injections from ColorFormatter (also fixes the NO_COLOR-on-a-TTY variant and stops the escape leaking into non-terminal handlers such as the MCP capture handler). * mtui/cli/prompter.py: hold spinner_suspended() for the whole stdin read so the SSH command-timeout prompt is not repainted over by a live 'run' spinner. Off a TTY nothing changes: spinners never register, spinner_suspended() writes nothing, and the handler behaves like a plain StreamHandler. Worker parallelism is untouched -- only terminal writes serialize. Regression tests drive the real spinner and the real create_logger handler against a pty and assert on the raw captured bytes: a record emitted mid-spin must be preceded by CR + ESC[K and render flush-left; the non-TTY path is pinned byte-exact.
1 parent 9f345a6 commit 1dab3b2

6 files changed

Lines changed: 368 additions & 19 deletions

File tree

CHANGELOG.md

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -434,6 +434,15 @@ and this project follows [Semantic Versioning](https://semver.org/spec/v2.0.0.ht
434434
(e.g. a plain file in the way) is now reported as one clear error naming the
435435
option instead of an `OSError` traceback, and openQA queries catch any
436436
remaining URL/transport error shape instead of crashing the command.
437+
- Log lines emitted while the TTY spinner is painting (e.g. the per-host
438+
`Removing repo … on <host>` lines under the `set_repo remove` spinner during
439+
`update`/`prepare`) no longer render with phantom leading padding — or, with
440+
colours off, glued to the leftover frame text. The spinner and the logging
441+
handler now coordinate through a shared paint lock: each record first erases
442+
the live frame and homes the cursor to column 0, then prints, and the spinner
443+
repaints on its next tick. Interactive prompts raised under a live spinner
444+
(e.g. the SSH command-timeout question) also pause the spinner for the whole
445+
read instead of repainting over the prompt. Off a TTY nothing changes.
437446

438447
## 18.2.0 - 2026-06-23
439448

mtui/cli/colors/formatter.py

Lines changed: 28 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@
33
import inspect
44
import logging
55

6+
from ...support.spinner import spinner_suspended
67
from .mode import colors_enabled
78

89
# ANSI color offsets (added to 30 to form the foreground color escape code).
@@ -60,21 +61,15 @@ def formatColor(self, levelname: str) -> str:
6061
if not colors_enabled():
6162
return levelname.lower() + suffix
6263
return (
63-
"\033[2K"
64-
+ COLOR_SEQ.format(30 + COLORS[levelname])
64+
COLOR_SEQ.format(30 + COLORS[levelname])
6565
+ levelname.lower()
6666
+ RESET_SEQ
6767
+ suffix
6868
+ RESET_SEQ
6969
)
7070
if not colors_enabled():
7171
return levelname.lower()
72-
return (
73-
"\033[2K"
74-
+ COLOR_SEQ.format(30 + COLORS[levelname])
75-
+ levelname.lower()
76-
+ RESET_SEQ
77-
)
72+
return COLOR_SEQ.format(30 + COLORS[levelname]) + levelname.lower() + RESET_SEQ
7873

7974
@staticmethod
8075
def _find_caller_frame() -> tuple[object, str] | None:
@@ -113,8 +108,31 @@ def format(self, record: logging.LogRecord) -> str:
113108
return logging.Formatter.format(self, record)
114109

115110

111+
class SpinnerAwareStreamHandler(logging.StreamHandler):
112+
"""A stream handler that coordinates with a live TTY spinner.
113+
114+
Every record is emitted inside :func:`spinner_suspended`: while a
115+
:class:`mtui.support.spinner.TtySpinner` is painting, the handler
116+
erases the current frame (``\\r`` + erase-to-end, homing the cursor
117+
to column 0), writes the record from a clean line, and lets the
118+
spinner repaint on its next tick. Without this, a record emitted
119+
mid-spin starts at the column where the frame write left the
120+
cursor, rendering with phantom leading padding (or, with colours
121+
off, appended straight after the frame text).
122+
123+
When no spinner is active — notably off a TTY, where spinners never
124+
start — the wrapper adds nothing and the handler behaves exactly
125+
like a plain :class:`logging.StreamHandler`.
126+
"""
127+
128+
def emit(self, record: logging.LogRecord) -> None:
129+
"""Emit the record with any live spinner frame erased first."""
130+
with spinner_suspended():
131+
super().emit(record)
132+
133+
116134
def create_logger(name: str, level: str = "INFO") -> logging.Logger:
117-
"""Creates a logger with a colorized output.
135+
"""Creates a logger with a colorized, spinner-aware output.
118136
119137
Args:
120138
name: The name of the logger.
@@ -126,7 +144,7 @@ def create_logger(name: str, level: str = "INFO") -> logging.Logger:
126144
"""
127145
out = logging.getLogger(name) if name else logging.getLogger()
128146
out.setLevel(level)
129-
handler = logging.StreamHandler()
147+
handler = SpinnerAwareStreamHandler()
130148
formatter = ColorFormatter("%(levelname)s: %(message)s")
131149
handler.setFormatter(formatter)
132150
out.addHandler(handler)

mtui/cli/prompter.py

Lines changed: 8 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,8 @@
1919
import threading
2020
from collections.abc import Callable
2121

22+
from ..support.spinner import spinner_suspended
23+
2224

2325
class Prompter:
2426
"""Serialise interactive prompts across worker threads.
@@ -53,7 +55,11 @@ def ask(self, text: str) -> str:
5355
"""Prompt the user with ``text`` and return the typed response.
5456
5557
Acquires the prompter's lock for the duration of the read so
56-
sibling workers cannot race for ``stdin``.
58+
sibling workers cannot race for ``stdin``, and holds
59+
:func:`mtui.support.spinner.spinner_suspended` for the whole
60+
read so a live TTY spinner (e.g. ``run_parallel``'s) erases its
61+
frame and stops repainting over the prompt until the user has
62+
answered. A no-op when no spinner is active.
5763
5864
Args:
5965
text: The prompt text shown to the user.
@@ -63,5 +69,5 @@ def ask(self, text: str) -> str:
6369
identical to :func:`input`).
6470
6571
"""
66-
with self._lock:
72+
with self._lock, spinner_suspended():
6773
return self._reader(text)

mtui/support/spinner.py

Lines changed: 57 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,14 @@
44
stderr is a TTY. Off a TTY (pytest, redirected output, log files, the
55
``mtui-mcp`` transport) it is a no-op, so test output and log files stay clean
66
and the MCP layer can surface progress through its own channel instead.
7+
8+
Frame painting is serialised through a module-level paint lock so other
9+
writers on the same terminal can coordinate with a live spinner: wrap the
10+
write in :func:`spinner_suspended` to erase the current frame, keep the
11+
spinner from repainting while the block runs, and write from column 0. The
12+
logging handler installed by :func:`mtui.cli.colors.create_logger` does this
13+
for every record, so worker-thread log lines emitted mid-spin render
14+
flush-left instead of starting at the cursor column the frame left behind.
715
"""
816

917
from __future__ import annotations
@@ -13,6 +21,38 @@
1321
from collections.abc import Callable, Iterator
1422
from contextlib import contextmanager, suppress
1523

24+
#: Serialises every write that repaints or erases a spinner frame. An
25+
#: ``RLock`` so a thread already holding it (e.g. a prompt inside
26+
#: :func:`spinner_suspended`) can log without deadlocking itself.
27+
_paint_lock = threading.RLock()
28+
29+
#: Spinners currently painting frames (TTY-enabled and started, not yet
30+
#: stopped). Guarded by :data:`_paint_lock`. Empty off a TTY, so
31+
#: :func:`spinner_suspended` is a strict no-op there.
32+
_active: set[TtySpinner] = set()
33+
34+
35+
@contextmanager
36+
def spinner_suspended() -> Iterator[None]:
37+
"""Pause spinner painting for the block and erase any visible frame.
38+
39+
Acquires the paint lock for the whole block, so a live spinner cannot
40+
repaint while the caller writes to the terminal. If a spinner is
41+
active, the current frame is erased first (``\\r`` + erase-to-end) and
42+
the cursor is homed to column 0, so the caller's output starts on a
43+
clean line. The spinner repaints on its next tick after the block
44+
exits.
45+
46+
A no-op (beyond taking the lock) when no spinner is active — in
47+
particular off a TTY, where spinners never register.
48+
"""
49+
with _paint_lock:
50+
if _active:
51+
with suppress(Exception):
52+
sys.stderr.write("\r\033[K")
53+
sys.stderr.flush()
54+
yield
55+
1656

1757
class TtySpinner:
1858
"""A ``|/-\\`` spinner driven by one daemon thread; a no-op off a TTY.
@@ -33,6 +73,8 @@ def start(self) -> None:
3373
"""Start the spinner thread (no-op when stderr is not a TTY)."""
3474
if not self._enabled:
3575
return
76+
with _paint_lock:
77+
_active.add(self)
3678
self._thread = threading.Thread(target=self._spin, daemon=True)
3779
self._thread.start()
3880

@@ -47,9 +89,12 @@ def stop(self) -> None:
4789
self._thread.join(timeout=1.0)
4890
self._thread = None
4991
# Erase the spinner line so the next caller writes from column 0.
50-
with suppress(Exception):
51-
sys.stderr.write("\r\033[K")
52-
sys.stderr.flush()
92+
# Under the paint lock so the erase cannot race a frame repaint.
93+
with _paint_lock:
94+
_active.discard(self)
95+
with suppress(Exception):
96+
sys.stderr.write("\r\033[K")
97+
sys.stderr.flush()
5398

5499
def is_stopped(self) -> bool:
55100
"""True once :meth:`stop` has been called (set even off a TTY).
@@ -62,9 +107,15 @@ def is_stopped(self) -> bool:
62107
def _spin(self) -> None:
63108
i = 0
64109
while not self._stop.is_set():
65-
with suppress(Exception):
66-
sys.stderr.write(f"\r[{self._FRAMES[i % 4]}] {self._desc}")
67-
sys.stderr.flush()
110+
with _paint_lock:
111+
# Re-check under the lock: a long ``spinner_suspended`` hold
112+
# (e.g. an interactive prompt) can outlive ``stop()``; never
113+
# repaint a frame that ``stop`` has already erased.
114+
if self._stop.is_set():
115+
return
116+
with suppress(Exception):
117+
sys.stderr.write(f"\r[{self._FRAMES[i % 4]}] {self._desc}")
118+
sys.stderr.flush()
68119
i += 1
69120
self._stop.wait(self._INTERVAL)
70121

tests/test_spinner.py

Lines changed: 22 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -43,7 +43,10 @@ def test_spin_paints_a_frame(monkeypatch):
4343
fake = _fake_tty(monkeypatch)
4444
s = TtySpinner("regen")
4545

46-
calls = iter([False, True]) # one loop body, then exit
46+
# ``_spin`` checks the stop event twice per iteration: once in the loop
47+
# condition and once under the paint lock (so a frame is never repainted
48+
# after ``stop`` erased it). One painted frame, then exit.
49+
calls = iter([False, False, True])
4750
s._stop = MagicMock() # noqa: SLF001
4851
s._stop.is_set.side_effect = lambda: next(calls) # noqa: SLF001
4952
s._stop.wait.return_value = None # noqa: SLF001
@@ -81,3 +84,21 @@ def test_is_stopped_set_even_off_a_tty(monkeypatch):
8184
assert s.is_stopped() is False
8285
s.stop()
8386
assert s.is_stopped() is True
87+
88+
89+
def test_spin_never_repaints_after_stop_wins_the_lock(monkeypatch):
90+
"""stop() landing between the while-check and the paint lock wins.
91+
92+
A long ``spinner_suspended`` hold can outlive ``stop()``; the frame
93+
painter must re-check the stop flag under the lock and bail without
94+
painting, or it would repaint a frame stop() already erased.
95+
"""
96+
fake = _fake_tty(monkeypatch)
97+
s = TtySpinner("desc")
98+
# First is_set(): the outer while condition (not stopped yet). Second:
99+
# the re-check under the paint lock (stop() got there first).
100+
s._stop.is_set = MagicMock(side_effect=[False, True])
101+
102+
s._spin()
103+
104+
fake.write.assert_not_called()

0 commit comments

Comments
 (0)