Skip to content

Commit 462be01

Browse files
committed
feat: instrument the fix loops — count attempts, detect a stuck loop
Every loss in the retry5-era benchmarks was a fix loop spending its whole budget re-patching one file against one unchanging failure: cli-password-manager 20 conformance attempts on vault_cli FRID 2, loglens the same on loglens_cli FRID 2, python_tui 16+ unit-test attempts on FRID 1. The loop could not tell it was stuck, and the only externally visible outcome was "did the render abort" — a rare binary event, too coarse to compare configurations against. Adds per-(module, FRID, loop) accounting for both loops. Each script run is recorded with a fingerprint of its failure output, normalised past the tokens that differ between two runs of the same failure (renderer temp paths, durations, addresses) while leaving genuinely different failures apart. Consecutive identical fingerprints are counted, and three in a row are reported as they happen rather than at exhaustion. Counts are emitted as a greppable line per FRID: [fix-loop] module=vault_cli frid=2 conformance=20 conformance_failed=20 max_repeat=20 on FRID completion, and for the whole render on both the completed and the failed path — the FRID that exhausted its budget never reaches FinishFunctionalRequirement, and its numbers are the ones worth having. This is measurement, not behaviour: nothing here changes what the renderer produces, so results stay comparable across the change. It makes iterations-to-convergence observable per FRID, which is what a rare binary outcome could not give: a near-continuous measure that says something after a single run. Switching strategy on detection (instrument/diagnose/delete rather than re-patch) is deliberately not included — that would change renderer output and break comparability with the runs in flight.
1 parent a6fb7ba commit 462be01

9 files changed

Lines changed: 375 additions & 0 deletions

render_machine/actions/exit_with_error.py

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,12 @@ class ExitWithError(BaseAction):
1212
def execute(self, render_context: RenderContext, previous_action_payload: Any | None):
1313
console.error(self._error_message(render_context, previous_action_payload))
1414

15+
# The FRID that failed is the one whose fix-loop counts matter most, and it never
16+
# reaches FinishFunctionalRequirement — so the whole render's counts are reported
17+
# here rather than lost with it.
18+
for summary in render_context.fix_loop_metrics.render_summary():
19+
console.info(summary)
20+
1521
render_context.codeplain_api.fail_functional_requirement(
1622
render_context.frid_context.frid,
1723
module_name=render_context.module_name,

render_machine/actions/finish_functional_requirement.py

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,13 +1,16 @@
11
from typing import Any
22

33
from render_machine.actions.commit_implementation_code_changes import CommitImplementationCodeChanges
4+
from render_machine.fix_loop_metrics import report_frid_fix_loop_summary
45
from render_machine.render_context import RenderContext
56

67

78
class FinishFunctionalRequirement(CommitImplementationCodeChanges):
89
SUCCESSFUL_OUTCOME = "functional_requirement_finished"
910

1011
def execute(self, render_context: RenderContext, previous_action_payload: Any | None):
12+
report_frid_fix_loop_summary(render_context, render_context.frid_context.frid)
13+
1114
render_context.plain_module.update_frid_in_module_metadata(render_context.frid_context.frid)
1215

1316
super().execute(render_context, previous_action_payload)

render_machine/actions/run_conformance_tests.py

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
import render_machine.render_utils as render_utils
55
from plain2code_console import console
66
from render_machine.actions.base_action import BaseAction
7+
from render_machine.fix_loop_metrics import CONFORMANCE_LOOP, report_fix_loop_attempt
78
from render_machine.platform_test_runtime import platform_test_runtime_available
89
from render_machine.render_context import RenderContext
910
from render_machine.render_types import RenderError
@@ -63,6 +64,14 @@ def execute(self, render_context: RenderContext, _previous_action_payload: Any |
6364
render_context, exit_code, conformance_tests_issue
6465
)
6566

67+
report_fix_loop_attempt(
68+
render_context,
69+
loop=CONFORMANCE_LOOP,
70+
frid=render_context.conformance_tests_running_context.current_testing_frid,
71+
passed=exit_code == 0,
72+
output=conformance_tests_issue,
73+
)
74+
6675
if exit_code == 0:
6776
if (
6877
render_context.conformance_tests_running_context.current_testing_module_name

render_machine/actions/run_unit_tests.py

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
import render_machine.render_utils as render_utils
55
from plain2code_console import console
66
from render_machine.actions.base_action import BaseAction
7+
from render_machine.fix_loop_metrics import UNIT_LOOP, report_fix_loop_attempt
78
from render_machine.render_context import RenderContext
89
from render_machine.render_types import RenderError
910

@@ -31,6 +32,15 @@ def execute(self, render_context: RenderContext, _previous_action_payload: Any |
3132

3233
render_context.script_execution_history.latest_unit_test_output_path = unittests_temp_log_file_path
3334
render_context.script_execution_history.should_update_script_outputs = True
35+
36+
report_fix_loop_attempt(
37+
render_context,
38+
loop=UNIT_LOOP,
39+
frid=render_context.frid_context.frid if render_context.frid_context else None,
40+
passed=exit_code == 0,
41+
output=unittests_issue,
42+
)
43+
3444
if exit_code == 0:
3545
return self.SUCCESSFUL_OUTCOME, None
3646

render_machine/code_renderer.py

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@
33

44
from transitions.extensions.diagrams import HierarchicalGraphMachine
55

6+
from plain2code_console import console
67
from plain2code_events import (
78
RenderModuleCompleted,
89
RenderModuleFailed,
@@ -79,6 +80,8 @@ def run(self):
7980
break
8081

8182
if self.render_context.state == States.RENDER_COMPLETED.value:
83+
for summary in self.render_context.fix_loop_metrics.render_summary():
84+
console.info(summary)
8285
self.render_context.event_bus.publish(
8386
RenderModuleCompleted(module_name=self.render_context.module_name)
8487
)

render_machine/fix_loop_metrics.py

Lines changed: 143 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,143 @@
1+
"""Per-FRID accounting for the two fix loops, and detection of a loop that is stuck.
2+
3+
Both loops — unit tests during implementation, conformance tests afterwards — patch,
4+
re-run the script, and repeat until a budget runs out. Neither noticed when an attempt
5+
changed nothing: benchmark renders spent twenty attempts rewriting one file against one
6+
unchanging assertion before abandoning the render. Two things were missing, and this
7+
module supplies both.
8+
9+
*Detection*: a failure is fingerprinted, and consecutive identical fingerprints for the
10+
same loop and FRID are counted. A streak means the loop is re-patching without effect,
11+
which is the moment worth reporting — not the exhaustion twenty attempts later.
12+
13+
*Measurement*: attempts and failures are counted per (module, FRID, loop), so a render
14+
reports how many iterations convergence took rather than only whether it eventually gave
15+
up. Exhaustion is a rare binary event and a poor basis for comparing configurations;
16+
iterations-to-convergence is close to continuous and says something after a single run.
17+
18+
Recording never affects rendering. These are observations.
19+
"""
20+
21+
import hashlib
22+
import re
23+
from dataclasses import dataclass, field
24+
from typing import Dict, List, Optional, Tuple
25+
26+
from plain2code_console import console
27+
28+
UNIT_LOOP = "unit"
29+
CONFORMANCE_LOOP = "conformance"
30+
31+
# Parts of a test script's output that differ between two runs of the very same failure.
32+
# Left in place, any one of them would make every attempt look novel and hide a stuck
33+
# loop; over-normalising would do the reverse and merge failures that differ for real, so
34+
# only demonstrably volatile tokens are erased.
35+
_VOLATILE_PATTERNS = (
36+
re.compile(r"/tmp/[^\s'\"]+"), # renderer scratch paths: /tmp/tmpk8flk7f1.script_output
37+
re.compile(r"\b0x[0-9a-fA-F]+\b"), # memory addresses
38+
re.compile(r"\b[0-9a-fA-F]{8,}\b"), # hashes, uuids, run ids
39+
re.compile(r"\b\d+(?:\.\d+)?\s*m?s\b"), # durations: "1335.821531 ms", "22.5s"
40+
re.compile(r"duration_ms\s+[\d.]+"),
41+
)
42+
43+
44+
def failure_fingerprint(output: str) -> str:
45+
"""A stable identity for one failure, insensitive to run-to-run noise."""
46+
normalized = output or ""
47+
for pattern in _VOLATILE_PATTERNS:
48+
normalized = pattern.sub("", normalized)
49+
normalized = " ".join(normalized.split())
50+
return hashlib.sha1(normalized.encode("utf-8", errors="replace")).hexdigest()[:12]
51+
52+
53+
@dataclass
54+
class _LoopCounters:
55+
attempts: int = 0
56+
failures: int = 0
57+
max_repeat: int = 1
58+
last_fingerprint: Optional[str] = None
59+
current_repeat: int = 0
60+
61+
62+
@dataclass
63+
class FixLoopMetrics:
64+
"""One per render. Keyed by (module, frid) so a re-rendered FRID keeps accumulating."""
65+
66+
_counters: Dict[Tuple[str, str], Dict[str, _LoopCounters]] = field(default_factory=dict)
67+
_order: List[Tuple[str, str]] = field(default_factory=list)
68+
69+
def record(self, loop: str, module: str, frid: str, passed: bool, output: str) -> Optional[int]:
70+
"""Records one script run. Returns the streak length when this failure is a
71+
repeat of the one before it in the same loop, otherwise None."""
72+
key = (module, str(frid))
73+
if key not in self._counters:
74+
self._counters[key] = {}
75+
self._order.append(key)
76+
counters = self._counters[key].setdefault(loop, _LoopCounters())
77+
78+
counters.attempts += 1
79+
if passed:
80+
counters.last_fingerprint = None
81+
counters.current_repeat = 0
82+
return None
83+
84+
counters.failures += 1
85+
fingerprint = failure_fingerprint(output)
86+
if fingerprint == counters.last_fingerprint:
87+
counters.current_repeat += 1
88+
counters.max_repeat = max(counters.max_repeat, counters.current_repeat)
89+
return counters.current_repeat
90+
91+
counters.last_fingerprint = fingerprint
92+
counters.current_repeat = 1
93+
return None
94+
95+
def frid_summary(self, module: str, frid: str) -> Optional[str]:
96+
"""One greppable line per FRID, or None if no script ran for it."""
97+
counters = self._counters.get((module, str(frid)))
98+
if not counters:
99+
return None
100+
101+
parts = [f"[fix-loop] module={module} frid={frid}"]
102+
for loop in (UNIT_LOOP, CONFORMANCE_LOOP):
103+
if loop in counters:
104+
parts.append(f"{loop}={counters[loop].attempts} {loop}_failed={counters[loop].failures}")
105+
parts.append(f"max_repeat={max(loop.max_repeat for loop in counters.values())}")
106+
return " ".join(parts)
107+
108+
def render_summary(self) -> List[str]:
109+
"""Every FRID that ran a test script, in the order it was first reached."""
110+
summaries = (self.frid_summary(module, frid) for module, frid in self._order)
111+
return [summary for summary in summaries if summary]
112+
113+
114+
# How many identical failures in a row before the loop is called out. Two can happen when
115+
# a patch legitimately addresses something else first; by three the loop is re-patching
116+
# against a failure it is not moving.
117+
REPEATED_FAILURE_WARNING_THRESHOLD = 3
118+
119+
120+
def report_fix_loop_attempt(render_context, loop: str, frid: Optional[str], passed: bool, output: str) -> None:
121+
"""Records one script run and tells the user when the loop stops making progress."""
122+
if frid is None:
123+
return
124+
125+
streak = render_context.fix_loop_metrics.record(
126+
loop, module=render_context.module_name, frid=frid, passed=passed, output=output
127+
)
128+
129+
if streak is not None and streak >= REPEATED_FAILURE_WARNING_THRESHOLD:
130+
console.warning(
131+
f"The {loop} tests for functionality {frid} have failed the same way {streak} times in a row. "
132+
f"The last {streak - 1} fix attempts changed nothing that the tests can see."
133+
)
134+
135+
136+
def report_frid_fix_loop_summary(render_context, frid: Optional[str]) -> None:
137+
"""Emits the per-FRID counts once the FRID is done, successfully or not."""
138+
if frid is None:
139+
return
140+
141+
summary = render_context.fix_loop_metrics.frid_summary(render_context.module_name, frid)
142+
if summary:
143+
console.info(summary)

render_machine/render_context.py

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@
1313
from plain_modules import PlainModule
1414
from render_machine import triggers
1515
from render_machine.conformance_tests import CONFORMANCE_TESTS_DEFINITION_FILE_NAME, ConformanceTests
16+
from render_machine.fix_loop_metrics import FixLoopMetrics
1617
from render_machine.render_types import (
1718
AcceptanceTestPhase,
1819
ConformanceTestsRunningContext,
@@ -95,6 +96,10 @@ def __init__(
9596

9697
self.machine = None
9798
self.last_error_message: str | None = None
99+
# Observations only — see render_machine/fix_loop_metrics.py. Deliberately not
100+
# part of the snapshot: a rolled-back FRID still consumed the attempts it made,
101+
# and hiding them would understate what convergence cost.
102+
self.fix_loop_metrics = FixLoopMetrics()
98103

99104
def set_machine(self, machine):
100105
self.machine = machine

tests/test_fix_loop_metrics.py

Lines changed: 120 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,120 @@
1+
"""Tests for the fix-loop instrumentation.
2+
3+
Every loss in the retry5-era benchmarks was a fix loop spending its whole budget
4+
re-patching one file against one failure. The loop could not tell it was stuck, and the
5+
only externally visible outcome was a rare binary "did the render abort" — too coarse to
6+
compare configurations against. This turns both into observations: a streak counter that
7+
names a repeated-identical failure while it is happening, and per-FRID attempt counts
8+
that make convergence a continuous measure.
9+
10+
The fingerprint has to survive the parts of a test-script's output that change on every
11+
run — temp paths, durations, addresses — while still separating genuinely different
12+
failures, since both mistakes destroy the signal in opposite directions.
13+
"""
14+
15+
from render_machine.fix_loop_metrics import CONFORMANCE_LOOP, UNIT_LOOP, FixLoopMetrics, failure_fingerprint
16+
17+
18+
def test_the_same_failure_fingerprints_the_same():
19+
first = "FAILED test_header.py::test_subtitle\nAssertionError: subtitle not shown"
20+
second = "FAILED test_header.py::test_subtitle\nAssertionError: subtitle not shown"
21+
22+
assert failure_fingerprint(first) == failure_fingerprint(second)
23+
24+
25+
def test_volatile_noise_does_not_change_the_fingerprint():
26+
"""Two runs of one failing suite differ in temp path, duration and address."""
27+
first = "Output stored in /tmp/tmpk8flk7f1.script_output\n# duration_ms 1335.821531\nat 0x7f3a2b1c AssertionError: x"
28+
second = "Output stored in /tmp/tmpy0wo02yi.script_output\n# duration_ms 22.5\nat 0x55e1ff90 AssertionError: x"
29+
30+
assert failure_fingerprint(first) == failure_fingerprint(second)
31+
32+
33+
def test_a_different_failure_fingerprints_differently():
34+
assert failure_fingerprint("AssertionError: subtitle not shown") != failure_fingerprint(
35+
"AssertionError: button not found"
36+
)
37+
38+
39+
def test_a_first_failure_is_not_a_repeat():
40+
metrics = FixLoopMetrics()
41+
42+
streak = metrics.record(UNIT_LOOP, module="m", frid="1", passed=False, output="boom")
43+
44+
assert streak is None
45+
46+
47+
def test_the_same_failure_twice_reports_a_streak():
48+
metrics = FixLoopMetrics()
49+
50+
metrics.record(UNIT_LOOP, module="m", frid="1", passed=False, output="boom")
51+
streak = metrics.record(UNIT_LOOP, module="m", frid="1", passed=False, output="boom")
52+
53+
assert streak == 2
54+
55+
56+
def test_a_different_failure_restarts_the_streak():
57+
metrics = FixLoopMetrics()
58+
59+
metrics.record(UNIT_LOOP, module="m", frid="1", passed=False, output="boom")
60+
metrics.record(UNIT_LOOP, module="m", frid="1", passed=False, output="boom")
61+
streak = metrics.record(UNIT_LOOP, module="m", frid="1", passed=False, output="different")
62+
63+
assert streak is None
64+
65+
66+
def test_the_two_loops_are_counted_apart():
67+
"""A unit-test failure must not extend a conformance streak, or vice versa."""
68+
metrics = FixLoopMetrics()
69+
70+
metrics.record(UNIT_LOOP, module="m", frid="1", passed=False, output="boom")
71+
streak = metrics.record(CONFORMANCE_LOOP, module="m", frid="1", passed=False, output="boom")
72+
73+
assert streak is None
74+
75+
76+
def test_each_frid_counts_its_own_attempts():
77+
metrics = FixLoopMetrics()
78+
79+
metrics.record(UNIT_LOOP, module="m", frid="1", passed=False, output="a")
80+
metrics.record(UNIT_LOOP, module="m", frid="1", passed=True, output="")
81+
metrics.record(UNIT_LOOP, module="m", frid="2", passed=True, output="")
82+
83+
assert metrics.frid_summary("m", "1") == "[fix-loop] module=m frid=1 unit=2 unit_failed=1 max_repeat=1"
84+
assert metrics.frid_summary("m", "2") == "[fix-loop] module=m frid=2 unit=1 unit_failed=0 max_repeat=1"
85+
86+
87+
def test_a_frid_summary_reports_both_loops_and_the_worst_streak():
88+
metrics = FixLoopMetrics()
89+
90+
for _ in range(3):
91+
metrics.record(CONFORMANCE_LOOP, module="m", frid="2", passed=False, output="same")
92+
metrics.record(UNIT_LOOP, module="m", frid="2", passed=True, output="")
93+
94+
summary = metrics.frid_summary("m", "2")
95+
96+
assert "conformance=3" in summary
97+
assert "conformance_failed=3" in summary
98+
assert "unit=1" in summary
99+
assert "max_repeat=3" in summary
100+
101+
102+
def test_an_unseen_frid_has_no_summary():
103+
assert FixLoopMetrics().frid_summary("m", "9") is None
104+
105+
106+
def test_the_render_summary_covers_every_frid_touched():
107+
metrics = FixLoopMetrics()
108+
metrics.record(UNIT_LOOP, module="m", frid="1", passed=True, output="")
109+
metrics.record(CONFORMANCE_LOOP, module="m", frid="2", passed=False, output="x")
110+
111+
lines = metrics.render_summary()
112+
113+
assert len(lines) == 2
114+
assert any("frid=1" in line for line in lines)
115+
assert any("frid=2" in line for line in lines)
116+
117+
118+
def test_the_render_summary_is_empty_when_no_script_ran():
119+
"""A render that failed before any test script must not emit a misleading summary."""
120+
assert FixLoopMetrics().render_summary() == []

0 commit comments

Comments
 (0)