Skip to content

A warning logged during a turn prints above the prompt - #227

Merged
shoom1 merged 2 commits into
developfrom
fix/log-lines-above-prompt
Nov 4, 2026
Merged

shoom1 merged 2 commits into
developfrom
fix/log-lines-above-prompt

Conversation

@shoom1

@shoom1 shoom1 commented Nov 4, 2026

Copy link
Copy Markdown
Owner

A warning logged during a turn (here arxiv_rate_limited) was written straight to stderr. thinking-prompt doesn't capture stderr, so the line landed on the prompt line and left the screen garbled. Any of the framework's ~100 logger.warning calls could do this at the default log level.

What changes

  • Every logger writes to one stream, agentic_cli.logging.LOG_STREAM: structlog's PrintLoggerFactory and the standard library's StreamHandler. With no sink it writes to sys.stderr as before. log_lines_to(sink) sends each complete line to a sink instead, keeping each thread's partial line separate.
  • While the prompt runs, BaseCLIApp sets a sink, _log_lines_above_prompt. It hands each line to the event loop with call_soon_threadsafe, and the loop adds it to the session with add_rich, so it prints above the prompt. This works whichever thread logged it, including an executor thread with no access to the loop's context.
  • The warnings hook writes Python's other warnings to the same stream.
  • The format and the level are unchanged. When the prompt ends, lines go to stderr again.

Tests

  • A pty test runs the console app with its stderr sent to a file. A turn logs from the loop, from asyncio.to_thread, and from a plain thread, logs a standard-library warning, and raises a Python warning. On the old code all four lines went to the file (RED); now all four reach the screen and none reach the file.
  • A unit test checks that lines from any thread reach the session on the loop thread, and that stderr is used again afterwards. Mutation check: adding the line on the calling thread fails the test.
  • tests/conftest.py::logging_configured puts structlog's configuration back after a test, including its processors list. Without it, a second configure_logging() left capture_logs() tests later in the run capturing nothing.
  • Full offline suite: 6069 passed, plus the known empty-HOME artifact test_workspace_path_expansion.

configure_logging pointed structlog and the standard library's logging at
the process's stderr, and thinking-prompt does not capture stderr, so a log
line written mid-turn (arxiv_rate_limited, say) landed wherever the cursor
was, on the prompt line, and the next redraw did not know it was there: the
screen was left garbled. Any of the framework's warnings could do it.

Every logger now writes to one stream, agentic_cli.logging.LOG_STREAM:
stderr, or, while log_lines_to(sink) has set one, the sink, a complete line
a call (each thread's partial line kept apart). While the prompt runs,
BaseCLIApp sets a sink that hands each line to the event loop, which adds
it to the session (add_rich), so it prints above the prompt from whichever
thread logged it, an executor's included. The warnings hook writes Python's
warnings to the same stream. The format and the level are unchanged.

tests/conftest.py gains logging_configured: configure_logging() for one
test, with structlog's configuration put back after, its processors list
included, since a logger cached before keeps the old list and a later
capture_logs() then sees nothing from it.
… review follow-ups

- With stderr redirected (app 2>run.log), the session's log lines stay in
  the file: they are drawn above the prompt only when stderr is a terminal.
- A line logged on the event loop's thread is shown at once, so it keeps
  its place among the session's output (a turn's rate-limit warning before
  the error shown after it); lines from other threads are still handed to
  the loop. A line logged while one is shown goes to stderr: no recursion.
- structlog writes through a small lock-free logger (_LineLogger): its
  PrintLogger holds a lock while writing, so a log call made while a line
  is shown, inside that write, waited on it forever.
- A thread's unfinished line goes where its newline goes, and a process
  without a stderr drops lines instead of raising.
- Only Python's own warning hook is given LOG_STREAM; another (logging's
  captureWarnings) gets the warning's file unchanged.
- Tests: stderr on a second terminal (lines on the screen, none on it) and
  on a file (lines in it, none on the screen); a console's exit also checks
  its stderr for a traceback; the trafilatura test restores structlog.
@shoom1
shoom1 merged commit 9c5b89b into develop Nov 4, 2026
5 checks passed
@shoom1
shoom1 deleted the fix/log-lines-above-prompt branch November 4, 2026 11:40
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant