From 570cd1b01c39d9f38883038c7145415cce739660 Mon Sep 17 00:00:00 2001 From: Goran Dodig Date: Thu, 20 Aug 2026 07:21:44 +0200 Subject: [PATCH] Log to stdout in headless mode Headless suppresses Rich output and attaches no TUI handler, so the only sink was the log file. The process printed nothing for its entire run, and a CI job collects that file only after the render ends, so a wedged render and a healthy one are indistinguishable for as long as it matters. A stdout handler now carries the same records with the same formatting. StreamHandler flushes per record, so they arrive as they happen. Attaching a second handler exposed a bug in the formatters. One record is passed to every handler in turn, and both formatters rewrote record.msg in place, so each re-indented the continuation lines the other had already indented. They now format a copy. --- docs/plain2code_cli.md | 6 +- plain2code.py | 14 +++ plain2code_arguments.py | 4 +- plain2code_logger.py | 52 +++++++--- tests/test_headless_logging.py | 177 +++++++++++++++++++++++++++++++++ 5 files changed, 233 insertions(+), 20 deletions(-) create mode 100644 tests/test_headless_logging.py diff --git a/docs/plain2code_cli.md b/docs/plain2code_cli.md index d737597c..01764ad8 100644 --- a/docs/plain2code_cli.md +++ b/docs/plain2code_cli.md @@ -118,9 +118,9 @@ options: If set, render the state machine graph. --logging-config-path LOGGING_CONFIG_PATH Path to the logging configuration file. - --headless Run in headless mode: no TUI, no terminal output - except a single render-started message. All logs are - written to the log file. + --headless Run in headless mode: no TUI. Progress is written to + the log file and streamed to stdout as it happens; the + specification text itself stays in the log file only. --status Display account status including user information, API key label, and rendering credits. Does not render any code. diff --git a/plain2code.py b/plain2code.py index 3c30deda..d6c08223 100644 --- a/plain2code.py +++ b/plain2code.py @@ -44,11 +44,13 @@ ) from plain2code_logger import ( LOGGER_NAME, + NARRATION_HANDLER_NAME, CrashLogHandler, ElapsedTimeFormatter, IndentedFormatter, LoggingHandler, dump_crash_logs, + stop_narrating, ) from plain2code_state import RunState from plain2code_telemetry import capture_crash, initialize_telemetry @@ -125,6 +127,17 @@ def setup_logging( handler = LoggingHandler(event_bus, run_state) handler.setFormatter(formatter) root_logger.addHandler(handler) + else: + # Headless has no TUI to narrate the render and suppresses Rich output, so + # without this the process says nothing on stdout for its entire run: a CI job + # cannot distinguish a render wedged for hours from a healthy one until the + # log file is collected at the end. StreamHandler flushes + # per record, so these arrive as they happen. + stdout_handler = logging.StreamHandler(sys.stdout) + stdout_handler.setFormatter(file_formatter) + stdout_handler.setLevel(configured_log_level) + stdout_handler.set_name(NARRATION_HANDLER_NAME) + root_logger.addHandler(stdout_handler) if log_to_file: try: @@ -423,6 +436,7 @@ def main(): # noqa: C901 if exc_info: dump_crash_logs(args, run_state) capture_crash(exc_info, run_state, args) + stop_narrating() print_exit_summary( run_state, args.filename, diff --git a/plain2code_arguments.py b/plain2code_arguments.py index c4b19ee6..679d1fca 100644 --- a/plain2code_arguments.py +++ b/plain2code_arguments.py @@ -424,8 +424,8 @@ def create_parser(): "--headless", action="store_true", default=False, - help="Run in headless mode: no TUI, no terminal output except a single render-started message. " - "All logs are written to the log file.", + help="Run in headless mode: no TUI. Progress is written to the log file and streamed " + "to stdout as it happens; the specification text itself stays in the log file only.", ) parser.add_argument( diff --git a/plain2code_logger.py b/plain2code_logger.py index 0203b81f..69da31dd 100644 --- a/plain2code_logger.py +++ b/plain2code_logger.py @@ -1,3 +1,4 @@ +import copy import logging from event_bus import EventBus @@ -17,18 +18,28 @@ FILE_LOG_DATE_FORMAT = "%Y-%m-%d %H:%M:%S" +def _with_indented_message(record, indent: str): + """A copy of the record whose continuation lines are indented. + + One record is handed to every attached handler in turn, so a formatter that + rewrites `record.msg` in place is rewriting it for the handlers that come after + it too — a headless render logging to both stdout and a file would indent each + continuation line twice, once per formatter. Copying keeps each handler's + formatting local to that handler. + """ + indented = copy.copy(record) + indented.msg = record.getMessage().replace("\n", "\n" + indent) + indented.args = None # getMessage() already interpolated them into msg + return indented + + class IndentedFormatter(logging.Formatter): def __init__(self, fmt=None, datefmt=None, indent=16): super().__init__(fmt=fmt, datefmt=datefmt) self._indent = " " * indent def format(self, record): - original_message = record.getMessage() - - modified_message = original_message.replace("\n", "\n" + self._indent) - - record.msg = modified_message - return super().format(record) + return super().format(_with_indented_message(record, self._indent)) class ElapsedTimeFormatter(logging.Formatter): @@ -51,16 +62,11 @@ def format(self, record): seconds = offset_seconds % 60 elapsed_time = f"[{hours:02d}:{minutes:02d}:{seconds:02d}]" - # Add elapsed_time to the record so it can be used in the format string - record.elapsed_time = elapsed_time - - # Handle multi-line messages with proper indentation - original_message = record.getMessage() - indent = " " * len(elapsed_time + " ") - modified_message = original_message.replace("\n", "\n" + indent) - record.msg = modified_message + # Continuation lines line up under the message, past the timestamp column. + indented = _with_indented_message(record, " " * len(elapsed_time + " ")) + indented.elapsed_time = elapsed_time - return super().format(record) + return super().format(indented) class LoggingHandler(logging.Handler): @@ -132,3 +138,19 @@ def dump_crash_logs(args, run_state: RunState, formatter=None): if crash_handler and args.filename: crash_handler.dump_to_file(args.log_file_name, formatter) + + +NARRATION_HANDLER_NAME = "headless-narration" + + +def stop_narrating() -> None: + """Detaches the headless stdout sink once the render is over. + + The summary prints with Rich and bypasses logging, so a still-attached sink reports + every failure twice. + """ + root_logger = logging.getLogger(LOGGER_NAME) + for handler in list(root_logger.handlers): + if handler.get_name() == NARRATION_HANDLER_NAME: + root_logger.removeHandler(handler) + handler.close() diff --git a/tests/test_headless_logging.py b/tests/test_headless_logging.py new file mode 100644 index 00000000..0552fbb9 --- /dev/null +++ b/tests/test_headless_logging.py @@ -0,0 +1,177 @@ +"""Tests for what a headless render says while it is running. + +Headless suppresses Rich output and attaches no TUI handler, so before this the only +sink was the log file — the process was silent on stdout for its entire run and a +CI job could not tell a render wedged for hours from a healthy one until the file was +collected at the end. One four-hour render produced 858 lines, all of them in its first +two minutes. + +The second half of this file guards the hazard that adding a second handler exposes: +one record is handed to every handler in turn, so a formatter that rewrites +`record.msg` in place corrupts the output of the handlers after it. +""" + +import logging +import sys +from unittest.mock import MagicMock + +import pytest + +from plain2code import setup_logging +from plain2code_console import console +from plain2code_logger import ( + LOGGER_NAME, + ElapsedTimeFormatter, + IndentedFormatter, + stop_narrating, +) + + +@pytest.fixture +def run_state(): + state = MagicMock() + state.get_live_render_time.return_value = 3661 # 01:01:01 + return state + + +def record(message, args=None): + return logging.LogRecord( + name="codeplain", + level=logging.INFO, + pathname=__file__, + lineno=1, + msg=message, + args=args, + exc_info=None, + ) + + +def test_the_elapsed_formatter_stamps_the_render_time(run_state): + assert ElapsedTimeFormatter(run_state).format(record("hello")) == "[01:01:01] INFO codeplain: hello" + + +def test_continuation_lines_are_indented_past_the_timestamp(run_state): + formatted = ElapsedTimeFormatter(run_state).format(record("first\nsecond")) + + assert formatted == "[01:01:01] INFO codeplain: first\n second" + + +def test_formatting_twice_does_not_indent_twice(run_state): + """Two handlers share one record. Formatting must be idempotent from the record's + point of view, or the file log inherits the stdout log's indentation.""" + formatter = ElapsedTimeFormatter(run_state) + entry = record("first\nsecond") + + first_pass = formatter.format(entry) + second_pass = formatter.format(entry) + + assert first_pass == second_pass + + +def test_two_different_formatters_do_not_corrupt_each_other(run_state): + """The real pairing in a headless render that also logs to a file.""" + entry = record("first\nsecond") + + IndentedFormatter("%(levelname)s:%(name)s:%(message)s").format(entry) + elapsed = ElapsedTimeFormatter(run_state).format(entry) + + assert elapsed == "[01:01:01] INFO codeplain: first\n second" + + +def test_the_indented_formatter_leaves_the_record_alone(run_state): + entry = record("first\nsecond") + + IndentedFormatter("%(levelname)s:%(name)s:%(message)s").format(entry) + + assert entry.msg == "first\nsecond" + + +def test_arguments_are_interpolated_exactly_once(run_state): + """The copy carries an already-interpolated message, so its args must be cleared — + otherwise the parent formatter interpolates a second time and raises.""" + assert ElapsedTimeFormatter(run_state).format(record("value is %s", ("x",))).endswith("value is x") + + +@pytest.fixture +def configured_handlers(run_state): + """setup_logging mutates the process-wide "codeplain" logger; restore it after.""" + logger = logging.getLogger(LOGGER_NAME) + saved_handlers, saved_level = list(logger.handlers), logger.level + + def configure(headless): + logger.handlers = [] + args = MagicMock() + args.verbose = False + args.logging_config_path = None + setup_logging(args, MagicMock(), run_state, log_to_file=False, log_file_path="", headless=headless) + return logger.handlers + + yield configure + + logger.handlers, logger.level = saved_handlers, saved_level + + +def stdout_handlers(handlers): + return [h for h in handlers if type(h) is logging.StreamHandler and h.stream is sys.stdout] + + +def test_a_headless_render_narrates_to_stdout(configured_handlers): + assert len(stdout_handlers(configured_handlers(headless=True))) == 1 + + +def test_the_stdout_handler_carries_the_elapsed_time_format(configured_handlers): + """It has to be readable as a render log, not just present.""" + handler = stdout_handlers(configured_handlers(headless=True))[0] + + assert isinstance(handler.formatter, ElapsedTimeFormatter) + + +def test_an_interactive_render_does_not_duplicate_output_on_stdout(configured_handlers): + """The TUI already draws the log; a second copy on stdout would fight it for the + terminal.""" + assert stdout_handlers(configured_handlers(headless=False)) == [] + + +def test_the_formatter_survives_a_run_state_that_cannot_report_time(): + """A record can be logged before the render clock exists; it must still be readable.""" + broken = MagicMock() + broken.get_live_render_time.side_effect = RuntimeError("no clock yet") + + assert ElapsedTimeFormatter(broken).format(record("hello")) == "[00:00:00] INFO codeplain: hello" + + +@pytest.fixture +def quiet_console(): + """Headless suppresses Rich output, so stdout carries the log sink and nothing else.""" + saved, console.quiet = console.quiet, True + yield + console.quiet = saved + + +def test_specification_text_reaches_the_stdout_sink(configured_handlers, quiet_console, capsys): + """The narration carries the functional requirement, like every other record. + + These logs are the user's own, on the user's own machine, and the specification is + theirs. Withholding it here buys nothing and costs them the detail that says which + requirement a wedged render is stuck on. The rule this sink was briefly written + against is about what *we* retain - see the Sentry and analytics scrubbers, which + keep specification text out of anything leaving the machine.""" + configured_handlers(headless=True) + + console.info("Rendering functionality 3: the user's whole functional requirement") + console.info("Running unit tests.") + + printed = capsys.readouterr().out + assert "whole functional requirement" in printed + assert "Running unit tests." in printed + + +def test_narration_stops_before_the_exit_summary(configured_handlers, quiet_console, capsys): + """The summary bypasses logging, so a still-attached sink reports a failure twice.""" + configured_handlers(headless=True) + capsys.readouterr() + + stop_narrating() + console.info("this arrives after the render is over") + + assert "after the render is over" not in capsys.readouterr().out