From 201f4ed292aaa24543af400751a309b5a7ffeb20 Mon Sep 17 00:00:00 2001 From: Sergio Garcia Date: Mon, 17 Nov 2025 23:59:17 +0100 Subject: [PATCH] Modernize output on TTY Dynamic output, docker-style. Always displays the current package, the following ones, and time elapsed per-step --- alibuild_helpers/build.py | 38 +++- alibuild_helpers/log.py | 424 +++++++++++++++++++++++++++++++++----- alibuild_helpers/sync.py | 8 +- tests/test_log.py | 42 ++-- 4 files changed, 419 insertions(+), 93 deletions(-) diff --git a/alibuild_helpers/build.py b/alibuild_helpers/build.py index b9074739..ebdbaf03 100644 --- a/alibuild_helpers/build.py +++ b/alibuild_helpers/build.py @@ -17,7 +17,7 @@ from alibuild_helpers.scm import SCMError from alibuild_helpers.sync import remote_from_url from alibuild_helpers.workarea import logged_scm, updateReferenceRepoSpec, checkout_sources -from alibuild_helpers.log import ProgressPrint, log_current_package +from alibuild_helpers.log import ProgressPrint, log_current_package, BuildProgress from glob import glob from textwrap import dedent from collections import OrderedDict @@ -69,7 +69,7 @@ def update_repo(package, git_prompt): ".", prompt=git_prompt, logOutput=False) specs[package]["scm_refs"] = specs[package]["scm"].parseRefs(output) - progress = ProgressPrint("Updating repositories") + progress = ProgressPrint(begin_msg="Updating repositories") requires_auth = set() with concurrent.futures.ThreadPoolExecutor(max_workers=4) as executor: future_to_download = { @@ -730,6 +730,20 @@ def performPreferCheckWithTempDir(pkg, cmd): mainPackage = buildOrder.pop() warning("Not rebuilding %s because --only-deps option provided.", mainPackage) + # Initialize the pretty build progress output (enabled by default for TTY, disabled in debug mode) + buildProgress = None + import sys + if sys.stdout.isatty() and not args.debug: + buildProgress = BuildProgress( + total_packages=len(buildOrder), + max_log_lines=5 + ) + # Pre-populate the package list + for pkg in buildOrder: + pkg_spec = specs[pkg] + version = (getattr(args, "develPrefix", None) if pkg_spec.get("is_devel_pkg") else pkg_spec.get("version", "")) or "UNKNOWN" + buildProgress.add_package(pkg, version) + while buildOrder: p = buildOrder[0] spec = specs[p] @@ -1108,12 +1122,12 @@ def performPreferCheckWithTempDir(pkg, cmd): build_command = "%s -e -x %s/build.sh 2>&1" % (BASH, quote(scriptDir)) debug("Build command: %s", build_command) - progress = ProgressPrint( - ("Unpacking %s@%s" if cachedTarball else - "Compiling %s@%s (use --debug for full output)") % - (spec["package"], - args.develPrefix if "develPrefix" in args and spec["is_devel_pkg"] else spec["version"]) - ) + begin_msg = ("Unpacking %s@%s" if cachedTarball else + "Compiling %s@%s (use --debug for full output)") % \ + (spec["package"], + args.develPrefix if "develPrefix" in args and spec["is_devel_pkg"] else spec["version"]) + + progress = ProgressPrint(buildProgress, begin_msg) err = execute(build_command, printer=progress) progress.end("failed" if err else "done", err) report_event("BuildError" if err else "BuildSuccess", spec["package"], " ".join(( @@ -1172,6 +1186,9 @@ def performPreferCheckWithTempDir(pkg, cmd): except Exception as exc: warning("Failed to gather build info", exc_info=exc) + # Clean up progress display before showing error + if buildProgress and err: + buildProgress.cleanup() dieOnError(err, buildErrMsg.strip()) @@ -1209,4 +1226,9 @@ def performPreferCheckWithTempDir(pkg, cmd): if untrackedFilesDirectories: banner("Untracked files in the following directories resulted in a rebuild of " "the associated package and its dependencies:\n%s\n\nPlease commit or remove them to avoid useless rebuilds.", "\n".join(untrackedFilesDirectories)) + + # Cleanup build progress output + if buildProgress: + buildProgress.cleanup() + debug("Everything done") diff --git a/alibuild_helpers/log.py b/alibuild_helpers/log.py index 6f0e3434..23fe2c88 100644 --- a/alibuild_helpers/log.py +++ b/alibuild_helpers/log.py @@ -3,6 +3,10 @@ import re import time import datetime +import signal +import os +from collections import deque +from typing import Optional, List def dieOnError(err, msg) -> None: if err: @@ -53,61 +57,45 @@ def log_current_package(package, main_package, specs, devel_prefix) -> None: class ProgressPrint: - def __init__(self, begin_msg="", min_interval=0.) -> None: - self.count = -1 - self.lasttime = 0 - self.STAGES = ".", "..", "...", "....", ".....", "....", "...", ".." + def __init__(self, build_progress=None, begin_msg=""): + self.build_progress = build_progress self.begin_msg = begin_msg - self.percent = -1 - self.min_interval = min_interval - self.last_update = 0 - - def __call__(self, txt, *args) -> None: - now = time.time() - if (now - self.last_update) < self.min_interval: - return - self.last_update = now - - if logger.level <= logging.DEBUG or not sys.stdout.isatty(): - debug(txt, *args) - return - if time.time() - self.lasttime < 0.5: - return - if self.count == -1 and self.begin_msg: - sys.stderr.write("\033[1;35m==>\033[m " + self.begin_msg) - txt %= args - self.erase() - m = re.search(r"((^|[^0-9])([0-9]{1,2})%|\[([0-9]+)/([0-9]+)\])", txt) - if m: - if m.group(3) is not None: - self.percent = int(m.group(3)) - else: - num = int(m.group(4)) - den = int(m.group(5)) - if num >= 0 and den > 0: - self.percent = 100 * num / den - if self.percent > -1: - sys.stderr.write(" [%2d%%] " % self.percent) - self.count = (self.count+1) % len(self.STAGES) - sys.stderr.write(self.STAGES[self.count]) - self.lasttime = time.time() - sys.stderr.flush() - - def erase(self) -> None: - nerase = len(self.STAGES[self.count]) if self.count > -1 else 0 - if self.percent > -1: - nerase = nerase + 7 - sys.stderr.write("\b"*nerase+" "*nerase+"\b"*nerase) - sys.stderr.flush() - - def end(self, msg="", error=False): - if self.count == -1: - return - self.erase() - if msg: - sys.stderr.write(": %s%s\033[m" % ("\033[31m" if error else "\033[32m", msg)) - sys.stderr.write("\n") - sys.stderr.flush() + self.started = False + + def __call__(self, txt: str, *args): + """Log a line of output.""" + if args: + txt = txt % args + + if self.build_progress: + if not self.started: + self.started = True + # Parse package name from begin_msg if present + # Format: "Compiling PACKAGE@VERSION" or "Unpacking PACKAGE@VERSION" + if self.begin_msg: + match = re.match(r'(?:Compiling|Unpacking)\s+([^@]+)(?:@(.+))?', + self.begin_msg) + if match: + package = match.group(1) + version = match.group(2) or "" + self.build_progress.start_package(package, version) + + self.build_progress.log(txt) + else: + # No TTY: just print debug output + debug(txt) + + def erase(self): + """No-op for compatibility.""" + pass + + def end(self, msg: str = "", error: bool = False): + """Finish the current operation.""" + if self.build_progress and self.started: + self.build_progress.finish_package(failed=error) + elif msg: + # No TTY: print the final message + debug(msg) # Add loglevel BANNER (same as INFO but with more emphasis on ttys) @@ -137,3 +125,331 @@ def log_success(self, message, *args, **kws): info = logger.info banner = logger.banner success = logger.success + + +class BuildStep: + """Represents a single build step with timing information.""" + + STATUS_PENDING = "pending" + STATUS_IN_PROGRESS = "in_progress" + STATUS_DONE = "done" + STATUS_FAILED = "failed" + + def __init__(self, name: str, version: str = ""): + self.name = name + self.version = version + self.status = self.STATUS_PENDING + self.start_time: Optional[float] = None + self.end_time: Optional[float] = None + + def start(self): + """Mark this step as started.""" + self.status = self.STATUS_IN_PROGRESS + self.start_time = time.time() + + def finish(self, failed: bool = False): + """Mark this step as completed.""" + self.end_time = time.time() + self.status = self.STATUS_FAILED if failed else self.STATUS_DONE + + def get_duration(self) -> float: + """Get the duration of this step in seconds.""" + if self.start_time is None: + return 0.0 + end = self.end_time if self.end_time is not None else time.time() + return end - self.start_time + + def format_duration(self) -> str: + """Format the duration as a human-readable string.""" + duration = self.get_duration() + if duration == 0: + return "" + elif duration < 60: + return f"{duration:.1f}s" + elif duration < 3600: + minutes = int(duration / 60) + seconds = duration % 60 + return f"{minutes}m {seconds:.0f}s" + else: + hours = int(duration / 3600) + minutes = int((duration % 3600) / 60) + return f"{hours}h {minutes}m" + + +class BuildProgress: + def __init__(self, total_packages: int, max_log_lines: int = 5): + self.total_packages = total_packages + self.max_log_lines = max_log_lines + self.build_steps: List[BuildStep] = [] + self.current_step: Optional[BuildStep] = None + self.log_buffer = deque(maxlen=max_log_lines) + self.is_tty = sys.stderr.isatty() + self.enabled = self.is_tty + self.last_update = 0 + self.update_interval = 0.1 # Update display at most every 100ms + self.last_output = "" + self.terminal_width = 80 + self.terminal_height = 24 + self.needs_redraw = False + + # ANSI escape codes + self.CLEAR_LINE = "\033[2K" + self.CLEAR_SCREEN = "\033[2J" + self.CURSOR_HOME = "\033[H" + self.HIDE_CURSOR = "\033[?25l" + self.SHOW_CURSOR = "\033[?25h" + self.SAVE_CURSOR = "\033[7" + self.RESTORE_CURSOR = "\033[8" + + # Status symbols and colors + self.SYMBOL_DONE = "\033[32m✓\033[m" # Green checkmark + self.SYMBOL_FAILED = "\033[31m✗\033[m" # Red X + self.SYMBOL_BUILDING = "\033[34m⋯\033[m" # Blue ellipsis + self.COLOR_DIM = "\033[2m" + self.COLOR_RESET = "\033[m" + self.COLOR_BOLD = "\033[1m" + + if self.enabled: + self._update_terminal_size() + self._setup_signal_handlers() + sys.stderr.write(self.HIDE_CURSOR) + sys.stderr.flush() + + def _setup_signal_handlers(self): + """ + Set up signal handlers for terminal resize. We try to keep the output + as clean as possible when resizing the terminal + """ + try: + signal.signal(signal.SIGWINCH, self._handle_resize) + except (AttributeError, ValueError): + # SIGWINCH not available on this platform or not in main thread + pass + + def _handle_resize(self, signum, frame): + """Handle terminal resize signal.""" + self._update_terminal_size() + self.needs_redraw = True + + def _update_terminal_size(self): + """Update the cached terminal size.""" + try: + size = os.get_terminal_size(sys.stderr.fileno()) + self.terminal_width = size.columns + self.terminal_height = size.lines + except (OSError, AttributeError): + self.terminal_width = 80 + self.terminal_height = 24 + + def add_package(self, package_name: str, version: str = "") -> BuildStep: + """Add a new package to the build queue.""" + step = BuildStep(package_name, version) + self.build_steps.append(step) + return step + + def start_package(self, package_name: str, version: str = ""): + """Start building a package.""" + # Find existing step or create new one + step = None + for s in self.build_steps: + if s.name == package_name: + step = s + break + + if step is None: + step = self.add_package(package_name, version) + + step.start() + self.current_step = step + self.log_buffer.clear() + + if self.enabled: + self._render() + + def finish_package(self, failed: bool = False): + """Finish the current package.""" + if self.current_step: + self.current_step.finish(failed) + self.current_step = None + + if self.enabled: + self._render() + + def log(self, line: str): + """Add a log line to the scrolling buffer.""" + if not line: + return + + # Strip ANSI codes for length calculation + clean_line = re.sub(r'\033\[[0-9;]*m', '', line) + + # Truncate very long lines to terminal width + max_len = self.terminal_width - 5 # Leave room for " => " prefix + if len(clean_line) > max_len: + line = clean_line[:max_len - 3] + "..." + + self.log_buffer.append(line) + + if self.enabled: + now = time.time() + # Rate limit updates + if now - self.last_update > self.update_interval or self.needs_redraw: + self._render() + self.last_update = now + + def _format_step_line(self, step: BuildStep, index: int) -> str: + """Format a single build step line""" + step_num = f"[{index + 1}/{self.total_packages}]" + version_str = f"@{step.version}" if step.version else "" + name_with_version = f"{step.name}{version_str}" + + if step.status == BuildStep.STATUS_DONE: + duration = step.format_duration() + return f"{self.COLOR_DIM}{step_num}{self.COLOR_RESET} {self.SYMBOL_DONE} {name_with_version} {self.COLOR_DIM}{duration}{self.COLOR_RESET}" + elif step.status == BuildStep.STATUS_FAILED: + duration = step.format_duration() + return f"{self.COLOR_DIM}{step_num}{self.COLOR_RESET} {self.SYMBOL_FAILED} {name_with_version} {self.COLOR_DIM}{duration}{self.COLOR_RESET}" + elif step.status == BuildStep.STATUS_IN_PROGRESS: + # Animate with spinner + spinner_chars = ["⠋", "⠙", "⠹", "⠸", "⠼", "⠴", "⠦", "⠧", "⠇", "⠏"] + spinner_idx = int((time.time() * 10) % len(spinner_chars)) + spinner = f"\033[36m{spinner_chars[spinner_idx]}\033[m" # Cyan + duration = step.format_duration() + return f"{self.COLOR_DIM}{step_num}{self.COLOR_RESET} {spinner} {self.COLOR_BOLD}{name_with_version}{self.COLOR_RESET} {self.COLOR_DIM}{duration}{self.COLOR_RESET}" + else: + # Pending + return f"{self.COLOR_DIM}{step_num} • {name_with_version}{self.COLOR_RESET}" + + def _format_output(self) -> str: + """Format the complete output""" + lines = [] + + # Calculate available terminal lines (leave some margin for safety) + max_lines = max(10, self.terminal_height - 3) + + # Find current step index + current_idx = -1 + if self.current_step: + for i, step in enumerate(self.build_steps): + if step == self.current_step: + current_idx = i + break + + # Count completed steps + completed_count = sum(1 for s in self.build_steps if s.status == BuildStep.STATUS_DONE) + failed_count = sum(1 for s in self.build_steps if s.status == BuildStep.STATUS_FAILED) + + # Estimate lines needed for current step (step line + log lines) + current_step_lines = 1 + (len(self.log_buffer) if self.current_step and self.log_buffer else 0) + + # Reserve lines for: summary line + current step + some context + lines_for_summary = 1 if self.total_packages > 10 else 0 + available_for_steps = max_lines - lines_for_summary - current_step_lines + + # If we have many packages, show a summary + windowed view + if len(self.build_steps) > available_for_steps: + # Show summary of completed packages + if completed_count > 0 or failed_count > 0: + status_parts = [] + if completed_count > 0: + status_parts.append(f"{self.SYMBOL_DONE} {completed_count}") + if failed_count > 0: + status_parts.append(f"{self.SYMBOL_FAILED} {failed_count}") + summary = f"{self.COLOR_DIM}[{' '.join(status_parts)} / {self.total_packages} total]{self.COLOR_RESET}" + lines.append(summary) + + # Determine window of steps to show + # Show: last 2 completed + current + next 3 pending + steps_to_show = [] + + if current_idx >= 0: + # Show recent completed steps (up to 2) + recent_completed = [] + for i in range(current_idx - 1, -1, -1): + if self.build_steps[i].status in (BuildStep.STATUS_DONE, BuildStep.STATUS_FAILED): + recent_completed.insert(0, i) + if len(recent_completed) >= 2: + break + + # Show pending steps (up to 3) + upcoming_pending = [] + for i in range(current_idx + 1, len(self.build_steps)): + if self.build_steps[i].status == BuildStep.STATUS_PENDING: + upcoming_pending.append(i) + if len(upcoming_pending) >= 3: + break + + steps_to_show = recent_completed + [current_idx] + upcoming_pending + else: + # No current step, show first available steps + steps_to_show = list(range(min(available_for_steps, len(self.build_steps)))) + + # Render the windowed steps + for i in steps_to_show: + step = self.build_steps[i] + lines.append(self._format_step_line(step, i)) + + # Show log output only for the currently building step + if step == self.current_step and self.log_buffer: + for log_line in self.log_buffer: + lines.append(f" {self.COLOR_DIM}=>{self.COLOR_RESET} {log_line}") + else: + # Terminal is large enough, show all steps + for i, step in enumerate(self.build_steps): + lines.append(self._format_step_line(step, i)) + + # Show log output only for the currently building step + if step == self.current_step and self.log_buffer: + for log_line in self.log_buffer: + # Add " => " prefix like Docker + lines.append(f" {self.COLOR_DIM}=>{self.COLOR_RESET} {log_line}") + + return "\n".join(lines) + + def _render(self): + """Render the complete display.""" + if not self.enabled: + return + + new_output = self._format_output() + + # Handle terminal resize by doing a more aggressive clear + if self.needs_redraw and self.last_output: + # After resize, line wrapping changes, so calculate actual screen lines + # Use a conservative estimate (double the logical lines, capped at 100) + estimated_lines = min(self.last_output.count("\n") * 2 + 5, 100) + sys.stderr.write(f"\033[{estimated_lines}A") + sys.stderr.write("\r") + # Clear everything from here down + sys.stderr.write("\033[J") + self.needs_redraw = False + elif self.last_output: + # Normal case: move cursor to beginning of last output + num_lines = self.last_output.count("\n") + if num_lines > 0: + sys.stderr.write(f"\033[{num_lines}A") + sys.stderr.write("\r") + # Clear everything below cursor + sys.stderr.write("\033[J") + + # Write new output + sys.stderr.write(new_output) + sys.stderr.flush() + + self.last_output = new_output + + def cleanup(self): + """Clean up terminal state.""" + if self.enabled: + # Move to next line and show cursor + sys.stderr.write("\n") + sys.stderr.write(self.SHOW_CURSOR) + sys.stderr.flush() + self.enabled = False # Prevent duplicate cleanup + + def __del__(self): + """Ensure cursor is shown on deletion.""" + try: + self.cleanup() + except Exception: + pass diff --git a/alibuild_helpers/sync.py b/alibuild_helpers/sync.py index a6471ce9..962c87c6 100644 --- a/alibuild_helpers/sync.py +++ b/alibuild_helpers/sync.py @@ -180,8 +180,8 @@ def fetch_tarball(self, spec) -> None: destPath = os.path.join(self.workdir, store_path, use_tarball) if not os.path.isfile(destPath): # do not download twice - progress = ProgressPrint("Downloading tarball for %s@%s" % - (spec["package"], spec["version"]), min_interval=5.0) + progress = ProgressPrint(begin_msg="Downloading tarball for %s@%s" % + (spec["package"], spec["version"])) progress("[0%%] Starting download of %s", use_tarball) # initialise progress bar self.getRetry("/".join((self.remoteStore, store_path, use_tarball)), destPath, session=session, progress=progress) @@ -553,8 +553,8 @@ def fetch_tarball(self, spec) -> None: # ever use one anyway.) for tarball in self._s3_listdir(store_path): debug("Fetching tarball %s", tarball) - progress = ProgressPrint("Downloading tarball for %s@%s" % - (spec["package"], spec["version"]), min_interval=5.0) + progress = ProgressPrint(begin_msg="Downloading tarball for %s@%s" % + (spec["package"], spec["version"])) progress("[0%%] Starting download of %s", tarball) # initialise progress bar # Create containing directory locally. (exist_ok= is python3-specific.) os.makedirs(os.path.join(self.workdir, store_path), exist_ok=True) diff --git a/tests/test_log.py b/tests/test_log.py index 3831bf80..6b4b2909 100644 --- a/tests/test_log.py +++ b/tests/test_log.py @@ -18,33 +18,21 @@ def test_dieOnError(self, mock_sys, mock_error): mock_error.assert_not_called() mock_sys.exit.assert_not_called() - @patch("sys.stdout.isatty", new=MagicMock(return_value=True)) - @patch("sys.stderr", new=MagicMock(return_value=True)) - def test_ProgressPrint(self) -> None: - """Make sure ProgressPrint updates correctly.""" - # ProgressPrint only parses messages every 0.5s. Trick it into thinking - # the last message was seconds ago. - interval = 0.6 - p = ProgressPrint("begin") - p("%s", "First message") - self.assertEqual(p.percent, -1) - p("%s", "[100/200] Update too fast") - self.assertEqual(p.percent, -1) # unchanged - p.lasttime -= interval - p("%s", "Has percentage: 80%") - self.assertEqual(p.percent, 80) - p.lasttime -= interval - p("%s", "No percentage") - self.assertEqual(p.percent, 80) # unchanged - p.lasttime -= interval - p("%s", "[100/200] Building CXX object this/is/a/ninja/test") - self.assertEqual(p.percent, 50) - p.lasttime -= interval - p("%s", "[100/0] Wrong-styled Ninja progress") - self.assertEqual(p.percent, 50) # unchanged - p.lasttime -= interval - p("%s", "Last message") - p.end() + @patch("sys.stdout.isatty", new=MagicMock(return_value=False)) + @patch("sys.stderr", new=MagicMock(return_value=False)) + @patch("alibuild_helpers.log.debug") + def test_ProgressPrint(self, mock_debug) -> None: + """Make sure ProgressPrint works without TTY (no BuildProgress).""" + # When no build_progress is provided, ProgressPrint falls back to debug() + p = ProgressPrint(begin_msg="Testing") + p("First message") + mock_debug.assert_called_with("First message") + p("Second message") + mock_debug.assert_called_with("Second message") + p.end("done") + # end() with message should also call debug when no build_progress + mock_debug.assert_called_with("done") + p.erase() # Should be a no-op if __name__ == '__main__': unittest.main()