Skip to content

Commit 9700655

Browse files
authored
fix(update): retry post-install smoke check and surface verification failure (#241)
* fix(update): retry post-install smoke check and surface verification failure The smoke check ran once, immediately after the package-manager upgrade. Homebrew can report success moments before its opt launcher symlink is repointed at the new keg, so the probe exercised the old binary, reported the old version, and recorded a false VERIFICATION_FAILED — leaving the footer stuck on the stale update notice while the screen said "Updated successfully!". Retry the smoke check up to 3 times, 1s apart, off the event loop (asyncio.to_thread) so the probe can no longer block the shell either. When verification genuinely fails after all attempts, print the failure where the install success was shown so the on-screen outcome matches the recorded status. * test(tui): pin wall-clock-rotated spinner verb in Working-regression guards Three tests assert 'Working' is absent from the rendered activity spinner to guard against the old static 'Working…' placeholder. The verb rotates on time.monotonic() over a list that legitimately includes 'Working', so the suite fails deterministically for the verb's 10-minute rotation window every ~21 hours. Pin spinner_message in those tests so the guard only catches the real regression. * fix(update): record terminal status when the update job is cancelled Cancellation lands on the job's await points and skipped the failure handler, releasing the update lock while the status file still said RUNNING. Catch CancelledError, write a terminal FAILED status, and re-raise.
1 parent 30d2cf3 commit 9700655

5 files changed

Lines changed: 168 additions & 8 deletions

File tree

CHANGELOG.md

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,8 @@ GitHub Releases page; `0.8.0` is the new starting line.
1515

1616
## Unreleased
1717

18+
- 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.
19+
1820
## 0.62.0 (2026-07-22)
1921

2022
- Treat the repository-root `.agents/` directory as local agent configuration and keep it out of version control.

src/pythinker_code/ui/shell/update_orchestrator.py

Lines changed: 59 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
from __future__ import annotations
22

3+
import asyncio
34
import contextlib
45
import json
56
import os
@@ -408,7 +409,7 @@ async def run_update_job(
408409
append_update_log(message)
409410
_write_last_success(job_id=job_id, message=message)
410411
else:
411-
smoke_ok, smoke_message = run_post_install_smoke_check(
412+
smoke_ok, smoke_message = await _run_smoke_check_with_retry(
412413
target_version=_read_target_version()
413414
)
414415
append_update_log(smoke_message)
@@ -422,6 +423,13 @@ async def run_update_job(
422423
final_state = _result_state(reported_result)
423424
# Never promote a staged binary that can't even print --version.
424425
_finalize_native_staging(promote=False)
426+
# The install step has already printed its own success line;
427+
# leaving the screen at "Updated successfully!" while the
428+
# recorded state is VERIFICATION_FAILED would misreport the
429+
# outcome (the footer keeps the update notice for the same
430+
# reason). Surface the failure where the success was shown.
431+
if print_output:
432+
console.print(f"[{_get_tui_tokens().warning}]{message}[/]")
425433

426434
write_update_status(
427435
_new_status(
@@ -435,6 +443,27 @@ async def run_update_job(
435443
)
436444
)
437445
return reported_result
446+
except asyncio.CancelledError:
447+
# Cancellation lands on the await points (do_update, the smoke-check
448+
# thread, retry sleeps) and would otherwise skip the failure handler
449+
# below, releasing the lock with the job still recorded as RUNNING —
450+
# a stale "in progress" status with no process behind it. Record a
451+
# terminal state, then propagate. The smoke-check subprocess is not
452+
# interrupted mid-flight, but its own timeout bounds it.
453+
message = "Update job cancelled."
454+
append_update_log(message)
455+
write_update_status(
456+
_new_status(
457+
job_id=job_id,
458+
state=UpdateJobState.FAILED,
459+
source=source,
460+
started_at=started_at,
461+
finished_at=time.time(),
462+
result=UpdateResult.FAILED.name,
463+
message=message,
464+
)
465+
)
466+
raise
438467
except Exception as exc:
439468
message = f"Update failed: {exc}"
440469
append_update_log(message)
@@ -548,6 +577,35 @@ def _smoke_check_env() -> dict[str, str]:
548577
return env
549578

550579

580+
_SMOKE_CHECK_ATTEMPTS = 3
581+
_SMOKE_CHECK_RETRY_DELAY_SECONDS = 1.0
582+
583+
584+
async def _run_smoke_check_with_retry(target_version: str | None) -> tuple[bool, str]:
585+
"""Run the post-install smoke check, retrying transient failures.
586+
587+
Package managers can report success moments before the launcher they manage
588+
is repointed at the new install (observed with Homebrew's ``opt`` symlink):
589+
an immediate probe then exercises the OLD binary, reports the old version,
590+
and records a false ``VERIFICATION_FAILED``. A short retry window absorbs
591+
that race; a real bad install still fails every attempt. The subprocess
592+
probe runs off the event loop so a slow/hung binary cannot stall the shell.
593+
"""
594+
smoke_ok, smoke_message = False, "Smoke check did not run."
595+
for attempt in range(1, _SMOKE_CHECK_ATTEMPTS + 1):
596+
smoke_ok, smoke_message = await asyncio.to_thread(
597+
run_post_install_smoke_check, target_version=target_version
598+
)
599+
if smoke_ok or attempt == _SMOKE_CHECK_ATTEMPTS:
600+
break
601+
append_update_log(
602+
f"Smoke check attempt {attempt}/{_SMOKE_CHECK_ATTEMPTS} failed "
603+
f"({smoke_message}); retrying in {_SMOKE_CHECK_RETRY_DELAY_SECONDS:g}s..."
604+
)
605+
await asyncio.sleep(_SMOKE_CHECK_RETRY_DELAY_SECONDS)
606+
return smoke_ok, smoke_message
607+
608+
551609
def run_post_install_smoke_check(target_version: str | None = None) -> tuple[bool, str]:
552610
command = _smoke_check_command()
553611
try:

tests/ui_and_conv/test_empty_think_part_indicator.py

Lines changed: 10 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -213,10 +213,16 @@ def test_moon_fallback_during_active_turn():
213213
assert agent_blocks[0].plain.strip() == ""
214214

215215

216-
def test_working_indicator_stays_visible_when_content_block_visible():
216+
def test_working_indicator_stays_visible_when_content_block_visible(monkeypatch):
217217
"""The activity spinner stays visible while content streams."""
218218
from rich.text import Text
219219

220+
from pythinker_code.ui.shell.visualize import _live_view
221+
222+
# The verb rotates on wall-clock over a list that legitimately includes
223+
# "Working"; pin it so the static-"Working…" regression guard below cannot
224+
# false-positive during that verb's 10-minute rotation window.
225+
monkeypatch.setattr(_live_view, "spinner_message", lambda now=None, **_kw: "Composing…")
220226
view = _LiveView(StatusUpdate())
221227
view.dispatch_wire_message(TurnBegin(user_input="test"))
222228
view.dispatch_wire_message(StepBegin(n=1))
@@ -286,7 +292,10 @@ def test_moon_fallback_after_all_tools_flushed(monkeypatch):
286292
def test_working_indicator_stays_visible_while_parallel_tool_still_running(monkeypatch):
287293
"""The activity spinner stays visible while tool blocks are visible."""
288294
from pythinker_code.ui.shell.console import console as shell_console
295+
from pythinker_code.ui.shell.visualize import _live_view
289296

297+
# Pin the wall-clock-rotated verb; see the content-block variant above.
298+
monkeypatch.setattr(_live_view, "spinner_message", lambda now=None, **_kw: "Composing…")
290299
view = _LiveView(StatusUpdate())
291300
monkeypatch.setattr(shell_console, "print", lambda *args, **kwargs: None)
292301

tests/ui_and_conv/test_modal_lifecycle.py

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -914,12 +914,17 @@ async def test_compose_equals_panels_plus_agent_output() -> None:
914914

915915

916916
@pytest.mark.asyncio
917-
async def test_compose_agent_output_includes_spinners_and_tool_calls() -> None:
917+
async def test_compose_agent_output_includes_spinners_and_tool_calls(monkeypatch) -> None:
918918
"""compose_agent_output() should include activity indicators and tool call blocks."""
919919
from rich.text import Text
920920

921+
from pythinker_code.ui.shell.visualize import _live_view
921922
from pythinker_code.wire.types import ToolCall
922923

924+
# The spinner verb rotates on wall-clock over a list that legitimately
925+
# includes "Working"; pin it so the static-"Working…" regression guard
926+
# below cannot false-positive during that verb's rotation window.
927+
monkeypatch.setattr(_live_view, "spinner_message", lambda now=None, **_kw: "Composing…")
923928
view = _LiveView(StatusUpdate())
924929
view._active_turn_depth = 1 # working fallback requires active turn
925930

tests/ui_and_conv/test_update_orchestrator.py

Lines changed: 91 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -173,17 +173,23 @@ async def fake_do_update(
173173
return update.UpdateResult.UPDATED
174174

175175
monkeypatch.setattr(update, "do_update", fake_do_update)
176-
monkeypatch.setattr(
177-
orchestrator,
178-
"run_post_install_smoke_check",
179-
lambda **_kw: (False, "Smoke check failed: broken"),
180-
)
176+
monkeypatch.setattr(orchestrator, "_SMOKE_CHECK_RETRY_DELAY_SECONDS", 0.0)
177+
attempts = 0
178+
179+
def fake_smoke(**_kw):
180+
nonlocal attempts
181+
attempts += 1
182+
return (False, "Smoke check failed: broken")
183+
184+
monkeypatch.setattr(orchestrator, "run_post_install_smoke_check", fake_smoke)
181185

182186
result = await orchestrator.run_update_job(
183187
print_output=False, intent=update.UpdateIntent.INSTALL, source="test"
184188
)
185189

186190
assert result is update.UpdateResult.VERIFICATION_FAILED
191+
# A hard failure is retried before being reported — every attempt failed.
192+
assert attempts == orchestrator._SMOKE_CHECK_ATTEMPTS
187193
status = orchestrator.read_update_status()
188194
assert status is not None
189195
assert status.state is orchestrator.UpdateJobState.FAILED
@@ -192,6 +198,86 @@ async def fake_do_update(
192198
assert not orchestrator.UPDATE_LAST_SUCCESS_FILE.exists()
193199

194200

201+
@pytest.mark.asyncio
202+
async def test_update_job_smoke_check_retry_absorbs_launcher_relink_race(monkeypatch, tmp_path):
203+
"""A transiently stale launcher (e.g. brew's opt link mid-relink) must not
204+
record VERIFICATION_FAILED when a later attempt passes."""
205+
_isolate_update_files(monkeypatch, tmp_path)
206+
207+
async def fake_do_update(
208+
*, print_output: bool, intent: update.UpdateIntent, output_callback=None
209+
):
210+
return update.UpdateResult.UPDATED
211+
212+
monkeypatch.setattr(update, "do_update", fake_do_update)
213+
monkeypatch.setattr(orchestrator, "_SMOKE_CHECK_RETRY_DELAY_SECONDS", 0.0)
214+
attempts = 0
215+
216+
def fake_smoke(**_kw):
217+
nonlocal attempts
218+
attempts += 1
219+
if attempts == 1:
220+
return (False, "Smoke check reported 0.60.0, expected 0.62.0")
221+
return (True, "Smoke check passed: pythinker, version 0.62.0")
222+
223+
monkeypatch.setattr(orchestrator, "run_post_install_smoke_check", fake_smoke)
224+
225+
result = await orchestrator.run_update_job(
226+
print_output=False, intent=update.UpdateIntent.INSTALL, source="test"
227+
)
228+
229+
assert result is update.UpdateResult.UPDATED
230+
assert attempts == 2
231+
status = orchestrator.read_update_status()
232+
assert status is not None
233+
assert status.state is orchestrator.UpdateJobState.UPDATED
234+
assert orchestrator.UPDATE_LAST_SUCCESS_FILE.exists()
235+
log = "\n".join(orchestrator.read_update_log_tail())
236+
assert "retrying" in log
237+
238+
239+
@pytest.mark.asyncio
240+
async def test_update_job_cancellation_records_terminal_status_and_releases_lock(
241+
monkeypatch, tmp_path
242+
):
243+
"""Cancelling the job mid-await must not leave a stale RUNNING status."""
244+
import asyncio
245+
246+
_isolate_update_files(monkeypatch, tmp_path)
247+
248+
async def fake_do_update(
249+
*, print_output: bool, intent: update.UpdateIntent, output_callback=None
250+
):
251+
return update.UpdateResult.UPDATED
252+
253+
monkeypatch.setattr(update, "do_update", fake_do_update)
254+
255+
started = asyncio.Event()
256+
257+
async def hanging_smoke_check(**_kw):
258+
started.set()
259+
await asyncio.sleep(60)
260+
return (True, "unreachable")
261+
262+
monkeypatch.setattr(orchestrator, "_run_smoke_check_with_retry", hanging_smoke_check)
263+
264+
task = asyncio.create_task(
265+
orchestrator.run_update_job(
266+
print_output=False, intent=update.UpdateIntent.INSTALL, source="test"
267+
)
268+
)
269+
await started.wait()
270+
task.cancel()
271+
with pytest.raises(asyncio.CancelledError):
272+
await task
273+
274+
assert not orchestrator.UPDATE_LOCK_FILE.exists()
275+
status = orchestrator.read_update_status()
276+
assert status is not None
277+
assert status.state is orchestrator.UpdateJobState.FAILED
278+
assert "cancelled" in (status.message or "").lower()
279+
280+
195281
@pytest.mark.asyncio
196282
async def test_run_update_prompt_routes_check_through_runner(monkeypatch):
197283
calls: list[update.UpdateIntent] = []

0 commit comments

Comments
 (0)