fix(debugger): cancel timed-out commands on dump sessions

src/mcp_windbg/debug_session.py

@@ -13,10 +13,11 @@
   with a monotonic ``<n>``. The reader only completes on the marker the current
   command is waiting for, so a slow command whose output arrives late can never
   be mistaken for the next command's completion.
-- **Cancel-on-timeout for live targets.** When a command on a live session
-  (user-mode remote or kernel) outruns its timeout, the debugger is still busy
-  executing it. We send CTRL+BREAK to break back in, drain to the pending
-  marker, and only then report the timeout - leaving the session resynchronized
+- **Cancel-on-timeout.** When a command outruns its timeout, the debugger is
+  still busy executing it - on a live target, and on a static dump too (a
+  ``!process 0 7`` over a kernel dump runs for minutes, and every command sent
+  after it queues behind it). We send CTRL+BREAK to break back in, drain to the
+  pending marker, and only then report the timeout - leaving the session resynchronized
   instead of wedged.
 - **Go-class commands do not use the marker at all.** ``g`` and its relatives
   hand the CPU back to the target, and the debugger stops reading stdin until
@@ -275,9 +276,10 @@ def __init__(
         self._debugger_exited = False
 
         try:
-            creationflags = 0
-            if os.name == "nt" and self.is_live_session:
-                creationflags = subprocess.CREATE_NEW_PROCESS_GROUP
+            # Every session gets its own process group, so a CTRL+BREAK can be
+            # aimed at it alone: live sessions to break into the target, dump
+            # sessions to cancel a command that outran its timeout.
+            creationflags = subprocess.CREATE_NEW_PROCESS_GROUP if os.name == "nt" else 0
             self.process: Optional[subprocess.Popen] = subprocess.Popen(
                 launch_args,
                 stdin=subprocess.PIPE,
@@ -301,6 +303,11 @@ def __init__(
         self._log_path: Optional[str] = None
         self._log_offset = 0
         self._log_active = False
+        #: Markers of commands abandoned on a timeout, oldest first. Their
+        #: segments are still in the log ahead of the next command's, so the
+        #: next log read skips each one once it has landed (see
+        #: _read_log_segment).
+        self._abandoned_log_markers: List[str] = []
 
         self.reader_thread = threading.Thread(target=self._read_output, daemon=True)
         self.reader_thread.start()
@@ -357,6 +364,15 @@ def _read_output(self) -> None:
                             self._reader_buffer = buffer
                             self._expected_marker = None
                             self.ready_event.set()
+                        elif not self.is_live_session:
+                            # A dump has no target printing on its own, so what
+                            # came before an abandoned marker is the abandoned
+                            # command's late output. Left in the buffer it would
+                            # lead the next command's reply. (A live target's
+                            # stop banner can precede a stray probe marker and
+                            # must survive, so this is dump-only.)
+                            buffer = []
+                            self._reader_buffer = buffer
                         continue
                     buffer.append(line)
                     self._on_output_line(line)
@@ -628,6 +644,9 @@ def _send_marked(
             raise DebuggerError("Session was closed while the command was running")
         self._raise_if_exited(doing)
         if not landed and not self._marker_landed():
+            if self._log_active:
+                # Before the abort: it queues the no-op's marker behind this one.
+                self._abandoned_log_markers.append(marker)
             partial_output = self._snapshot_partial_output()
             resynced = self._abort_running_command()
             detail = "" if resynced else " (session may need a manual break-in)"
@@ -707,6 +726,19 @@ def _read_log_segment(self, marker: str) -> Optional[List[str]]:
                     text = handle.read().decode("utf-16-le", errors="replace")
             except OSError:
                 return None
+            # Skip what timed-out commands left in the log first; otherwise
+            # their late output would lead this command's reply (#449).
+            while self._abandoned_log_markers:
+                stale = self._abandoned_log_markers[0]
+                first = text.find(stale)
+                second = text.find(stale, first + len(stale)) if first != -1 else -1
+                if second == -1:
+                    break
+                end_nl = text.find("\n", second)
+                end = len(text) if end_nl == -1 else end_nl + 1
+                self._log_offset += len(text[:end].encode("utf-16-le"))
+                text = text[end:]
+                self._abandoned_log_markers.pop(0)
             first = text.find(marker)
             second = text.find(marker, first + len(marker)) if first != -1 else -1
             if first != -1 and second != -1:
@@ -762,25 +794,55 @@ def _run_then_resume(self, command: str, go_at: int, cmd_timeout: int) -> List[s
         return output
 
     def _abort_running_command(self) -> bool:
-        """Break into a live target still running a timed-out command.
+        """Cancel a command that outran its timeout.
 
         Sends CTRL+BREAK, then waits briefly for the pending marker to arrive so
         the session lands back at a clean prompt. Returns True if it resynced.
-        For a dump (not live) there is nothing to break into.
+        On a live target this breaks in; on a dump it cancels the command itself
+        (verified on kd: ``!process 0 7`` over a kernel dump stops within a
+        second and the next command runs normally, #449). Without it, every
+        later command on the session queued behind the runaway one and timed
+        out too.
         """
         resynced = False
-        if self.is_live_session and self.process and self.process.poll() is None:
+        if self.process and self.process.poll() is None:
             try:
                 self.process.send_signal(signal.CTRL_BREAK_EVENT)
                 # The queued marker runs once the target breaks in; wait for it.
                 resynced = self.ready_event.wait(min(10, max(3, self.timeout)))
             except Exception:
                 resynced = False
+            if resynced:
+                try:
+                    self._absorb_stray_break()
+                except Exception:
+                    pass  # the resync itself worked; a failed no-op must not undo that
         with self.lock:
             self.output_lines = []
             self._expected_marker = None
         return resynced
 
+    def _absorb_stray_break(self) -> None:
+        """Run a no-op so a break that hit an idle debugger is spent on it.
+
+        If the timed-out command finished between the timeout and the signal,
+        the CTRL+BREAK reached a debugger with nothing to cancel and may stay
+        pending, aborting the next real command early with truncated output
+        that would read as success (#468). `.echo` is cheap and is the command
+        that takes the hit instead. Best effort: if it does not answer, the
+        session is left as the caller's resync found it.
+        """
+        marker = self._next_marker()
+        self.ready_event.clear()
+        with self.lock:
+            self.output_lines = []
+            self._expected_marker = marker
+        if self._log_active:
+            self._abandoned_log_markers.append(marker)
+        self.process.stdin.write(f".echo {marker}\n")
+        self.process.stdin.flush()
+        self.ready_event.wait(min(3, max(1, self.timeout)))
+
     def _resume_target(self, command: str) -> List[str]:
         """Write a go-class command and return without waiting for a prompt.
 

src/mcp_windbg/tests/test_debug_session.py

@@ -94,6 +94,11 @@ def __init__(
         #: transcript to this file the way cdb/kd do, so the log-content channel
         #: can be exercised without a real multibyte debugger.
         self._log_path = None
+        #: Commands that keep the debugger busy (a long ``!process 0 7`` on a
+        #: dump): they print a first line, then stdin queues behind them until
+        #: CTRL+BREAK cancels them or :meth:`finish_busy` lets them complete.
+        self.busy_commands: set = set()
+        self._busy = False
 
     def _feed(self, text: str):
         for line in text.splitlines():
@@ -132,6 +137,12 @@ def _handle(self, line: str):
             # quit / detach: the real process exits, ending the reader loop
             self._alive = False
             self._out.put(_STOP)
+        elif line in self.busy_commands:
+            self._out.put(f"PARTIAL:{line}")
+            if logging:
+                self._log_write(f"PARTIAL:{line}\r\n")
+            self.running = True
+            self._busy = True
         elif self._resumes_on_go and line.split()[:1] and line.split()[0] in _GO:
             self.running = True
         else:
@@ -164,9 +175,19 @@ def poll(self):
 
     def send_signal(self, sig):
         self.signals.append(sig)
-        if self._breaks_on_signal:
+        if not self._breaks_on_signal:
+            return
+        if self._busy:
+            self._busy = False
+            self.target_stops()  # a cancelled command just stops; no banner
+        else:
             self.target_stops("Break instruction exception - code 80000003 (first chance)")
 
+    def finish_busy(self):
+        """The busy command completes on its own, late."""
+        self._busy = False
+        self.target_stops("LATE:output of the slow command")
+
     def terminate(self):
         self._alive = False
         self._out.put(_STOP)
@@ -241,6 +262,63 @@ def test_timeout_raises_when_marker_never_arrives(make_session):
     assert "timed out" in str(exc.value).lower()
 
 
+def test_a_dump_command_that_times_out_is_cancelled_and_the_next_one_runs(make_session):
+    """#449: on a kernel dump, `!process 0 7` outruns any sane timeout. Before,
+    only live sessions were broken into, so kd kept running it and every later
+    command - the retry, `!irql`, even `.echo` - queued behind it and timed out."""
+    session, proc = make_session(timeout=1)
+    proc.busy_commands = {"!process 0 7"}
+    with pytest.raises(DebuggerError) as exc:
+        session.send_command("!process 0 7")
+    assert "timed out" in str(exc.value).lower()
+    assert "manual break-in" not in str(exc.value)  # it resynced
+    assert debug_session.signal.CTRL_BREAK_EVENT in proc.signals
+    assert session.send_command("!irql") == ["OUT:!irql"]
+
+
+def test_a_timed_out_command_is_followed_by_a_noop_before_the_next_one(make_session):
+    """#468: if the slow command finished just before the CTRL+BREAK, the break
+    can stay pending on an idle debugger and abort the next real command early.
+    A `.echo` goes in first, so it takes the hit."""
+    session, proc = make_session(timeout=1)
+    proc.busy_commands = {"!process 0 7"}
+    written = []
+    real_write = proc.stdin.write
+    proc.stdin.write = lambda text: (written.append(text), real_write(text))[1]
+    with pytest.raises(DebuggerError):
+        session.send_command("!process 0 7")
+    assert written[-1].startswith(".echo ") and proc.signals
+    written.clear()
+    assert session.send_command("!process 0 0") == ["OUT:!process 0 0"]
+    assert written[0].startswith("!process 0 0")  # nothing else queued ahead of it
+
+
+def test_late_output_of_an_abandoned_dump_command_does_not_lead_the_next_reply(make_session):
+    """If the break-in does not land, the runaway command finishes later. Its
+    output arrives ahead of its own (abandoned) marker and must be dropped, not
+    handed to whichever command waits next."""
+    session, proc = make_session(timeout=1, breaks_on_signal=False)
+    proc.busy_commands = {"!process 0 7"}
+    with pytest.raises(DebuggerError):
+        session.send_command("!process 0 7")
+    threading.Timer(0.2, proc.finish_busy).start()
+    assert session.send_command("!irql", timeout=5) == ["OUT:!irql"]
+
+
+def test_a_cancelled_dump_command_does_not_lead_the_next_reply_from_the_log(make_session, monkeypatch):
+    """#449 on a multibyte code page: replies come from the Unicode log, where
+    the cancelled command's partial output and marker sit ahead of the next
+    command's segment. The next reply must hold only its own output."""
+    monkeypatch.setattr(debug_session, "_acp_is_multibyte", lambda: True)
+    session, proc = make_session(timeout=1)
+    assert session._log_active is True
+    proc.busy_commands = {"!process 0 7"}
+    with pytest.raises(DebuggerError):
+        session.send_command("!process 0 7")
+    assert session.send_command("!irql") == ["OUT:!irql"]
+    assert session.send_command("k") == ["OUT:k"]
+
+
 def test_timeout_error_preserves_output_seen_before_marker(make_session):
     """A command that never reaches its marker must retain useful output."""
     session, proc = make_session(timeout=1)
@@ -254,6 +332,19 @@ def test_timeout_error_preserves_output_seen_before_marker(make_session):
     assert exc.value.partial_output == ["OUT:!clrstack"]
 
 
+def test_timeout_after_an_abandoned_marker_still_reports_partial_output(make_session):
+    """A late marker from an abandoned command is discarded along with what
+    preceded it. The command that times out after that must still report its
+    own partial output, not an empty or stale list."""
+    session, proc = make_session(timeout=1)
+    proc._out.put(f"{debug_session.MARKER_BASE}_stale")
+    proc._swallow = True
+    with pytest.raises(DebuggerError) as exc:
+        session.send_command("!clrstack", timeout=1)
+
+    assert exc.value.partial_output == ["OUT:!clrstack"]
+
+
 def test_partial_timeout_output_has_line_and_size_limits(make_session):
     session, _ = make_session(timeout=1)
     with session.lock: