Skip to content

Commit 67efbac

Browse files
authored
fix: escape undecodable subprocess output bytes and deflake graceful shutdown test (#277)
Follow-up to #275, which decoded subprocess stdout/stderr with errors="replace" to keep the stream-reader thread alive when a child process emits non-UTF-8 (locale-encoded) bytes. Switch the decode error handler from "replace" to "backslashreplace" so undecodable bytes are escaped (e.g. b"\xc7" -> "\xc7") instead of collapsed to U+FFFD. This keeps the reader alive exactly the same way while preserving the original byte values in the logs, which helps identify the codepage a DCC batch renderer is emitting. Add integration tests covering single invalid bytes, consecutive invalid bytes, cp1252 text runs, truncated UTF-8 sequences, and that valid multi-byte UTF-8 passes through unescaped. Also fix the flaky test_graceful_shutdown integration test that failed on the Python 3.12 macOS CI job for #275. The test slept a fixed 0.5s after spawning fake_client.py before sending SIGTERM; on a slow CI host the signal could arrive before the client registered its handler, killing the process with empty output. The client now prints a ready line after handler registration and the test blocks on it before signaling. Signed-off-by: David Leong <116610336+leongdl@users.noreply.github.com>
1 parent b42405c commit 67efbac

5 files changed

Lines changed: 86 additions & 10 deletions

File tree

src/openjd/adaptor_runtime/process/_logging_subprocess.py

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -69,8 +69,12 @@ def __init__(
6969
# error handling a single undecodable byte raises UnicodeDecodeError in the
7070
# stream-reader thread, killing it. Once the reader thread is gone the pipe is
7171
# no longer drained, the subprocess blocks on a full stdout pipe, and the job
72-
# deadlocks. Replacing undecodable bytes keeps the reader alive.
73-
errors="replace",
72+
# deadlocks. Escaping undecodable bytes (e.g. b"\xc7" -> "\\xc7") keeps the
73+
# reader alive while preserving the original byte values in the logs, which
74+
# helps identify the codepage the subprocess is emitting.
75+
# Note: encoding/errors also apply to stdin, so text written to the child's
76+
# stdin would have unencodable characters escaped silently rather than raising.
77+
errors="backslashreplace",
7478
cwd=startup_directory,
7579
)
7680
if OSName.is_windows(): # pragma: is-posix

test/openjd/adaptor_runtime/integ/process/test_integration_logging_subprocess.py

Lines changed: 67 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -174,13 +174,77 @@ def test_non_utf8_output_does_not_kill_reader(self, caplog):
174174
# WHEN
175175
p = LoggingSubprocess(args=[sys.executable, "-c", script])
176176
p.wait()
177-
p._cleanup_io_threads()
178177

179178
# THEN
180179
# "after" is only logged if the reader thread survived the undecodable byte.
181180
assert "after" in caplog.text
182-
# The undecodable byte is replaced rather than raising.
183-
assert "�" in caplog.text
181+
# The undecodable byte is escaped rather than raising.
182+
assert "bad \\xc7 byte" in caplog.text
183+
184+
@pytest.mark.timeout(10)
185+
@pytest.mark.parametrize(
186+
argnames=("raw_bytes", "expected_escaped"),
187+
argvalues=[
188+
# 0xc7 is "Ç" in cp1252 (observed from 3dsmaxbatch.exe on stdout).
189+
(b"bad \xc7 byte", "bad \\xc7 byte"),
190+
# 0xff is never valid anywhere in UTF-8.
191+
(b"bad \xff byte", "bad \\xff byte"),
192+
# Consecutive invalid bytes must each be escaped separately.
193+
(b"bad \xc7\xff bytes", "bad \\xc7\\xff bytes"),
194+
# cp1252-encoded "Çé" — an invalid two-byte run in UTF-8.
195+
(b"bad \xc7\xe9 text", "bad \\xc7\\xe9 text"),
196+
# A truncated UTF-8 multi-byte sequence (0xe4 0xbd is an incomplete
197+
# 3-byte sequence) followed by valid ASCII.
198+
(b"truncated \xe4\xbd then ok", "truncated \\xe4\\xbd then ok"),
199+
],
200+
ids=["cp1252-byte", "invalid-byte", "consecutive-invalid", "cp1252-text", "truncated-utf8"],
201+
)
202+
def test_non_utf8_output_is_escaped(self, caplog, raw_bytes: bytes, expected_escaped: str):
203+
"""
204+
Undecodable bytes in subprocess output must be escaped with backslashreplace
205+
(e.g. b"\xc7" -> "\\xc7") so the original byte values are preserved in the logs.
206+
"""
207+
# GIVEN
208+
caplog.set_level(_STDOUT_LEVEL)
209+
script = (
210+
"import sys; "
211+
f"sys.stdout.buffer.write({raw_bytes + b'!'!r}); "
212+
"sys.stdout.buffer.flush()"
213+
)
214+
215+
# WHEN
216+
p = LoggingSubprocess(args=[sys.executable, "-c", script])
217+
p.wait()
218+
219+
# THEN
220+
# The trailing "!" proves the full line was logged, not truncated at the bad byte.
221+
assert expected_escaped + "!" in caplog.text
222+
# The replacement character must not appear; the byte value must be preserved.
223+
assert "�" not in caplog.text
224+
225+
@pytest.mark.timeout(10)
226+
def test_valid_utf8_is_not_escaped(self, caplog):
227+
"""
228+
Valid multi-byte UTF-8 sequences must pass through unmodified — escaping applies
229+
only to genuinely invalid sequences, even when a multi-byte character could be
230+
split across internal read chunk boundaries.
231+
"""
232+
# GIVEN
233+
caplog.set_level(_STDOUT_LEVEL)
234+
message = "héllo wörld Ç 星期五"
235+
script = (
236+
"import sys; "
237+
f"sys.stdout.buffer.write({message.encode('utf-8')!r} + b'\\n'); "
238+
"sys.stdout.buffer.flush()"
239+
)
240+
241+
# WHEN
242+
p = LoggingSubprocess(args=[sys.executable, "-c", script])
243+
p.wait()
244+
245+
# THEN
246+
assert message in caplog.text
247+
assert "\\x" not in caplog.text
184248

185249
def test_executable_not_found(self):
186250
"""When calling LoggingSubprocess with a missing executable, FileNotFoundError will be raised"""

test/openjd/adaptor_runtime/unit/process/test_logging_subprocess.py

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -69,7 +69,7 @@ def test_process_creation(self, mock_popen: mock.Mock, mock_stream_logger: mock.
6969
popen_params = dict(
7070
args=args,
7171
encoding="utf-8",
72-
errors="replace",
72+
errors="backslashreplace",
7373
stdin=subprocess.PIPE,
7474
stdout=subprocess.PIPE,
7575
stderr=subprocess.PIPE,
@@ -483,7 +483,7 @@ def test_startup_directory_default(self, mock_popen_autospec: mock.Mock):
483483
stdout=subprocess.PIPE,
484484
stderr=subprocess.PIPE,
485485
encoding="utf-8",
486-
errors="replace",
486+
errors="backslashreplace",
487487
cwd=None,
488488
)
489489
if OSName.is_windows():
@@ -506,7 +506,7 @@ def test_start_directory(self, mock_popen_autospec: mock.Mock):
506506
stdout=subprocess.PIPE,
507507
stderr=subprocess.PIPE,
508508
encoding="utf-8",
509-
errors="replace",
509+
errors="backslashreplace",
510510
cwd="startup_dir",
511511
)
512512
if OSName.is_windows():

test/openjd/adaptor_runtime_client/integ/fake_client.py

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -37,6 +37,9 @@ def run(self):
3737

3838
def run_client():
3939
test_client = FakeClient("1234")
40+
# Signal handler registration (in the main thread) happens in the constructor above.
41+
# Tests wait for this line before sending signals to avoid a startup race.
42+
print("client ready", flush=True)
4043
test_client.run()
4144

4245

test/openjd/adaptor_runtime_client/integ/test_integration_client_interface.py

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -33,8 +33,13 @@ def test_graceful_shutdown(self) -> None:
3333
popen_params.update(creationflags=_subprocess.CREATE_NEW_PROCESS_GROUP) # type: ignore[attr-defined]
3434
client_subprocess = _subprocess.Popen(**popen_params)
3535

36-
# To avoid a race condition, giving some extra time for the logging subprocess to start.
37-
_sleep(0.5 if OSName.is_posix() else 4)
36+
# Wait for the client to report that it has started (and registered its signal
37+
# handler) before sending the signal. A fixed sleep is racy on slow CI hosts: if the
38+
# signal arrives before the handler is registered, the default handler kills the
39+
# process and the test fails with empty output.
40+
assert client_subprocess.stdout is not None
41+
ready_line = client_subprocess.stdout.readline()
42+
assert "client ready" in ready_line
3843
signal_type: signal.Signals
3944
if OSName.is_windows():
4045
signal_type = signal.CTRL_BREAK_EVENT # type: ignore[attr-defined]

0 commit comments

Comments
 (0)