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) )