From e28e42a432217e55f1e878a8c582d7cbed3f0761 Mon Sep 17 00:00:00 2001 From: Chris Hennes Date: Fri, 31 Jul 2026 18:46:55 -0400 Subject: [PATCH] Add pip output monitoring to installer window --- .../app/test_dependency_installer.py | 13 ++ AddonManagerTest/app/test_utilities.py | 76 ++++++++++++ AddonManagerTest/gui/test_installer_gui.py | 17 ++- addonmanager_dependency_installer.py | 19 ++- addonmanager_installer_gui.py | 29 +++-- addonmanager_python_deps.py | 2 +- addonmanager_utilities.py | 115 ++++++++++++++++-- 7 files changed, 243 insertions(+), 28 deletions(-) diff --git a/AddonManagerTest/app/test_dependency_installer.py b/AddonManagerTest/app/test_dependency_installer.py index 5f145e69..9786d601 100644 --- a/AddonManagerTest/app/test_dependency_installer.py +++ b/AddonManagerTest/app/test_dependency_installer.py @@ -171,6 +171,19 @@ def test_install_required_failure(self): self.assertEqual(sm.call_count, 1) self.assertIn("failure", self.signals_caught) + def test_install_required_emits_progress_and_disables_progress_bar(self): + sm = SubprocessMock() + sm.succeed = True + self.test_object._subprocess_wrapper = sm.subprocess_interceptor + progress = [] + self.test_object.progress_message.connect(progress.append) + self.test_object.python_requires = ["somepackage"] + self.test_object._install_required("vendor_path") + self.assertTrue(any("somepackage" in message for message in progress)) + logged_args = sm.arg_log[0] + self.assertIn("--progress-bar", logged_args) + self.assertIn("off", logged_args) + def test_install_optional_loops(self): sm = SubprocessMock() sm.succeed = True diff --git a/AddonManagerTest/app/test_utilities.py b/AddonManagerTest/app/test_utilities.py index fbb1c1d1..5b3c18ce 100644 --- a/AddonManagerTest/app/test_utilities.py +++ b/AddonManagerTest/app/test_utilities.py @@ -53,9 +53,37 @@ remember_git_host, resolve_constraints_location, run_interruptable_subprocess, + run_monitored_subprocess, + ProcessInterrupted, + SubprocessTimeout, ) +class _FakeStream: + """A minimal stand-in for a process stdout stream that yields preset lines then EOF.""" + + def __init__(self, lines): + self._lines = list(lines) + + def readline(self): + return self._lines.pop(0) if self._lines else "" + + +class _FakeProcess: + """A minimal Popen stand-in for exercising run_monitored_subprocess.""" + + def __init__(self, lines, returncode=0): + self.stdout = _FakeStream(lines) + self.returncode = returncode + self.killed = False + + def wait(self): + return self.returncode + + def kill(self): + self.killed = True + + class TestUtilities(unittest.TestCase): @classmethod @@ -257,6 +285,54 @@ def fake_time(): with patch("time.time", fake_time): run_interruptable_subprocess(["arg0", "arg1"], 0.1) + @patch("subprocess.Popen") + def test_run_interruptable_subprocess_none_timeout_never_expires(self, mock_popen): + """With no timeout the call keeps waiting through repeated poll timeouts until the + process finishes.""" + + def communicate(timeout=None): + communicate.calls += 1 + if communicate.calls <= 3: + raise subprocess.TimeoutExpired("Test", timeout) + return "done", "" + + communicate.calls = 0 + + mock_process = MagicMock() + mock_process.communicate = communicate + mock_process.returncode = 0 + mock_popen.return_value = mock_process + + result = run_interruptable_subprocess(["arg0", "arg1"], None) + self.assertEqual(0, result.returncode) + self.assertEqual("done", result.stdout) + + @patch("subprocess.Popen") + def test_run_monitored_subprocess_streams_lines_and_collects_output(self, mock_popen): + mock_popen.return_value = _FakeProcess(["Collecting x\n", "Downloading x (5 MB)\n"], 0) + received = [] + + result = run_monitored_subprocess(["pip", "install", "x"], line_callback=received.append) + + self.assertEqual(["Collecting x", "Downloading x (5 MB)"], received) + self.assertEqual("Collecting x\nDownloading x (5 MB)\n", result.stdout) + self.assertEqual(0, result.returncode) + + @patch("subprocess.Popen") + def test_run_monitored_subprocess_nonzero_exit_raises(self, mock_popen): + mock_popen.return_value = _FakeProcess(["error occurred\n"], 1) + with self.assertRaises(subprocess.CalledProcessError): + run_monitored_subprocess(["pip", "install", "x"]) + + @patch("subprocess.Popen") + @patch("addonmanager_utilities._interruption_requested", return_value=True) + def test_run_monitored_subprocess_interruption_raises(self, _mock_interrupt, mock_popen): + process = _FakeProcess(["Collecting x\n"], 0) + mock_popen.return_value = process + with self.assertRaises(ProcessInterrupted): + run_monitored_subprocess(["pip", "install", "x"]) + self.assertTrue(process.killed) + def test_process_date_string_to_python_datetime_non_numeric(self): with self.assertRaises(ValueError): process_date_string_to_python_datetime("TwentyTwentyFour-January-ThirtyFirst") diff --git a/AddonManagerTest/gui/test_installer_gui.py b/AddonManagerTest/gui/test_installer_gui.py index 3e57cf96..f3543daa 100644 --- a/AddonManagerTest/gui/test_installer_gui.py +++ b/AddonManagerTest/gui/test_installer_gui.py @@ -561,6 +561,7 @@ class MockDependencyInstaller(QtCore.QObject): no_pip = QtCore.Signal(str) failure = QtCore.Signal(str, str) finished = QtCore.Signal(bool) + progress_message = QtCore.Signal(str) class MockResult(IntEnum): OK = 0 @@ -646,6 +647,17 @@ def test_run_with_required_allowed_package_installs_package( self.assertTrue(gui.dependency_installer.moved_to_thread) self.assertEqual(["in_the_allowlist"], gui.dependency_installer.python_requires) + def test_update_dependency_progress_shows_message_in_label(self): + """A progress message from the installer is displayed in the dialog's label.""" + gui = AddonDependencyInstallerGUI([], self.create_mock_deps()) + holder = QtWidgets.QWidget() + holder.label = QtWidgets.QLabel(holder) + gui.dependency_installation_dialog = holder + + gui._update_dependency_progress("Collecting somepackage") + + self.assertIn("Collecting", holder.label.text()) + @patch("addonmanager_installer_gui.utils.blocking_get", MagicMock(return_value=None)) @patch("addonmanager_installer_gui.AddonInstaller") @patch("addonmanager_installer_gui.DependencyInstaller") @@ -677,9 +689,10 @@ def test_run_with_optional_unchecked_allowed_package_does_not_install_package( self.assertTrue( dialog_watcher.dialog_found, "Failed to find the Resolve Dependencies dialog box" ) - self.assertTrue( + # Nothing was selected, so no dependency installation runs and no installing dialog opens. + self.assertFalse( installing_dialog_watcher.dialog_found, - "Failed to find the Installing Dependencies dialog box", + "Unexpectedly found an Installing Dependencies dialog when nothing was selected", ) proceed_monitor.wait_for_at_most(500) self.assertTrue(proceed_monitor.good()) diff --git a/addonmanager_dependency_installer.py b/addonmanager_dependency_installer.py index 03bd557f..288cdba5 100644 --- a/addonmanager_dependency_installer.py +++ b/addonmanager_dependency_installer.py @@ -51,6 +51,7 @@ class DependencyInstaller(QtCore.QObject): no_pip = QtCore.Signal(str) # Attempted command failure = QtCore.Signal(str, str) # Short message, detailed message finished = QtCore.Signal(bool) # True if everything completed normally, otherwise false + progress_message = QtCore.Signal(str) # A human-readable line describing current activity def __init__( self, @@ -125,10 +126,15 @@ def _install_required(self, vendor_path: str) -> bool: continue # Do not attempt to install PySide, which must be part of FreeCAD already if QtCore.QThread.currentThread().isInterruptionRequested(): return False + self.progress_message.emit( + translate("AddonsInstaller", "Installing Python package {}").format(pymod) + ) try: proc = self._run_pip( [ "install", + "--progress-bar", + "off", "--target", vendor_path, pymod, @@ -153,10 +159,15 @@ def _install_optional(self, vendor_path: str): for pymod in self.python_optional: if QtCore.QThread.currentThread().isInterruptionRequested(): return + self.progress_message.emit( + translate("AddonsInstaller", "Installing Python package {}").format(pymod) + ) try: proc = self._run_pip( [ "install", + "--progress-bar", + "off", "--target", vendor_path, pymod, @@ -175,10 +186,10 @@ def _run_pip(self, args): final_args = utils.create_pip_call(args) return self._subprocess_wrapper(final_args) - @staticmethod - def _subprocess_wrapper(args) -> subprocess.CompletedProcess: - """Wrap subprocess call so test code can mock it.""" - return utils.run_interruptable_subprocess(args, timeout_secs=120) + def _subprocess_wrapper(self, args) -> subprocess.CompletedProcess: + """Run pip with no wall-clock timeout, forwarding each output line as a progress message. + Wrapped in a single method so test code can mock it.""" + return utils.run_monitored_subprocess(args, line_callback=self.progress_message.emit) def _install_addons(self): for addon in self.addons: diff --git a/addonmanager_installer_gui.py b/addonmanager_installer_gui.py index 3ca449f6..25a5c643 100644 --- a/addonmanager_installer_gui.py +++ b/addonmanager_installer_gui.py @@ -764,6 +764,7 @@ def _run_dependency_installer(self, addons, python_requires, python_optional): self.dependency_installer.no_pip.connect(self._report_no_pip) self.dependency_installer.failure.connect(self._report_dependency_failure) self.dependency_installer.finished.connect(self._dependencies_finished) + self.dependency_installer.progress_message.connect(self._update_dependency_progress) self.dependency_worker_thread = QtCore.QThread(self) self.dependency_worker_thread.setObjectName("Dependency Installer Thread") @@ -771,20 +772,34 @@ def _run_dependency_installer(self, addons, python_requires, python_optional): self.dependency_worker_thread.started.connect(self.dependency_installer.run) self.dependency_installer.finished.connect(self.dependency_worker_thread.quit) - self.dependency_installation_dialog = QtWidgets.QMessageBox( - QtWidgets.QMessageBox.Information, - translate("AddonsInstaller", "Installing Dependencies", "Window title"), - translate("AddonsInstaller", "Installing dependencies…", "Window text"), - QtWidgets.QMessageBox.Cancel, - parent=utils.get_main_am_window(), + self.dependency_installation_dialog = fci.loadUi( + os.path.join(os.path.dirname(__file__), "progress.ui") ) self.dependency_installation_dialog.setObjectName( "AddonManager_InstallingDependenciesDialog" ) + self.dependency_installation_dialog.setWindowTitle( + translate("AddonsInstaller", "Installing Dependencies", "Window title") + ) + self.dependency_installation_dialog.label.setText( + translate("AddonsInstaller", "Installing dependencies…", "Window text") + ) + # An indeterminate range animates the bar so the user can see work is ongoing during a + # download whose duration is not known in advance. + self.dependency_installation_dialog.progressBar.setRange(0, 0) self.dependency_installation_dialog.rejected.connect(self._cancel_dependency_installation) self.dependency_installation_dialog.show() self.dependency_worker_thread.start() + def _update_dependency_progress(self, message: str) -> None: + """Show the latest line of pip activity in the dependency installation dialog, elided so + a long line does not resize the dialog.""" + if self.dependency_installation_dialog is None: + return + label = self.dependency_installation_dialog.label + elided = label.fontMetrics().elidedText(message, QtCore.Qt.ElideMiddle, 360) + label.setText(elided) + def _report_no_python_exe(self) -> None: """Callback for the dependency installer failing to locate a Python executable.""" if self.dependency_installation_dialog is not None: @@ -840,8 +855,6 @@ def _report_dependency_failure(self, short_message: str, details: str) -> None: """Callback for dependency installation failure.""" if self.dependency_installation_dialog is not None: self.dependency_installation_dialog.hide() - if self.dependency_installer and hasattr(self.dependency_installer, "finished"): - self.dependency_installer.finished.disconnect(self._report_dependency_success) fci.Console.PrintError(details + "\n") result = MessageDialog.show_modal( MessageDialog.DialogType.ERROR, diff --git a/addonmanager_python_deps.py b/addonmanager_python_deps.py index 0939e154..b0296158 100644 --- a/addonmanager_python_deps.py +++ b/addonmanager_python_deps.py @@ -64,7 +64,7 @@ def call_pip(args: List[str]) -> List[str]: raise PipFailed() from exception try: - proc = run_interruptable_subprocess(call_args, 120) + proc = run_interruptable_subprocess(call_args, timeout_secs=None) except subprocess.CalledProcessError as exception: raise PipFailed(f"pip call failed:\n{exception}") from exception diff --git a/addonmanager_utilities.py b/addonmanager_utilities.py index 2d91cba2..5d12b1f2 100644 --- a/addonmanager_utilities.py +++ b/addonmanager_utilities.py @@ -26,10 +26,11 @@ from dataclasses import dataclass from datetime import datetime -from typing import Dict, Optional, Any, List, Tuple +from typing import Callable, Dict, Optional, Any, List, Tuple import json import os import platform +import queue import shutil import stat import subprocess @@ -110,6 +111,15 @@ class ProcessInterrupted(RuntimeError): """An interruption request was received and the process killed because of it.""" +class SubprocessTimeout(subprocess.CalledProcessError): + """A subprocess exceeded its wall-clock timeout and was killed. It subclasses + CalledProcessError so existing handlers still catch it, but reports the timeout honestly + rather than as a phantom termination signal.""" + + def __str__(self) -> str: + return f"Command '{self.cmd}' timed out and was terminated." + + def symlink(source, link_name): """Creates a symlink of a file, if possible. Note that it fails on most modern Windows installations""" @@ -644,8 +654,11 @@ def blocking_get(url: str, method=None) -> bytes: return p -def run_interruptable_subprocess(args, timeout_secs: int = 10) -> subprocess.CompletedProcess: - """Wrap subprocess call so it can be interrupted gracefully.""" +def run_interruptable_subprocess( + args, timeout_secs: Optional[float] = 10 +) -> subprocess.CompletedProcess: + """Wrap subprocess call so it can be interrupted gracefully. If timeout_secs is None there + is no wall-clock limit, and the call runs until the process finishes or is interrupted.""" creation_flags = 0 if hasattr(subprocess, "CREATE_NO_WINDOW"): # Added in Python 3.7 -- only used on Windows @@ -671,23 +684,99 @@ def run_interruptable_subprocess(args, timeout_secs: int = 10) -> subprocess.Com stdout, stderr = p.communicate(timeout=1) return_code = p.returncode except subprocess.TimeoutExpired as timeout_exception: - if ( - hasattr(QtCore, "QThread") - and QtCore.QThread.currentThread().isInterruptionRequested() - ): + if _interruption_requested(): p.kill() raise ProcessInterrupted() from timeout_exception - if time.time() - start_time >= timeout_secs: # The real timeout + if timeout_secs is not None and time.time() - start_time >= timeout_secs: p.kill() stdout, stderr = p.communicate() - return_code = -1 - if return_code is None or return_code != 0: - raise subprocess.CalledProcessError( - return_code if return_code is not None else -1, args, stdout, stderr - ) + raise SubprocessTimeout(-1, args, stdout, stderr) from timeout_exception + if return_code != 0: + raise subprocess.CalledProcessError(return_code, args, stdout, stderr) return subprocess.CompletedProcess(args, return_code, stdout, stderr) +def _interruption_requested() -> bool: + """Return True if the current QThread has been asked to stop. Isolated so tests can drive + the interruption logic without a running QThread.""" + return hasattr(QtCore, "QThread") and QtCore.QThread.currentThread().isInterruptionRequested() + + +def run_monitored_subprocess( + args, line_callback: Optional[Callable[[str], None]] = None +) -> subprocess.CompletedProcess: + """Run a subprocess with no wall-clock timeout, streaming its combined output line by line + to an optional callback as it arrives. Remains responsive to interruption a few times per + second. Raises ProcessInterrupted if interrupted, or CalledProcessError on a non-zero exit. + + This is intended for long, unbounded operations such as installing large Python packages, + where the caller wants live progress and the user cancels via interruption rather than a + timeout.""" + creation_flags = 0 + if hasattr(subprocess, "CREATE_NO_WINDOW"): + creation_flags = subprocess.CREATE_NO_WINDOW + try: + process = subprocess.Popen( + args, + stdout=subprocess.PIPE, + stderr=subprocess.STDOUT, + creationflags=creation_flags, + text=True, + encoding="utf-8", + bufsize=1, + ) + except OSError as e: + raise subprocess.CalledProcessError(-1, args, "", e.strerror) + + lines: "queue.Queue[Optional[str]]" = queue.Queue() + reader = threading.Thread(target=_enqueue_lines, args=(process.stdout, lines), daemon=True) + reader.start() + + collected: List[str] = [] + finished_reading = False + while not finished_reading: + try: + line = lines.get(timeout=0.2) + except queue.Empty: + if _interruption_requested(): + _terminate(process, reader) + raise ProcessInterrupted() + continue + if line is None: + finished_reading = True + continue + collected.append(line) + if line_callback is not None: + line_callback(line.rstrip()) + if _interruption_requested(): + _terminate(process, reader) + raise ProcessInterrupted() + + process.wait() + reader.join() + output = "".join(collected) + if process.returncode != 0: + raise subprocess.CalledProcessError(process.returncode, args, output, "") + return subprocess.CompletedProcess(args, process.returncode, output, "") + + +def _enqueue_lines(stream, lines: "queue.Queue[Optional[str]]") -> None: + """Read a text stream line by line onto a queue, appending a None sentinel at end of file.""" + try: + for line in iter(stream.readline, ""): + lines.put(line) + finally: + lines.put(None) + + +def _terminate(process: subprocess.Popen, reader: threading.Thread) -> None: + """Kill a process and wait for its reader thread to drain, so no output thread is left + running after an interruption.""" + process.kill() + process.wait() + reader.join() + + def process_date_string_to_python_datetime(date_string: str) -> datetime: """For modern macros the expected date format is ISO 8601, YYYY-MM-DD. For older macros this standard was not always used, and various orderings and separators were used. This function