Skip to content

Commit 801d892

Browse files
committed
fix: end every render's log file with what the render did
The exit summary reaches the terminal through Rich's print, which never touches logging, so codeplain.log simply stopped at whatever happened to be logged last. An artifact that ends mid-render is indistinguishable from a process that died silently — originally noted for hycu's ConflictingRequirements abort, and it just blocked a real diagnosis: cli-password-manager in codeplain-tty-capability-run2 rendered to completion (22 functionalities, 48m54s) yet delivered a build with no CLI entry point, and the captured log ended at 01:29:57 mid-render with no record of how it finished. Adds a trailer written through the codeplain logger — so it lands in the log file — on every exit path, since print_exit_summary is called from a finally: [render-trailer] outcome=completed render_id=... functionalities=22 render_time_s=2934 generated_code=- spec=vault_cli...plain [render-trailer] error=<reason> (failed renders only) Handlers are flushed explicitly; a process exiting immediately after would otherwise defeat the point of writing it. The trailer doubles as a probe: because it is written unconditionally, a captured log *without* one proves the file was truncated rather than merely uninformative — which is the open question behind the missing entry point.
1 parent 462be01 commit 801d892

2 files changed

Lines changed: 148 additions & 0 deletions

File tree

cli_output/render_summary.py

Lines changed: 47 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,11 +1,19 @@
11
"""Render completion summary display."""
22

3+
import logging
34
from typing import Optional
45

6+
import plain2code_logger
57
from plain2code_console import console
68
from plain2code_state import RunState
79
from usage_summary import format_usage_summary
810

11+
logger = logging.getLogger(plain2code_logger.LOGGER_NAME)
12+
13+
# Marks the last line of a render's log file. Greppable on purpose: benchmark runs and
14+
# support artifacts are read by tooling before they are read by a person.
15+
RENDER_TRAILER_PREFIX = "[render-trailer]"
16+
917

1018
def print_exit_summary(
1119
run_state: RunState,
@@ -30,3 +38,42 @@ def print_exit_summary(
3038
if not run_state.render_succeeded and error_message:
3139
console.error(error_message)
3240
console.quiet = True
41+
42+
log_render_trailer(run_state, spec_filename, error_message)
43+
44+
45+
def log_render_trailer(
46+
run_state: RunState,
47+
spec_filename: str,
48+
error_message: Optional[str] = None,
49+
) -> None:
50+
"""Writes the render's outcome to the log file, as its last line.
51+
52+
The summary above reaches the terminal through Rich, which never touches logging, so
53+
a captured `codeplain.log` used to stop at whatever happened to be logged last —
54+
indistinguishable from a process that died silently. This ends every log with what
55+
the render did, and because it is written on every exit path a log *without* a
56+
trailer is itself evidence that the file was truncated.
57+
"""
58+
if run_state.render_succeeded:
59+
outcome = "completed"
60+
elif run_state.render_cancelled:
61+
outcome = "cancelled"
62+
else:
63+
outcome = "failed"
64+
65+
logger.info(
66+
f"{RENDER_TRAILER_PREFIX} outcome={outcome} "
67+
f"render_id={run_state.render_id} "
68+
f"functionalities={run_state.rendered_functionalities} "
69+
f"render_time_s={run_state.render_time_accumulated} "
70+
f"generated_code={run_state.render_generated_code_path or '-'} "
71+
f"spec={spec_filename}"
72+
)
73+
if outcome == "failed" and error_message:
74+
logger.error(f"{RENDER_TRAILER_PREFIX} error={error_message}")
75+
76+
# The process may exit immediately after this; an unflushed trailer would defeat the
77+
# purpose of writing one.
78+
for handler in logger.handlers:
79+
handler.flush()

tests/test_render_trailer.py

Lines changed: 101 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,101 @@
1+
"""Tests for the render trailer written to the log file.
2+
3+
The pretty exit summary goes out through Rich's print, which bypasses logging entirely,
4+
so `codeplain.log` simply stopped at whatever was logged last. An artifact that ends
5+
mid-render is indistinguishable from a process that died silently — and when
6+
cli-password-manager delivered a build with no entry point, that missing ending is
7+
exactly what blocked the diagnosis.
8+
9+
The trailer is therefore both the fix and a probe: it is the last thing written on every
10+
exit path, so an artifact without one proves the log was truncated rather than merely
11+
uninformative.
12+
"""
13+
14+
import logging
15+
from unittest.mock import MagicMock
16+
17+
import pytest
18+
19+
from cli_output.render_summary import RENDER_TRAILER_PREFIX, log_render_trailer
20+
21+
22+
def run_state(succeeded=True, cancelled=False):
23+
state = MagicMock()
24+
state.render_succeeded = succeeded
25+
state.render_cancelled = cancelled
26+
state.render_id = "5f1c25b7"
27+
state.rendered_functionalities = 22
28+
state.render_time_accumulated = 2934
29+
state.render_generated_code_path = "/int-plainlang-examples/cli-password-manager/dist/"
30+
return state
31+
32+
33+
@pytest.fixture
34+
def trailer_lines(caplog):
35+
caplog.set_level(logging.INFO, logger="codeplain")
36+
37+
def emit(state, spec="vault_cli.plain", error_message=None):
38+
caplog.clear()
39+
log_render_trailer(state, spec, error_message)
40+
return [record.getMessage() for record in caplog.records if RENDER_TRAILER_PREFIX in record.getMessage()]
41+
42+
return emit
43+
44+
45+
def test_a_completed_render_records_its_outcome(trailer_lines):
46+
lines = trailer_lines(run_state())
47+
48+
assert len(lines) == 1
49+
assert "outcome=completed" in lines[0]
50+
51+
52+
def test_the_trailer_carries_what_a_later_diagnosis_needs(trailer_lines):
53+
lines = trailer_lines(run_state())
54+
55+
assert "render_id=5f1c25b7" in lines[0]
56+
assert "functionalities=22" in lines[0]
57+
assert "render_time_s=2934" in lines[0]
58+
assert "generated_code=/int-plainlang-examples/cli-password-manager/dist/" in lines[0]
59+
60+
61+
def test_a_missing_generated_code_path_is_explicit(trailer_lines):
62+
"""The run that delivered no entry point reported this field empty; it has to be
63+
legible in the log rather than a blank gap."""
64+
state = run_state()
65+
state.render_generated_code_path = None
66+
67+
lines = trailer_lines(state)
68+
69+
assert "generated_code=-" in lines[0]
70+
71+
72+
def test_a_failed_render_records_the_reason(trailer_lines):
73+
lines = trailer_lines(run_state(succeeded=False), error_message="Conformance tests could not be fixed.")
74+
75+
assert any("outcome=failed" in line for line in lines)
76+
assert any("error=Conformance tests could not be fixed." in line for line in lines)
77+
78+
79+
def test_a_cancelled_render_is_not_reported_as_failed(trailer_lines):
80+
lines = trailer_lines(run_state(succeeded=False, cancelled=True))
81+
82+
assert "outcome=cancelled" in lines[0]
83+
84+
85+
def test_a_failure_without_a_message_still_ends_the_log(trailer_lines):
86+
lines = trailer_lines(run_state(succeeded=False))
87+
88+
assert any("outcome=failed" in line for line in lines)
89+
90+
91+
def test_the_trailer_is_flushed_so_it_survives_an_abrupt_exit():
92+
handler = MagicMock()
93+
handler.level = logging.NOTSET # logging compares record.levelno against this
94+
logger = logging.getLogger("codeplain")
95+
logger.addHandler(handler)
96+
try:
97+
log_render_trailer(run_state(), "vault_cli.plain")
98+
finally:
99+
logger.removeHandler(handler)
100+
101+
assert handler.flush.called

0 commit comments

Comments
 (0)