From 5d424cd8da090f21b8233e7c8964ecb2898ce4e9 Mon Sep 17 00:00:00 2001 From: David Leong <116610336+leongdl@users.noreply.github.com> Date: Mon, 3 Aug 2026 11:55:52 -0700 Subject: [PATCH] fix: decode subprocess output with errors=backslashreplace LoggingSubprocess created its Popen with encoding="utf-8" but no errors= parameter, so decoding defaulted to strict. A single byte of subprocess output that is not valid UTF-8 (for example a Windows DCC application writing cp1252, such as Unreal Engine emitting the 0x97 em dash) raised UnicodeDecodeError inside the _enqueue_stdout reader thread. The thread died silently, and all subsequent stdout from the subprocess was lost, masking any later errors from the job. Decode with errors="backslashreplace" so undecodable bytes are escaped (e.g. b"\x97" -> "\\x97") instead of raising. This keeps the reader thread alive while preserving the original byte values in the logs, which helps identify the codepage the subprocess is emitting. This ports the fix that openjd-adaptor-runtime-for-python applied to its own LoggingSubprocess in PRs #275 and #277. Regression tests cover: the reader thread surviving undecodable bytes, escape formatting for single/consecutive/truncated invalid sequences, valid multi-byte UTF-8 passing through unescaped, the behavior under a non-default encoding, and the errors= kwarg on the Popen construction shared by the sudo and Windows-as-user paths. Every test was mutation-checked: removing the errors= parameter, substituting replace/ignore handlers, and forcing an ASCII encoding each fail at least one test. Signed-off-by: David Leong <116610336+leongdl@users.noreply.github.com> --- src/openjd/sessions/_subprocess.py | 9 + test/openjd/sessions_v0/test_subprocess.py | 198 +++++++++++++++++++++ 2 files changed, 207 insertions(+) diff --git a/src/openjd/sessions/_subprocess.py b/src/openjd/sessions/_subprocess.py index d1c7335e..8ee6c6be 100644 --- a/src/openjd/sessions/_subprocess.py +++ b/src/openjd/sessions/_subprocess.py @@ -462,6 +462,15 @@ def _start_subprocess(self) -> Optional[Popen]: stdout=PIPE, stderr=STDOUT, encoding=self._encoding, + # A subprocess (e.g. a Windows DCC application writing cp1252) can emit + # bytes that are not valid in the configured encoding. With the default + # strict error handling a single undecodable byte raises + # UnicodeDecodeError in the stdout reader thread, killing it; all + # subsequent output from the subprocess is then silently lost. Escaping + # undecodable bytes (e.g. b"\x97" -> "\\x97") keeps the reader alive + # while preserving the original byte values in the logs, which helps + # identify the codepage the subprocess is emitting. + errors="backslashreplace", start_new_session=True, cwd=self._working_dir, ) diff --git a/test/openjd/sessions_v0/test_subprocess.py b/test/openjd/sessions_v0/test_subprocess.py index 27b86e96..a5fdb349 100644 --- a/test/openjd/sessions_v0/test_subprocess.py +++ b/test/openjd/sessions_v0/test_subprocess.py @@ -7,6 +7,7 @@ import time import os import getpass +from base64 import b64encode from concurrent.futures import ThreadPoolExecutor, wait from logging.handlers import QueueHandler from pathlib import Path @@ -125,6 +126,203 @@ def test_basic_operation_with_sameuser( messages = collect_queue_messages(message_queue) assert message in messages + def test_non_utf8_output_does_not_kill_reader( + self, + message_queue: SimpleQueue, + queue_handler: QueueHandler, + python_exe: str, + ) -> None: + # A child process that emits bytes that are not valid UTF-8 (e.g. a Windows + # DCC application writing cp1252 to stdout) must not crash the stdout reader + # thread. If the reader dies, all subsequent output is silently lost. + # Regression test for the customer-reported UnicodeDecodeError on byte 0x97 + # (cp1252 em dash from Unreal Engine). + + # GIVEN + logger = build_logger(queue_handler) + script = ( + "import sys; " + "sys.stdout.buffer.write(b'before\\n'); " + "sys.stdout.buffer.flush(); " + "sys.stdout.buffer.write(b'bad \\x97 byte\\n'); " + "sys.stdout.buffer.flush(); " + "sys.stdout.buffer.write(b'after\\n'); " + "sys.stdout.buffer.flush()" + ) + subproc = LoggingSubprocess( + logger=logger, + args=[python_exe, "-c", script], + ) + + # WHEN + subproc.run() + + # THEN + assert subproc.exit_code == 0 + messages = collect_queue_messages(message_queue) + assert "before" in messages + # "after" is only logged if the reader thread survived the undecodable byte. + assert "after" in messages + + @pytest.mark.parametrize( + argnames=("raw_bytes", "expected_escaped"), + argvalues=[ + # 0x97 is the em dash in cp1252 — the exact byte from the customer report + # (Unreal Engine on Windows writing cp1252 to stdout). + (b"bad \x97 byte", "bad \\x97 byte"), + # 0xff is never valid anywhere in UTF-8. + (b"bad \xff byte", "bad \\xff byte"), + # Consecutive invalid bytes must each be escaped separately. + (b"bad \xc7\xff bytes", "bad \\xc7\\xff bytes"), + # cp1252-encoded text run — an invalid two-byte sequence in UTF-8. + (b"bad \xc7\xe9 text", "bad \\xc7\\xe9 text"), + # A truncated UTF-8 multi-byte sequence (0xe4 0xbd is an incomplete + # 3-byte sequence) followed by valid ASCII. + (b"truncated \xe4\xbd then ok", "truncated \\xe4\\xbd then ok"), + ], + ids=[ + "cp1252-em-dash", + "invalid-byte", + "consecutive-invalid", + "cp1252-text", + "truncated-utf8", + ], + ) + def test_non_utf8_output_is_escaped( + self, + message_queue: SimpleQueue, + queue_handler: QueueHandler, + python_exe: str, + raw_bytes: bytes, + expected_escaped: str, + ) -> None: + # Undecodable bytes in subprocess output must be escaped with backslashreplace + # (e.g. b"\x97" -> "\\x97") so the original byte values are preserved in the + # logs. Preserving the byte values (rather than collapsing to U+FFFD) helps + # identify the codepage the subprocess is emitting. + + # GIVEN + logger = build_logger(queue_handler) + # The trailing "!" proves the full line was logged, not truncated at the bad + # byte; the newline terminates the line for the reader's readline(). + payload = raw_bytes + b"!\n" + script = ( + "import sys; " f"sys.stdout.buffer.write({payload!r}); " "sys.stdout.buffer.flush()" + ) + subproc = LoggingSubprocess( + logger=logger, + args=[python_exe, "-c", script], + ) + + # WHEN + subproc.run() + + # THEN + assert subproc.exit_code == 0 + messages = collect_queue_messages(message_queue) + # The trailing "!" proves the full line was logged, not truncated at the bad byte. + assert expected_escaped + "!" in messages + # The replacement character must not appear; the byte value must be preserved. + replaced = [m for m in messages if "\ufffd" in m] + assert not replaced + + def test_valid_utf8_is_not_escaped( + self, + message_queue: SimpleQueue, + queue_handler: QueueHandler, + python_exe: str, + ) -> None: + # Valid multi-byte UTF-8 sequences must pass through unmodified — escaping + # applies only to genuinely invalid sequences. + + # GIVEN + logger = build_logger(queue_handler) + message = "héllo wörld Ç 星期五" + # Pass the payload base64-encoded so the "Running command" log line does not + # itself contain backslash-x escape sequences (from the bytes repr), which + # would defeat the "no escapes appeared" assertion below. + payload_b64 = b64encode(message.encode("utf-8")).decode("ascii") + script = ( + "import sys, base64; " + f"sys.stdout.buffer.write(base64.b64decode('{payload_b64}') + b'\\n'); " + "sys.stdout.buffer.flush()" + ) + subproc = LoggingSubprocess( + logger=logger, + args=[python_exe, "-c", script], + ) + + # WHEN + subproc.run() + + # THEN + assert subproc.exit_code == 0 + messages = collect_queue_messages(message_queue) + assert message in messages + # Scope the escape sweep to subprocess output lines. The "Running command" + # log line contains the interpreter path, which on Windows contains + # backslashes that could false-positive this assertion. + output_messages = [m for m in messages if not m.startswith("Running command")] + escaped = [m for m in output_messages if "\\x" in m] + assert not escaped + replaced = [m for m in output_messages if "\ufffd" in m] + assert not replaced + + def test_non_utf8_output_is_escaped_with_non_default_encoding( + self, + message_queue: SimpleQueue, + queue_handler: QueueHandler, + python_exe: str, + ) -> None: + # The escape behavior must hold for any configured encoding, not only the + # utf-8 default: bytes that are invalid in that encoding are escaped, and + # bytes that are valid in it decode normally. + + # GIVEN + logger = build_logger(queue_handler) + # 0x81 is undefined in cp1252 and must be escaped; 0x97 is the em dash in + # cp1252 and must decode to U+2014. + payload = b"undef \x81 byte, dash \x97 ok!\n" + script = ( + "import sys; " f"sys.stdout.buffer.write({payload!r}); " "sys.stdout.buffer.flush()" + ) + subproc = LoggingSubprocess( + logger=logger, + args=[python_exe, "-c", script], + encoding="cp1252", + ) + + # WHEN + subproc.run() + + # THEN + assert subproc.exit_code == 0 + messages = collect_queue_messages(message_queue) + assert "undef \\x81 byte, dash \u2014 ok!" in messages + + def test_popen_uses_backslashreplace_error_handler(self) -> None: + # Pin the errors= kwarg on the Popen construction itself. This protects all + # construction paths that reuse the shared popen_args dict (same-user Popen, + # the posix sudo path, and PopenWindowsAsUser, which CI integration tests + # cannot all reach) against a refactor that moves or drops the kwarg. + + # GIVEN + logger = MagicMock() + subproc = LoggingSubprocess( + logger=logger, + args=[sys.executable, "-c", "pass"], + ) + + # WHEN + with patch.object(subprocess_impl_mod, "Popen") as mock_popen: + subproc._start_subprocess() + + # THEN + mock_popen.assert_called_once() + kwargs = mock_popen.call_args.kwargs + assert kwargs["errors"] == "backslashreplace" + assert kwargs["encoding"] == "utf-8" + def test_cannot_run(self, message_queue: SimpleQueue, queue_handler: QueueHandler) -> None: # Make sure that we log a message, and don't blow up when we cannot # run the process for some reason.