forgetest: clear a latched controller error, bound the move-start check, and follow the fail-tier restart

Three acceptance tests broke on the WI-4/WI-5 firmware, all from a
behavior a change moved and no test tracked.

motion: soft limits are armed after a home (the driver's, since the bed
has no switches), so a jog past the bed is refused with error:15 - and
grblHAL then answers error:15 to every following G-code line, across a
fresh connection, until a blank line acknowledges it. A prior test's or
the baseline hand-back's rejected jog left that latch, and the next
test's first move failed with a stale error unrelated to the move.
clean_slate now clears it with a blank line before the first move. The
four "send G1, sleep, check Run once" sites are replaced by start_move,
which waits for Run on a bound and, when it does not come, names the
reply, the state, the drained messages and a forgectrl snapshot - the
capture that turned "the move did not start" into "answered error:15".

cooling.fire-watch-tiers: the FIRE fail tier now stops the controller
through the supervisor and starts it again, so leg 2's Grbl connection
dies mid-leg. It now records the pid, reads FIRE from the engine and
the latch from sysfs, waits out the restart, proves the supervisor
logged the fail-tier stop, and opens a fresh session for the legs that
follow; src/super.* added to its covers.

Proof: full forgetest host suite green; coverage lint clean (90 tests);
bench reference on the dev image, unattended queue: motion.* and
cooling.* pass, cooling.fire-watch-tiers and cooling.fail-tier-stop
pass with the button-lamp driver fix (grblHAL-glowforge).

forgetest/forgetest/suite/cooling.py

@@ -746,7 +746,7 @@ FIRE_WAIT_S = 25            # settings re-read at run start, two-tick breach, 1
 
 @test("cooling.fire-watch-tiers", title="The lid-IR fire watch pauses at its alert and fails at its critical",
       subsystem="cooling", kind="auto", mode="grbl", est_min=6,
-      covers=_COOL_COVERS, requires=["kernel.latch-locked-idle"],
+      covers=_COOL_COVERS + [("forgectrl", "src/super.*")], requires=["kernel.latch-locked-idle"],
       steps=["Machine idle, lid closed, lid lamp at its resting level. The test moves the flame "
              "thresholds under the lamp's own reading and restores them; three M8/M9 sessions, "
              "no fire."],
@@ -759,6 +759,7 @@ FIRE_WAIT_S = 25            # settings re-read at run start, two-tick breach, 1
                   "read as the four flame gates off and the watch reads watch. Restored, the "
                   "watch reads armed at OK.")
 def fire_watch_tiers(ctx):
+    from .motion import FORGECTRL_LOG, _log_lines, _log_offset
     fc = ctx.forgectrl
     ev = ctx.evidence
     before = fc.settings()
@@ -810,7 +811,16 @@ def fire_watch_tiers(ctx):
             ctx.check(c.get("verdict") == "OK", "the alert survived into a fresh session: %s", c)
 
             # Leg 2: the fail tier. The q1 critical under the lamp reading
-            # stops the session and latches FIRE until it ends.
+            # latches FIRE and locks the laser; the fail tier then stops
+            # the controller through the supervisor and starts it again,
+            # so no run start can relight what was locked and the sender
+            # sees the job end. The Grbl socket dies with the restart -
+            # FIRE is read from the engine, the latch from sysfs, the stop
+            # from the supervisor's log, and a fresh session is opened for
+            # the legs that follow.
+            st, m0 = fc.get("/mode")
+            pid0 = m0.get("pid") if isinstance(m0, dict) else None
+            off = _log_offset(FORGECTRL_LOG)
             _set_gates(ctx, fc, {"cool_fire_q1_critical": str(max(2, q1 - 5)),
                                  "cool_fire_q1_alert": str(max(1, q1 - 10))})
             grbl.command("M8")
@@ -821,19 +831,38 @@ def fire_watch_tiers(ctx):
                 c = _cool(fc)
                 if c.get("verdict") == "FIRE":
                     break
+            ilk = hw.sysfs_int("cnc/interlock_circuit")
             ev["critical"] = c
-            ctx.log("critical leg: verdict %s fire_watch %s", c.get("verdict"), c.get("fire_watch"))
+            ev["interlock_circuit"] = ilk
+            ctx.log("critical leg: verdict %s fire_watch %s interlock_circuit %s",
+                    c.get("verdict"), c.get("fire_watch"), ilk)
             ctx.check(c.get("verdict") == "FIRE", "q1 critical under the lamp did not latch FIRE: %s", c)
             ctx.check(c.get("fire_watch") == "ALARM", "fire_watch %r during FIRE, expected ALARM", c.get("fire_watch"))
-            ilk = hw.sysfs_int("cnc/interlock_circuit")
-            ev["interlock_circuit"] = ilk
             ctx.check(ilk is not None and (ilk & 8), "the laser latch is not locked under FIRE (interlock_circuit=%s)", ilk)
             ctx.check(_tail_wait(ctx, fc, "LID IR FIRE SIGNAL (quartiles "),
                       "the FIRE line is missing from the forgectrl log")
+            # the fail tier stops the controller and starts it again; the
+            # Grbl socket dies with it. Wait out the restart, prove the
+            # supervisor logged the stop, restore the thresholds, and open
+            # a fresh session on the new controller.
+            grbl.close()
+            m1 = None
+            t0 = time.time()
+            while time.time() - t0 < 60:
+                st, m1 = fc.get("/mode")
+                if isinstance(m1, dict) and m1.get("controller") == "running" and m1.get("pid") != pid0:
+                    break
+                ctx.sleep(0.5)
+            ev["restart"] = {"pid_before": pid0, "mode_after": m1}
+            ctx.log("after FIRE: %s", ev["restart"])
+            ctx.check(m1 and m1.get("controller") == "running" and m1.get("pid") != pid0,
+                      "the controller was not stopped and started again after FIRE: %s", m1)
+            ctx.check(_log_lines(FORGECTRL_LOG, off, "lid IR fire signal - the controller is stopped"),
+                      "the supervisor did not log the fail-tier stop after FIRE")
             _set_gates(ctx, fc, {"cool_fire_q1_critical": orig["cool_fire_q1_critical"],
                                  "cool_fire_q1_alert": orig["cool_fire_q1_alert"]})
-            grbl.command("M9")
+            ctx.check(fc.wait_idle(30, abort=ctx.aborted), "machine not idle after the FIRE restart")
-            _session_ended(ctx, fc, "critical leg")
+            grbl.connect()      # a fresh session on the restarted controller
 
             # Leg 3: all four at zero: the watch off, said so, session OK.
             _set_gates(ctx, fc, {k: "0" for k in FIRE_KEYS})

forgetest/forgetest/suite/motion.py

@@ -136,9 +136,68 @@ def clean_slate(ctx, g):
             ctx.log("unlock: %s", g.command("$X"))
     st = g.status_report()
     ctx.check(st["state"].startswith("Idle"), "controller is %s, expected Idle", st["state"])
+    clear_error(ctx, g)
     return st
 
 
+def clear_error(ctx, g):
+    """Clear a latched line error before the test's first move.
+
+    Soft limits are armed after a home (the driver's, since the bed has
+    no switches), so a jog past the bed is refused with error:15 - and
+    grblHAL then answers error:15 to every following G-code line, across
+    a fresh connection, until a blank line acknowledges it ($ commands
+    and the ? report are unaffected, so a sender that queries on connect
+    self-clears; a bare G-code stream does not). A prior test's or the
+    baseline hand-back's rejected jog would otherwise make this test's
+    first move fail with a stale error unrelated to the move. A blank
+    line clears it and returns ok. Harmless and idempotent at Idle."""
+    r = g.command("")
+    ctx.check(r and r[-1] == "ok" and not any(x.startswith("error") for x in r),
+              "the controller answered %s to a blank line at the start - not a clean parser", r)
+
+
+MOVE_START_S = 2.0      # Run is there within 100 ms; a loaded board gets this long
+
+
+def start_move(ctx, g, line):
+    """Start a travel job with `line` and see the controller in Run. The
+    wait is bounded, not a fixed sleep. When Run never comes, the failure
+    names what happened instead: the reply (a refused block answers
+    error), the state the controller sits in (Hold, Door, Alarm, or an
+    Idle that never took the block), every line it said meanwhile, and
+    the machine as forgectrl sees it - the evidence a bare "did not
+    start" leaves out. Recorded in the evidence either way."""
+    reply = g.command(line, timeout=1.0)
+    end = time.time() + MOVE_START_S
+    t0 = time.time()
+    said = ""
+    st = None
+    while time.time() < end:
+        ctx.checkpoint()
+        st = g.status_report()
+        if st["state"].startswith("Run"):
+            break
+        said += g.drain()
+        time.sleep(0.1)
+    rec = {"line": line, "reply": reply, "state": st["state"] if st else None,
+           "after_s": round(time.time() - t0, 2)}
+    ctx.evidence.setdefault("move_start", []).append(rec)
+    if st is not None and st["state"].startswith("Run"):
+        return st
+    msgs = [ln.strip() for ln in said.splitlines() if ln.strip()]
+    rec["said"] = msgs
+    s = ctx.forgectrl.status() or {}
+    gr = ((s.get("grbl") or {}).get("report") or {})
+    rec["forgectrl"] = {"state": s.get("state"), "switches": s.get("switches"),
+                        "laser_locked": s.get("laser_locked"), "grbl": gr.get("state"),
+                        "alarm": gr.get("alarm"), "sender": (gr.get("sender") or {}).get("connected")}
+    ctx.check(False, "the move did not start: %s answered %s; controller %s %.1f s later, said %s; "
+                     "forgectrl sees kernel %s, grbl %s (alarm %s), switches %s, laser locked %s",
+              line, reply, st["state"] if st else "no report", rec["after_s"], msgs or "nothing",
+              s.get("state"), gr.get("state"), gr.get("alarm"), s.get("switches"), s.get("laser_locked"))
+
+
 @test("motion.pacing", title="Protocol-loop pacing (idle, parked, moving) and hold/resume position",
       subsystem="motion", kind="auto", mode="grbl", est_min=1,
       covers=_MOTION_COVERS, requires=["kernel.latch-locked-idle"],
@@ -1334,9 +1393,7 @@ def button_hold_resume(ctx):
                   "moves; the job holds and the test sees it.")
         g.command("M5")
         g.command("G91")
-        g.command("G1X40F300", timeout=0.5)               # an 8 s move
+        start_move(ctx, g, "G1X40F300")               # 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 here
         w = Watch(g)
         ctx.act("button", "press", until=w.in_state("Hold"), timeout=12, fail=False)
@@ -1412,9 +1469,7 @@ def lid_cancel_home(ctx):
                   "leave it open until the head has come back on its own.")
         g.command("M5")
         g.command("G91")
-        g.command("G1X40F300", timeout=0.5)               # an 8 s move
+        start_move(ctx, g, "G1X40F300")               # 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 here
         ctx.act("lid", "open", text="Leave it open until the head has come back.", timeout=12)
         drift = expect_cancel_and_return(ctx, g, ev, start, k0, "lid opened", "running")
@@ -1507,9 +1562,7 @@ def interlock_cancel_home(ctx):
                   "moves and leave it open until the head has come back on its own.")
         g.command("M5")
         g.command("G91")
-        g.command("G1X60F300", timeout=0.5)               # a 12 s move
+        start_move(ctx, g, "G1X60F300")               # a 12 s move
-        ctx.sleep(0.5)
-        ctx.check(g.status_report()["state"].startswith("Run"), "the move did not start")
         g.drain()
         ctx.act("interlock", "open", text="Leave it open until the head has come back.", timeout=16)
         sw = (ctx.forgectrl.status().get("switches") or {})
@@ -1571,9 +1624,7 @@ def lid_policy_hold(ctx):
                       "the job parks in the door state and waits.")
             g.command("M5")
             g.command("G91")
-            g.command("G1X40F300", timeout=0.5)           # an 8 s move
+            start_move(ctx, g, "G1X40F300")           # an 8 s move
-            ctx.sleep(0.5)
-            ctx.check(g.status_report()["state"].startswith("Run"), "the move did not start")
             g.drain()
             ctx.act("lid", "open", timeout=12)
             st, text = wait_state_text(ctx, g, "Door", 8)