From 4dae4ea802e08601e55324fe93e602ae151683b5 Mon Sep 17 00:00:00 2001 From: Ian Flores Siaca <18703558+ian-flores@users.noreply.github.com> Date: Mon, 31 Aug 2026 09:56:15 -0700 Subject: [PATCH] fix(workbench): explain a terminal_run timeout instead of only reporting it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit terminal_run's timeout said only that the done marker never appeared in the capture file. That single message covers three unrelated faults — the console never became usable, so the command's own progress is unknown; the file read back empty, so the command never started; or the file held output, so the command was still running when the budget expired — and the caller cannot act until they are told apart. test_clone_positron has failed this way three times in the daily Workbench suite with no progress on any of them, because every occurrence produced the same uninformative line. Track the readback outcomes the polling loop already observes and report the matching diagnosis, quoting the captured output tail when there is one. --- selftests/test_workbench_exec.py | 67 +++++++++++++++++++++++++++ src/vip_tests/workbench/exec.py | 78 ++++++++++++++++++++++++++++++-- 2 files changed, 141 insertions(+), 4 deletions(-) diff --git a/selftests/test_workbench_exec.py b/selftests/test_workbench_exec.py index 61073691..2b3e1a92 100644 --- a/selftests/test_workbench_exec.py +++ b/selftests/test_workbench_exec.py @@ -1029,6 +1029,73 @@ def test_still_times_out_when_marker_never_appears(self, monkeypatch): with pytest.raises(ExecError, match="timed out"): exec_mod.terminal_run(page, "sleep 999", timeout=10) + def test_timeout_reports_last_readback_content(self, monkeypatch): + """A timeout must quote what the capture file actually held. + + Whether the command never started, is still running, or finished while + the readback failed are three different bugs, and the bare + "timed out ... waiting for done marker" message cannot tell them apart -- + which is why the CI flake it reports has recurred unchanged. Readback + succeeding with partial output proves the command started, so that + content has to survive into the message. + """ + self._patch_common(monkeypatch) + monkeypatch.setattr(exec_mod, "read_file", MagicMock(return_value="Cloning into 'repo'...")) + monkeypatch.setattr(exec_mod.time, "sleep", lambda s: None) + page = MagicMock() + + with pytest.raises(ExecError) as excinfo: + exec_mod.terminal_run(page, "git clone ...", timeout=10) + + msg = str(excinfo.value) + assert "timed out" in msg + assert "Cloning into 'repo'..." in msg + + def test_timeout_reports_empty_capture_file(self, monkeypatch): + """A readable but empty capture file means the command never started. + + Distinct from a partial-output timeout: the console is fine and the file + exists, so the typed command never reached the terminal -- pointing at + input delivery rather than at the command or the budget. + """ + self._patch_common(monkeypatch) + monkeypatch.setattr(exec_mod, "read_file", MagicMock(return_value=" ")) + monkeypatch.setattr(exec_mod.time, "sleep", lambda s: None) + page = MagicMock() + + with pytest.raises(ExecError) as excinfo: + exec_mod.terminal_run(page, "git clone ...", timeout=10) + + msg = str(excinfo.value) + assert "read back empty" in msg + assert "never to have started" in msg + + def test_timeout_reports_when_no_readback_ever_succeeded(self, monkeypatch): + """A timeout where every readback failed must say so, and say why. + + This is the opposite diagnosis to a partial-output timeout: the console + never became usable, so the capture file was never read at all and the + command's own progress is unknown. Reporting the last readback error + distinguishes it instead of blaming the command. + """ + self._patch_common(monkeypatch, ide="positron") + monkeypatch.setattr( + exec_mod, + "read_file", + MagicMock(side_effect=ExecError("console not ready")), + ) + monkeypatch.setattr(exec_mod, "_positron_console_state_label", lambda p: None) + monkeypatch.setattr(exec_mod.time, "sleep", lambda s: None) + page = MagicMock() + + with pytest.raises(ExecError) as excinfo: + exec_mod.terminal_run(page, "git clone ...", timeout=10) + + msg = str(excinfo.value) + assert "timed out" in msg + assert "never read back successfully" in msg + assert "console not ready" in msg + def test_positron_attempt_timeout_is_capped(self, monkeypatch): """Positron attempts must be capped to _POSITRON_READBACK_ATTEMPT_MS, not handed the outer loop's entire remaining budget: read_file's diff --git a/src/vip_tests/workbench/exec.py b/src/vip_tests/workbench/exec.py index 3b30e550..abf36384 100644 --- a/src/vip_tests/workbench/exec.py +++ b/src/vip_tests/workbench/exec.py @@ -907,6 +907,60 @@ def _ensure_terminal_open(page: Page, timeout: int = 30_000) -> None: expect(_visible_terminal_input(page)).to_be_visible(timeout=timeout) +# Max characters of captured output quoted in a timeout message. Enough to show +# a clone's progress lines or a shell error, without pasting a whole build log +# into a pytest failure. +_TIMEOUT_CONTENT_CHARS = 400 + + +def _timeout_diagnostics( + last_content: str | None, + last_readback_error: str | None, + readback_successes: int, +) -> str: + """Explain a ``terminal_run`` timeout from what the polling loop observed. + + A timeout only ever says the done marker never appeared. That is consistent + with three unrelated faults, and the caller cannot act until they are told + apart: + + * the readback never worked -- the console never became usable, so nothing is + known about the command itself (report the readback error, not the command); + * the readback worked and the file was empty -- the command never started, so + the terminal never received the typed input; + * the readback worked and the file held output -- the command started and was + still running when the budget ran out, so the timeout is the thing to + question. + + Returns a sentence for each case, with the captured output tail truncated to + :data:`_TIMEOUT_CONTENT_CHARS`. + """ + if readback_successes == 0: + detail = last_readback_error or "no error recorded" + return ( + "The capture file was never read back successfully " + f"({readback_successes} successful reads), so the command's own progress is " + f"unknown -- the console, not the command, is the likely fault. " + f"Last readback error: {detail}" + ) + + content = last_content or "" + if not content.strip(): + return ( + f"The capture file read back empty after {readback_successes} successful " + "reads, so the command appears never to have started -- suspect the " + "terminal never received the typed command." + ) + + tail = content[-_TIMEOUT_CONTENT_CHARS:] + elided = "..." if len(content) > _TIMEOUT_CONTENT_CHARS else "" + return ( + f"The capture file read back after {readback_successes} successful reads but " + "never contained the done marker, so the command started and was still " + f"running when the budget expired. Last captured output: {elided}{tail!r}" + ) + + def terminal_run( page: Page, cmd: str, @@ -1002,6 +1056,14 @@ def terminal_run( deadline = time.monotonic() + timeout / 1000.0 poll_interval = 1.0 + # Readback bookkeeping, reported if this call times out. A timeout means the + # marker never appeared, but *why* splits three ways -- the command never + # started, it is still running, or it finished and the readback could not be + # read -- and only these values distinguish them. See _timeout_diagnostics. + last_content: str | None = None + last_readback_error: str | None = None + readback_successes = 0 + if ide == "vscode": # VS Code: poll the one-line sentinel file (donefile) in the Monaco # editor. It is a single line, so Monaco's viewport virtualization @@ -1013,8 +1075,11 @@ def terminal_run( _open_file_in_vscode_editor(page, donefile, timeout=5_000) marker_text = _read_vscode_editor_text(page, timeout=5_000) _close_active_editor(page) - except Exception: + readback_successes += 1 + last_content = marker_text + except Exception as exc: marker_text = "" + last_readback_error = f"{type(exc).__name__}: {exc}" parsed = _parse_done_marker(marker_text, done_marker) if parsed is not None: _, exit_code = parsed @@ -1082,14 +1147,18 @@ def terminal_run( attempt_ms = remaining_ms try: content = read_file(page, tmpfile, timeout=attempt_ms, lang=readback_lang) - except ExecError: + except ExecError as exc: + last_readback_error = f"ExecError: {exc}" if ide == "positron": time.sleep(poll_interval) continue raise - except Exception: + except Exception as exc: + last_readback_error = f"{type(exc).__name__}: {exc}" time.sleep(poll_interval) continue + readback_successes += 1 + last_content = content parsed = _parse_done_marker(content, done_marker) if parsed is not None: output, exit_code = parsed @@ -1101,7 +1170,8 @@ def terminal_run( time.sleep(poll_interval) raise ExecError( - f"terminal_run timed out after {timeout}ms waiting for done marker in {tmpfile!r}" + f"terminal_run timed out after {timeout}ms waiting for done marker in {tmpfile!r}. " + + _timeout_diagnostics(last_content, last_readback_error, readback_successes) )