diff --git a/docs/ACCEPTANCE.md b/docs/ACCEPTANCE.md index 35f9297..7f5f782 100644 --- a/docs/ACCEPTANCE.md +++ b/docs/ACCEPTANCE.md @@ -112,11 +112,12 @@ items: **fixed** resting values the boot establishes (the kernel module defaults, forgectrl's start-up writes, the GRBL controller's init writes: `motor_lock=8`, `x/y_mode=8`, `x/y_decay=1`, `step_freq=28160`, `ramp_rate=125000`, `streaming=0`, `state=idle`, latch locked, hold -currents, camera lamps and button LEDs off, heater and TEC off; forgectrl: -the controller running with motion verified, no diagnostic, the camera -engine and cooling engine idle), and **preserved** state with no resting -policy that a run must hand back as it found it (the lid lamp level, the -position counters, the settings map, the controller mode). Deviations are +currents, head lamp and button LEDs off, heater and TEC off, the lid lamp +at forgectrl's `lid_lamp_idle` setting; forgectrl: the controller running +with motion verified, no diagnostic, the camera engine and cooling engine +idle), and **preserved** state with no resting policy that a run must +hand back as it found it (the position counters, the settings map, the +controller mode). Deviations are **leftovers**: logged in the run pane, kept in the result's `evidence` (`baseline.pre` / `baseline.post`), and surfaced in the page's message line - a leftover found before a run is attributed to the previous run; one @@ -129,12 +130,11 @@ verified, or the ladder's verdict) before and after every takeover. **Power-cycle before a campaign.** forgetest takes a **fresh-boot reference** once per boot (`/data/forgetest/boot-.json`, taken only within the first ten minutes after boot, after the supervisor -settles): the whole idle picture of this machine as the image boots it. It -is the session's resting lid-lamp level and the check on the fixed values; -without one the lamp level is unknown and the page says so. Take it after -a **power cycle**, not a warm `reboot`: the PIC lights the lid lamp at -power-on (132), and a warm reboot leaves it dark because the module's -remove path turns it off - the machine's true fresh state is the lit one. +settles): the whole idle picture of this machine as the image boots it, +the check on the fixed values, and the record a leftover is judged +against. Take it after a **power cycle**, not a warm `reboot` - the +machine's true fresh state is the powered-on one (the PIC's own lamp and +sensor defaults, then forgectrl's start-up writes on top). A displaced head is jogged back along its own path by the kernel-measured X/Y delta (bounded to 100 mm; Z is never touched); beyond that the counters are reported and the run must be fixed. A run that legitimately diff --git a/forgetest/forgetest/baseline.py b/forgetest/forgetest/baseline.py index 75f5201..77f7dcf 100644 --- a/forgetest/forgetest/baseline.py +++ b/forgetest/forgetest/baseline.py @@ -9,9 +9,12 @@ restores it after (on every exit path), so a test cannot hand the next one the GRBL controller's init writes. Verified against the value, restored by writing it back. preserved state with no resting policy that a run must hand back as it - found it: the lid lamp level, the position counters, the - settings map, the controller mode. Captured before the run, - compared after, restored where the interface allows. + found it: the position counters, the settings map, the + controller mode. Captured before the run, compared after, + restored where the interface allows. + +The lid lamp is fixed too, at forgectrl's `lid_lamp_idle` setting (unset = +236): the daemon asserts it at start and at every controller spawn. Everything found off-baseline is a "leftover": logged, kept in the run's evidence, and surfaced on the page. The pre-run pass attributes leftovers @@ -63,7 +66,10 @@ LATCH_BIT = 0x08 # interlock_circuit bit 3: latch locked BUTTON_LEDS = ("button_led_1", "button_led_2", "button_led_3") -PRESERVED_SYSFS = ["pic/lid_led"] # captured before, restored after +PRESERVED_SYSFS = [] # sysfs attrs captured before, restored after + +LID_LAMP_ATTR = "pic/lid_led" +LID_LAMP_DEFAULT = "236" # forgectrl's lid_lamp_idle default BOOT_MAX_AGE_S = 600 # a boot reference is taken only this soon after boot SETTLE_S = 150 # the supervisor's probe + rail-off ladder @@ -165,6 +171,7 @@ class Baseline: t0 = time.time() deadline = t0 + timeout last = seen = heard = None + pending_since = None # verified but not running: the spawn follows while time.time() < deadline and not self.abort(): try: st, body = self.fc().get("/mode") @@ -181,12 +188,20 @@ class Baseline: if key != seen: seen = key self.log("/mode controller=%s motion=%s" % key) - if (body.get("motion") == "verified" - or body.get("controller") in ("motion-fault", "standby")): - if body.get("controller") == "motion-fault": + ctl = body.get("controller") + if ctl in ("motion-fault", "standby") or (ctl == "running" and body.get("motion") == "verified"): + if ctl == "motion-fault": self.log("WARNING - motion liveness ladder failed, controllers are " "down (motion-fault); retry via POST /mode") return body + if body.get("motion") == "verified": + # the probe passed; the spawn (or a respawn backoff of up to + # 30 s) is in flight - give it a bounded moment + pending_since = pending_since or time.time() + if time.time() - pending_since > 35: + return body + else: + pending_since = None time.sleep(1.0) self.log("WARNING - forgectrl did not settle within %d s (last /mode: %s)" % (timeout, last)) return last @@ -214,6 +229,7 @@ class Baseline: left = [] self._forgectrl_side(left) self._kernel_side(left) + self._lamp_side(left) self._preserved(left, captured) if left: self.log("%s: %d leftover(s): %s" % (phase, len(left), "; ".join(str(x) for x in left))) @@ -305,6 +321,23 @@ class Baseline: left.append(Leftover("cool", found, "idle/unarmed/no hold", "waited" if w is not None else "failed: still %s" % found)) + def _lamp_side(self, left): + """The lid lamp at forgectrl's idle level (the lid_lamp_idle setting).""" + st, body = self.fc_get("/settings") + if st != 200 or not isinstance(body, dict): + return + want = (body.get("lid_lamp_idle") or "").strip() or LID_LAMP_DEFAULT + got = hw.sysfs_read(LID_LAMP_ATTR) + if got is None or got == want: + return + try: + hw.sysfs_write(LID_LAMP_ATTR, want) + back = hw.sysfs_read(LID_LAMP_ATTR) + act = "restored" if back == want else "failed: reads %s" % back + except OSError as e: + act = "failed: %s" % e + left.append(Leftover(LID_LAMP_ATTR, got, want, act)) + def _kernel_side(self, left): if hw.sysfs_read("cnc/state") is None: self.log("kernel sysfs not present - kernel-side checks skipped") @@ -414,7 +447,8 @@ class Baseline: for k, v in was.items(): if body.get(k) == v: continue - st2, b2 = self.fc_post("/settings", data={k: v}) + st2, b2 = (self.fc_post("/settings", params={k: ""}) if v == "" + else self.fc_post("/settings", data={k: v})) left.append(Leftover("settings." + k, body.get(k), v, "restored" if st2 == 200 else "failed: %s %s" % (st2, b2))) @@ -514,8 +548,8 @@ def boot_reference(log, data_dir): pass up = uptime_s() if up is None or up > BOOT_MAX_AGE_S: - log("baseline: no fresh-boot reference for this boot (uptime %s s > %d s) - " - "the lid lamp resting level is unknown; reboot to take one" % (up, BOOT_MAX_AGE_S)) + log("baseline: no fresh-boot reference for this boot (uptime %s s > %d s); " + "power-cycle to take one" % (up, BOOT_MAX_AGE_S)) return None bl = Baseline(log) bl.wait_settled() diff --git a/forgetest/forgetest/runner.py b/forgetest/forgetest/runner.py index adf4883..ca95d40 100644 --- a/forgetest/forgetest/runner.py +++ b/forgetest/forgetest/runner.py @@ -422,9 +422,7 @@ class Runner: record what the previous run left behind. Returns the captured preserved state for the post pass.""" bl = _baseline.Baseline(run.log, abort=run.aborted.is_set) - ref = self.boot_ref - session = {"sysfs": {a: (ref.get("sysfs") or {}).get(a) for a in _baseline.PRESERVED_SYSFS}} if ref else None - left = bl.enforce("pre", captured=session) + left = bl.enforce("pre", captured=None) if left: who = self.last.id if self.last is not None else "an earlier run" self.messages.append("leftovers before %s (left by %s): %s" diff --git a/forgetest/forgetest/suite/forgectrl.py b/forgetest/forgetest/suite/forgectrl.py index 14ab202..d49fe09 100644 --- a/forgetest/forgetest/suite/forgectrl.py +++ b/forgetest/forgetest/suite/forgectrl.py @@ -1,6 +1,7 @@ """forgectrl.* - the machine-services daemon's API, access control, and panel.""" import json import socket +import time from ..catalog import test from .. import hw @@ -107,9 +108,11 @@ def auth(ctx): @test("forgectrl.settings-bounds", title="Settings validation and restore", subsystem="forgectrl", kind="auto", est_min=1, - covers=[("forgectrl", "src/settings.*"), ("forgectrl", "src/main.c")], + covers=[("forgectrl", "src/settings.*"), ("forgectrl", "src/main.c"), ("forgectrl", "src/cam.c")], description="An over-length value and an out-of-range value are refused (400) and leave the " - "settings byte-identical; an in-range value is accepted (200).") + "settings byte-identical; an in-range value is accepted (200). The lid lamp " + "idles at lid_lamp_idle (unset = 236), an out-of-range level is refused, a new " + "level applies to the lamp at once, and clearing it returns the default.") def settings_bounds(ctx): fc = ctx.forgectrl ev = ctx.evidence @@ -158,6 +161,44 @@ def settings_bounds(ctx): ctx.check(others_before == others_after, "other settings changed by the write") ctx.check(final.get(key) == val, "%s reads back %r, wrote %r", key, final.get(key), val) + # the lid lamp's idle level: resting at the setting, bounded, applied live + lamp_was = (before.get("lid_lamp_idle") or "").strip() + want = lamp_was or "236" + got = ctx.sysfs("pic/lid_led") + ev["lid_lamp"] = {"setting": lamp_was, "resting": got} + ctx.log("lid lamp: setting %r, pic/lid_led=%s (expected %s)", lamp_was, got, want) + ctx.check(got == want, "lid lamp rests at %s, lid_lamp_idle is %s", got, want) + for bad in ("256", "-1", "bright"): + st, body = fc.post("/settings", data={"lid_lamp_idle": bad}) + ctx.check(st == 400, "lid_lamp_idle=%s -> %s, expected 400", bad, st) + ctx.log("lid_lamp_idle 256 / -1 / bright refused") + try_level = "100" if want != "100" else "120" + st, body = fc.post("/settings", data={"lid_lamp_idle": try_level}) + ctx.check(st == 200, "lid_lamp_idle=%s -> %s, expected 200", try_level, st) + applied = None + t0 = time.time() + while time.time() - t0 < 5: + applied = ctx.sysfs("pic/lid_led") + if applied == try_level: + break + ctx.sleep(0.2) + ctx.log("lid_lamp_idle=%s -> pic/lid_led=%s after %.1f s", try_level, applied, time.time() - t0) + # an empty value clears the key: the query-string form carries it + st, body = (fc.post("/settings", params={"lid_lamp_idle": ""}) if not lamp_was + else fc.post("/settings", data={"lid_lamp_idle": lamp_was})) + ctx.check(st == 200, "restoring lid_lamp_idle=%r -> %s", lamp_was, st) + t0 = time.time() + back = None + while time.time() - t0 < 5: + back = ctx.sysfs("pic/lid_led") + if back == want: + break + ctx.sleep(0.2) + ev["lid_lamp"].update({"applied": applied, "restored": back}) + ctx.check(applied == try_level, "lamp did not follow lid_lamp_idle=%s (reads %s)", try_level, applied) + ctx.check(back == want, "lamp did not return to %s after the restore (reads %s)", want, back) + ctx.log("lid lamp follows the setting live and returns to %s", want) + @test("forgectrl.panel-serves", title="Control panel and status endpoints", subsystem="forgectrl", kind="auto", est_min=1, diff --git a/forgetest/forgetest/suite/motion.py b/forgetest/forgetest/suite/motion.py index 58fb6f9..9ee492f 100644 --- a/forgetest/forgetest/suite/motion.py +++ b/forgetest/forgetest/suite/motion.py @@ -5,6 +5,7 @@ Ported from `scripts/bench/pacing_test.py` (protocol-loop pacing) and and round-trip; the laser stays latched (the tests never touch it); the suite is the only Grbl client while a test runs. """ +import os import time from ..catalog import test @@ -230,13 +231,23 @@ def jog_roundtrip(ctx): kind="auto", est_min=1, covers=[("forgectrl", "src/super.c"), ("forgectrl", "src/liveness.c"), ("kernel-module-glowforge", "**")], requires=["kernel.latch-locked-idle"], - steps=["Bed clear, lid closed: the probe jogs the head a few mm (+X first)."], + steps=["Bed clear, lid closed: the probe jogs the head 15 mm out and back (+X first); " + "forgectrl is restarted once for a fresh probe."], description="forgectrl's supervisor reports the head-accelerometer liveness probe as " "verified for the running controller (the DRV8825s are not wedged); when the " - "probe was skipped at spawn, the controller is respawned once so it runs.") + "probe was skipped at spawn, the controller is respawned once so it runs. Then " + "the regression: with every axis masked (cnc/motor_lock=15, as a bench tool " + "may leave it) forgectrl is restarted and its fresh probe must still read " + "MOTION OK - the probe unmasks the axes itself - with the head-accel p2p at " + "or above the moving threshold.") def liveness_probe(ctx): fc = ctx.forgectrl ev = ctx.evidence + _liveness_verdict(ctx, fc, ev) + _liveness_masked_restart(ctx, fc, ev) + + +def _liveness_verdict(ctx, fc, ev): st, m = fc.get("/mode") ctx.check(st == 200 and isinstance(m, dict), "GET /mode -> %s", st) ev["mode_before"] = m @@ -263,6 +274,64 @@ def liveness_probe(ctx): ctx.check(m.get("motion") == "verified", "liveness is %r, expected verified", m.get("motion")) +FORGECTRL_LOG = "/data/log/forgefirm/forgectrl/forgectrl.log" + + +def _log_offset(path): + try: + return os.path.getsize(path) + except OSError: + return 0 + + +def _probe_lines(path, offset): + try: + with open(path, "rb") as f: + f.seek(offset) + data = f.read().decode("utf-8", "replace") + except OSError: + return [] + return [ln.strip() for ln in data.splitlines() if "liveness probe:" in ln] + + +def _liveness_masked_restart(ctx, fc, ev): + """The regression: a leftover motor_lock must not read as a wedge.""" + ctx.check(fc.wait_idle(15, abort=ctx.aborted), "machine not idle before the masked restart") + x0 = _kernel_x_mm(ctx) + hw.sysfs_write("cnc/motor_lock", "15") + ctx.log("masked every axis (cnc/motor_lock=15); restarting forgectrl for a fresh probe") + off = _log_offset(FORGECTRL_LOG) + rc, out = hw.initd("forgectrl", "restart") + ctx.check(rc == 0, "forgectrl restart -> rc %s", rc) + m = None + t0 = time.time() + while time.time() - t0 < 150: + ctx.checkpoint() + try: + st, m = fc.get("/mode") + except hw.HwError: + m = None # the daemon is still coming up + if isinstance(m, dict) and ((m.get("controller") == "running" and m.get("motion") == "verified") + or m.get("controller") == "motion-fault"): + break + ctx.sleep(1) + lines = _probe_lines(FORGECTRL_LOG, off) + for ln in lines: + ctx.log(" %s", ln.split(" INFO ", 1)[-1] if " INFO " in ln else ln[-160:]) + ev["masked_restart"] = {"mode": m, "probe_lines": lines[-4:], "motor_lock_after": ctx.sysfs("cnc/motor_lock")} + ctx.check(m and m.get("controller") == "running" and m.get("motion") == "verified", + "fresh probe under a leftover mask did not verify motion: %s", m) + ctx.check(lines and "MOTION OK" in lines[0], + "the first probe after the restart was not MOTION OK: %s", lines[:1]) + ctx.check(len(lines) == 1, "the probe needed the recovery ladder (%d probes) - a false dead verdict", len(lines)) + ctx.check(ctx.sysfs("cnc/motor_lock") == "8", "motor_lock reads %s after the controller start (expected 8)", + ctx.sysfs("cnc/motor_lock")) + ctx.check(fc.wait_idle(15, abort=ctx.aborted), "machine not idle after the probe") + x1 = _kernel_x_mm(ctx) + ctx.log("kernel X %s -> %s mm across the probe (out and back)", x0, x1) + ctx.log("PASS: masked restart probed MOTION OK on the first try, mask cleared, controller up") + + # ---------------------------------------------------------------- cancel / abort @test("motion.cancel-abort", title="Jog cancel and controlled abort recover cleanly", subsystem="motion", diff --git a/forgetest/tests/test_baseline.py b/forgetest/tests/test_baseline.py index c21984c..82cbd28 100644 --- a/forgetest/tests/test_baseline.py +++ b/forgetest/tests/test_baseline.py @@ -105,31 +105,26 @@ class BaselineTests(unittest.TestCase): self._sync_leds() self.assertEqual(baseline.read_led("button_led_2"), "0") - def test_preserved_lamp_and_position(self): + def test_preserved_position(self): b = self.bl() - self._attr("pic/lid_led", "132") cap = b.capture() - self.assertEqual(cap["sysfs"]["pic/lid_led"], "132") self.assertEqual(cap["position"], [0, 0, 0]) - # the run turned the lamp off and shifted the counters - self._attr("pic/lid_led", "0") + # the run shifted the counters self._pos(1000, 0, 0) left = b.enforce("post", captured=cap) items = {x.item: x for x in left} - self.assertEqual(set(items), {"pic/lid_led", "position"}) - self.assertEqual(items["pic/lid_led"].action, "restored") - self.assertEqual(self._read("pic/lid_led"), "132") + self.assertEqual(set(items), {"position"}) # no GRBL controller on the host: the head cannot be jogged back self.assertTrue(items["position"].action.startswith("unrestorable"), items["position"].action) self.assertEqual(items["position"].found, [1000, 0, 0]) - def test_session_resting_lamp_from_boot_reference(self): - # the pre pass hands the lamp back to the boot level + def test_lamp_needs_forgectrl(self): + # the lamp's idle level comes from forgectrl's settings: without the + # daemon there is nothing to compare against self._attr("pic/lid_led", "77") - session = {"sysfs": {"pic/lid_led": "0"}} - left = self.bl().enforce("pre", captured=session) - self.assertEqual([(x.item, x.action) for x in left], [("pic/lid_led", "restored")]) - self.assertEqual(self._read("pic/lid_led"), "0") + left = self.bl().enforce("pre", captured=None) + self.assertEqual(left, []) + self.assertEqual(self._read("pic/lid_led"), "77") def test_no_sysfs_means_skip(self): os.environ["GF_SYSFS_ROOT"] = os.path.join(self.tmp, "nope") + os.sep