forgetest: kernel counters prove the return, and ring residue is a leftover that blocks the jog

The lid-cancel tests (motion.lid-cancel-home, laser.lid-cancel-mid-fire)
now check that the KERNEL position counters returned to the job start,
not only grbl's MPos - grbl's drift read 0.000 while the head had not
moved. The baseline reports unplayed bytes queued in the kernel ring
(cnc/position total minus processed) as a leftover and refuses its
return jog while any exist: a run started on top of them replays them
first, which is what put the head into the rail. BRINGUP item 16 records
the bench finding and the stream-engine fix.
This commit is contained in:
ScottW514
2026-08-16 20:47:32 -04:00
parent b68d790b71
commit 9878c8d3b9
5 changed files with 103 additions and 0 deletions
+23
View File
@@ -3053,6 +3053,29 @@ dev image (the confirmation campaign's image).**
`lid_policy=hold`), `python3-gfhardware/tests/test_machine_lid_button.py` `lid_policy=hold`), `python3-gfhardware/tests/test_machine_lid_button.py`
(22 cases), gfutilities tests (58), forgetest unit + coverage lint; (22 cases), gfutilities tests (58), forgetest unit + coverage lint;
forgectrl builds clean with the three new settings and panel cards. 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`, - **Bench validation pending (acceptance catalog):** `laser.arm-wait-lid`,
`motion.button-hold-resume`, `motion.lid-cancel-home`, `motion.button-hold-resume`, `motion.lid-cancel-home`,
`laser.lid-cancel-mid-fire` (live), `cloud.lid-abort` (live), `laser.lid-cancel-mid-fire` (live), `cloud.lid-abort` (live),
+25
View File
@@ -109,6 +109,20 @@ def read_position():
return None 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: class Leftover:
def __init__(self, item, found, expected, action): def __init__(self, item, found, expected, action):
self.item = item self.item = item
@@ -354,6 +368,10 @@ class Baseline:
except OSError as e: except OSError as e:
act = "failed: %s" % e act = "failed: %s" % e
left.append(Leftover("laser_latch", "unlocked (interlock 0x%x)" % ilk, "locked", act)) 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: for attr, want in FIXED_SYSFS:
got = hw.sysfs_read(attr) got = hw.sysfs_read(attr)
if got is None or got == want: if got is None or got == want:
@@ -386,6 +404,13 @@ class Baseline:
return "unrestorable (Z only)" if now[2] != was[2] else "restored" return "unrestorable (Z only)" if now[2] != was[2] else "restored"
if abs(dx) > RETURN_MAX_MM or abs(dy) > RETURN_MAX_MM: 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) 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 # a controller may be inside a respawn backoff (seconds): wait for it
mode = None mode = None
deadline = time.time() + 30 deadline = time.time() + 30
+6
View File
@@ -17,6 +17,7 @@ import time
from ..catalog import test from ..catalog import test
from .. import hw from .. import hw
from ..runner import Failed from ..runner import Failed
from .motion import kernel_xy_mm, check_kernel_returned
_LASER_COVERS = [("grblhal-glowforge", "src/**"), ("kernel-module-glowforge", "**"), _LASER_COVERS = [("grblhal-glowforge", "src/**"), ("kernel-module-glowforge", "**"),
("forgectrl", "src/super.c"), ("forgectrl", "src/cool.c"), ("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): with ctx.grbl() as g, LiveJob(ctx, g):
prepare(ctx, g) prepare(ctx, g)
start = g.status_report()["MPos"] start = g.status_report()["MPos"]
k0 = kernel_xy_mm(ctx)
ev["kernel_start"] = k0
ctx.instruct(ARM_CUE % "40 mm +X and +Y") ctx.instruct(ARM_CUE % "40 mm +X and +Y")
stream(g, ["G91", "G21", "M4", "S400", stream(g, ["G91", "G21", "M4", "S400",
"G1 X40 F200", "G1 Y40 F200", "G1 X-40 F200", "G1 Y-40 F200", "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, ctx.log("returned: drift %.3f mm; armed=%s latch_locked=%s button_latch=%s", drift,
ev["armed_after"], ev["latch_locked"], ev["button_latch"]) 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) 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(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["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"]) ctx.check(ev["button_latch"] == 1, "hardware button latch not SET after the lid open (%s)", ev["button_latch"])
+28
View File
@@ -559,6 +559,28 @@ _LID_COVERS = _MOTION_COVERS + [("grblhal-glowforge", "src/glowforge_switches.c"
("grblhal-glowforge", "src/glowforge_laser.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): def drain_text(g, seconds):
"""Everything the controller said in the next `seconds`.""" """Everything the controller said in the next `seconds`."""
end = time.time() + seconds end = time.time() + seconds
@@ -631,6 +653,8 @@ def lid_cancel_home(ctx):
with ctx.grbl() as g: with ctx.grbl() as g:
clean_slate(ctx, g) clean_slate(ctx, g)
start = g.status_report()["MPos"] start = g.status_report()["MPos"]
k0 = kernel_xy_mm(ctx)
ev["kernel_start"] = k0
ev["start"] = start ev["start"] = start
g.command("M5") g.command("M5")
g.command("G91") g.command("G91")
@@ -663,6 +687,10 @@ def lid_cancel_home(ctx):
ev["drift_mm"] = round(drift, 3) ev["drift_mm"] = round(drift, 3)
ctx.log("back at the job start: drift %.3f mm (lid still open)", drift) 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) 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 {}) sw = (ctx.forgectrl.status().get("switches") or {})
ev["lid_at_return"] = sw.get("lid") ev["lid_at_return"] = sw.get("lid")
ctx.instruct("Close the lid, then click Done.") ctx.instruct("Close the lid, then click Done.")
+21
View File
@@ -119,6 +119,27 @@ class BaselineTests(unittest.TestCase):
self.assertTrue(items["position"].action.startswith("unrestorable"), items["position"].action) self.assertTrue(items["position"].action.startswith("unrestorable"), items["position"].action)
self.assertEqual(items["position"].found, [1000, 0, 0]) 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): def test_lamp_needs_forgectrl(self):
# the lamp's idle level comes from forgectrl's settings: without the # the lamp's idle level comes from forgectrl's settings: without the
# daemon there is nothing to compare against # daemon there is nothing to compare against