diff --git a/selftests/test_workbench_exec.py b/selftests/test_workbench_exec.py index 104b274d..dd07203d 100644 --- a/selftests/test_workbench_exec.py +++ b/selftests/test_workbench_exec.py @@ -27,6 +27,7 @@ _detect_ide, _extract_between_markers, _make_sentinels, + _parse_done_marker, _split_marker, _strip_r_index, _wrap_python_expr, @@ -293,6 +294,58 @@ def test_strips_whitespace_after_index(self): assert not result.startswith(" ") +# --------------------------------------------------------------------------- +# _parse_done_marker +# --------------------------------------------------------------------------- + + +class TestParseDoneMarker: + def test_returns_none_when_marker_absent(self): + """Command still running: no marker line yet, regardless of content.""" + assert _parse_done_marker("some partial output", "VIP_DONE_abc") is None + + def test_parses_success_exit_code(self): + content = "hello\nworld\nVIP_DONE_abc:0" + result = _parse_done_marker(content, "VIP_DONE_abc") + assert result == ("hello\nworld", 0) + + def test_parses_nonzero_exit_code(self): + """Regression guard for #439: marker is now written even on failure.""" + content = "fatal: destination path 'x' already exists\nVIP_DONE_abc:128" + result = _parse_done_marker(content, "VIP_DONE_abc") + assert result == ("fatal: destination path 'x' already exists", 128) + + def test_marker_line_removed_from_output(self): + content = "line1\nVIP_DONE_abc:1\nline2" + output, exit_code = _parse_done_marker(content, "VIP_DONE_abc") + assert "VIP_DONE_abc" not in output + assert "line1" in output + assert "line2" in output + assert exit_code == 1 + + def test_empty_output_between_marker(self): + content = "VIP_DONE_abc:0" + assert _parse_done_marker(content, "VIP_DONE_abc") == ("", 0) + + def test_does_not_match_different_marker(self): + """A different run's marker must not be mistaken for this one.""" + content = "output\nVIP_DONE_other:0" + assert _parse_done_marker(content, "VIP_DONE_abc") is None + + def test_marker_glued_to_output_with_no_trailing_newline(self): + """cmd's last line lacking a trailing newline glues the marker onto + it (`>>` appends raw bytes with no separator); the glued-on leading + text is real output and must be kept, not dropped.""" + content = "foobar" + "VIP_DONE_abc:0" + assert _parse_done_marker(content, "VIP_DONE_abc") == ("foobar", 0) + + def test_returns_none_for_non_digit_suffix(self): + """A marker line whose exit-code suffix isn't purely digits yet (a + partial write mid-poll) must be treated as still-running, not raise.""" + content = "VIP_DONE_abc:" + assert _parse_done_marker(content, "VIP_DONE_abc") is None + + # --------------------------------------------------------------------------- # _detect_ide # --------------------------------------------------------------------------- @@ -538,3 +591,109 @@ def test_vscode_read_ignores_lang_parameter(self, monkeypatch): assert result_py == "editor contents" assert mock_editor_read.call_count == 2 mock_rstudio_eval.assert_not_called() + + +# --------------------------------------------------------------------------- +# terminal_run +# --------------------------------------------------------------------------- + + +class _FixedUUID: + hex = "deadbeef" + + +class TestTerminalRun: + """Regression coverage for #439: fast-failing commands must raise + ExecError immediately with the real output, not a generic timeout.""" + + def _patch_common(self, monkeypatch, ide="rstudio"): + monkeypatch.setattr(exec_mod, "_detect_ide", lambda p: ide) + monkeypatch.setattr(exec_mod, "_ensure_terminal_open", lambda p, timeout=30_000: None) + monkeypatch.setattr(exec_mod.uuid, "uuid4", lambda: _FixedUUID()) + + def test_writes_done_marker_unconditionally(self, monkeypatch): + """The marker must be appended with ``;`` so it is written even when + *cmd* fails -- ``&&`` silently drops it on non-zero exit (#439).""" + self._patch_common(monkeypatch) + monkeypatch.setattr( + exec_mod, "read_file", MagicMock(return_value="ok\nVIP_DONE_deadbeef:0") + ) + page = MagicMock() + + exec_mod.terminal_run(page, "false", timeout=1_000) + + typed_cmd = page.locator.return_value.type.call_args[0][0] + assert "&&" not in typed_cmd + assert 'echo "VIP_DONE_deadbeef:$?"' in typed_cmd + + def test_returns_output_on_success(self, monkeypatch): + self._patch_common(monkeypatch) + monkeypatch.setattr( + exec_mod, "read_file", MagicMock(return_value="hello\nVIP_DONE_deadbeef:0") + ) + page = MagicMock() + + result = exec_mod.terminal_run(page, "echo hello", timeout=1_000) + + assert result == "hello" + + def test_raises_exec_error_immediately_on_nonzero_exit(self, monkeypatch): + """Fast failure must surface as an immediate ExecError with the real + output, not a 120s timeout with the output discarded.""" + self._patch_common(monkeypatch) + error_output = "fatal: destination path 'repo' already exists" + mock_read_file = MagicMock(return_value=f"{error_output}\nVIP_DONE_deadbeef:128") + monkeypatch.setattr(exec_mod, "read_file", mock_read_file) + page = MagicMock() + + with pytest.raises(ExecError, match="128") as excinfo: + exec_mod.terminal_run(page, "git clone ...", timeout=1_000) + + assert error_output in str(excinfo.value) + # Must not have looped until timeout -- a single poll is enough. + mock_read_file.assert_called_once() + + def test_still_times_out_when_marker_never_appears(self, monkeypatch): + """A genuinely hung command (no marker at all) still times out.""" + self._patch_common(monkeypatch) + monkeypatch.setattr(exec_mod, "read_file", MagicMock(return_value="still running...")) + monkeypatch.setattr(exec_mod.time, "sleep", lambda s: None) + page = MagicMock() + + with pytest.raises(ExecError, match="timed out"): + exec_mod.terminal_run(page, "sleep 999", timeout=10) + + def _patch_vscode(self, monkeypatch, content): + """VS Code polls via editor-open/read/close instead of ``read_file``.""" + self._patch_common(monkeypatch, ide="vscode") + monkeypatch.setattr( + exec_mod, "_open_file_in_vscode_editor", lambda p, path, timeout=5_000: None + ) + monkeypatch.setattr(exec_mod, "_close_active_editor", lambda p: None) + mock_read = MagicMock(return_value=content) + monkeypatch.setattr(exec_mod, "_read_vscode_editor_text", mock_read) + return mock_read + + def test_vscode_returns_output_on_success(self, monkeypatch): + """The VS Code editor-open polling path has its own copy of the + marker-parsing logic and must be covered independently of the + RStudio/Positron ``read_file`` path exercised above.""" + self._patch_vscode(monkeypatch, "hello\nVIP_DONE_deadbeef:0") + page = MagicMock() + + result = exec_mod.terminal_run(page, "echo hello", timeout=1_000) + + assert result == "hello" + + def test_vscode_raises_exec_error_immediately_on_nonzero_exit(self, monkeypatch): + """Regression guard: the VS Code branch must also raise ExecError + immediately on failure rather than looping until timeout (#439).""" + error_output = "fatal: destination path 'repo' already exists" + mock_read = self._patch_vscode(monkeypatch, f"{error_output}\nVIP_DONE_deadbeef:128") + page = MagicMock() + + with pytest.raises(ExecError, match="128") as excinfo: + exec_mod.terminal_run(page, "git clone ...", timeout=1_000) + + assert error_output in str(excinfo.value) + mock_read.assert_called_once() diff --git a/src/vip_tests/workbench/exec.py b/src/vip_tests/workbench/exec.py index d8ef332b..b3f44ee0 100644 --- a/src/vip_tests/workbench/exec.py +++ b/src/vip_tests/workbench/exec.py @@ -134,6 +134,41 @@ def _strip_r_index(text: str) -> str: return "\n".join(lines).strip() +def _parse_done_marker(content: str, done_marker: str) -> tuple[str, int] | None: + """Look for a ``{done_marker}:`` line in *content*. + + ``terminal_run`` writes this marker unconditionally, with the command's + exit code appended, so a fast failure can be told apart from "still + running" (see issue #439 -- a marker written only via ``&&`` never + appears when the command exits non-zero). + + The marker is searched for anywhere within a line, not just at its start: + if *cmd*'s final output line has no trailing newline, the marker glues + onto it (``>>`` appends raw bytes with no separator), and any text before + the marker on that line is real output that must be kept, not discarded. + A suffix that isn't purely digits means the marker line is still being + written, so this reports "not done yet" rather than raising. + + Returns: + ``(captured_output, exit_code)`` with the marker line removed (any + leading output on that line is preserved), or ``None`` if the marker + has not fully appeared in *content* yet. + """ + prefix = f"{done_marker}:" + lines = content.splitlines() + for i, line in enumerate(lines): + pos = line.find(prefix) + if pos == -1: + continue + code = line[pos + len(prefix) :].strip() + if not code.isdigit(): + return None + before = line[:pos] + kept = lines[:i] + ([before] if before else []) + lines[i + 1 :] + return "\n".join(kept).strip(), int(code) + return None + + # --------------------------------------------------------------------------- # Console / cell eval primitives # --------------------------------------------------------------------------- @@ -559,14 +594,19 @@ def terminal_run( Strategy: 1. Ensure the IDE terminal is open (activate the RStudio Terminal tab or create a VS Code/Positron terminal) so its input is present. - 2. Type ``{cmd} > {tmpfile} 2>&1 && echo VIP_DONE >> {tmpfile}`` in the - terminal input (``.xterm-helper-textarea``). + 2. Type ``{cmd} > {tmpfile} 2>&1; echo "{done_marker}:$?" >> {tmpfile}`` in the + terminal input (``.xterm-helper-textarea``). The marker is appended + with ``;`` rather than ``&&`` so it is always written, even when *cmd* + fails -- see issue #439. 3. Press Enter to execute. 4. Poll for the done marker: - RStudio/Positron: call ``read_file`` (console eval, fresh each call). - VS Code: open the file once in the Monaco editor, then loop: read ``.view-lines``; if done_marker present → done; else close tab and re-open so the editor re-reads from disk. + 5. Once the marker appears, parse the exit code appended to it. A + non-zero exit code raises ``ExecError`` immediately with the captured + output, instead of waiting out the full timeout. Args: page: Playwright page for an active IDE session. @@ -579,6 +619,11 @@ def terminal_run( Returns: Captured stdout/stderr of the command as a string. + Raises: + ExecError: *cmd* exited with a non-zero status (message includes the + exit code and captured output), or the done marker never + appeared within *timeout*. + Note: The VS Code editor-open polling path is UNVALIDATED and pending a live git_ops run. The open/close/re-read loop may be slow; it will be tuned @@ -586,7 +631,7 @@ def terminal_run( """ done_marker = f"VIP_DONE_{uuid.uuid4().hex}" tmpfile = f"/tmp/vip_term_{uuid.uuid4().hex}.txt" - shell_cmd = f'{cmd} > {tmpfile} 2>&1 && echo "{done_marker}" >> {tmpfile}' + shell_cmd = f'{cmd} > {tmpfile} 2>&1; echo "{done_marker}:$?" >> {tmpfile}' ide = _detect_ide(page) @@ -607,11 +652,18 @@ def terminal_run( try: _open_file_in_vscode_editor(page, tmpfile, timeout=5_000) content = _read_vscode_editor_text(page, timeout=5_000) - if done_marker in content: - _close_active_editor(page) - lines = [ln for ln in content.splitlines() if ln.strip() != done_marker] - return "\n".join(lines).strip() _close_active_editor(page) + parsed = _parse_done_marker(content, done_marker) + if parsed is not None: + output, exit_code = parsed + if exit_code != 0: + raise ExecError( + f"terminal_run: command {cmd!r} exited with status " + f"{exit_code}: {output}" + ) + return output + except ExecError: + raise except Exception: pass time.sleep(poll_interval) @@ -620,9 +672,17 @@ def terminal_run( while time.monotonic() < deadline: try: content = read_file(page, tmpfile, timeout=5_000, lang=readback_lang) - if done_marker in content: - lines = [ln for ln in content.splitlines() if ln.strip() != done_marker] - return "\n".join(lines).strip() + parsed = _parse_done_marker(content, done_marker) + if parsed is not None: + output, exit_code = parsed + if exit_code != 0: + raise ExecError( + f"terminal_run: command {cmd!r} exited with status " + f"{exit_code}: {output}" + ) + return output + except ExecError: + raise except Exception: pass time.sleep(poll_interval) diff --git a/validation_docs/demo-fix-terminal-run-timeout.md b/validation_docs/demo-fix-terminal-run-timeout.md new file mode 100644 index 00000000..517c544c --- /dev/null +++ b/validation_docs/demo-fix-terminal-run-timeout.md @@ -0,0 +1,83 @@ +# Fix #439: terminal_run swallows real command errors as a generic timeout + +*2026-07-08T18:58:25Z by Showboat 0.6.1* + + +Root cause: terminal_run's shell wrapper only wrote the done-marker via `&&`, so a fast-failing command (non-zero exit) never wrote the marker at all. The polling loop then waited out the full timeout and raised a generic 'timed out' error, discarding the real output sitting in the temp file the whole time. + +The fix writes the marker unconditionally via `;` with the exit code appended (`marker:$?`), and a new pure helper `_parse_done_marker` parses it. `terminal_run` now raises `ExecError` immediately with the real captured output when the exit code is non-zero, instead of waiting out the full configured timeout. + +## Before: the old `&&` marker is silently dropped on failure + +This reproduces the exact shell wrapper that used to run inside the IDE terminal. + +```bash +tmpfile=$(mktemp); cmd="false"; done_marker="VIP_DONE_old"; sh -c "${cmd} > ${tmpfile} 2>&1 && echo \"${done_marker}\" >> ${tmpfile}"; echo "--- tmpfile contents after a failing command ---"; cat "${tmpfile}"; echo "--- (marker present? )"; grep -q "${done_marker}" "${tmpfile}" && echo yes || echo "no -- polling loop would spin until timeout" +``` + +```output +--- tmpfile contents after a failing command --- +--- (marker present? ) +no -- polling loop would spin until timeout +``` + +## After: the new `;` marker is always written, with the exit code + +This reproduces the new shell wrapper used by the fixed `terminal_run`. + +```bash +tmpfile=$(mktemp); cmd="ls /this/path/does/not/exist"; done_marker="VIP_DONE_new"; sh -c "${cmd} > ${tmpfile} 2>&1; echo \"${done_marker}:\$?\" >> ${tmpfile}"; echo "--- tmpfile contents after a failing command ---"; cat "${tmpfile}"; echo "--- (marker present? )"; grep -q "${done_marker}" "${tmpfile}" && echo "yes -- terminal_run parses this and raises ExecError immediately with the real output" || echo no +``` + +```output +--- tmpfile contents after a failing command --- +ls: cannot access '/this/path/does/not/exist': No such file or directory +VIP_DONE_new:2 +--- (marker present? ) +yes -- terminal_run parses this and raises ExecError immediately with the real output +``` + +## New unit tests covering the fix + +`_parse_done_marker` is a pure, Playwright-free helper (matching this module's existing pattern) that parses the marker+exit-code line. `terminal_run` itself is also covered end-to-end with a mocked Playwright `page`, confirming: the marker is written unconditionally, success still returns output, a non-zero exit raises `ExecError` immediately (single poll, not a full timeout loop), and a genuinely hung command still times out. + +```bash +uv run pytest selftests/test_workbench_exec.py -k "TestParseDoneMarker or TestTerminalRun" -v -n0 2>&1 | grep -E "PASSED|FAILED|ERROR|passed|failed" | sed -E "s/ in [0-9.]+s//" +``` + +```output +selftests/test_workbench_exec.py::TestParseDoneMarker::test_returns_none_when_marker_absent PASSED [ 10%] +selftests/test_workbench_exec.py::TestParseDoneMarker::test_parses_success_exit_code PASSED [ 20%] +selftests/test_workbench_exec.py::TestParseDoneMarker::test_parses_nonzero_exit_code PASSED [ 30%] +selftests/test_workbench_exec.py::TestParseDoneMarker::test_marker_line_removed_from_output PASSED [ 40%] +selftests/test_workbench_exec.py::TestParseDoneMarker::test_empty_output_between_marker PASSED [ 50%] +selftests/test_workbench_exec.py::TestParseDoneMarker::test_does_not_match_different_marker PASSED [ 60%] +selftests/test_workbench_exec.py::TestTerminalRun::test_writes_done_marker_unconditionally PASSED [ 70%] +selftests/test_workbench_exec.py::TestTerminalRun::test_returns_output_on_success PASSED [ 80%] +selftests/test_workbench_exec.py::TestTerminalRun::test_raises_exec_error_immediately_on_nonzero_exit PASSED [ 90%] +selftests/test_workbench_exec.py::TestTerminalRun::test_still_times_out_when_marker_never_appears PASSED [100%] +====================== 10 passed, 48 deselected ======================= +``` + +## Full selftest suite still passes + +```bash +uv run pytest selftests/ --ignore=selftests/test_load_engine.py -q 2>&1 | grep -E "passed|failed" | sed -E "s/ in [0-9.]+s//" +``` + +```output +870 passed, 26 warnings +``` + +## Lint and format checks pass + +```bash +env -u VIRTUAL_ENV just check 2>&1 +``` + +```output +uv run ruff check src/ selftests/ examples/ docker/ +All checks passed! +uv run ruff format --check src/ selftests/ examples/ docker/ +149 files already formatted +```