Skip to content

Commit eca732a

Browse files
committed
fix: read command output from a UTF-16 log on multibyte code pages
On a multibyte system code page (Chinese 936, Japanese 932, Korean 949, or the "Use Unicode UTF-8" setting 65001) the debugger truncates its text output over a pipe: it writes each line's character count as a byte count, so the tail of any line with non-ASCII text, its newline included, is dropped. This lost the end of du strings and other Unicode output, and a line cut in the middle of a character wedged the session. It affects every command, not just du, and no debugger output mode over the pipe avoids it. .logopen /u writes a UTF-16 log that is complete and flushes per command. So on a multibyte code page the session now opens such a log at startup and reads each command's output from it, keyed by the same .echo markers the pipe already uses to synchronize. The pipe stays the control channel; only the returned content comes from the log. Single-byte code pages (e.g. Western 1252), where the pipe is lossless, are detected via GetCPInfo and keep the pipe path, byte-for-byte unchanged. The pipe is also decoded with the debugger's own ANSI code page and with errors="replace", so a multibyte sequence split across reads cannot raise in the reader thread on the paths that still read the pipe (a live target's asynchronous output). Verified on a Windows 11 VM with cdb 10.0.26100.1742 under code pages 1252 (passthrough), 936 and 65001 (all commands return complete Unicode). Fixes #102.
1 parent d3d1fd0 commit eca732a

4 files changed

Lines changed: 300 additions & 1 deletion

File tree

CHANGELOG.md

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,12 @@ All notable changes to the MCP Server for WinDbg Crash Analysis project will be
55
The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
66
and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
77

8+
## [Unreleased]
9+
10+
### Fixed
11+
12+
- **Unicode command output on Chinese, Japanese and Korean Windows** ([#102](https://github.com/svnscha/mcp-windbg/issues/102)) - on a multibyte system code page (936, 932, 949, or the "Use Unicode UTF-8" setting 65001) the debugger truncates its text output over a pipe, dropping the tail of any line that contains non-ASCII text; a `du` of a Chinese string came back empty or partial, other Unicode output was cut short, and a line split in the middle of a character could leave the session unresponsive. On these code pages the session now mirrors output to a UTF-16 log and reads each command's output from it, keyed by the markers it already uses to synchronize; the result is complete for every command. Single-byte code pages (such as Western 1252), where the pipe is lossless, are detected and left on the pipe path unchanged.
13+
814
## [1.2.1] - 2026-08-27
915

1016
### Changed

src/mcp_windbg/debug_session.py

Lines changed: 159 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -28,11 +28,14 @@
2828

2929
from __future__ import annotations
3030

31+
import locale
3132
import os
3233
import re
3334
import signal
3435
import subprocess
36+
import tempfile
3537
import threading
38+
import time
3639
from typing import List, Optional
3740

3841
# Detects a CDB/KD prompt line such as ``0:000>`` or ``3: kd>``.
@@ -132,6 +135,69 @@ def find_executable(paths: List[str], custom_path: Optional[str] = None) -> Opti
132135
return None
133136

134137

138+
def _debugger_output_encoding() -> str:
139+
"""The code page cdb/kd write their output in - the process ANSI code page,
140+
which ``locale.getencoding`` reports (``getpreferredencoding`` on 3.10)."""
141+
if hasattr(locale, "getencoding"):
142+
return locale.getencoding()
143+
return locale.getpreferredencoding(False)
144+
145+
146+
# A prompt at the head of a logged line: ``0:000> ``, ``0: kd> ``, ``1:001:x86> ``,
147+
# the local-kernel ``lkd> ``/``kd> `` forms, and the remote form that carries a
148+
# ``[server (tcp ...)]`` banner first. In the Unicode log these prefix the
149+
# command echo and the .echo marker line; the debugger's own output lines never
150+
# start with one.
151+
_LOGGED_PROMPT = re.compile(r"^(?:\[.*\]\s*)?(?:\d+:[^>]*|l?kd)>")
152+
153+
154+
def _acp_is_multibyte() -> bool:
155+
"""True when this machine's ANSI code page is multibyte (DBCS or UTF-8).
156+
157+
That is exactly when the debugger truncates its text output over a pipe, so
158+
it is the gate for reading output from the Unicode log instead. Uses
159+
``GetCPInfo(GetACP()).MaxCharSize`` - 1 for a single-byte page such as
160+
Western 1252, greater for 932/936/949/950/65001. False where the call is
161+
unavailable, so a single-byte or non-Windows host keeps the pipe path.
162+
"""
163+
try:
164+
import ctypes
165+
166+
class _CPINFO(ctypes.Structure):
167+
_fields_ = [
168+
("MaxCharSize", ctypes.c_uint),
169+
("DefaultChar", ctypes.c_char * 2),
170+
("LeadByte", ctypes.c_char * 12),
171+
]
172+
173+
kernel32 = ctypes.windll.kernel32 # type: ignore[attr-defined]
174+
info = _CPINFO()
175+
if kernel32.GetCPInfo(kernel32.GetACP(), ctypes.byref(info)):
176+
return info.MaxCharSize > 1
177+
except Exception:
178+
pass
179+
return False
180+
181+
182+
def _extract_log_output(segment: str) -> List[str]:
183+
"""The debugger's own output lines from one command's Unicode-log segment.
184+
185+
The segment runs from just after the previous command's marker up to (not
186+
including) the line that echoes this command's ``.echo <marker>``. Its first
187+
line is the echo of the command itself; both it and any other prompt-prefixed
188+
line are the transcript's scaffolding, not output, and are dropped. Leading
189+
and trailing blank lines (a bare prompt writes one) are trimmed so a command
190+
that prints nothing yields ``[]``, as the pipe path does.
191+
"""
192+
lines = [ln.rstrip("\r") for ln in segment.split("\n")]
193+
kept = [ln for ln in lines if not _LOGGED_PROMPT.match(ln)]
194+
while kept and kept[0] == "":
195+
kept.pop(0)
196+
while kept and kept[-1] == "":
197+
kept.pop()
198+
return kept
199+
200+
135201
class DebuggerSession:
136202
"""A debugger subprocess plus the marker protocol used to drive it.
137203
@@ -185,16 +251,29 @@ def __init__(
185251
stdout=subprocess.PIPE,
186252
stderr=subprocess.STDOUT,
187253
text=True,
254+
# cdb/kd write output in the process ANSI code page (GetACP),
255+
# regardless of PYTHONUTF8; decode with the same one, and never
256+
# strictly, so a byte a multibyte code page split across reads
257+
# cannot raise in the reader thread and wedge the session.
258+
encoding=_debugger_output_encoding(),
259+
errors="replace",
188260
bufsize=1,
189261
creationflags=creationflags,
190262
)
191263
except Exception as e: # pragma: no cover - Popen rarely fails once the exe is located
192264
raise DebuggerError(f"Failed to start debugger process: {e}")
193265

266+
#: Unicode-log content channel (see _enable_unicode_log). Inactive until
267+
#: the log is open, and only ever opened on a multibyte code page.
268+
self._log_path: Optional[str] = None
269+
self._log_offset = 0
270+
self._log_active = False
271+
194272
self.reader_thread = threading.Thread(target=self._read_output, daemon=True)
195273
self.reader_thread.start()
196274

197275
self._startup()
276+
self._enable_unicode_log()
198277

199278
# -- Subclass hooks ---------------------------------------------------
200279

@@ -438,7 +517,85 @@ def _send_marked(
438517
f"Command timed out after {cmd_timeout} seconds: {command}{detail}{lost}"
439518
)
440519

441-
return self._take_output()
520+
pipe_output = self._take_output()
521+
if self._log_active:
522+
# The pipe truncates multibyte output; the log does not. Prefer the
523+
# log segment for this command, falling back to the pipe if the log
524+
# has not caught up (it always should, the marker just landed).
525+
logged = self._read_log_segment(marker)
526+
if logged is not None:
527+
return logged
528+
return pipe_output
529+
530+
# -- Unicode log content channel --------------------------------------
531+
532+
def _enable_unicode_log(self) -> None:
533+
"""On a multibyte code page, mirror output to a UTF-16 log and read
534+
command output from it instead of the truncating ANSI pipe.
535+
536+
cdb/kd write pipe (and ANSI-log) output short by each line's multibyte
537+
expansion, losing the tail of any non-ASCII line; ``.logopen /u`` writes
538+
a UTF-16 log that is complete and flushes per command. The pipe stays the
539+
sync channel - the ``.echo`` markers are logged too, so each command's
540+
output is the log slice ahead of its marker. Best effort: any failure
541+
leaves the session on the pipe path exactly as before.
542+
"""
543+
if not _acp_is_multibyte():
544+
return
545+
try:
546+
fd, path = tempfile.mkstemp(prefix="mcp_windbg_", suffix=".ulog")
547+
os.close(fd)
548+
os.remove(path) # cdb creates it; a pre-existing file would be appended to
549+
self._send_marked(f".logopen /u {path}", self.timeout)
550+
if not os.path.exists(path):
551+
return
552+
self._log_path = path
553+
self._log_offset = 0
554+
self._log_active = True
555+
# The log opens mid-command, so it starts with its banner and the
556+
# logopen echo. One throwaway marked command drains all of that and
557+
# leaves the offset at a clean boundary - robust to log-flush timing
558+
# in a way that trusting the post-open file size is not.
559+
self._send_marked(".echo", self.timeout)
560+
except Exception:
561+
self._cleanup_log()
562+
563+
def _read_log_segment(self, marker: str) -> Optional[List[str]]:
564+
"""This command's output from the Unicode log, or None if not ready.
565+
566+
The marker appears twice in the log: first in the echoed ``.echo
567+
<marker>`` command, then as that command's output. Everything before the
568+
first is this command's transcript; consuming through the second leaves
569+
the offset at a clean boundary for the next command.
570+
"""
571+
deadline = time.time() + max(2.0, self.timeout / 10)
572+
while True:
573+
try:
574+
with open(self._log_path, "rb") as handle:
575+
handle.seek(self._log_offset)
576+
text = handle.read().decode("utf-16-le", errors="replace")
577+
except OSError:
578+
return None
579+
first = text.find(marker)
580+
second = text.find(marker, first + len(marker)) if first != -1 else -1
581+
if first != -1 and second != -1:
582+
line_start = text.rfind("\n", 0, first) + 1
583+
end_nl = text.find("\n", second)
584+
end = len(text) if end_nl == -1 else end_nl + 1
585+
self._log_offset += len(text[:end].encode("utf-16-le"))
586+
return _extract_log_output(text[:line_start])
587+
if time.time() >= deadline:
588+
return None
589+
time.sleep(0.02)
590+
591+
def _cleanup_log(self) -> None:
592+
self._log_active = False
593+
if self._log_path:
594+
try:
595+
os.remove(self._log_path)
596+
except OSError:
597+
pass
598+
self._log_path = None
442599

443600
def _marker_landed(self) -> bool:
444601
"""True if the pending marker arrived just as the deadline expired."""
@@ -710,6 +867,7 @@ def shutdown(self) -> None:
710867
print(f"Error during shutdown: {e}")
711868
finally:
712869
self.process = None
870+
self._cleanup_log()
713871

714872
def _terminate_process(self) -> None:
715873
"""Kill the debugger process. On Windows use a tree kill: cdb.exe/kd.exe

src/mcp_windbg/tests/test_debug_session.py

Lines changed: 67 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@
1111

1212
from __future__ import annotations
1313

14+
import os
1415
import queue
1516
import threading
1617
import time
@@ -88,6 +89,10 @@ def __init__(
8889
#: test hang one specific command without also hanging the break-in
8990
#: probe that precedes it.
9091
self.answer_budget: "int | None" = None
92+
#: When a ``.logopen /u <path>`` is seen, the fake mirrors a UTF-16
93+
#: transcript to this file the way cdb/kd do, so the log-content channel
94+
#: can be exercised without a real multibyte debugger.
95+
self._log_path = None
9196

9297
def _feed(self, text: str):
9398
for line in text.splitlines():
@@ -96,7 +101,20 @@ def _feed(self, text: str):
96101
else:
97102
self._handle(line)
98103

104+
def _open_log(self, path: str):
105+
self._log_path = path
106+
with open(path, "wb") as handle:
107+
handle.write(b"\xff\xfe") # UTF-16LE BOM, as cdb writes
108+
self._log_write("Opened log file\r\n")
109+
110+
def _log_write(self, text: str):
111+
with open(self._log_path, "ab") as handle:
112+
handle.write(text.encode("utf-16-le"))
113+
99114
def _handle(self, line: str):
115+
logging = self._log_path is not None and not line.startswith(".logopen")
116+
if logging:
117+
self._log_write(f"0:000> {line}\r\n") # the transcript echoes the command
100118
if line.startswith(".echo "):
101119
marker = line[len(".echo "):]
102120
if self.answer_budget is not None:
@@ -105,6 +123,10 @@ def _handle(self, line: str):
105123
self.answer_budget -= 1
106124
if not self._swallow:
107125
self._out.put(marker)
126+
if logging:
127+
self._log_write(f"{marker}\r\n")
128+
elif line.startswith(".logopen /u "):
129+
self._open_log(line[len(".logopen /u "):].strip())
108130
elif line in ("q", "\x02"):
109131
# quit / detach: the real process exits, ending the reader loop
110132
self._alive = False
@@ -113,6 +135,8 @@ def _handle(self, line: str):
113135
self.running = True
114136
else:
115137
self._out.put(f"OUT:{line}")
138+
if logging:
139+
self._log_write(f"OUT:{line}\r\n")
116140

117141
def target_stops(self, *lines: str):
118142
"""The target halts on its own (bugcheck, breakpoint), draining stdin."""
@@ -599,3 +623,46 @@ def test_a_timed_out_prefix_still_reports_why_the_target_stopped(make_session):
599623
with pytest.raises(DebuggerError) as exc:
600624
session.send_command("bp nt!NtCreateFile; g", timeout=1)
601625
assert "Fatal System Error" in str(exc.value)
626+
627+
628+
def test_output_is_read_from_the_unicode_log_on_a_multibyte_code_page(make_session, monkeypatch):
629+
"""On a multibyte code page the session opens a UTF-16 log and returns each
630+
command's output from it (the fake mirrors that log). The pipe still drives
631+
the markers; only the returned content comes from the log."""
632+
monkeypatch.setattr(debug_session, "_acp_is_multibyte", lambda: True)
633+
session, proc = make_session()
634+
635+
assert session._log_active is True
636+
assert proc._log_path is not None and os.path.exists(proc._log_path)
637+
# Content comes from the log, marker-synced, with the prompt/echo scaffolding
638+
# stripped - the same lines the pipe path would have returned.
639+
assert session.send_command("r rip") == ["OUT:r rip"]
640+
assert session.send_command("du @rsp") == ["OUT:du @rsp"]
641+
642+
logpath = session._log_path
643+
session.shutdown()
644+
assert not os.path.exists(logpath) # the temp log is cleaned up
645+
646+
647+
def test_a_missing_log_falls_back_to_the_pipe_without_raising(make_session, monkeypatch):
648+
"""If the log cannot be read, the command still returns (from the pipe)
649+
rather than failing - the reader must never depend on the log existing."""
650+
monkeypatch.setattr(debug_session, "_acp_is_multibyte", lambda: True)
651+
session, proc = make_session()
652+
assert session._log_active is True
653+
654+
# Drop the log out from under the reader: the next command falls back.
655+
os.remove(session._log_path)
656+
proc._log_path = None
657+
assert session.send_command("lm") == ["OUT:lm"]
658+
659+
660+
def test_the_log_is_left_untouched_on_a_single_byte_code_page(make_session, monkeypatch):
661+
"""The default (single-byte) path never opens a log and returns pipe output
662+
verbatim, so a Western setup is byte-for-byte unchanged."""
663+
monkeypatch.setattr(debug_session, "_acp_is_multibyte", lambda: False)
664+
session, proc = make_session()
665+
666+
assert session._log_active is False
667+
assert proc._log_path is None
668+
assert session.send_command("r rip") == ["OUT:r rip"]
Lines changed: 68 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,68 @@
1+
"""Hermetic tests for the Unicode-log content extraction.
2+
3+
The full log transport (opening ``.logopen /u`` and reading complete UTF-16 for
4+
every command on a multibyte code page) is exercised end to end against a real
5+
cdb on the VM noted in the pull request; CI cannot reach that. What is unit-
6+
tested here is the pure slice-to-output-lines logic, which is where the parsing
7+
risk lives.
8+
"""
9+
10+
from __future__ import annotations
11+
12+
from mcp_windbg import debug_session
13+
from mcp_windbg.debug_session import _extract_log_output
14+
15+
16+
def test_drops_the_command_echo_and_keeps_the_output():
17+
segment = "0:000> du @rsp L20\n00000008`7fafe858 \"中文\"\n"
18+
assert _extract_log_output(segment) == ['00000008`7fafe858 "中文"']
19+
20+
21+
def test_a_command_that_prints_nothing_yields_no_lines():
22+
# ew echoes the command and prints nothing; the pipe path returns [] too.
23+
assert _extract_log_output("0:000> ew @rsp 4e2d 0\n") == []
24+
25+
26+
def test_multiple_output_lines_are_kept_in_order():
27+
segment = (
28+
"0:000> dw @rsp L8\n"
29+
"00000008`7fafe858 4e2d 6587 0000 0000 0000 0000 0000 0000\n"
30+
"00000008`7fafe868 0000 0000\n"
31+
)
32+
assert _extract_log_output(segment) == [
33+
"00000008`7fafe858 4e2d 6587 0000 0000 0000 0000 0000 0000",
34+
"00000008`7fafe868 0000 0000",
35+
]
36+
37+
38+
def test_kernel_and_wow64_prompts_are_recognised_as_scaffolding():
39+
segment = "1:001:x86> r eax\neax=00000001\n0: kd> \n"
40+
assert _extract_log_output(segment) == ["eax=00000001"]
41+
42+
43+
def test_local_kernel_prompt_is_recognised_as_scaffolding():
44+
# Local kernel debugging (kd -kl) prompts with "lkd>", not "N: kd>".
45+
segment = "lkd> lm m nt\nfffff803`ec600000 nt\nlkd> \n"
46+
assert _extract_log_output(segment) == ["fffff803`ec600000 nt"]
47+
48+
49+
def test_a_remote_servers_bracketed_prompt_is_recognised_as_scaffolding():
50+
# A user-mode -remote client prompt carries a [server (tcp ...)] banner.
51+
segment = (
52+
"[BOX\\user (tcp [::1]:5005)] 0:000> du @rsp L20\n"
53+
"0000004a`5ccff240 \"中文\"\n"
54+
)
55+
assert _extract_log_output(segment) == ['0000004a`5ccff240 "中文"']
56+
57+
58+
def test_output_lines_are_never_mistaken_for_prompts():
59+
# A real output line does not start with the N:...> prompt shape.
60+
segment = "0:000> lm\nstart end module\n00400000 0041f000 app\n"
61+
assert _extract_log_output(segment) == [
62+
"start end module",
63+
"00400000 0041f000 app",
64+
]
65+
66+
67+
def test_acp_gate_returns_a_bool():
68+
assert isinstance(debug_session._acp_is_multibyte(), bool)

0 commit comments

Comments
 (0)