fix(workbench): explain a terminal_run timeout instead of only reporting it

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

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