mirror of
https://github.com/openglow-org/forgefirm.git
synced 2026-09-27 16:51:12 -07:00
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.
This commit is contained in:
@@ -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
|
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
|
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)."""
|
floor past the spin-up grace is a fault for the rest of the run)."""
|
||||||
|
import os
|
||||||
import time
|
import time
|
||||||
|
|
||||||
from ..catalog import test
|
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_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_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_VERDICT_WAIT_S = 120 # the window opens ~15 s into the session and runs 50 s
|
||||||
LOAD_LOG_LINES = "300"
|
|
||||||
_LOAD_LINE_RX = None
|
_LOAD_LINE_RX = None
|
||||||
|
|
||||||
|
|
||||||
@@ -1270,9 +1270,19 @@ def _load_fill():
|
|||||||
return lines
|
return lines
|
||||||
|
|
||||||
|
|
||||||
def _forgectrl_tail(fc):
|
def _log_since(path, offset):
|
||||||
st, body = fc.get("/logs/tail", params={"name": "forgectrl", "lines": LOAD_LOG_LINES})
|
"""The text a log gained since byte `offset`. A count of lines in a
|
||||||
return body.get("text", "") if st == 200 and isinstance(body, dict) else ""
|
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",
|
@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.")
|
"the tube's share off and read its baseline as a mean.")
|
||||||
def flow_under_load(ctx):
|
def flow_under_load(ctx):
|
||||||
from .laser import sample, prepare, LiveJob, ARM_CUE, run_and_sample, wait_disarm
|
from .laser import sample, prepare, LiveJob, ARM_CUE, run_and_sample, wait_disarm
|
||||||
|
from .motion import FORGECTRL_LOG, _log_offset
|
||||||
fc = ctx.forgectrl
|
fc = ctx.forgectrl
|
||||||
ev = ctx.evidence
|
ev = ctx.evidence
|
||||||
state, check_s = _gate_state(fc, "cool_flow_check_s")
|
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(state != "off" and check_s, "the flow check is off (cool_flow_check_s=%s)", check_s)
|
||||||
ctx.check(limit, "cool_flow_rise unreadable")
|
ctx.check(limit, "cool_flow_rise unreadable")
|
||||||
ev.update({"check_s": check_s, "limit_c": limit})
|
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 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.
|
# 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))
|
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()
|
ctx.checkpoint()
|
||||||
if hw.sysfs_int("thermal/heater_pwm", 0) > 0:
|
if hw.sysfs_int("thermal/heater_pwm", 0) > 0:
|
||||||
heater_seen = True
|
heater_seen = True
|
||||||
text = _forgectrl_tail(fc)
|
m = None
|
||||||
if text.count("heater rise") > before:
|
for m in _load_verdict_rx().finditer(_log_since(FORGECTRL_LOG, off)):
|
||||||
m = None
|
pass
|
||||||
for m in _load_verdict_rx().finditer(text):
|
if m:
|
||||||
pass
|
line = m.group(0)
|
||||||
line = m.group(0) if m else None
|
|
||||||
break
|
break
|
||||||
ctx.sleep(1)
|
ctx.sleep(1)
|
||||||
ev["heater_seen"] = heater_seen
|
ev["heater_seen"] = heater_seen
|
||||||
|
|||||||
@@ -734,3 +734,51 @@ class FanGateTests(unittest.TestCase):
|
|||||||
self.run_test()
|
self.run_test()
|
||||||
self.assertIn("lacks exhaust", str(cm.exception))
|
self.assertIn("lacks exhaust", str(cm.exception))
|
||||||
self.assertEqual(self.fc.state["settings"]["cool_tach_exhaust_min_rpm"], "")
|
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), "")
|
||||||
|
|||||||
Reference in New Issue
Block a user