diff --git a/docs/BRINGUP.md b/docs/BRINGUP.md index 7234541..362a9c5 100644 --- a/docs/BRINGUP.md +++ b/docs/BRINGUP.md @@ -3053,6 +3053,29 @@ dev image (the confirmation campaign's image).** `lid_policy=hold`), `python3-gfhardware/tests/test_machine_lid_button.py` (22 cases), gfutilities tests (58), forgetest unit + coverage lint; forgectrl builds clean with the three new settings and panel cards. + - **First bench run (dev image 20260817000107, 2026-08-17 00:26 UTC):** + `laser.lid-cancel-mid-fire` FAILED - the beam stopped and the job was + cancelled as designed, grbl reported "returned to the job start" with + 0.000 mm drift, but the head never moved: the kernel counters stayed at + +1440 counts (27 mm, where the lid opened), and the baseline's return + jog then moved 54 mm and hit the left rail (counters -1442). Root cause + in the stream engine, not the cancel policy: the park's `cnc/run` landed + while the kernel was still playing the hold's queued tail (state + `running`) - the request was refused with EPERM and `ship_pass` treated + "refused, kernel running" as started; the kernel then hit its own + end-of-data and idled with the park bytes stranded in the ring, and the + NEXT run (the baseline jog) played them first (stale 27 mm -X) plus + the jog. Fixed (grblHAL-glowforge): a refused run on a busy kernel stays + *pending* and is re-issued the moment the kernel reads idle + (`pending_pass`); a soft reset no longer `stop`s a kernel that is only + draining a completed stream, and after a mid-motion reset the unplayed + residue is cleared (`lseek 1`) once the stop has played out, before + any new bytes ship or the device changes hands; the cancel path waits + for the kernel drain before the reset. forgetest: the two lid-cancel + tests now check the KERNEL counters returned (grbl's belief is not + proof), and the baseline reports unplayed ring bytes as a leftover and + refuses to jog while any exist. To re-run: `motion.lid-cancel-home` + first, then `laser.lid-cancel-mid-fire`. - **Bench validation pending (acceptance catalog):** `laser.arm-wait-lid`, `motion.button-hold-resume`, `motion.lid-cancel-home`, `laser.lid-cancel-mid-fire` (live), `cloud.lid-abort` (live), diff --git a/forgetest/forgetest/baseline.py b/forgetest/forgetest/baseline.py index 6e1b18b..e2e164b 100644 --- a/forgetest/forgetest/baseline.py +++ b/forgetest/forgetest/baseline.py @@ -109,6 +109,20 @@ def read_position(): return None +def read_ring_residue(): + """Unplayed bytes queued in the kernel pulse ring: total written minus + processed (the cnc/position byte counters), or None when unreadable. + Anything but 0 at idle is stale motion that the NEXT run would replay + before its own bytes.""" + try: + with open(hw.sysfs_root() + "cnc/position", "rb") as f: + raw = f.read(32) + processed, total = struct.unpack("<2I", raw[12:20]) + return int(total) - int(processed) + except (OSError, struct.error): + return None + + class Leftover: def __init__(self, item, found, expected, action): self.item = item @@ -354,6 +368,10 @@ class Baseline: except OSError as e: act = "failed: %s" % e left.append(Leftover("laser_latch", "unlocked (interlock 0x%x)" % ilk, "locked", act)) + residue = read_ring_residue() + if residue: + left.append(Leftover("pulse ring", "%d unplayed bytes" % residue, "0 (nothing queued)", + "unrestorable: the next run would replay them first")) for attr, want in FIXED_SYSFS: got = hw.sysfs_read(attr) if got is None or got == want: @@ -386,6 +404,13 @@ class Baseline: return "unrestorable (Z only)" if now[2] != was[2] else "restored" if abs(dx) > RETURN_MAX_MM or abs(dy) > RETURN_MAX_MM: return "unrestorable: %.1f/%.1f mm exceeds %.0f mm" % (dx, dy, RETURN_MAX_MM) + # Never jog on top of stale bytes: a run started now would replay + # whatever the ring still holds before the jog, in a direction and + # for a distance nobody asked for. Report and leave the head. + residue = read_ring_residue() + if residue: + return ("unrestorable: %d unplayed bytes queued in the kernel ring - a jog would " + "replay them; clear the ring (controller restart) before moving" % residue) # a controller may be inside a respawn backoff (seconds): wait for it mode = None deadline = time.time() + 30 diff --git a/forgetest/forgetest/suite/laser.py b/forgetest/forgetest/suite/laser.py index 25abcb6..9413be4 100644 --- a/forgetest/forgetest/suite/laser.py +++ b/forgetest/forgetest/suite/laser.py @@ -17,6 +17,7 @@ import time from ..catalog import test from .. import hw from ..runner import Failed +from .motion import kernel_xy_mm, check_kernel_returned _LASER_COVERS = [("grblhal-glowforge", "src/**"), ("kernel-module-glowforge", "**"), ("forgectrl", "src/super.c"), ("forgectrl", "src/cool.c"), @@ -514,6 +515,8 @@ def lid_cancel_mid_fire(ctx): with ctx.grbl() as g, LiveJob(ctx, g): prepare(ctx, g) start = g.status_report()["MPos"] + k0 = kernel_xy_mm(ctx) + ev["kernel_start"] = k0 ctx.instruct(ARM_CUE % "40 mm +X and +Y") stream(g, ["G91", "G21", "M4", "S400", "G1 X40 F200", "G1 Y40 F200", "G1 X-40 F200", "G1 Y-40 F200", @@ -576,6 +579,9 @@ def lid_cancel_mid_fire(ctx): ctx.log("returned: drift %.3f mm; armed=%s latch_locked=%s button_latch=%s", drift, ev["armed_after"], ev["latch_locked"], ev["button_latch"]) ctx.check(drift <= 0.05, "head not back at the job start (drift %.3f mm)", drift) + # what the MACHINE did: the kernel counters must agree + ctx.check(ctx.forgectrl.wait_idle(10, abort=ctx.aborted), "machine not idle after the return") + check_kernel_returned(ctx, ev, k0) ctx.check(not ev["armed_after"], "armed window still open after the cancel") ctx.check(ev["latch_locked"], "kernel latch not locked after the cancel") ctx.check(ev["button_latch"] == 1, "hardware button latch not SET after the lid open (%s)", ev["button_latch"]) diff --git a/forgetest/forgetest/suite/motion.py b/forgetest/forgetest/suite/motion.py index 6c5a7ed..0ac6a05 100644 --- a/forgetest/forgetest/suite/motion.py +++ b/forgetest/forgetest/suite/motion.py @@ -559,6 +559,28 @@ _LID_COVERS = _MOTION_COVERS + [("grblhal-glowforge", "src/glowforge_switches.c" ("grblhal-glowforge", "src/glowforge_laser.c")] +def kernel_xy_mm(ctx): + """The kernel's own position counters, in mm (forgectrl /status pos): + what the machine physically did, independent of what grbl believes.""" + pos = (ctx.forgectrl.status().get("pos") or {}) + return float(pos.get("x", 0.0)), float(pos.get("y", 0.0)) + + +def check_kernel_returned(ctx, ev, k0, tol_mm=0.1): + """After a return-to-start: the kernel counters must be back where the + job started too. grbl's own drift can read 0.000 while the head never + moved (a run the kernel did not take), which is exactly the failure + that must not pass.""" + k1 = kernel_xy_mm(ctx) + kdrift = max(abs(k1[0] - k0[0]), abs(k1[1] - k0[1])) + ev["kernel_drift_mm"] = round(kdrift, 3) + ctx.log("kernel counters: start (%.2f, %.2f) -> now (%.2f, %.2f), drift %.3f mm", + k0[0], k0[1], k1[0], k1[1], kdrift) + ctx.check(kdrift <= tol_mm, + "the kernel counters did not return to the job start (drift %.3f mm) - " + "the return move was counted by grbl but not played by the machine", kdrift) + + def drain_text(g, seconds): """Everything the controller said in the next `seconds`.""" end = time.time() + seconds @@ -631,6 +653,8 @@ def lid_cancel_home(ctx): with ctx.grbl() as g: clean_slate(ctx, g) start = g.status_report()["MPos"] + k0 = kernel_xy_mm(ctx) + ev["kernel_start"] = k0 ev["start"] = start g.command("M5") g.command("G91") @@ -663,6 +687,10 @@ def lid_cancel_home(ctx): ev["drift_mm"] = round(drift, 3) ctx.log("back at the job start: drift %.3f mm (lid still open)", drift) ctx.check(drift <= 0.05, "head not back at the job start (drift %.3f mm)", drift) + # what the MACHINE did: the kernel counters must agree (the return + # move must have been played, not only planned) + machine_idle(ctx, 10) + check_kernel_returned(ctx, ev, k0) sw = (ctx.forgectrl.status().get("switches") or {}) ev["lid_at_return"] = sw.get("lid") ctx.instruct("Close the lid, then click Done.") diff --git a/forgetest/tests/test_baseline.py b/forgetest/tests/test_baseline.py index 8a5f358..302517c 100644 --- a/forgetest/tests/test_baseline.py +++ b/forgetest/tests/test_baseline.py @@ -119,6 +119,27 @@ class BaselineTests(unittest.TestCase): self.assertTrue(items["position"].action.startswith("unrestorable"), items["position"].action) self.assertEqual(items["position"].found, [1000, 0, 0]) + def _pos_bytes(self, x, y, z, processed, total): + with open(self.sysfs + "cnc/position", "wb") as f: + f.write(struct.pack("<3i2I", x, y, z, processed, total)) + + def test_ring_residue_is_a_leftover_and_blocks_the_return_jog(self): + b = self.bl() + cap = b.capture() + # the run left 40 unplayed bytes queued in the kernel ring and the + # head 1000 counts out: the residue is reported, and the return jog + # is refused (it would replay the residue first) + self._pos_bytes(1000, 0, 0, 100, 140) + left = b.enforce("post", captured=cap) + items = {x.item: x for x in left} + self.assertIn("pulse ring", items) + self.assertEqual(items["pulse ring"].found, "40 unplayed bytes") + self.assertIn("unplayed bytes queued", items["position"].action) + self.assertEqual(baseline.read_ring_residue(), 40) + + def test_clean_ring_reads_zero_residue(self): + self.assertEqual(baseline.read_ring_residue(), 0) + 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