diff --git a/src/keboola_agent_cli/auto_update.py b/src/keboola_agent_cli/auto_update.py index 3255b176..0ea76d51 100644 --- a/src/keboola_agent_cli/auto_update.py +++ b/src/keboola_agent_cli/auto_update.py @@ -16,6 +16,7 @@ import subprocess import sys import time +from dataclasses import dataclass from importlib.metadata import distribution from pathlib import Path @@ -47,6 +48,7 @@ prepare_kbagent_update_plan, prepare_mcp_update_plan, resolve_kbagent_wheel_url, + summarize_failure_tail, ) logger = logging.getLogger(__name__) @@ -66,6 +68,28 @@ class UpdateOutcome(enum.Enum): FAILED = "failed" +@dataclass(frozen=True) +class UpdateAttempt: + """One self-update subprocess run: its outcome plus *why* it ended that way. + + The startup hook runs the installer with ``capture_output=True`` and used to + throw the transcript away, so a failed auto-update printed a bare + "Auto-update failed" and every bug report arrived without the one line that + explains it -- see issues #528 and #545, where the venv was left broken on + Windows and neither report could say what uv actually refused to do. The + explicit ``kbagent update`` path has always surfaced ``result.stderr``; + carrying the tail here closes that asymmetry. + + Attributes: + outcome: SUCCESS / TIMEOUT / FAILED. + detail: Last actionable line of the installer transcript (empty when + there is nothing to report, e.g. on SUCCESS or TIMEOUT). + """ + + outcome: UpdateOutcome + detail: str = "" + + # Process-level sentinel for the auto-update flow. # # Bug D fix from issue #263: ``kbagent repl`` re-enters the entire CLI @@ -270,7 +294,7 @@ def _should_skip() -> bool: def _perform_update( latest_version: str, *, command: tuple[str, ...] | None = None -) -> UpdateOutcome: +) -> UpdateAttempt: """Download and install the latest version. Delegates to :func:`build_kbagent_upgrade_command` so this path stays @@ -285,9 +309,12 @@ def _perform_update( latest_version: The version being updated to (for logging). Returns: - :class:`UpdateOutcome`: ``SUCCESS`` on a clean install, ``TIMEOUT`` when - the install subprocess outran :func:`get_update_timeout` (a slow git+ - build -- retried next run, not a real failure), ``FAILED`` otherwise. + :class:`UpdateAttempt` carrying ``SUCCESS`` on a clean install, + ``TIMEOUT`` when the install subprocess outran + :func:`get_update_timeout` (a slow git+ build -- retried next run, not a + real failure), ``FAILED`` otherwise. A FAILED attempt also carries the + last actionable line of the installer transcript so the banner can say + what went wrong instead of only that something did. """ # ``command`` is supplied by the startup planner. Keep the fallback only # for direct legacy callers; it must never be used after another stage has @@ -298,7 +325,9 @@ def _perform_update( else: cmd = list(command) if cmd is None: - return UpdateOutcome.FAILED + return UpdateAttempt( + UpdateOutcome.FAILED, "no installer found on PATH (neither uv nor pip)" + ) try: result = subprocess.run( @@ -307,11 +336,16 @@ def _perform_update( text=True, timeout=get_update_timeout(), ) - return UpdateOutcome.SUCCESS if result.returncode == 0 else UpdateOutcome.FAILED + if result.returncode == 0: + return UpdateAttempt(UpdateOutcome.SUCCESS) + # uv writes its diagnostics to stderr; fall back to stdout for + # installers that do not (and so the tail is never empty by accident). + transcript = result.stderr or result.stdout + return UpdateAttempt(UpdateOutcome.FAILED, summarize_failure_tail(transcript)) except subprocess.TimeoutExpired: - return UpdateOutcome.TIMEOUT - except OSError: - return UpdateOutcome.FAILED + return UpdateAttempt(UpdateOutcome.TIMEOUT) + except OSError as exc: + return UpdateAttempt(UpdateOutcome.FAILED, str(exc)) def _re_exec() -> None: @@ -608,9 +642,10 @@ def maybe_auto_update() -> None: return sys.stderr.write(f"Updating kbagent v{__version__} -> v{kbagent_plan.latest_version}...\n") - outcome = _perform_update( + attempt = _perform_update( kbagent_plan.latest_version or __version__, command=kbagent_plan.command ) + outcome = attempt.outcome if outcome is UpdateOutcome.SUCCESS: sys.stderr.write(f"Updated to v{kbagent_plan.latest_version}. Re-launching...\n") os.environ[ENV_UPDATED_FROM] = __version__ @@ -622,8 +657,13 @@ def maybe_auto_update() -> None: f"{kbagent_plan.recovery_command}\n" ) else: + # The installer's own last line is the only clue to WHY the upgrade + # failed, and on Windows a failed upgrade can leave the tool + # environment mid-swap (#528 / #545) -- so it must reach the user, + # not just the discarded subprocess buffer. + reason = f" ({attempt.detail})" if attempt.detail else "" sys.stderr.write( - "Auto-update failed; continuing with current version. Recover with: " + f"Auto-update failed{reason}; continuing with current version. Recover with: " f"{kbagent_plan.recovery_command}\n" ) except Exception: diff --git a/src/keboola_agent_cli/services/version_service.py b/src/keboola_agent_cli/services/version_service.py index d6eb2c1e..d6f2fdc2 100644 --- a/src/keboola_agent_cli/services/version_service.py +++ b/src/keboola_agent_cli/services/version_service.py @@ -248,6 +248,26 @@ def build_kbagent_upgrade_command( return cmd +def summarize_failure_tail(message: str | None) -> str: + """Compress a multi-line installer transcript to its last non-empty line. + + Subprocess failures embed the whole uv/pip transcript; the actionable line + (e.g. ``error: Executable already exists: kbagent``, or a Windows + ``failed to remove file ... (os error 32)``) is last. Callers surface only + that tail in a one-line message and keep the full transcript for + ``--json`` / ``--verbose``. + + Args: + message: The captured transcript, or None. + + Returns: + The last non-empty line, or ``"update failed"`` when there is nothing + to report. + """ + lines = [ln.strip() for ln in (message or "").splitlines() if ln.strip()] + return lines[-1] if lines else "update failed" + + def _render_command(command: tuple[str, ...]) -> str: """Render argv for the current platform's interactive shell.""" if os.name == "nt": @@ -958,13 +978,11 @@ def self_update(self, *, include_prerelease: bool = False) -> dict[str, Any]: def _summarize_failure_tail(message: str | None) -> str: """Compress a multi-line failure message to its last non-empty line. - Subprocess failures embed the whole uv/pip transcript; the actionable - line (e.g. ``error: Executable already exists: kbagent``) is last. We - surface only that tail in the one-line summary -- the full transcript - stays in the result's ``output`` for ``--json`` / ``--verbose``. + Thin delegate to :func:`summarize_failure_tail` so the startup + auto-update hook and the explicit ``kbagent update`` path report a + failure the same way. """ - lines = [ln.strip() for ln in (message or "").splitlines() if ln.strip()] - return lines[-1] if lines else "update failed" + return summarize_failure_tail(message) @classmethod def _compose_update_summary( diff --git a/tests/test_auto_update.py b/tests/test_auto_update.py index 46b5714d..1441035f 100644 --- a/tests/test_auto_update.py +++ b/tests/test_auto_update.py @@ -9,6 +9,7 @@ import keboola_agent_cli.auto_update as auto_update_module from keboola_agent_cli.auto_update import ( + UpdateAttempt, UpdateOutcome, _get_cache_path, _is_cache_fresh, @@ -245,7 +246,7 @@ class TestPerformUpdate: def test_update_with_uv_success(self, mock_run, mock_which): mock_which.return_value = "/usr/local/bin/uv" mock_run.return_value = MagicMock(returncode=0) - assert _perform_update("2.0.0") is UpdateOutcome.SUCCESS + assert _perform_update("2.0.0").outcome is UpdateOutcome.SUCCESS # Verify uv was called call_args = mock_run.call_args assert "uv" in call_args[0][0][0] @@ -255,7 +256,7 @@ def test_update_with_uv_success(self, mock_run, mock_which): def test_update_with_uv_failure(self, mock_run, mock_which): mock_which.return_value = "/usr/local/bin/uv" mock_run.return_value = MagicMock(returncode=1, stderr="error") - assert _perform_update("2.0.0") is UpdateOutcome.FAILED + assert _perform_update("2.0.0").outcome is UpdateOutcome.FAILED @patch("shutil.which") @patch("subprocess.run") @@ -265,14 +266,14 @@ def test_update_pip_fallback(self, mock_run, mock_which): None if cmd == "uv" else "/usr/bin/pip" if cmd == "pip" else None ) mock_run.return_value = MagicMock(returncode=0) - assert _perform_update("2.0.0") is UpdateOutcome.SUCCESS + assert _perform_update("2.0.0").outcome is UpdateOutcome.SUCCESS call_args = mock_run.call_args assert "pip" in call_args[0][0][0] @patch("shutil.which") def test_update_no_tools(self, mock_which): mock_which.return_value = None - assert _perform_update("2.0.0") is UpdateOutcome.FAILED + assert _perform_update("2.0.0").outcome is UpdateOutcome.FAILED @patch("shutil.which") @patch("subprocess.run") @@ -281,7 +282,7 @@ def test_update_timeout(self, mock_run, mock_which): mock_which.return_value = "/usr/local/bin/uv" mock_run.side_effect = sp.TimeoutExpired(cmd="uv", timeout=120) - assert _perform_update("2.0.0") is UpdateOutcome.TIMEOUT + assert _perform_update("2.0.0").outcome is UpdateOutcome.TIMEOUT @patch( "keboola_agent_cli.services.version_service.has_server_extras", @@ -302,7 +303,7 @@ def test_update_preserves_server_extras(self, mock_run, mock_which, mock_has_ser ``--force`` when ``fastapi`` is importable. """ mock_run.return_value = MagicMock(returncode=0) - assert _perform_update("2.0.0") is UpdateOutcome.SUCCESS + assert _perform_update("2.0.0").outcome is UpdateOutcome.SUCCESS argv = mock_run.call_args[0][0] # The extras live in the primary PEP 508 requirement so the complete # environment is resolved in one forced reinstall. @@ -320,7 +321,7 @@ def test_update_preserves_server_extras(self, mock_run, mock_which, mock_has_ser def test_update_without_server_extras_uses_upgrade(self, mock_run, mock_which, mock_has_server): """No-extras installs are also a full forced reinstall.""" mock_run.return_value = MagicMock(returncode=0) - assert _perform_update("2.0.0") is UpdateOutcome.SUCCESS + assert _perform_update("2.0.0").outcome is UpdateOutcome.SUCCESS argv = mock_run.call_args[0][0] assert "--force" in argv assert "--reinstall" in argv @@ -344,7 +345,7 @@ def test_installs_wheel_when_asset_present( mock_head.return_value = MagicMock(status_code=200) mock_run.return_value = MagicMock(returncode=0) - assert _perform_update("2.0.0") is UpdateOutcome.SUCCESS + assert _perform_update("2.0.0").outcome is UpdateOutcome.SUCCESS argv = mock_run.call_args[0][0] # PEP 508 direct ref to the versioned wheel, --force, and no git+ source. @@ -360,12 +361,118 @@ def test_falls_back_to_git_when_no_asset(self, mock_run, mock_which, mock_head): mock_head.return_value = MagicMock(status_code=404) mock_run.return_value = MagicMock(returncode=0) - assert _perform_update("2.0.0") is UpdateOutcome.SUCCESS + assert _perform_update("2.0.0").outcome is UpdateOutcome.SUCCESS argv = mock_run.call_args[0][0] assert any("git+" in part for part in argv) +class TestPerformUpdateFailureDetail: + """A failed startup update must say WHY (issues #528 / #545). + + The installer runs with ``capture_output=True``; before this the transcript + was discarded and the banner said only "Auto-update failed", so a Windows + user whose tool environment was left mid-swap could not report what uv + actually refused to do. The explicit ``kbagent update`` path has always + surfaced ``result.stderr``. + """ + + @patch("shutil.which", return_value="/usr/local/bin/uv") + @patch("subprocess.run") + def test_failure_carries_stderr_tail(self, mock_run, mock_which): + mock_run.return_value = MagicMock( + returncode=1, + stderr=( + "Resolved 52 packages in 1.20s\n" + "error: failed to remove file `...\\Scripts\\kbagent.exe`\n" + " Caused by: Access is denied. (os error 5)\n" + ), + stdout="", + ) + attempt = _perform_update("2.0.0") + assert attempt.outcome is UpdateOutcome.FAILED + assert attempt.detail == "Caused by: Access is denied. (os error 5)" + + @patch("shutil.which", return_value="/usr/local/bin/uv") + @patch("subprocess.run") + def test_falls_back_to_stdout_when_stderr_empty(self, mock_run, mock_which): + # Not every installer writes diagnostics to stderr; an empty tail would + # put us right back to "something failed, no idea what". + mock_run.return_value = MagicMock(returncode=1, stderr="", stdout="ERROR: no matching dist") + assert _perform_update("2.0.0").detail == "ERROR: no matching dist" + + @patch("shutil.which", return_value=None) + def test_missing_installer_is_explained(self, mock_which): + attempt = _perform_update("2.0.0") + assert attempt.outcome is UpdateOutcome.FAILED + assert "neither uv nor pip" in attempt.detail + + @patch("shutil.which", return_value="/usr/local/bin/uv") + @patch("subprocess.run", side_effect=OSError("Permission denied")) + def test_os_error_is_explained(self, mock_run, mock_which): + attempt = _perform_update("2.0.0") + assert attempt.outcome is UpdateOutcome.FAILED + assert "Permission denied" in attempt.detail + + @patch("shutil.which", return_value="/usr/local/bin/uv") + @patch("subprocess.run") + def test_timeout_carries_no_detail(self, mock_run, mock_which): + import subprocess as sp + + mock_run.side_effect = sp.TimeoutExpired(cmd="uv", timeout=1) + attempt = _perform_update("2.0.0") + assert attempt.outcome is UpdateOutcome.TIMEOUT + assert attempt.detail == "" + + +class TestFailureBannerText: + """The failure banner surfaces the installer's own last line.""" + + @staticmethod + def _run_failed_update(monkeypatch, attempt: UpdateAttempt) -> None: + monkeypatch.setattr(auto_update_module, "_AUTO_UPDATE_RAN", False) + monkeypatch.setattr(auto_update_module, "_should_skip_all", lambda: False) + monkeypatch.setattr(auto_update_module, "_should_skip_kbagent_stage", lambda: False) + monkeypatch.setattr(auto_update_module, "_read_cache", lambda: None) + monkeypatch.setattr( + auto_update_module, "_fetch_kbagent_latest_version", lambda **_: "2.0.0" + ) + monkeypatch.setattr(auto_update_module, "_fetch_mcp_latest_version", lambda **_: None) + monkeypatch.setattr(auto_update_module, "_apply_prepared_mcp_update", lambda _plan: None) + monkeypatch.setattr(auto_update_module, "_write_cache", lambda **_: None) + monkeypatch.setattr(auto_update_module, "_is_up_to_date", lambda *_: False) + monkeypatch.setattr( + auto_update_module, + "prepare_kbagent_update_plan", + lambda latest: KbagentUpdatePlan( + current_version="1.0.0", + latest_version="2.0.0", + up_to_date=False, + command=("uv", "tool", "install"), + recovery_command="uv tool install --force --reinstall keboola-cli", + ), + ) + monkeypatch.setattr(auto_update_module, "_perform_update", lambda *_a, **_k: attempt) + monkeypatch.setattr(auto_update_module, "_re_exec", lambda: None) + maybe_auto_update() + + def test_detail_is_printed(self, monkeypatch, capsys): + self._run_failed_update( + monkeypatch, + UpdateAttempt(UpdateOutcome.FAILED, "error: Access is denied. (os error 5)"), + ) + err = capsys.readouterr().err + assert "Auto-update failed (error: Access is denied. (os error 5))" in err + assert "uv tool install --force --reinstall keboola-cli" in err + + def test_banner_stays_clean_without_detail(self, monkeypatch, capsys): + # No empty parentheses when the installer told us nothing. + self._run_failed_update(monkeypatch, UpdateAttempt(UpdateOutcome.FAILED)) + err = capsys.readouterr().err + assert "Auto-update failed; continuing with current version." in err + assert "()" not in err + + # --------------------------------------------------------------------------- # _re_exec # --------------------------------------------------------------------------- @@ -512,7 +619,10 @@ def test_up_to_date_no_update( @patch("keboola_agent_cli.auto_update._fetch_kbagent_latest_version", return_value="2.0.0") @patch("keboola_agent_cli.auto_update._write_cache") @patch("keboola_agent_cli.auto_update._is_up_to_date", return_value=False) - @patch("keboola_agent_cli.auto_update._perform_update", return_value=UpdateOutcome.SUCCESS) + @patch( + "keboola_agent_cli.auto_update._perform_update", + return_value=UpdateAttempt(UpdateOutcome.SUCCESS), + ) @patch("keboola_agent_cli.auto_update._re_exec") @patch("keboola_agent_cli.auto_update.__version__", "1.0.0") def test_newer_available_updates_and_reexec( @@ -534,7 +644,10 @@ def test_newer_available_updates_and_reexec( @patch("keboola_agent_cli.auto_update._fetch_kbagent_latest_version", return_value="2.0.0") @patch("keboola_agent_cli.auto_update._write_cache") @patch("keboola_agent_cli.auto_update._is_up_to_date", return_value=False) - @patch("keboola_agent_cli.auto_update._perform_update", return_value=UpdateOutcome.FAILED) + @patch( + "keboola_agent_cli.auto_update._perform_update", + return_value=UpdateAttempt(UpdateOutcome.FAILED), + ) @patch("keboola_agent_cli.auto_update._re_exec") @patch("keboola_agent_cli.auto_update.__version__", "1.0.0") def test_update_failure_continues( @@ -556,7 +669,7 @@ def test_update_failure_continues( @patch("keboola_agent_cli.auto_update._is_up_to_date", return_value=False) @patch( "keboola_agent_cli.auto_update._perform_update", - return_value=UpdateOutcome.TIMEOUT, + return_value=UpdateAttempt(UpdateOutcome.TIMEOUT), ) @patch("keboola_agent_cli.auto_update._re_exec") @patch("keboola_agent_cli.auto_update._apply_prepared_mcp_update") @@ -836,7 +949,10 @@ def test_kbagent_uptodate_still_runs_mcp_stage( @patch("keboola_agent_cli.auto_update._read_cache", return_value=None) @patch("keboola_agent_cli.auto_update._fetch_kbagent_latest_version", return_value="2.0.0") @patch("keboola_agent_cli.auto_update._is_up_to_date", return_value=False) - @patch("keboola_agent_cli.auto_update._perform_update", return_value=UpdateOutcome.FAILED) + @patch( + "keboola_agent_cli.auto_update._perform_update", + return_value=UpdateAttempt(UpdateOutcome.FAILED), + ) @patch("keboola_agent_cli.auto_update._apply_prepared_mcp_update") @patch("keboola_agent_cli.auto_update._detect_mcp_install_method", return_value="uv_tool") @patch("keboola_agent_cli.auto_update._write_cache") @@ -1110,12 +1226,12 @@ def write_cache(**kwargs: object) -> None: assert not mutated events.append("cache") - def perform(version: str, *, command: tuple[str, ...]) -> UpdateOutcome: + def perform(version: str, *, command: tuple[str, ...]) -> UpdateAttempt: nonlocal mutated assert events[-1] == "cache" mutated = True events.append("kbagent") - return UpdateOutcome.SUCCESS + return UpdateAttempt(UpdateOutcome.SUCCESS) def reexec() -> None: assert mutated diff --git a/tests/test_version_service.py b/tests/test_version_service.py index 0409ae1b..7a75eb94 100644 --- a/tests/test_version_service.py +++ b/tests/test_version_service.py @@ -26,6 +26,7 @@ build_kbagent_upgrade_command, get_update_timeout, resolve_kbagent_wheel_url, + summarize_failure_tail, ) @@ -1419,3 +1420,10 @@ def test_failure_tail_is_last_nonempty_line(self) -> None: assert VersionService._summarize_failure_tail(msg) == "error: the real reason" assert VersionService._summarize_failure_tail("") == "update failed" assert VersionService._summarize_failure_tail(None) == "update failed" + + def test_failure_tail_shared_with_startup_hook(self) -> None: + # The startup auto-update hook imports the module-level function, so + # both update paths must compress a transcript identically (#545). + msg = "Resolved 52 packages\nerror: Access is denied. (os error 5)\n" + assert summarize_failure_tail(msg) == VersionService._summarize_failure_tail(msg) + assert summarize_failure_tail(msg) == "error: Access is denied. (os error 5)"