fix(logging): resolve sys.stderr at emit time so log records stop scribbling over the prompt

[Ken Chau (kenotron-ms)]

The defect

_configure_console_logging() installs the process's only root logging handler, and it did so with a stock logging.StreamHandler(sys.stderr) (main.py:229). CPython binds that stream eagerly:

# logging/__init__.py
def __init__(self, stream=None):
    if stream is None:
        stream = sys.stderr
    self.stream = stream          # captured here, once

def emit(self, record):
    stream = self.stream          # ...and written to here, forever
    stream.write(msg + self.terminator)

main() calls _configure_console_logging() at process entry (main.py:4621), long before any patch_stdout() context exists. And patch_stdout() works by rebinding the names:

# prompt_toolkit/patch_stdout.py (3.0.52)
sys.stdout = cast(TextIO, proxy)
sys.stderr = cast(TextIO, proxy)

Rebinding a name cannot reach an object something else already captured. So every logger.warning(...) in the process wrote straight past the proxy, into a terminal prompt_toolkit was actively rendering into — the text landed at the cursor, on top of the input box, with none of the erase/redraw that run_in_terminal exists to provide.

Rich never had this bug, and the reason is already recorded in this repo as a load-bearing assumption — steering_input.py:10-14:

Rich's Console.file property reads sys.stdout dynamically (self._file is None by default in the singleton created at module import), so the patched proxy is picked up at write time automatically — no changes to console.py are required.

That is exactly right (rich/console.py:762). It was simply never extended to logging. This PR extends it.

Why there is no safe window

A prompt_toolkit Application is live essentially all the time in an interactive session:

Where	What holds the terminal
main.py:3853	patch_stdout(raw=True) around the whole turn
main.py:3854 -> steering_input.py:392	SteeringInputManager.run() pins a prompt at the bottom for the turn's entire duration
main.py:4014	patch_stdout() around prompt_async() between turns

There is no gap to land a log record in. Nor is there any handler-level mitigation to lean on: logging.disable, NullHandler, removeHandler, QueueHandler, MemoryHandler are 0 hits each across amplifier_app_cli/ and tests/, and the two existing filters act on record content (ui/log_filter.py:32) and exception metadata (main.py:235) — neither touches stream binding.

The fix

_LateBoundStderrHandler(logging.StreamHandler) makes stream a property that resolves sys.stderr on every access. Five lines of behavior; the rest is the docstring explaining why.

The setter is required, not decorative. StreamHandler.__init__ assigns self.stream, and setStream() assigns it again — a bare read-only property raises AttributeError during construction. The setter distinguishes the two cases:

assignment	behavior
the current sys.stderr (all __init__ does)	ignored — stays late-bound
anything else (setStream(open(...)))	pinned — stock StreamHandler semantics preserved
None	resets to late-bound

setLevel, the existing _suppress_traceback filter and LLMErrorLogFilter are untouched — they act on records, not streams. No FileHandler path is affected: this repo constructs exactly one logging handler anywhere (main.py:229) and defines no other logging.Handler subclass.

This fixes every logger.warning in the process at once, not one message.

Evidence: real pty, raw bytes

A mock, a StringIO, or a captured-stderr assertion passes identically on the broken and the fixed build — both variants log the same string, at the same level, through the same filters. The only thing that differs is where the bytes land relative to the prompt render, which is observable only on a real terminal. tests/test_log_over_prompt_integration.py drives a real pty, puts a live prompt_async() prompt up, and emits the warning from a background asyncio task (matching the real trigger — see below).

Measured on Linux, prompt_toolkit 3.0.52 — bytes between the completed prompt render and the log text:

stock   ...PROMPTBOX>\x1b[10D\x1b[11C\x1b[?7h\x1b[0m\x1b[?12l\x1b[?25h
        WARNTEXT_...                       <- at the cursor. no prologue.
        \x1b[11D\x1b[J...\x1b[?2004l       <- teardown only afterwards

fixed   ...PROMPTBOX>\x1b[10D\x1b[11C\x1b[?7h\x1b[0m\x1b[?12l\x1b[?25h
        \x1b[11D\x1b[J\x1b[0m\x1b[?7h\x1b[?2004l\x1b[?7h   <- erase prologue
        WARNTEXT_...                       <- clean line
        \x1b[?2004h...PROMPTBOX>...        <- prompt redrawn below

The tests are not vacuous — shown by mutation

mutation applied	which tests fail
make the stream property eager again (pin at __init__)	test_late_bound_handler_routes_log_text_through_run_in_terminal, test_late_bound_handler_is_transparent_without_patch_stdout
revert main.py:229 to logging.StreamHandler(sys.stderr)	test_configure_console_logging_installs_the_late_bound_handler
none (this branch)	5 passed

The wiring test exists specifically because the pty tests construct the handler directly and would keep passing if _configure_console_logging() regressed.

test_stock_streamhandler_injects_log_text_at_the_cursor deliberately asserts the broken behavior. If CPython or prompt_toolkit ever changes such that an eagerly-bound handler stops corrupting the prompt, that test fails and this fix gets re-evaluated instead of cargo-culted.

Evidence: isolated environment, real installed wheel

Verified in an isolated Incus container (Digital Twin Universe dtu-30bb4c32, since destroyed) running Amplifier installed the way a user installs it — uv tool install git+https://github.com/microsoft/amplifier — with a URL rewrite pointing the amplifier-app-cli dependency at this branch. Not an editable install, not the working tree:

$ amplifier --version
amplifier, version 2026.09.04-0d00796 (core 1.6.1)

$ cat .../site-packages/amplifier_app_cli-*.dist-info/direct_url.json
{"url":"https://github.com/microsoft/amplifier-app-cli",
 "vcs_info":{"vcs":"git","commit_id":"0d0079699477bb0b8161e5d68f35b4709cc0bde2",
             "requested_revision":"main"}}

FILE            : /root/.local/share/uv/tools/amplifier/lib/python3.12/site-packages/amplifier_app_cli/main.py
HAS CLASS       : True
IS StreamHandler: True
stream is prop  : True
HANDLER CTOR    : ['handler = _LateBoundStderrHandler()']

A real two-turn interactive amplifier run --mode chat session in that container, configured with two different-vendor providers (anthropic at the lowest numeric priority, so it answers the session) and routing.matrix: openai — which makes hooks-session-naming emit its genuine cross-provider refusal on turn 2. Raw bytes off the pty, at the moment the warning lands:

\x1b[?2004h                      <- prompt_toolkit Application live
\x1b[?25l...\x1b[J...\r\r\n
\x1b[0;32;1m>\x08\x1b[2C          <- input box drawn
\x1b[?7h\x1b[0m\x1b[?12l\x1b[?25h <- cursor shown, render complete
                                    (this is where the old build injected)
\x1b[2D\x1b[A\x1b[J               <- ERASE PROLOGUE: left, up, erase-down
\x1b[0m\x1b[?7h\x1b[?2004l\x1b[?7h <- app suspended for run_in_terminal
model_role 'fast' resolved to provider 'openai', but it is a different
provider vendor than the one answering this session. REFUSING to borrow
it: session naming will run on 'anthropic', ...
\r\n
\x1b[?2004h...\x1b[J...>\x08\x1b[2C  <- prompt redrawn below

The input box is not touched.

What this PR does not do

The session-naming warning is correct and is deliberately left alone. It reports a real routing misconfiguration — a model_role resolving to a foreign vendor, which naming correctly refuses to borrow — and hooks-session-naming is right to say so. Nothing here silences, filters, downgrades or defers it. That message's content is tracked separately as microsoft-amplifier/amplifier-support#511; this change is to the display path only, and it applies equally to every other logger.warning in the process.

Honest limits

• The A/B is within one build. Both variants in the pty tests and in the container run against the same installed artifact, constructing the stock and fixed handler side by side. The real interactive two-turn session was captured on the patched build only — capturing the same session on unpatched upstream would have required a second isolated environment, which was outside the resource budget for this work. The pre-fix byte signature is nonetheless captured directly, in the same container, from the same live prompt.
• The intended isolation used a local Gitea mirror, per the amplifier-user-sim profile pattern. Docker was unavailable on the verification host, so the rewrite target was a public fork whose main carried this exact commit — structurally the same mechanism (same url_rewrites mitmproxy path, same @main ref), different host.
• POSIX only. The pty tests are @pytest.mark.integration and pytest.skip on win32, matching every other pty test here and the deliberate matrix.os exclusion in ci.yml. The fix itself is platform-independent.
• One unrelated artifact appears in the capture: prompt_toolkit's own "your terminal doesn't support cursor position requests (CPR)" notice. That is not a logging record — Application.cpr_not_supported_callback writes it via self.output (already wrapped in run_in_terminal), and it only appears because the harness's pty does not answer CPR. Out of scope, unaffected either way.

Suite

	before (35ab604)	after
uv run pytest -q	1682 passed, 1 skipped, 13 deselected, 1 xfailed	1682 passed, 1 skipped, 18 deselected, 1 xfailed
uv run pytest -m integration -q	13 passed	18 passed
failure set	empty	empty (diffed, identical)

Pass count is unchanged; the 5 new tests are integration-marked, hence deselected 13 -> 18 by default and +5 under -m integration. ruff check amplifier_app_cli/main.py produces a byte-identical finding set before and after this change; ruff format would touch the same 4 lines on both (pre-existing debt, deliberately not swept into this diff). The new test file is ruff check and ruff format clean.