Skip to content

Keep stdout clean on a stdio protocol channel

Problem

A tool server speaking a line-oriented RPC protocol over stdio shares that channel with every library in the process. One dependency that writes a banner, a deprecation notice or a progress bar to stdout corrupts the protocol stream.

The failure does not look like a logging problem. The client fails to parse a frame and terminates the subprocess, which surfaces to the caller as a bare non-zero exit with no message. Nothing in the traceback mentions stdout, and the library that printed is usually not one you called directly.

Technique

Redirect logging to stderr before any other import.

# first executable lines in the server entrypoint
import logging, sys
logging.basicConfig(stream=sys.stderr)
for handler in logging.root.handlers:
    handler.setStream(sys.stderr)
# structured-logging libraries need their own redirect here too

import everything_else            # only now

Import order is the whole technique. Configuring logging after importing a library is too late: the library captured or configured a stdout handler at import time, and reconfiguring the root logger afterwards does not reclaim it.

When it applies

Any process whose stdout is a protocol channel: stdio-based tool servers, language servers, editor plugins, CLI filters in a pipeline, anything wrapped by a parent that parses its output.

When it does NOT apply

A service speaking over a socket or HTTP has a separate channel already, and this adds nothing. Nor does it help where the corruption is your own deliberate output — if the program is printing protocol frames and diagnostics to the same stream by design, the fix is to separate them, not to move logging.

It is also not a substitute for capturing stderr. Redirecting logging there makes the protocol safe; it does not make the diagnostics visible.

Evidence

A documentation-generation pipeline lost its tool subprocess intermittently with exit code 1 and no diagnostic. The cause was a transitive dependency printing to stdout during initialisation, corrupting the first RPC frame.

The reason it took so long to find is worth recording: the crash was attributed to the agent runtime for weeks, because the runtime was what reported it. The process that actually broke the contract never appeared in any stack trace.

See also