forgetest: a resume is proven by leaving the hold, and status polling no longer eats [MSG:] lines

Bench (image 20260817124714): motion.button-hold-resume FAILED on a machine
that did exactly the right thing. The operator paused about 7 s into an 8 s
move, so the resume had a fraction of a second of travel left; the job was
already Idle by the next poll and the test - which insisted on catching the
Run state - called it "the second press did not resume the job". Its own
evidence contradicted the verdict: the kernel counters read 2133 = 40.000 mm,
the whole move, and the position check two lines below would have passed.

Catching the state a command moves INTO is a race whenever the remaining work
is short. What proves the press was acted on is the job LEAVING the hold, so
that is what the test waits for now (wait_left_state), with the state it left
into required to be Run or Idle - not Alarm or Door - and the existing "landed
on its target" check still doing the real work. laser.pause-resume-lid-cancel
had the same shape and gets the same treatment.

Second defect, visible in the same record as "message seen: False": the driver
DOES report "button pressed - job paused", but Grbl.status_report() began by
discarding the read buffer and then kept only what followed the report, so
every asynchronous [MSG:] line that landed during a poll was thrown away. It
now consumes status reports only - stale ones included, which is what that
discard was for - and leaves everything else for drain(). Tests that assert on
what the controller said open their window with an explicit drain() before the
prompt, so the text they judge is the text from the action.

forgetest/forgetest/hw.py

@@ -228,7 +228,8 @@ class Grbl:
                 pass
             self.sock = None
 
-    def drain(self):
+    def _recv(self):
+        """Pull whatever is waiting into the buffer; never blocks long."""
         self.sock.settimeout(0.05)
         try:
             while True:
@@ -238,6 +239,22 @@ class Grbl:
                 self.buf += d
         except (socket.timeout, OSError):
             pass
+
+    def _take_report(self):
+        """Remove every complete <...> report from the buffer and return the
+        last one, keeping the text around them. Status reports are the only
+        thing consumed here: the driver's [MSG:] lines stay for drain()."""
+        last = None
+        while True:
+            i = self.buf.find(b"<")
+            j = self.buf.find(b">", i + 1) if i >= 0 else -1
+            if i < 0 or j <= i:
+                return last
+            last = self.buf[i + 1:j].decode("utf-8", "replace")
+            self.buf = self.buf[:i] + self.buf[j + 1:]
+
+    def drain(self):
+        self._recv()
         out, self.buf = self.buf, b""
         return out.decode("utf-8", "replace")
 
@@ -279,8 +296,12 @@ class Grbl:
         """One '?' report, parsed: {'state': 'Idle', 'MPos': (x,y,z), ...}.
         The '?' is re-sent every 0.5 s until a report arrives: a soft
         reset (^X) flushes the controller's read buffer and eats a '?'
-        that lands in it."""
-        self.drain()
+        that lands in it. Reports already buffered are stale and dropped -
+        but only the reports: anything else the controller said is left in
+        the buffer, so a test that polls for a state does not lose the
+        [MSG:] line that explains it."""
+        self._recv()
+        self._take_report()                 # stale: predates this '?'
         self.send_raw(b"?")
         deadline = time.time() + self.timeout
         resend = time.time() + 0.5
@@ -295,11 +316,8 @@ class Grbl:
             if time.time() >= resend:
                 self.send_raw(b"?")
                 resend = time.time() + 0.5
-            i = self.buf.find(b"<")
-            j = self.buf.find(b">", i + 1) if i >= 0 else -1
-            if i >= 0 and j > i:
-                rep = self.buf[i + 1:j].decode("utf-8", "replace")
-                self.buf = self.buf[j + 1:]
+            rep = self._take_report()
+            if rep is not None:
                 return parse_report(rep)
         raise HwError("no status report from grbl")
 

forgetest/forgetest/suite/laser.py

@@ -17,7 +17,8 @@ import time
 from ..catalog import test
 from .. import hw
 from ..runner import Failed
-from .motion import kernel_xy_mm, check_kernel_returned, wait_state, wait_idle, drain_text
+from .motion import (kernel_xy_mm, check_kernel_returned, wait_state, wait_state_text,
+                     wait_left_state, wait_idle, drain_text)
 
 _LASER_COVERS = [("grblhal-glowforge", "src/**"), ("kernel-module-glowforge", "**"),
                  ("forgectrl", "src/super.c"), ("forgectrl", "src/cool.c"),
@@ -544,11 +545,11 @@ def pause_resume_lid_cancel(ctx):
         ctx.log("emission live (%s) - asking the operator to pause", smp["emission"])
 
         # -- the button pauses ------------------------------------------------
+        g.drain()                                   # the message window opens at the prompt
         ctx.instruct("The laser is cutting. Press the button ONCE now (pause), then click Done - "
                      "do not wait long before the next step.")
-        st = wait_state(ctx, g, "Hold", 8)
+        st, text = wait_state_text(ctx, g, "Hold", 8)
         ctx.check(st is not None, "the press did not hold the job (state %s)", g.status_report()["state"])
-        text = drain_text(g, 0.5)
         ev["hold_state"] = st["state"]
         ev["pause_message"] = "job paused" in text
         paused = []
@@ -574,10 +575,15 @@ def pause_resume_lid_cancel(ctx):
                   "the kernel latch relocked on the pause - the resume could not fire without a new arm press")
 
         # -- the button resumes -----------------------------------------------
+        g.drain()
         ctx.instruct("Press the button once more now (resume), then click Done.")
-        st = wait_state(ctx, g, "Run", 10)
+        st, text = wait_left_state(ctx, g, "Hold", 10)
         ev["resumed_state"] = st["state"] if st else g.status_report()["state"]
-        ctx.check(st is not None, "the second press did not resume the job (state %s)", ev["resumed_state"])
+        ev["resume_message"] = "job resumed" in text
+        ctx.check(st is not None, "the second press did not resume the job (still held: %s)",
+                  ev["resumed_state"])
+        ctx.check(st["state"].startswith(("Run", "Idle")),
+                  "the job left the hold into %s, not into motion", st["state"])
         back = False
         t2 = time.time()
         trail = []
@@ -596,6 +602,7 @@ def pause_resume_lid_cancel(ctx):
         ctx.check(back, "emission did not return after the resume: %s", trail[-6:])
 
         # -- the lid cancels --------------------------------------------------
+        g.drain()
         ctx.instruct("The cut is running again. Open the lid NOW and leave it open, then click Done.")
         t_lid = time.time()
         lid_trail = []

forgetest/forgetest/suite/motion.py

@@ -49,6 +49,39 @@ def wait_state(ctx, g, prefix, timeout):
     return None
 
 
+def wait_state_text(ctx, g, prefix, timeout):
+    """wait_state, keeping everything the controller said while polling.
+    The driver reports a press with a [MSG:] line the moment it acts on it -
+    inside the poll window - so a test that wants both the state and the
+    message has to collect them together."""
+    end = time.time() + timeout
+    text = ""
+    while time.time() < end:
+        ctx.checkpoint()
+        st = g.status_report()
+        text += g.drain()
+        if st["state"].startswith(prefix):
+            return st, text
+        time.sleep(0.1)
+    return None, text + g.drain()
+
+
+def wait_left_state(ctx, g, prefix, timeout):
+    """The first report whose state is no longer `prefix`, with the text.
+    Leaving a state is what proves a command was acted on; catching the
+    state it moves INTO is a race whenever the remaining work is short."""
+    end = time.time() + timeout
+    text = ""
+    while time.time() < end:
+        ctx.checkpoint()
+        st = g.status_report()
+        text += g.drain()
+        if not st["state"].startswith(prefix):
+            return st, text
+        time.sleep(0.1)
+    return None, text + g.drain()
+
+
 def wait_idle(ctx, g, timeout=30.0, poll=0.05, grace=0.3):
     """Poll until Idle; returns (peak_feed_mm_min, states_seen, final_report).
     An Idle report inside the first `grace` seconds counts only once a
@@ -660,19 +693,32 @@ def button_hold_resume(ctx):
         g.command("G1X40F300", timeout=0.5)               # an 8 s move
         ctx.sleep(0.5)
         ctx.check(g.status_report()["state"].startswith("Run"), "the move did not start")
+        g.drain()                                     # the message window opens at the prompt
         ctx.instruct("The head is moving. Press the button once now, then click Done.")
-        st = wait_state(ctx, g, "Hold", 8)
+        st, text = wait_state_text(ctx, g, "Hold", 8)
         ctx.check(st is not None, "the press did not hold the job (state %s)", g.status_report()["state"])
-        text = drain_text(g, 0.5)
         ev["held_state"] = st["state"]
+        ev["held_at_mm"] = round(st["MPos"][0] - start[0], 3)
         ev["pause_message"] = "job paused" in text
-        ctx.log("held: %s; message seen: %s", st["state"], ev["pause_message"])
+        ctx.log("held: %s at %.3f mm of 40; message seen: %s", st["state"], ev["held_at_mm"],
+                ev["pause_message"])
+        g.drain()
         ctx.instruct("The head is stopped. Press the button once more now, then click Done.")
-        st = wait_state(ctx, g, "Run", 8)
-        ctx.check(st is not None, "the second press did not resume the job (state %s)",
-                  g.status_report()["state"])
-        text = drain_text(g, 0.5)
+        # The press is proven by the job LEAVING the hold. Catching it in Run
+        # is a race: a pause late in the move leaves a fraction of a second of
+        # travel, which can be over before the next poll - the machine did
+        # exactly the right thing and the test would still have called it a
+        # failure.
+        st, text = wait_left_state(ctx, g, "Hold", 10)
+        ev["state_after_resume"] = st["state"] if st else None
         ev["resume_message"] = "job resumed" in text
+        ctx.check(st is not None, "the second press did not resume the job (still held: %s)",
+                  g.status_report()["state"])
+        # Leaving the hold for Run or Idle is the resume; leaving it for Alarm
+        # or Door is something else entirely, and must not read as a pass.
+        ctx.check(st["state"].startswith(("Run", "Idle")),
+                  "the job left the hold into %s, not into motion", st["state"])
+        ctx.log("resumed: %s; message seen: %s", ev["state_after_resume"], ev["resume_message"])
         peak, states, st = wait_idle(ctx, g, 40)
         ctx.check("TIMEOUT" not in states, "the resumed move did not complete: %s", states)
         moved = st["MPos"][0] - start[0]
@@ -715,6 +761,7 @@ def lid_cancel_home(ctx):
         g.command("G1X40F300", timeout=0.5)               # an 8 s move
         ctx.sleep(0.5)
         ctx.check(g.status_report()["state"].startswith("Run"), "the move did not start")
+        g.drain()                                     # the message window opens at the prompt
         ctx.instruct("The head is moving. Open the lid NOW and leave it open, then click Done.")
         drift = expect_cancel_and_return(ctx, g, ev, start, k0, "lid opened", "running")
         sw = (ctx.forgectrl.status().get("switches") or {})
@@ -739,13 +786,14 @@ def lid_cancel_home(ctx):
         g.command("G1X40F300", timeout=0.5)
         ctx.sleep(0.5)
         ctx.check(g.status_report()["state"].startswith("Run"), "the second move did not start")
+        g.drain()
         ctx.instruct("The head is moving again. Press the button once now (pause), then click Done.")
-        st = wait_state(ctx, g, "Hold", 8)
+        st, held = wait_state_text(ctx, g, "Hold", 8)
         ctx.check(st is not None, "the press did not hold the job (state %s)", g.status_report()["state"])
-        held = drain_text(g, 0.5)
         ev["hold_state"] = st["state"]
         ev["hold_pause_message"] = "job paused" in held
         ctx.log("paused: %s; message seen: %s", st["state"], ev["hold_pause_message"])
+        g.drain()
         ctx.instruct("The job is paused. Open the lid NOW and leave it open, then click Done.")
         hold_drift = expect_cancel_and_return(ctx, g, ev, start2, k1, "lid opened", "hold")
         ctx.check(not g.status_report()["state"].startswith("Hold"),
@@ -795,6 +843,7 @@ def interlock_cancel_home(ctx):
         g.command("G1X60F300", timeout=0.5)               # a 12 s move
         ctx.sleep(0.5)
         ctx.check(g.status_report()["state"].startswith("Run"), "the move did not start")
+        g.drain()
         ctx.instruct("The head is moving. Open the INTERLOCK loop now (unplug it / pull the jumper) and "
                      "leave it open, then click Done.")
         sw = (ctx.forgectrl.status().get("switches") or {})
@@ -850,11 +899,11 @@ def lid_policy_hold(ctx):
             g.command("G1X40F300", timeout=0.5)           # an 8 s move
             ctx.sleep(0.5)
             ctx.check(g.status_report()["state"].startswith("Run"), "the move did not start")
+            g.drain()
             ctx.instruct("The head is moving. Open the lid NOW and leave it open, then click Done.")
-            st = wait_state(ctx, g, "Door", 8)
+            st, text = wait_state_text(ctx, g, "Door", 8)
             ev["door_state"] = st["state"] if st else g.status_report()["state"]
             ctx.check(st is not None, "the lid did not park the job in Door (state %s)", ev["door_state"])
-            text = drain_text(g, 1.0)
             ev["messages"] = [ln for ln in text.splitlines() if ln.startswith("[MSG:")]
             ctx.check("job cancelled" not in text, "the job was cancelled under lid_policy=hold: %s", ev["messages"])
             ctx.check("returned to the job start" not in text,