diff --git a/CHANGELOG.md b/CHANGELOG.md index b521d111..38b582da 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,6 +15,8 @@ GitHub Releases page; `0.8.0` is the new starting line. ## Unreleased +- Retry the post-update smoke check briefly before recording `VERIFICATION_FAILED`, absorbing the Homebrew launcher-relink race that falsely failed successful upgrades, and print the verification failure on screen instead of leaving "Updated successfully!" as the last word when verification genuinely fails. + ## 0.62.0 (2026-07-22) - Treat the repository-root `.agents/` directory as local agent configuration and keep it out of version control. diff --git a/src/pythinker_code/ui/shell/update_orchestrator.py b/src/pythinker_code/ui/shell/update_orchestrator.py index a1c963f2..9e9715bb 100644 --- a/src/pythinker_code/ui/shell/update_orchestrator.py +++ b/src/pythinker_code/ui/shell/update_orchestrator.py @@ -1,5 +1,6 @@ from __future__ import annotations +import asyncio import contextlib import json import os @@ -408,7 +409,7 @@ async def run_update_job( append_update_log(message) _write_last_success(job_id=job_id, message=message) else: - smoke_ok, smoke_message = run_post_install_smoke_check( + smoke_ok, smoke_message = await _run_smoke_check_with_retry( target_version=_read_target_version() ) append_update_log(smoke_message) @@ -422,6 +423,13 @@ async def run_update_job( final_state = _result_state(reported_result) # Never promote a staged binary that can't even print --version. _finalize_native_staging(promote=False) + # The install step has already printed its own success line; + # leaving the screen at "Updated successfully!" while the + # recorded state is VERIFICATION_FAILED would misreport the + # outcome (the footer keeps the update notice for the same + # reason). Surface the failure where the success was shown. + if print_output: + console.print(f"[{_get_tui_tokens().warning}]{message}[/]") write_update_status( _new_status( @@ -435,6 +443,27 @@ async def run_update_job( ) ) return reported_result + except asyncio.CancelledError: + # Cancellation lands on the await points (do_update, the smoke-check + # thread, retry sleeps) and would otherwise skip the failure handler + # below, releasing the lock with the job still recorded as RUNNING — + # a stale "in progress" status with no process behind it. Record a + # terminal state, then propagate. The smoke-check subprocess is not + # interrupted mid-flight, but its own timeout bounds it. + message = "Update job cancelled." + append_update_log(message) + write_update_status( + _new_status( + job_id=job_id, + state=UpdateJobState.FAILED, + source=source, + started_at=started_at, + finished_at=time.time(), + result=UpdateResult.FAILED.name, + message=message, + ) + ) + raise except Exception as exc: message = f"Update failed: {exc}" append_update_log(message) @@ -548,6 +577,35 @@ def _smoke_check_env() -> dict[str, str]: return env +_SMOKE_CHECK_ATTEMPTS = 3 +_SMOKE_CHECK_RETRY_DELAY_SECONDS = 1.0 + + +async def _run_smoke_check_with_retry(target_version: str | None) -> tuple[bool, str]: + """Run the post-install smoke check, retrying transient failures. + + Package managers can report success moments before the launcher they manage + is repointed at the new install (observed with Homebrew's ``opt`` symlink): + an immediate probe then exercises the OLD binary, reports the old version, + and records a false ``VERIFICATION_FAILED``. A short retry window absorbs + that race; a real bad install still fails every attempt. The subprocess + probe runs off the event loop so a slow/hung binary cannot stall the shell. + """ + smoke_ok, smoke_message = False, "Smoke check did not run." + for attempt in range(1, _SMOKE_CHECK_ATTEMPTS + 1): + smoke_ok, smoke_message = await asyncio.to_thread( + run_post_install_smoke_check, target_version=target_version + ) + if smoke_ok or attempt == _SMOKE_CHECK_ATTEMPTS: + break + append_update_log( + f"Smoke check attempt {attempt}/{_SMOKE_CHECK_ATTEMPTS} failed " + f"({smoke_message}); retrying in {_SMOKE_CHECK_RETRY_DELAY_SECONDS:g}s..." + ) + await asyncio.sleep(_SMOKE_CHECK_RETRY_DELAY_SECONDS) + return smoke_ok, smoke_message + + def run_post_install_smoke_check(target_version: str | None = None) -> tuple[bool, str]: command = _smoke_check_command() try: diff --git a/tests/ui_and_conv/test_empty_think_part_indicator.py b/tests/ui_and_conv/test_empty_think_part_indicator.py index 35bd934a..bd9bd955 100644 --- a/tests/ui_and_conv/test_empty_think_part_indicator.py +++ b/tests/ui_and_conv/test_empty_think_part_indicator.py @@ -213,10 +213,16 @@ def test_moon_fallback_during_active_turn(): assert agent_blocks[0].plain.strip() == "" -def test_working_indicator_stays_visible_when_content_block_visible(): +def test_working_indicator_stays_visible_when_content_block_visible(monkeypatch): """The activity spinner stays visible while content streams.""" from rich.text import Text + from pythinker_code.ui.shell.visualize import _live_view + + # The verb rotates on wall-clock over a list that legitimately includes + # "Working"; pin it so the static-"Working…" regression guard below cannot + # false-positive during that verb's 10-minute rotation window. + monkeypatch.setattr(_live_view, "spinner_message", lambda now=None, **_kw: "Composing…") view = _LiveView(StatusUpdate()) view.dispatch_wire_message(TurnBegin(user_input="test")) view.dispatch_wire_message(StepBegin(n=1)) @@ -286,7 +292,10 @@ def test_moon_fallback_after_all_tools_flushed(monkeypatch): def test_working_indicator_stays_visible_while_parallel_tool_still_running(monkeypatch): """The activity spinner stays visible while tool blocks are visible.""" from pythinker_code.ui.shell.console import console as shell_console + from pythinker_code.ui.shell.visualize import _live_view + # Pin the wall-clock-rotated verb; see the content-block variant above. + monkeypatch.setattr(_live_view, "spinner_message", lambda now=None, **_kw: "Composing…") view = _LiveView(StatusUpdate()) monkeypatch.setattr(shell_console, "print", lambda *args, **kwargs: None) diff --git a/tests/ui_and_conv/test_modal_lifecycle.py b/tests/ui_and_conv/test_modal_lifecycle.py index c3fd4d36..27eed8dd 100644 --- a/tests/ui_and_conv/test_modal_lifecycle.py +++ b/tests/ui_and_conv/test_modal_lifecycle.py @@ -914,12 +914,17 @@ async def test_compose_equals_panels_plus_agent_output() -> None: @pytest.mark.asyncio -async def test_compose_agent_output_includes_spinners_and_tool_calls() -> None: +async def test_compose_agent_output_includes_spinners_and_tool_calls(monkeypatch) -> None: """compose_agent_output() should include activity indicators and tool call blocks.""" from rich.text import Text + from pythinker_code.ui.shell.visualize import _live_view from pythinker_code.wire.types import ToolCall + # The spinner verb rotates on wall-clock over a list that legitimately + # includes "Working"; pin it so the static-"Working…" regression guard + # below cannot false-positive during that verb's rotation window. + monkeypatch.setattr(_live_view, "spinner_message", lambda now=None, **_kw: "Composing…") view = _LiveView(StatusUpdate()) view._active_turn_depth = 1 # working fallback requires active turn diff --git a/tests/ui_and_conv/test_update_orchestrator.py b/tests/ui_and_conv/test_update_orchestrator.py index c578fbe8..ded152dc 100644 --- a/tests/ui_and_conv/test_update_orchestrator.py +++ b/tests/ui_and_conv/test_update_orchestrator.py @@ -173,17 +173,23 @@ async def fake_do_update( return update.UpdateResult.UPDATED monkeypatch.setattr(update, "do_update", fake_do_update) - monkeypatch.setattr( - orchestrator, - "run_post_install_smoke_check", - lambda **_kw: (False, "Smoke check failed: broken"), - ) + monkeypatch.setattr(orchestrator, "_SMOKE_CHECK_RETRY_DELAY_SECONDS", 0.0) + attempts = 0 + + def fake_smoke(**_kw): + nonlocal attempts + attempts += 1 + return (False, "Smoke check failed: broken") + + monkeypatch.setattr(orchestrator, "run_post_install_smoke_check", fake_smoke) result = await orchestrator.run_update_job( print_output=False, intent=update.UpdateIntent.INSTALL, source="test" ) assert result is update.UpdateResult.VERIFICATION_FAILED + # A hard failure is retried before being reported — every attempt failed. + assert attempts == orchestrator._SMOKE_CHECK_ATTEMPTS status = orchestrator.read_update_status() assert status is not None assert status.state is orchestrator.UpdateJobState.FAILED @@ -192,6 +198,86 @@ async def fake_do_update( assert not orchestrator.UPDATE_LAST_SUCCESS_FILE.exists() +@pytest.mark.asyncio +async def test_update_job_smoke_check_retry_absorbs_launcher_relink_race(monkeypatch, tmp_path): + """A transiently stale launcher (e.g. brew's opt link mid-relink) must not + record VERIFICATION_FAILED when a later attempt passes.""" + _isolate_update_files(monkeypatch, tmp_path) + + async def fake_do_update( + *, print_output: bool, intent: update.UpdateIntent, output_callback=None + ): + return update.UpdateResult.UPDATED + + monkeypatch.setattr(update, "do_update", fake_do_update) + monkeypatch.setattr(orchestrator, "_SMOKE_CHECK_RETRY_DELAY_SECONDS", 0.0) + attempts = 0 + + def fake_smoke(**_kw): + nonlocal attempts + attempts += 1 + if attempts == 1: + return (False, "Smoke check reported 0.60.0, expected 0.62.0") + return (True, "Smoke check passed: pythinker, version 0.62.0") + + monkeypatch.setattr(orchestrator, "run_post_install_smoke_check", fake_smoke) + + result = await orchestrator.run_update_job( + print_output=False, intent=update.UpdateIntent.INSTALL, source="test" + ) + + assert result is update.UpdateResult.UPDATED + assert attempts == 2 + status = orchestrator.read_update_status() + assert status is not None + assert status.state is orchestrator.UpdateJobState.UPDATED + assert orchestrator.UPDATE_LAST_SUCCESS_FILE.exists() + log = "\n".join(orchestrator.read_update_log_tail()) + assert "retrying" in log + + +@pytest.mark.asyncio +async def test_update_job_cancellation_records_terminal_status_and_releases_lock( + monkeypatch, tmp_path +): + """Cancelling the job mid-await must not leave a stale RUNNING status.""" + import asyncio + + _isolate_update_files(monkeypatch, tmp_path) + + async def fake_do_update( + *, print_output: bool, intent: update.UpdateIntent, output_callback=None + ): + return update.UpdateResult.UPDATED + + monkeypatch.setattr(update, "do_update", fake_do_update) + + started = asyncio.Event() + + async def hanging_smoke_check(**_kw): + started.set() + await asyncio.sleep(60) + return (True, "unreachable") + + monkeypatch.setattr(orchestrator, "_run_smoke_check_with_retry", hanging_smoke_check) + + task = asyncio.create_task( + orchestrator.run_update_job( + print_output=False, intent=update.UpdateIntent.INSTALL, source="test" + ) + ) + await started.wait() + task.cancel() + with pytest.raises(asyncio.CancelledError): + await task + + assert not orchestrator.UPDATE_LOCK_FILE.exists() + status = orchestrator.read_update_status() + assert status is not None + assert status.state is orchestrator.UpdateJobState.FAILED + assert "cancelled" in (status.message or "").lower() + + @pytest.mark.asyncio async def test_run_update_prompt_routes_check_through_runner(monkeypatch): calls: list[update.UpdateIntent] = []