From dc7170d0d18a9c4ca338ecd19793421498529239 Mon Sep 17 00:00:00 2001 From: ScottW514 Date: Sat, 19 Sep 2026 17:45:27 -0400 Subject: [PATCH] forgetest: cooling.flow-under-load finds the verdict by offset, not by a tail count The test counted "heater rise" in the last 300 lines of the forgectrl log before the job, then waited for the count to grow. A tail of fixed length cannot show that: the new verdict line comes in at the bottom as an old one leaves at the top, the count does not move, and a check that verified reads as one that never judged. Seen on the bench reference in campaign c-20260919210959-8780: the engine logged "coolant flow verified (heater rise 11.5 C, dT 9.5 C; laser 1.6 off 13.1)" at 21:37:46, 70 s into the job and inside the wait, and the test failed at 21:39:21 with "the engine published no flow verdict within 120 s". The 21:17:27 verdict of an earlier test sat near the top of the 300-line tail when the test began. Replayed against that log, the old method reads 4 before the job and 4 with the new verdict in the tail; the search from the byte offset finds the 21:37:46 line. The test now takes the log's byte offset before the job (_log_offset, as the fail-tier and liveness tests do) and searches what the file gained since with the verdict expression, stopping only on a line that matches. _log_since reads a file that is now shorter than the offset from its start: a rotation under the test leaves only newer lines. The /logs/tail helper and its line count are gone with their one user. Proven: tests/test_cooling_suite.py FlowVerdictLogTests - the text after the offset alone, the real verdict line through the expression, an old verdict before the offset not taken for the new one, a rotated log read whole, a missing log read as nothing; the cooling host tests pass under Linux, 24 tests. No component source changed, so no pin moves. --- forgetest/forgetest/suite/cooling.py | 32 ++++++++++++------ forgetest/tests/test_cooling_suite.py | 48 +++++++++++++++++++++++++++ 2 files changed, 69 insertions(+), 11 deletions(-) diff --git a/forgetest/forgetest/suite/cooling.py b/forgetest/forgetest/suite/cooling.py index 72c71ac..63bebe9 100644 --- a/forgetest/forgetest/suite/cooling.py +++ b/forgetest/forgetest/suite/cooling.py @@ -10,6 +10,7 @@ legal range trips the gate, the far end of the range turns it off by value, and both are said out loud: the settings reply, /status, the engine's run-start log line), and the airflow gates (a fan under its floor past the spin-up grace is a fault for the rest of the run).""" +import os import time from ..catalog import test @@ -1246,7 +1247,6 @@ LOAD_LINES = 27 # two 30 x 4 mm fills back to back, about 35 LOAD_SHARE_MIN_C = 0.3 # the tube was lit inside the window LOAD_MARGIN_C = 1.0 # the judged rise this far under the limit LOAD_VERDICT_WAIT_S = 120 # the window opens ~15 s into the session and runs 50 s -LOAD_LOG_LINES = "300" _LOAD_LINE_RX = None @@ -1270,9 +1270,19 @@ def _load_fill(): return lines -def _forgectrl_tail(fc): - st, body = fc.get("/logs/tail", params={"name": "forgectrl", "lines": LOAD_LOG_LINES}) - return body.get("text", "") if st == 200 and isinstance(body, dict) else "" +def _log_since(path, offset): + """The text a log gained since byte `offset`. A count of lines in a + tail of fixed length cannot tell a new line from an old one: the new + line comes in at the bottom as an old one leaves at the top. A file now + shorter than the offset was rotated under the test, and all of it is + newer.""" + try: + with open(path, "rb") as f: + if os.fstat(f.fileno()).st_size >= offset: + f.seek(offset) + return f.read().decode("utf-8", "replace") + except OSError: + return "" @test("cooling.flow-under-load", title="The flow check reads true with the tube lit through its window", @@ -1290,6 +1300,7 @@ def _forgectrl_tail(fc): "the tube's share off and read its baseline as a mean.") def flow_under_load(ctx): from .laser import sample, prepare, LiveJob, ARM_CUE, run_and_sample, wait_disarm + from .motion import FORGECTRL_LOG, _log_offset fc = ctx.forgectrl ev = ctx.evidence state, check_s = _gate_state(fc, "cool_flow_check_s") @@ -1297,7 +1308,7 @@ def flow_under_load(ctx): ctx.check(state != "off" and check_s, "the flow check is off (cool_flow_check_s=%s)", check_s) ctx.check(limit, "cool_flow_rise unreadable") ev.update({"check_s": check_s, "limit_c": limit}) - before = _forgectrl_tail(fc).count("heater rise") + off = _log_offset(FORGECTRL_LOG) # the verdict is a line written after this # The fill ends one line length out and (LOAD_LINES - 1) pitches up; # the job brings the head back so the baseline finds it where it began. back = "G0 X%g Y%g" % (-LOAD_WIDTH if LOAD_LINES % 2 else 0.0, -LOAD_PITCH * (LOAD_LINES - 1)) @@ -1332,12 +1343,11 @@ def flow_under_load(ctx): ctx.checkpoint() if hw.sysfs_int("thermal/heater_pwm", 0) > 0: heater_seen = True - text = _forgectrl_tail(fc) - if text.count("heater rise") > before: - m = None - for m in _load_verdict_rx().finditer(text): - pass - line = m.group(0) if m else None + m = None + for m in _load_verdict_rx().finditer(_log_since(FORGECTRL_LOG, off)): + pass + if m: + line = m.group(0) break ctx.sleep(1) ev["heater_seen"] = heater_seen diff --git a/forgetest/tests/test_cooling_suite.py b/forgetest/tests/test_cooling_suite.py index e72671a..e83f7a1 100644 --- a/forgetest/tests/test_cooling_suite.py +++ b/forgetest/tests/test_cooling_suite.py @@ -734,3 +734,51 @@ class FanGateTests(unittest.TestCase): self.run_test() self.assertIn("lacks exhaust", str(cm.exception)) self.assertEqual(self.fc.state["settings"]["cool_tach_exhaust_min_rpm"], "") + + +class FlowVerdictLogTests(unittest.TestCase): + """cooling.flow-under-load finds the engine's verdict in what the log + gained since the job began, not in a count over a tail of fixed length: + there a new verdict line comes in at the bottom as an old one leaves at + the top, the count does not move, and a check that verified reads as + one that never judged.""" + + VERDICT = ("2026-09-19T21:37:46.869674+00:00 forgectrl[2796] INFO cool: coolant flow verified " + "(heater rise 11.5 C, dT 9.5 C; laser 1.6 off 13.1)\n") + OLD = ("2026-09-19T21:17:27.200840+00:00 forgectrl[965] INFO cool: coolant flow verified " + "(heater rise 9.5 C, dT 8.7 C)\n") + + def setUp(self): + self.dir = tempfile.mkdtemp(prefix="flowlog.") + self.addCleanup(shutil.rmtree, self.dir, ignore_errors=True) + self.path = os.path.join(self.dir, "forgectrl.log") + + def write(self, text, mode="w"): + with open(self.path, mode, newline="\n") as f: + f.write(text) + + def test_only_the_text_after_the_offset_comes_back(self): + self.write(self.OLD + "filler\n" * 400) + off = os.path.getsize(self.path) + self.assertEqual(cooling._log_since(self.path, off), "") + self.write(self.VERDICT, mode="a") + text = cooling._log_since(self.path, off) + self.assertEqual(text, self.VERDICT) + m = cooling._load_verdict_rx().search(text) + self.assertEqual(m.group(1), "coolant flow verified") + self.assertEqual((m.group(2), m.group(5)), ("11.5", "1.6")) + + def test_an_old_verdict_before_the_offset_is_not_the_new_one(self): + self.write(self.OLD) + off = os.path.getsize(self.path) + self.write("2026-09-19T21:36:40+00:00 forgectrl[2796] INFO cool: crash watch armed\n", mode="a") + self.assertIsNone(cooling._load_verdict_rx().search(cooling._log_since(self.path, off))) + + def test_a_log_rotated_under_the_test_is_read_whole(self): + self.write(self.OLD + "filler\n" * 400) + off = os.path.getsize(self.path) + self.write(self.VERDICT) # the rotation: a new, shorter file + self.assertEqual(cooling._log_since(self.path, off), self.VERDICT) + + def test_a_missing_log_reads_as_nothing(self): + self.assertEqual(cooling._log_since(os.path.join(self.dir, "none.log"), 0), "")