mirror of
https://github.com/svnscha/mcp-windbg.git
synced 2026-10-17 04:41:56 +08:00
fix(debugger): preserve output on command timeout (#114)
Fixes #112. ## What this changes - Preserve the debugger lines already read when a marked CDB command times out. - Bound timeout diagnostics to 2,000 lines and 64 KiB, with a truncation note. - Document the preserved output in the timeout troubleshooting guide and changelog. ## Why The reader kept output in a private buffer until the completion marker arrived. A runaway SOS command such as `!clrstack` could therefore print useful frames and then lose all of them when the timeout path fired. The timeout error now includes that partial output and also exposes it on `DebuggerError.partial_output`; marker synchronization and the existing manual break-in warning are unchanged. ## How it was verified - The new timeout regression fails on `35b6cdb` and passes with the fix; the same test asserts the preserved line and the bounded diagnostic behavior. - `test_debug_session.py`: 66 passed. - Hermetic suite: 103 passed, 12 deselected; full suite: 103 passed, 12 skipped because this host has no CDB/KD or Git LFS debugger dumps. - `uv lock --check`, MCP schema validation, docs formatter, `compileall`, `uv build`, `twine check`, and `git diff --check` passed. Co-authored-by: Oscar <319719771+Oscar-Williams@users.noreply.github.com> Co-authored-by: Sven Scharmentke <sven.scharmentke@liasoft.de>
This commit is contained in:
@@ -15,6 +15,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
|
||||
and preserve the closing caller's kernel resume policy. Break-in keeps the
|
||||
validated session record so a concurrent close cannot cause a registry error
|
||||
(#109, #110). Thanks to @adity982 for the fix.
|
||||
- A command that times out before reaching its completion marker keeps the
|
||||
output already read, so the timeout error still shows useful diagnostics from
|
||||
runaway commands such as SOS `!clrstack`. The retained output is capped at
|
||||
2,000 lines and 64 KiB (#112, #114). Thanks to @Oscar-Williams for the fix.
|
||||
|
||||
## [1.3.0] - 2026-09-10
|
||||
|
||||
|
||||
@@ -50,6 +50,9 @@ A command that exceeds the per-command limit reports a timeout.
|
||||
|
||||
- Raise it with [`--timeout`](reference/cli.md#general), for example `--timeout 120`.
|
||||
- On large dumps, prefer targeted commands over broad analysis.
|
||||
- The timeout error includes the output read before CDB stopped responding. If the command
|
||||
produces more than the diagnostic limit, the response ends with a truncation note; increase
|
||||
the timeout or inspect the target directly for the complete output.
|
||||
|
||||
## Module not found (pip installs)
|
||||
|
||||
|
||||
@@ -45,6 +45,12 @@ PROMPT_REGEX = re.compile(r"^\d+:.*>\s*$")
|
||||
# appended so each command waits for its own, distinct marker.
|
||||
MARKER_BASE = "COMMAND_COMPLETED_MARKER"
|
||||
|
||||
# A runaway debugger command can produce output indefinitely. Keep timeout
|
||||
# diagnostics useful without turning the error itself into another unbounded
|
||||
# response.
|
||||
MAX_PARTIAL_OUTPUT_LINES = 2000
|
||||
MAX_PARTIAL_OUTPUT_CHARS = 64 * 1024
|
||||
|
||||
# How long ``wait_for_break`` blocks by default. Waiting on a resumed target is
|
||||
# open-ended by nature - you are waiting for a bugcheck or a breakpoint - so this
|
||||
# is deliberately unrelated to the per-command timeout.
|
||||
@@ -69,6 +75,10 @@ RESUME_CONFIRM_TIMEOUT = 0.5
|
||||
class DebuggerError(Exception):
|
||||
"""Raised for any debugger session failure (launch, timeout, I/O)."""
|
||||
|
||||
def __init__(self, message: str, *, partial_output: Optional[List[str]] = None):
|
||||
super().__init__(message)
|
||||
self.partial_output = list(partial_output or [])
|
||||
|
||||
|
||||
class _ReleaseOnExit:
|
||||
"""Context manager that releases an already-acquired lock on exit."""
|
||||
@@ -230,6 +240,10 @@ class DebuggerSession:
|
||||
self.verbose = verbose
|
||||
|
||||
self.output_lines: List[str] = []
|
||||
#: The reader's current command buffer. It is published under the same
|
||||
#: lock as marker state so a timeout can retain output before the marker
|
||||
#: arrives, even though the reader owns the list itself.
|
||||
self._reader_buffer: Optional[List[str]] = None
|
||||
self.lock = threading.Lock()
|
||||
#: Serializes whole operations on the debugger's stdin. ``self.lock``
|
||||
#: only guards individual field writes; it cannot make "install a
|
||||
@@ -302,6 +316,8 @@ class DebuggerSession:
|
||||
return
|
||||
|
||||
buffer: List[str] = []
|
||||
with self.lock:
|
||||
self._reader_buffer = buffer
|
||||
try:
|
||||
for line in self.process.stdout:
|
||||
line = line.rstrip()
|
||||
@@ -318,6 +334,7 @@ class DebuggerSession:
|
||||
if self._expected_marker and self._expected_marker in line:
|
||||
self.output_lines = buffer
|
||||
buffer = []
|
||||
self._reader_buffer = buffer
|
||||
self._expected_marker = None
|
||||
self.ready_event.set()
|
||||
continue
|
||||
@@ -340,6 +357,35 @@ class DebuggerSession:
|
||||
self.output_lines = []
|
||||
return result
|
||||
|
||||
def _snapshot_partial_output(self) -> List[str]:
|
||||
"""Return bounded output read before the current marker arrived."""
|
||||
with self.lock:
|
||||
lines = list(self._reader_buffer or [])
|
||||
|
||||
bounded: List[str] = []
|
||||
char_count = 0
|
||||
truncated = False
|
||||
for line in lines:
|
||||
if len(bounded) >= MAX_PARTIAL_OUTPUT_LINES:
|
||||
truncated = True
|
||||
break
|
||||
remaining = MAX_PARTIAL_OUTPUT_CHARS - char_count
|
||||
if remaining <= 0:
|
||||
truncated = True
|
||||
break
|
||||
if len(line) + 1 > remaining:
|
||||
bounded.append(line[: max(0, remaining - 1)])
|
||||
truncated = True
|
||||
break
|
||||
bounded.append(line)
|
||||
char_count += len(line) + 1
|
||||
|
||||
if truncated:
|
||||
bounded.append(
|
||||
"[partial output truncated; increase the command timeout or inspect the target directly]"
|
||||
)
|
||||
return bounded
|
||||
|
||||
def _abandon_marker(self) -> bool:
|
||||
"""Give up on the marker currently being waited for.
|
||||
|
||||
@@ -510,6 +556,7 @@ class DebuggerSession:
|
||||
if self._closing:
|
||||
raise DebuggerError("Session was closed while the command was running")
|
||||
if not landed and not self._marker_landed():
|
||||
partial_output = self._snapshot_partial_output()
|
||||
resynced = self._abort_running_command()
|
||||
detail = "" if resynced else " (session may need a manual break-in)"
|
||||
# The break-in output is the only record of why the target stopped
|
||||
@@ -519,8 +566,14 @@ class DebuggerSession:
|
||||
if preamble
|
||||
else ""
|
||||
)
|
||||
partial = (
|
||||
"\nPartial output before timeout:\n" + "\n".join(partial_output)
|
||||
if partial_output
|
||||
else ""
|
||||
)
|
||||
raise DebuggerError(
|
||||
f"Command timed out after {cmd_timeout} seconds: {command}{detail}{lost}"
|
||||
f"Command timed out after {cmd_timeout} seconds: {command}{detail}{lost}{partial}",
|
||||
partial_output=partial_output,
|
||||
)
|
||||
|
||||
pipe_output = self._take_output()
|
||||
|
||||
@@ -231,6 +231,33 @@ def test_timeout_raises_when_marker_never_arrives(make_session):
|
||||
assert "timed out" in str(exc.value).lower()
|
||||
|
||||
|
||||
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)
|
||||
proc._swallow = True
|
||||
with pytest.raises(DebuggerError) as exc:
|
||||
session.send_command("!clrstack", timeout=1)
|
||||
|
||||
message = str(exc.value)
|
||||
assert "timed out" in message.lower()
|
||||
assert "OUT:!clrstack" in message
|
||||
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:
|
||||
session._reader_buffer = ["frame"] * (debug_session.MAX_PARTIAL_OUTPUT_LINES + 1)
|
||||
lines = session._snapshot_partial_output()
|
||||
assert len(lines) == debug_session.MAX_PARTIAL_OUTPUT_LINES + 1
|
||||
assert lines[-1].startswith("[partial output truncated;")
|
||||
|
||||
with session.lock:
|
||||
session._reader_buffer = ["x" * debug_session.MAX_PARTIAL_OUTPUT_CHARS]
|
||||
lines = session._snapshot_partial_output()
|
||||
assert lines[-1].startswith("[partial output truncated;")
|
||||
|
||||
|
||||
# -- go-class commands ----------------------------------------------------
|
||||
#
|
||||
# The bug these cover: 'g' hands the CPU to the target, after which the debugger
|
||||
|
||||
Reference in New Issue
Block a user