|
| 1 | +"""Tests for what a headless render says while it is running. |
| 2 | +
|
| 3 | +Headless suppresses Rich output and attaches no TUI handler, so before this the only |
| 4 | +sink was the log file — the process was silent on stdout for its entire run and a |
| 5 | +CI job could not tell a render wedged for hours from a healthy one until the file was |
| 6 | +collected at the end. One four-hour render produced 858 lines, all of them in its first |
| 7 | +two minutes. |
| 8 | +
|
| 9 | +The second half of this file guards the hazard that adding a second handler exposes: |
| 10 | +one record is handed to every handler in turn, so a formatter that rewrites |
| 11 | +`record.msg` in place corrupts the output of the handlers after it. |
| 12 | +""" |
| 13 | + |
| 14 | +import logging |
| 15 | +import sys |
| 16 | +from unittest.mock import MagicMock |
| 17 | + |
| 18 | +import pytest |
| 19 | + |
| 20 | +from plain2code import setup_logging |
| 21 | +from plain2code_console import console |
| 22 | +from plain2code_logger import ( |
| 23 | + LOGGER_NAME, |
| 24 | + ElapsedTimeFormatter, |
| 25 | + IndentedFormatter, |
| 26 | + stop_narrating, |
| 27 | +) |
| 28 | + |
| 29 | + |
| 30 | +@pytest.fixture |
| 31 | +def run_state(): |
| 32 | + state = MagicMock() |
| 33 | + state.get_live_render_time.return_value = 3661 # 01:01:01 |
| 34 | + return state |
| 35 | + |
| 36 | + |
| 37 | +def record(message, args=None): |
| 38 | + return logging.LogRecord( |
| 39 | + name="codeplain", |
| 40 | + level=logging.INFO, |
| 41 | + pathname=__file__, |
| 42 | + lineno=1, |
| 43 | + msg=message, |
| 44 | + args=args, |
| 45 | + exc_info=None, |
| 46 | + ) |
| 47 | + |
| 48 | + |
| 49 | +def test_the_elapsed_formatter_stamps_the_render_time(run_state): |
| 50 | + assert ElapsedTimeFormatter(run_state).format(record("hello")) == "[01:01:01] INFO codeplain: hello" |
| 51 | + |
| 52 | + |
| 53 | +def test_continuation_lines_are_indented_past_the_timestamp(run_state): |
| 54 | + formatted = ElapsedTimeFormatter(run_state).format(record("first\nsecond")) |
| 55 | + |
| 56 | + assert formatted == "[01:01:01] INFO codeplain: first\n second" |
| 57 | + |
| 58 | + |
| 59 | +def test_formatting_twice_does_not_indent_twice(run_state): |
| 60 | + """Two handlers share one record. Formatting must be idempotent from the record's |
| 61 | + point of view, or the file log inherits the stdout log's indentation.""" |
| 62 | + formatter = ElapsedTimeFormatter(run_state) |
| 63 | + entry = record("first\nsecond") |
| 64 | + |
| 65 | + first_pass = formatter.format(entry) |
| 66 | + second_pass = formatter.format(entry) |
| 67 | + |
| 68 | + assert first_pass == second_pass |
| 69 | + |
| 70 | + |
| 71 | +def test_two_different_formatters_do_not_corrupt_each_other(run_state): |
| 72 | + """The real pairing in a headless render that also logs to a file.""" |
| 73 | + entry = record("first\nsecond") |
| 74 | + |
| 75 | + IndentedFormatter("%(levelname)s:%(name)s:%(message)s").format(entry) |
| 76 | + elapsed = ElapsedTimeFormatter(run_state).format(entry) |
| 77 | + |
| 78 | + assert elapsed == "[01:01:01] INFO codeplain: first\n second" |
| 79 | + |
| 80 | + |
| 81 | +def test_the_indented_formatter_leaves_the_record_alone(run_state): |
| 82 | + entry = record("first\nsecond") |
| 83 | + |
| 84 | + IndentedFormatter("%(levelname)s:%(name)s:%(message)s").format(entry) |
| 85 | + |
| 86 | + assert entry.msg == "first\nsecond" |
| 87 | + |
| 88 | + |
| 89 | +def test_arguments_are_interpolated_exactly_once(run_state): |
| 90 | + """The copy carries an already-interpolated message, so its args must be cleared — |
| 91 | + otherwise the parent formatter interpolates a second time and raises.""" |
| 92 | + assert ElapsedTimeFormatter(run_state).format(record("value is %s", ("x",))).endswith("value is x") |
| 93 | + |
| 94 | + |
| 95 | +@pytest.fixture |
| 96 | +def configured_handlers(run_state): |
| 97 | + """setup_logging mutates the process-wide "codeplain" logger; restore it after.""" |
| 98 | + logger = logging.getLogger(LOGGER_NAME) |
| 99 | + saved_handlers, saved_level = list(logger.handlers), logger.level |
| 100 | + |
| 101 | + def configure(headless): |
| 102 | + logger.handlers = [] |
| 103 | + args = MagicMock() |
| 104 | + args.verbose = False |
| 105 | + args.logging_config_path = None |
| 106 | + setup_logging(args, MagicMock(), run_state, log_to_file=False, log_file_path="", headless=headless) |
| 107 | + return logger.handlers |
| 108 | + |
| 109 | + yield configure |
| 110 | + |
| 111 | + logger.handlers, logger.level = saved_handlers, saved_level |
| 112 | + |
| 113 | + |
| 114 | +def stdout_handlers(handlers): |
| 115 | + return [h for h in handlers if type(h) is logging.StreamHandler and h.stream is sys.stdout] |
| 116 | + |
| 117 | + |
| 118 | +def test_a_headless_render_narrates_to_stdout(configured_handlers): |
| 119 | + assert len(stdout_handlers(configured_handlers(headless=True))) == 1 |
| 120 | + |
| 121 | + |
| 122 | +def test_the_stdout_handler_carries_the_elapsed_time_format(configured_handlers): |
| 123 | + """It has to be readable as a render log, not just present.""" |
| 124 | + handler = stdout_handlers(configured_handlers(headless=True))[0] |
| 125 | + |
| 126 | + assert isinstance(handler.formatter, ElapsedTimeFormatter) |
| 127 | + |
| 128 | + |
| 129 | +def test_an_interactive_render_does_not_duplicate_output_on_stdout(configured_handlers): |
| 130 | + """The TUI already draws the log; a second copy on stdout would fight it for the |
| 131 | + terminal.""" |
| 132 | + assert stdout_handlers(configured_handlers(headless=False)) == [] |
| 133 | + |
| 134 | + |
| 135 | +def test_the_formatter_survives_a_run_state_that_cannot_report_time(): |
| 136 | + """A record can be logged before the render clock exists; it must still be readable.""" |
| 137 | + broken = MagicMock() |
| 138 | + broken.get_live_render_time.side_effect = RuntimeError("no clock yet") |
| 139 | + |
| 140 | + assert ElapsedTimeFormatter(broken).format(record("hello")) == "[00:00:00] INFO codeplain: hello" |
| 141 | + |
| 142 | + |
| 143 | +@pytest.fixture |
| 144 | +def quiet_console(): |
| 145 | + """Headless suppresses Rich output, so stdout carries the log sink and nothing else.""" |
| 146 | + saved, console.quiet = console.quiet, True |
| 147 | + yield |
| 148 | + console.quiet = saved |
| 149 | + |
| 150 | + |
| 151 | +def test_specification_text_reaches_the_stdout_sink(configured_handlers, quiet_console, capsys): |
| 152 | + """The narration carries the functional requirement, like every other record. |
| 153 | +
|
| 154 | + These logs are the user's own, on the user's own machine, and the specification is |
| 155 | + theirs. Withholding it here buys nothing and costs them the detail that says which |
| 156 | + requirement a wedged render is stuck on. The rule this sink was briefly written |
| 157 | + against is about what *we* retain - see the Sentry and analytics scrubbers, which |
| 158 | + keep specification text out of anything leaving the machine.""" |
| 159 | + configured_handlers(headless=True) |
| 160 | + |
| 161 | + console.info("Rendering functionality 3: the user's whole functional requirement") |
| 162 | + console.info("Running unit tests.") |
| 163 | + |
| 164 | + printed = capsys.readouterr().out |
| 165 | + assert "whole functional requirement" in printed |
| 166 | + assert "Running unit tests." in printed |
| 167 | + |
| 168 | + |
| 169 | +def test_narration_stops_before_the_exit_summary(configured_handlers, quiet_console, capsys): |
| 170 | + """The summary bypasses logging, so a still-attached sink reports a failure twice.""" |
| 171 | + configured_handlers(headless=True) |
| 172 | + capsys.readouterr() |
| 173 | + |
| 174 | + stop_narrating() |
| 175 | + console.info("this arrives after the render is over") |
| 176 | + |
| 177 | + assert "after the render is over" not in capsys.readouterr().out |
0 commit comments