Skip to content

fix: decode subprocess output with errors=backslashreplace - #343

Merged
mwiebe merged 1 commit into
mainlinefrom
fix/subprocess-non-utf8-output
Aug 4, 2026
Merged

fix: decode subprocess output with errors=backslashreplace#343
mwiebe merged 1 commit into
mainlinefrom
fix/subprocess-non-utf8-output

Conversation

@leongdl

@leongdl leongdl commented Aug 3, 2026

Copy link
Copy Markdown
Contributor

What was the problem/requirement? (What/Why)

LoggingSubprocess creates its Popen with encoding="utf-8" but no errors= parameter, so decoding defaults to errors="strict". A single byte of subprocess output that is not valid UTF-8 raises UnicodeDecodeError inside the _enqueue_stdout reader thread, which has no exception handling:

File "openjd/sessions/_subprocess.py", line 371, in _enqueue_stdout
    for line in iter(_stream_readline_max_length, ""):
  File "openjd/sessions/_subprocess.py", line 362, in _stream_readline_max_length
    return stream.readline(LOG_LINE_MAX_LENGTH)
  File "<frozen codecs>", line 322, in decode
UnicodeDecodeError: 'utf-8' codec can't decode byte 0x97 in position 33: invalid start byte

The thread dies silently and all subsequent stdout from the subprocess is lost, which can mask real errors from the job. This was reported from a production Windows customer-managed fleet where Unreal Engine writes cp1252 to stdout (byte 0x97, the cp1252 em dash). Any Windows DCC application using the system code page (Unreal, 3ds Max, Houdini) can trigger it.

openjd-adaptor-runtime-for-python had the identical defect in its own LoggingSubprocess and fixed it in #275 / #277. This PR ports that fix.

What was the solution? (How)

Pass errors="backslashreplace" to the Popen. Undecodable bytes are escaped (e.g. b"\x97" becomes the text \x97) instead of raising. The reader thread stays alive, no output is lost, and the original byte values are preserved in the logs, which helps identify the codepage the subprocess is emitting (backslashreplace rather than replace, matching the adaptor runtime's follow-up in #277).

The shared popen_args dict is used by all three construction paths (same-user Popen, the posix sudo path, and PopenWindowsAsUser, which forwards kwargs to Popen.__init__), so all of them get the fix.

What is the impact of this change?

  • Jobs whose processes emit non-UTF-8 output no longer silently lose all log output after the first bad byte.
  • Log content changes for such processes: previously the line with the bad byte and everything after it was dropped; now every line is logged, with invalid bytes escaped as \xNN.
  • Valid UTF-8 output is unaffected (covered by a regression test).

How was this change tested?

Test-first: the regression tests were written before the fix and reproduce the exact customer stack trace against the unfixed code (6 of 7 fail before the fix; the valid-UTF-8 negative control passes, as expected).

New tests in test/openjd/sessions_v0/test_subprocess.py:

  • test_non_utf8_output_does_not_kill_reader — reader thread survives a bad byte; output written after it is still captured.
  • test_non_utf8_output_is_escaped (5 cases) — exact escape formatting for the customer's cp1252 em dash, an always-invalid byte, consecutive invalid bytes, cp1252 text runs, and a truncated UTF-8 multi-byte sequence; asserts U+FFFD does not appear.
  • test_valid_utf8_is_not_escaped — valid multi-byte UTF-8 passes through unmodified (guards against over-escaping).
  • test_non_utf8_output_is_escaped_with_non_default_encoding — the escape behavior holds for a configured encoding="cp1252": bytes undefined in cp1252 are escaped, valid cp1252 decodes normally.
  • test_popen_uses_backslashreplace_error_handler — pins the errors= kwarg on the Popen construction shared by the sudo and Windows-as-user paths, which platform CI cannot all reach.

Every test was mutation-checked. Four mutants were applied to _subprocess.py and each is caught by at least one test, with the full suite green when restored:

Mutant Caught by
remove errors= (revert the fix) 8 tests, incl. reader-survival
errors="replace" 7 tests (byte values must be preserved, not U+FFFD)
errors="ignore" 7 tests (bytes must not be dropped)
force encoding="ascii" 3 tests, incl. the valid-UTF-8 negative control

Full suite: 911 passed on macOS (the 8 failures on my machine are pre-existing and reproduce identically on unmodified mainline; they need a bare python on PATH or target-user env vars). black --check, ruff check, and mypy all pass.

Was this change documented?

Yes: the new errors= line carries a comment explaining the failure mode it prevents and why backslashreplace was chosen; each test documents what it pins.

Is this a breaking change?

No. The public API is unchanged. The only observable difference is that output which previously crashed the log reader (and was silently dropped) is now logged with invalid bytes escaped.

Does this change impact security?

No new files, directories, or permissions. Log content can now include escaped byte values that were previously dropped; these come from the same process output that is already logged.

Cross-port to openjd-rs

The Rust engine reads raw bytes and decodes with String::from_utf8_lossy, so it does not have the crash, but it collapses undecodable bytes to U+FFFD instead of preserving them; the issue tracks aligning it with the backslashreplace semantics.


By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

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>
@leongdl

leongdl commented Aug 3, 2026

Copy link
Copy Markdown
Contributor Author

Cross-reference: the openjd-rs parity change tracked by openjd-rs#296 is now open as openjd-rs#298, so both implementations land the same backslashreplace behavior.

@mwiebe
mwiebe merged commit e2e60d3 into mainline Aug 4, 2026
25 checks passed
@mwiebe
mwiebe deleted the fix/subprocess-non-utf8-output branch August 4, 2026 17:46
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants