From e9d5f3c842ebd74d1c17f3077102e55727be3e2e Mon Sep 17 00:00:00 2001 From: ScottW514 Date: Mon, 14 Sep 2026 16:07:55 -0400 Subject: [PATCH] Laser harness rules and catalog tests for the emission gates The GRBL driver's emission gates change (grblHAL-glowforge: the per-tick fire gate, the latch with an owner, the cooling verdict's two tiers, and the arm-flow gates). This commit carries the host rules and the catalog tests that hold them; the driver commit follows, because its CI fetches these harnesses unpinned. scripts/bench/laser_stream_test.py: - Rule 24 is the verdict's pause tier: the client holds the job under the open window, the first deceleration runs lit to the stop (the dark lead before the stop is at most 1000 ticks: the producer's lead plus one shipper period), a resume under the standing verdict moves dark and is held again, the clean verdict resumes lit with no press, and the latch sideband carries only the arm's unlock and the program end's lock. - Rule 25 is the fail tier: AIRFLOW mid-cut ends the job with ALARM:3, the stream ends dark well short of the line, the sideband ends on the lock, and a resume under the clean verdict that follows resumes nothing. - Rule 26: a sender change mid-M3 holds the job with the deceleration dark: the gate follows the window on every tick. - Rule 27: a verdict that goes stale holds the job at the cache's own expiry, lit to the stop, never a poll later; the engine's return resumes lit. - The stand-in engine publishes the verdict name and has a stale mode; the session steps gain expect_text, reconnect and a wait_state timeout; every session reads the latch sideband (GFSINK_LATCH_LOG). scripts/bench/laser_lifecycle_test.py: - Rules 11 to 15: the pause tier resumes with no press and no prompt, the fail tier ends the job and nothing resumes it, a sender change during a re-arm cancels it, a jog does not hold the window open, and a press counts only after the button has been seen up. The stand-in engine takes a live verdict dict. start_armed_move waits for a fresh prompt and a fresh armed message: a press that lands before the wait has begun is not consent, and the old stale match let one land early. forgetest/forgetest/suite/laser.py: - laser.verdict-cut (kind live, one press): a 40 mm M3 line; the test pauses the daemon for 3.5 s so the verdict goes stale (the settings route is idle-gated and the engine reloads its gates at a session start, so no setting can trip a pause mid-cut; the crash tiers need a physical knock). The controller must hold with the SoC latch and the hardware button latch both clear in every sample, emission must read 0 before the resume, and the clean verdict must resume the cut lit with no press and no prompt; M2 disarms as usual. - laser.armed-kill asserts that the respawned controller comes up with the latch still locked. Proof: both harnesses pass against the driver change on the host, and the forgetest unit tests pass. On the bench reference, laser.verdict-cut passed with no gap in the cut (held at +1.71 s after the pause began, both latches clear in every sample, emission 0 at +2.06 s after the hold, resumed lit at +4.0 s with the beam detector 678 counts over idle, kernel drift 0.0 mm, disarmed 0.1 s after Idle) and laser.armed-kill passed (emission 0 at +1.8 s after the supervisor's stop and +2.1 s after the SIGKILL, latch locked, respawned with the latch locked, button dark). Two earlier verdict-cut runs shaped the driver: a pause that locked the latch resumed dark, because a lock sets the hardware button latch, and a hold taken a poll after the gate closed left a several-mm gap. Catalog: one test added and one extended; both cover src/** of the driver through the existing laser covers. --- forgetest/forgetest/suite/laser.py | 170 +++++++++++++- scripts/bench/laser_lifecycle_test.py | 235 +++++++++++++++++-- scripts/bench/laser_stream_test.py | 318 ++++++++++++++++++++++---- 3 files changed, 655 insertions(+), 68 deletions(-) diff --git a/forgetest/forgetest/suite/laser.py b/forgetest/forgetest/suite/laser.py index 75a8676..3e7d4cf 100644 --- a/forgetest/forgetest/suite/laser.py +++ b/forgetest/forgetest/suite/laser.py @@ -792,10 +792,178 @@ def armed_kill(ctx): ctx.log("/mode after the kill: %s", m1) ctx.check(m1 and m1.get("controller") == "running" and m1.get("pid") != pid, "supervisor did not respawn the controller: %s", m1) + # The respawned controller starts locked and stays locked: a latch it + # did not unlock is never relit by a run start, and no arm has asked. + ctx.check(wait_grbl_port(ctx), "the respawned controller never accepted a Grbl connection") + ctx.sleep(2) + ilk = hw.sysfs_int("cnc/interlock_circuit") + ev["latch_locked_after_respawn"] = ilk is not None and bool(ilk & IL_LASER_LATCH) + ctx.check(ev["latch_locked_after_respawn"], + "the respawned controller unlocked the latch with no arm (interlock_circuit=%s)", ilk) ev["beam_at_fire_kill"] = smp.get("beam") check_button_dark(ctx, ev) ctx.log("PASS: expected stop 0 at +%s s and SIGKILL 0 at +%s s, latch locked, controller " - "respawned, button dark", ev["expected"]["zero_at_s"], zero_at) + "respawned with the latch still locked, button dark", ev["expected"]["zero_at_s"], zero_at) + + +@test("laser.verdict-cut", title="A blocked verdict mid-cut locks the latch and holds; the clean " + "verdict resumes with no press", + subsystem="laser", kind="live", mode="grbl", est_min=4, + covers=_LASER_COVERS, + requires=["laser.emission-witness"], actions=["button"], + steps=["Scrap under the head with 40 mm of free +X travel; lid closed; exhaust on.", + "Press the physical button when it lights white (the arm). Nothing else: the test " + "takes the cooling verdict away itself and gives it back."], + description="A 40 mm line at constant power (M3 S400/F300, 8 s). About 1.5 s in, the test " + "pauses the machine-services daemon for 3.5 s, so the cooling verdict the " + "controller reads goes stale: the controller's pause tier. The controller must " + "hold the job (grbl Hold) under the still-open armed window with the stream " + "masked dark, so the kernel's LASER_ON sample count reads 0 before the cut " + "resumes, and it must not write the latch: a lock sets the hardware button " + "latch, which only a press clears, so both bit 3 (the SoC lock) and bit 2 " + "(the button latch) of interlock_circuit stay clear through the whole run. " + "When the daemon returns (the verdict fresh, clean, resume_ok), the controller " + "must resume the cut lit from where it stopped, with no button press and no " + "prompt; the M2 program end then disarms as usual. The daemon's own dead-man " + "(5 s of silence) is not reached: the controller keeps reporting through the " + "pause. The beam detector witnesses the cut on both sides of the hold.") +def verdict_cut(ctx): + import os as _os + import signal as _signal + ev = ctx.evidence + fc = ctx.forgectrl + PAUSE_S = 3.5 + pids = hw.pidof("forgectrl") + ctx.check(pids, "no forgectrl process found to pause") + ev["daemon_pids"] = pids + state_path = "/run/forgefirm/grbl.state" + + def grbl_state_file(): + try: + with open(state_path) as f: + return f.read() + except OSError: + return "" + + def resume_daemon(): + for p in pids: + try: + _os.kill(p, _signal.SIGCONT) + except OSError: + pass + + trail = [] + text = "" + with ctx.grbl() as g, LiveJob(ctx, g): + prepare(ctx, g) + k0 = kernel_start(ctx) + base = sample(ctx) + ctx.check(base, "forgectrl /status or /cool/status unavailable") + ctx.check(not base["emission"], "emission_samples nonzero before the job (%s)", base["emission"]) + ctx.ready(ARM_CUE % "40 mm +X") + job = ["G91", "G21", "M3", "S400", "G1 X40 F300", "M5", "G0 X-40", "G90", "M2"] + smp = arm_and_fire(ctx, g, room="40 mm +X", job=job) + beams = [(smp.get("beam"), smp.get("beam_d"))] + ctx.log("emission live (%s); pausing the daemon in 1 s", smp["emission"]) + ctx.sleep(1.0) + g.drain() + t0 = time.time() + try: + for p in pids: + _os.kill(p, _signal.SIGSTOP) + ctx.log("daemon paused (SIGSTOP %s) for %.1f s: the verdict goes stale", pids, PAUSE_S) + # No HTTP while the daemon is paused: the controller's socket, + # sysfs and the controller's state file are the witnesses. + while time.time() - t0 < PAUSE_S: + st = g.status_report()["state"] + text += g.drain() + il = hw.sysfs_int("cnc/interlock_circuit") + trail.append({"t": round(time.time() - t0, 2), "gstate": st, "il": il, + "emission": hw.sysfs_int("cnc/laser_on_sampled"), + "armed": '"armed":true' in grbl_state_file()}) + time.sleep(0.12) + finally: + resume_daemon() + ctx.log("daemon resumed (SIGCONT) at +%.2f s", time.time() - t0) + # Through the resume and to the end of the cut, sampling the same + # witnesses (the daemon's own once it answers again). + resumed_at = None + end = time.time() + 30 + while time.time() < end: + ctx.checkpoint() + st = g.status_report()["state"] + text += g.drain() + il = hw.sysfs_int("cnc/interlock_circuit") + row = {"t": round(time.time() - t0, 2), "gstate": st, "il": il, + "emission": hw.sysfs_int("cnc/laser_on_sampled"), + "armed": '"armed":true' in grbl_state_file()} + if time.time() - t0 > PAUSE_S + 1.0: + s = sample(ctx) + if s: + row["beam"] = s.get("beam") + beams.append((s.get("beam"), s.get("beam_d"))) + trail.append(row) + if resumed_at is None and st.startswith("Run"): + resumed_at = time.time() - t0 + if st.startswith("Idle") and resumed_at is not None and time.time() - t0 > resumed_at + 3.0: + break + time.sleep(0.12) + for r in trail: + ctx.log(" %s", r) + ev["trail"] = trail + ev["messages"] = [ln for ln in text.splitlines() if ln.startswith("[MSG:") or ln.startswith("ALARM")] + ctx.log("controller: %s", ev["messages"]) + dt = wait_disarm(ctx, 75) + ev["disarm_after_idle_s"] = round(dt, 1) if dt is not None else None + ctx.check(ctx.forgectrl.wait_idle(15, abort=ctx.aborted), "machine not idle after the job") + check_kernel_returned(ctx, ev, k0) + + def locked(r): + return r["il"] is not None and bool(r["il"] & IL_LASER_LATCH) + + def button_latched(r): + return r["il"] is not None and bool(r["il"] & IL_BUTTON_LATCH) + + held = [r for r in trail if r["gstate"].startswith("Hold")] + ev.update({"held_at_s": held[0]["t"] if held else None, + "resumed_at_s": round(resumed_at, 2) if resumed_at else None, + "latch_locked_samples": sum(1 for r in trail if locked(r)), + "button_latch_set_samples": sum(1 for r in trail if button_latched(r))}) + ctx.check(held and held[0]["t"] < PAUSE_S, "the stale verdict did not hold the job during the " + "pause (first Hold at %s)", ev["held_at_s"]) + ctx.check("fire masked, job held" in text, "the controller did not report the pause tier") + ctx.check(ev["latch_locked_samples"] == 0, + "the pause tier wrote the latch (locked in %d samples): a lock sets the hardware " + "button latch and the resume would need a press", ev["latch_locked_samples"]) + ctx.check(ev["button_latch_set_samples"] == 0, + "the hardware button latch read SET in %d samples: the resume needed a press", + ev["button_latch_set_samples"]) + ctx.check(all(r["armed"] for r in trail if r["t"] < (resumed_at or PAUSE_S + 5)), + "the armed window closed during the pause") + ctx.check("press the button" not in text, "the resume asked for a button press") + ctx.check(DISARMED_MSG not in text.split("resuming")[0], "the pause tier disarmed the job") + # Dark from the hold until the resume: the gate masked the stream. + span = [r for r in trail if held and r["t"] >= held[0]["t"] + and (resumed_at is None or r["t"] < resumed_at)] + zero = next((r for r in span if r["emission"] == 0), None) + ev["emission_zero_after_hold_s"] = round(zero["t"] - held[0]["t"], 2) if zero else None + ctx.check(zero is not None and zero["t"] - held[0]["t"] <= 2.5, + "emission did not read 0 within 2.5 s of the hold (before the resume)") + ctx.check(resumed_at is not None, "the clean verdict did not resume the cut") + ctx.check("resuming" in text, "the controller did not report the resume") + after = [r for r in trail if resumed_at and r["t"] >= resumed_at] + ctx.check(any(r["emission"] for r in after), "the resumed cut ran dark (no emission after the resume)") + ctx.check("ALARM" not in text, "an alarm was raised on the pause tier") + ctx.check(dt is not None and dt < 10.0, "the M2 job did not disarm promptly at Idle (%s s)", dt) + beam_witness(ctx, ev, [{"beam": b, "beam_d": d} for b, d in beams], base) + judge_beam(ctx, ev["beam"], "the cut") + check_button_dark(ctx, ev) + ctx.log("PASS: held at +%s s with the latch untouched, emission 0 %s s after the hold, resumed " + "lit at +%s s with no press, disarmed %.1f s after Idle", ev["held_at_s"], + ev["emission_zero_after_hold_s"], ev["resumed_at_s"], dt) + + +DISARMED_MSG = "laser disarmed - latch locked" @test("laser.arm-wait-lid", title="Lid open during the arm wait cancels the job", diff --git a/scripts/bench/laser_lifecycle_test.py b/scripts/bench/laser_lifecycle_test.py index 22668dd..e04d3a3 100644 --- a/scripts/bench/laser_lifecycle_test.py +++ b/scripts/bench/laser_lifecycle_test.py @@ -39,6 +39,20 @@ reported messages: not to where it was paused (the core restarts a held cycle through Idle); a job abandoned in a hold and reset ends there, so the next job's start is captured afresh where it begins + 11. the cooling verdict's pause tier (OVERTEMP) holds the job under the + open window without writing the latch (a lock sets the hardware + button latch, which only a press clears); the clean verdict then + resumes it with no new button press: no prompt, no second arm + 12. the verdict's fail tier (AIRFLOW) ends the job: disarmed, reset with + ALARM:3, and a ~ under the clean verdict that follows resumes nothing + 13. a sender change during a re-arm cancels it: the press that follows + resumes nothing, the job stays held, and the new sender's own ~ + prompts afresh + 14. a jog does not hold the armed window open: with the spindle off the + grace counts down through jogs, and the window closes on time + 15. a press counts only after the button has been seen up: a press that + began before the wait is not consent (the harness's own presses + follow a fresh prompt for the same reason) The disarm grace is shortened via a temp config (GFHOME_CONF), the cooling verdict is published hermetically (GF_VERDICT_FILE), the same @@ -141,23 +155,29 @@ def wait_idle(sock, log): fail("controller never returned to Idle") -def publish_verdicts(path, stop, fire_ok, armed_ack=True, ack_after_s=0.0): - """Stand in for the cooling engine. "armed" is the engine's - acknowledgment that it has taken the controller's armed window and - applied the run airflow; the controller refuses to fire on a verdict - that lacks it, so an engine that never acknowledges (armed_ack - False) must produce a refused arm and no emission. ack_after_s - withholds the acknowledgment for that long first, which is the real - engine's case: it answers on its next tick, and the controller has - to see the refreshed verdict to get past the arm.""" +def publish_verdicts(path, stop, verdict): + """Stand in for the cooling engine. `verdict` is the session's live + dict: fire_ok, hold, resume_ok, name, armed_ack, ack_after_s. "armed" + is the engine's acknowledgment that it has taken the controller's + armed window and applied the run airflow; the controller refuses to + fire on a verdict that lacks it, so an engine that never + acknowledges (armed_ack False) must produce a refused arm and no + emission. ack_after_s withholds the acknowledgment for that long + first, which is the real engine's case: it answers on its next + tick, and the controller has to see the refreshed verdict to get + past the arm.""" t0 = time.monotonic() while not stop.is_set(): - acked = armed_ack and time.monotonic() - t0 >= ack_after_s - body = ('{"ts_mono":%.3f,"fire_ok":%s,"hold":false,' - '"resume_ok":true,"armed":%s,"reason":""}' + v = dict(verdict) + acked = v["armed_ack"] and time.monotonic() - t0 >= v["ack_after_s"] + body = ('{"ts_mono":%.3f,"fire_ok":%s,"verdict":"%s","hold":%s,' + '"resume_ok":%s,"armed":%s,"reason":"%s"}' % (time.clock_gettime(time.CLOCK_MONOTONIC), - "true" if fire_ok else "false", - "true" if acked else "false")) + "true" if v["fire_ok"] else "false", v["name"], + "true" if v["hold"] else "false", + "true" if v["resume_ok"] else "false", + "true" if acked else "false", + "" if v["fire_ok"] else "harness: %s" % v["name"])) tmp = path + ".tmp" with open(tmp, "w") as f: f.write(body) @@ -165,6 +185,20 @@ def publish_verdicts(path, stop, fire_ok, armed_ack=True, ack_after_s=0.0): stop.wait(0.5) +def wait_for_new(log, needle, n_before, timeout, sock=None): + """Wait until needle appears in the log more times than n_before: a + fresh occurrence, never a stale match from an earlier job.""" + end = time.time() + timeout + while time.time() < end: + if "".join(log).count(needle) > n_before: + return True + if sock is not None: + read_avail(sock, log, 0.2) + else: + time.sleep(0.1) + return False + + class Session: """One controller process with the lifecycle overrides applied.""" @@ -189,8 +223,10 @@ class Session: self.set_switches(switches) env["GF_SWITCH_FILE"] = self.switch_file self.stop = threading.Event() + self.verdict = {"fire_ok": fire_ok, "hold": False, "resume_ok": True, "name": "OK", + "armed_ack": armed_ack, "ack_after_s": ack_after_s} self.pub = threading.Thread(target=publish_verdicts, - args=(verdict, self.stop, fire_ok, armed_ack, ack_after_s), + args=(verdict, self.stop, self.verdict), daemon=True) self.pub.start() self.proc = subprocess.Popen([BIN, "-p", str(PORT)], @@ -220,6 +256,16 @@ class Session: f.write("%d\n" % word) os.replace(tmp, self.switch_file) + def set_verdict(self, name="OK", fire_ok=True, hold=False, resume_ok=True): + """The engine's next verdicts: a pause tier (OVERTEMP: fire + blocked, hold, no resume), a fail tier (AIRFLOW: the same under a + name the client ends the job on), or clean.""" + self.verdict.update({"name": name, "fire_ok": fire_ok, "hold": hold, + "resume_ok": resume_ok}) + + def count(self, needle): + return "".join(self.log).count(needle) + def send_raw(self, line): """Send a line without waiting for ok/error (the arm wait blocks the gcode stream, so the ok only comes once the button is pressed).""" @@ -867,13 +913,17 @@ def test_lid_open_in_wait(): def start_armed_move(s, tag, gcode="G1 X30 F60"): """Arm through the button and get a long move under way; returns once - the controller reports Run.""" + the controller reports Run. The prompt and the armed message are + waited for as fresh occurrences: a press that lands before the + wait has begun is not consent (rule 15), so the press must follow + THIS job's prompt, not an earlier job's.""" + prompts, armed = s.count(PROMPT), s.count(ARMED) s.send_raw("M4 S100") s.send_raw(gcode) - if not wait_for(s.log, PROMPT, 5, s.sock): + if not wait_for_new(s.log, PROMPT, prompts, 5, s.sock): fail("[%s] no button prompt" % tag) s.press_button() - if not wait_for(s.log, ARMED, 5, s.sock): + if not wait_for_new(s.log, ARMED, armed, 5, s.sock): fail("[%s] the button press did not arm" % tag) if not s.wait_state("Run", 5): fail("[%s] the job never reported Run" % tag) @@ -1045,9 +1095,158 @@ def test_lid_policy_hold(): s.close() +def test_verdict_pause_resumes_without_press(): + """Rule 11: the pause tier holds under the open window without a + latch write; the clean verdict resumes with no press. The window is + proven still open by the absence of any prompt and of a second arm.""" + s = Session("verdict-pause", disarm_s=60, switches=SW_CLOSED) + try: + start_armed_move(s, "verdict-pause", gcode="G1 X30 F120") # 15 s of motion + time.sleep(0.5) + s.set_verdict("OVERTEMP", fire_ok=False, hold=True, resume_ok=False) + if not s.wait_state("Hold", 5): + fail("[verdict-pause] the pause tier did not hold the job (state %s)" % s.state()) + if not wait_for(s.log, "fire masked, job held", 3, s.sock): + fail("[verdict-pause] the pause tier did not report the masked hold") + if "latch locked" in "".join(s.log): + fail("[verdict-pause] the pause tier wrote the latch") + if DISARMED in "".join(s.log): + fail("[verdict-pause] the pause tier closed the armed window") + time.sleep(1.5) + s.set_verdict("OK", fire_ok=True, hold=False, resume_ok=True) + if not s.wait_state("Run", 5): + fail("[verdict-pause] the clean verdict did not resume the job (state %s)" % s.state()) + if not wait_for(s.log, "resuming", 2, s.sock): + fail("[verdict-pause] the resume was not reported") + if RESUME_PROMPT in "".join(s.log) or s.count(PROMPT) != 1: + fail("[verdict-pause] the resume asked for a button press") + if s.armed_count() != 1: + fail("[verdict-pause] the resume armed again (armed messages: %d)" % s.armed_count()) + if "ALARM" in "".join(s.log): + fail("[verdict-pause] the pause tier raised an alarm") + s.sock.sendall(b"\x18") + print("PASS [verdict-pause]: OVERTEMP held under the open window with no latch write; " + "the clean verdict resumed with no press") + finally: + s.close() + + +def test_verdict_fail_tier_ends_job(): + """Rule 12: the fail tier disarms, resets the job with ALARM:3, and + nothing resumes it.""" + s = Session("verdict-fail", disarm_s=60, switches=SW_CLOSED) + try: + start_armed_move(s, "verdict-fail", gcode="G1 X30 F120") + time.sleep(0.5) + s.set_verdict("AIRFLOW", fire_ok=False, hold=True, resume_ok=False) + if not s.wait_state("Alarm", 5): + fail("[verdict-fail] the fail tier did not end the job in Alarm (state %s)" % s.state()) + if not wait_for(s.log, DISARMED, 3, s.sock): + fail("[verdict-fail] the fail tier did not close the armed window") + text = "".join(s.log) + if "ALARM:3" not in text: + fail("[verdict-fail] no ALARM:3 on the fail tier") + if "AIRFLOW" not in text: + fail("[verdict-fail] the fail tier did not name the verdict") + s.set_verdict("OK", fire_ok=True, hold=False, resume_ok=True) + time.sleep(1.5) + s.sock.sendall(b"~") + read_avail(s.sock, s.log, 1.0) + if not s.state().startswith("Alarm"): + fail("[verdict-fail] a ~ after the fail tier resumed something (state %s)" % s.state()) + if "resuming" in "".join(s.log): + fail("[verdict-fail] the client resumed after the fail tier") + send_line(s.sock, "$X", s.log) + if not s.wait_state("Idle", 3): + fail("[verdict-fail] $X did not unlock the alarm") + print("PASS [verdict-fail]: AIRFLOW disarmed, reset the job with ALARM:3, and nothing " + "resumed it") + finally: + s.close() + + +def test_sender_change_during_rearm_cancels(): + """Rule 13: a sender change while a re-arm waits for the press + cancels the re-arm; the press resumes nothing and the job stays + held; the new sender's ~ prompts afresh.""" + s = Session("rearm-sender-change", disarm_s=60, switches=SW_CLOSED) + try: + start_armed_move(s, "rearm-sender-change", gcode="G1 X30 F120") + time.sleep(1.0) + s.sock.close() # mid-move: held, disarmed + time.sleep(0.5) + s.sock = s.connect() + if s.wait_state("Hold", 5) is None: + fail("[rearm-sender-change] the job was not held on the sender change") + s.sock.sendall(b"~") + if not wait_for(s.log, RESUME_PROMPT, 5, s.sock): + fail("[rearm-sender-change] the resume did not prompt for the button") + # A second sender change, inside the re-arm wait. The cancel is + # reported at the disconnect, to nobody (output with no client is + # discarded), so the evidence is what the press does next: nothing. + s.sock.close() + time.sleep(0.5) + s.sock = s.connect() + st = read_state(s, '"connected":true') + if '"arming":false' not in st: + fail("[rearm-sender-change] the re-arm wait survived the sender change: %r" % st) + # A press now is the machine's resume button for the new sender: + # it resumes nothing and arms nothing, it opens a fresh re-arm + # prompt of its own (the displaced consent is gone), and only a + # second press, against that prompt, re-arms the held job. + before = s.armed_count() + prompts = s.count(RESUME_PROMPT) + s.press_button() + read_avail(s.sock, s.log, 1.0) + if s.armed_count() != before or not s.state().startswith("Hold"): + fail("[rearm-sender-change] a press after the canceled re-arm resumed the job " + "(armed %d -> %d, state %s)" % (before, s.armed_count(), s.state())) + if not wait_for_new(s.log, RESUME_PROMPT, prompts, 3, s.sock): + fail("[rearm-sender-change] the press after the cancel did not open a fresh re-arm prompt") + s.press_button() + end = time.time() + 10 + while time.time() < end and s.armed_count() != before + 1: + read_avail(s.sock, s.log, 0.2) + if s.armed_count() != before + 1: + fail("[rearm-sender-change] the second press did not re-arm the held job") + s.sock.sendall(b"\x18") + print("PASS [rearm-sender-change]: the sender change canceled the re-arm; the next press " + "resumed nothing and prompted afresh, and the press after it re-armed") + finally: + s.close() + + +def test_jog_does_not_extend_window(): + """Rule 14: with the spindle off, jogs do not reset the disarm grace: + the window closes on time through them.""" + s = Session("jog-grace", disarm_s=2) + try: + send_line(s.sock, "M4 S100", s.log) + send_line(s.sock, "G1 X1 F600", s.log) + if not wait_for(s.log, ARMED, 5, s.sock): + fail("[jog-grace] job did not arm") + send_line(s.sock, "M5", s.log) + wait_idle(s.sock, s.log) + t0 = time.time() + while time.time() - t0 < 5.0 and DISARMED not in "".join(s.log): + send_line(s.sock, "$J=G91X1F1200", s.log) + read_avail(s.sock, s.log, 0.3) + dt = time.time() - t0 + if DISARMED not in "".join(s.log): + fail("[jog-grace] the window stayed open through %.1f s of jogging (grace 2 s)" % dt) + wait_idle(s.sock, s.log) + print("PASS [jog-grace]: the window closed after %.1f s of jogging with the spindle off" % dt) + finally: + s.close() + + def main(): if not os.path.isfile(BIN): fail("controller binary not found at %s" % BIN) + test_verdict_pause_resumes_without_press() + test_verdict_fail_tier_ends_job() + test_sender_change_during_rearm_cancels() + test_jog_does_not_extend_window() test_job_window() test_status_files() test_laser_keys_reload() diff --git a/scripts/bench/laser_stream_test.py b/scripts/bench/laser_stream_test.py index 43f2e5e..0ff8ad2 100644 --- a/scripts/bench/laser_stream_test.py +++ b/scripts/bench/laser_stream_test.py @@ -79,12 +79,34 @@ over TCP, then checks the dumps against the kernel feeder contract: the default gamma of 2 than at gamma 1, and the cruise middle renders the same - the exponent shapes only the velocity-scaled rolloff, never the programmed level - 24. a hold verdict is held again after a resume: with the engine's - verdict at its fail tier (hold, fire blocked, no resume) the client - holds the job; a ~ under that verdict, which is what a button press - or a sender does, moves the head for at most one client poll, dark, - before the client holds it again and says so; the clean verdict then - resumes the hold the client took, and the rest of the line cuts lit + 24. the verdict's pause tier: with the engine's verdict at a pause + (OVERTEMP: hold, fire blocked, no resume) the client holds the job + under the open window; the deceleration into that first hold runs + lit to the stop, as a feed hold's does (the segments already planned + at speed would otherwise play dark and leave a gap in the cut), and + the stream engine's per-tick gate masks the stream from the stop on; + a ~ under that verdict, which is what a button press or a sender + does, moves the head dark for at most one client poll before the + client holds it again and says so; the clean verdict then resumes + the hold the client took with no new press, and the rest of the line + cuts lit. The latch is never written by a pause (a lock sets the + hardware button latch, which only a press clears): the latch + sideband (GFSINK_LATCH_LOG) carries the unlock at the arm and the + lock at the program end and nothing between + 25. the verdict's fail tier: a verdict named AIRFLOW (fire blocked, hold, + no resume) mid-M3 ends the job: the window closes, the latch locks, + the job is reset with ALARM:3, the stream ends dark well short of the + line, and a ~ under the clean verdict that follows resumes nothing; + the sideband ends on the lock and carries no unlock after it + 26. a sender change mid-M3 closes the window and holds the job, and the + deceleration into that hold ships dark: the gate follows the window + on every tick, so a fire state the core never updates cannot outlive + the consent it rode on + 27. a verdict that goes stale (the engine stops publishing mid-cut) + holds the job the moment the client's cache expires, on its own + clock between two of its file reads, lit to the stop like rule 24: + no dark cut runs out while the client waits for its next read; the + engine's return resumes the cut lit The analog sessions select the reference mode through the config; on hardware the controller ignores it (density is the only product model - @@ -401,28 +423,37 @@ def wait_state(sock, log, prefix, timeout=5.0): fail("controller never reached %s" % prefix) -# The published verdict is clean unless a session sets this: then it is -# the engine's fail tier (hold, fire blocked, no resume), what an airflow -# fault publishes. A ("verdict", "hold") step sets it, ("verdict", +# The published verdict is clean unless a session sets a mode: "hold" is +# the engine's pause tier (OVERTEMP: hold, fire blocked, no resume) and +# "fail" its fail tier (AIRFLOW: the same flags under a name the client +# ends the job on). A ("verdict", ) step sets it, ("verdict", # "clean") clears it. -VERDICT_HOLD = threading.Event() +VERDICT_MODE = {"mode": "clean"} +VERDICT_NAMES = {"hold": "OVERTEMP", "fail": "AIRFLOW"} def publish_verdicts(path, stop): """Publish a fresh cooling verdict every 0.5 s (the arm flow refuses - without one; freshness window is 2 s), clean unless VERDICT_HOLD is - set. Same-host monotonic clock, atomic rename so the reader never - sees a torn file. "armed" is the engine's acknowledgment that it has - taken the controller's armed window; the arm waits for it, so a - stand-in engine that means to let jobs run must assert it.""" + without one; freshness window is 2 s), clean unless VERDICT_MODE + says otherwise. Same-host monotonic clock, atomic rename so the + reader never sees a torn file. "armed" is the engine's + acknowledgment that it has taken the controller's armed window; the + arm waits for it, so a stand-in engine that means to let jobs run + must assert it.""" while not stop.is_set(): - hold = VERDICT_HOLD.is_set() - body = ('{"ts_mono":%.3f,"fire_ok":%s,"hold":%s,' + mode = VERDICT_MODE["mode"] + if mode == "stale": + stop.wait(0.5) # the engine has stopped publishing + continue + blocked = mode != "clean" + body = ('{"ts_mono":%.3f,"fire_ok":%s,"verdict":"%s","hold":%s,' '"resume_ok":%s,"armed":true,"reason":"%s"}' % (time.clock_gettime(time.CLOCK_MONOTONIC), - "false" if hold else "true", "true" if hold else "false", - "false" if hold else "true", - "harness: airflow fault" if hold else "")) + "false" if blocked else "true", + VERDICT_NAMES.get(mode, "OK"), + "true" if blocked else "false", + "false" if blocked else "true", + ("harness: %s" % VERDICT_NAMES[mode]) if blocked else "")) tmp = path + ".tmp" with open(tmp, "w") as f: f.write(body) @@ -442,8 +473,9 @@ def run_session(name, steps, conf=None, workdir=None, keep=False, workdir = tempfile.mkdtemp(prefix="laser-test-") dump = os.path.join(workdir, "stream.bin") verdict = os.path.join(workdir, "cooling.state") + latch_log = os.path.join(workdir, "latch.log") env = dict(os.environ, GFSINK_DUMP=dump, GF_VERDICT_FILE=verdict, - FFLOG_STDERR="1") + GFSINK_LATCH_LOG=latch_log, FFLOG_STDERR="1") # The lens reference the daemon leaves before a controller starts: # forgectrl sweeps the carriage onto the hall edge and marks it, and # the controller opens the Z envelope on that mark. Without one Z @@ -462,7 +494,7 @@ def run_session(name, steps, conf=None, workdir=None, keep=False, env["GFHOME_CONF"] = conf_path stop = threading.Event() - VERDICT_HOLD.clear() + VERDICT_MODE["mode"] = "clean" pub = threading.Thread(target=publish_verdicts, args=(verdict, stop), daemon=True) pub.start() @@ -494,12 +526,18 @@ def run_session(name, steps, conf=None, workdir=None, keep=False, elif isinstance(step, tuple) and step[0] == "rt": sock.sendall(step[1]) # a realtime character: no ok follows elif isinstance(step, tuple) and step[0] == "wait_state": - wait_state(sock, log, step[1]) + wait_state(sock, log, step[1], step[2] if len(step) > 2 else 5.0) elif isinstance(step, tuple) and step[0] == "verdict": - if step[1] == "hold": - VERDICT_HOLD.set() - else: - VERDICT_HOLD.clear() + VERDICT_MODE["mode"] = step[1] + elif isinstance(step, tuple) and step[0] == "expect_text": + if not wait_text(sock, log, step[1], step[2] if len(step) > 2 else 5.0): + fail("[%s] the controller never said %r" % (name, step[1])) + elif isinstance(step, tuple) and step[0] == "reconnect": + # A sender change: the socket closes and a new one connects. + sock.close() + time.sleep(step[1] if len(step) > 1 else 0.3) + sock = socket.create_connection(("127.0.0.1", PORT), timeout=1) + read_avail(sock, log, 0.5) else: send_line(sock, step, log) @@ -522,9 +560,13 @@ def run_session(name, steps, conf=None, workdir=None, keep=False, proc.kill() stop.set() pub.join(2) - VERDICT_HOLD.clear() + VERDICT_MODE["mode"] = "clean" data = open(dump, "rb").read() + try: + run_session.latch = open(latch_log).read().split() + except OSError: + run_session.latch = [] if not data and arm_required: fail("[%s] empty stream dump" % name) if not keep: @@ -532,6 +574,89 @@ def run_session(name, steps, conf=None, workdir=None, keep=False, return data +def wait_text(sock, log, needle, timeout): + """Drain the socket until needle appears in the accumulated log.""" + end = time.time() + timeout + while time.time() < end: + if needle in "".join(log): + return True + read_avail(sock, log, 0.2) + return needle in "".join(log) + + +def latch_transitions(lines): + """The sideband's lock/unlock lines with repeats collapsed: the + ownership sequence as transitions.""" + out = [] + for ln in lines: + if ln in ("lock", "unlock") and (not out or out[-1] != ln): + out.append(ln) + return out + + +def holds_in(ticks, min_run=2000): + """The stationary stretches (no X/Y/Z step for min_run ticks) inside + the motion, as (start, end) tick spans.""" + step = [1 if t & 0x25 else 0 for t in ticks] + first = step.index(1) + last = len(step) - 1 - step[::-1].index(1) + holds, run = [], 0 + for i in range(first, last + 1): + if step[i]: + if run >= min_run: + holds.append((i - run, i)) + run = 0 + else: + run += 1 + return holds + + +# The deceleration into a hold from F3000 (50 mm/s) at the board's +# 700 mm/s^2: 71 ms, about 2000 ticks. A gate that closes with the +# hold darkens all of it but the producer's lead (10 ms, ~280 ticks); +# a fire state that outlives the gate lights it to the last step. +DECEL_TICKS = int(50.0 / 700.0 * MACHINE_TICK_HZ) +DECEL_DARK_MIN = DECEL_TICKS - 600 + + +def dark_lead(ticks, hold): + """Ticks between the last FIRE tick before `hold` and its stop.""" + h0 = hold[0] + last = next((i for i in range(h0 - 1, -1, -1) if ticks[i] & 0x10), None) + return h0 - last if last is not None else h0 + + +def check_decel_dark(name, ticks, hold, what): + """No FIRE tick in the deceleration into `hold` beyond the lead: the + gate closed with the cause (a closed window, a lost sender).""" + lead = dark_lead(ticks, hold) + if lead < DECEL_DARK_MIN: + fail("[%s] the deceleration into the hold ran lit: the last FIRE tick is %d " + "ticks before the stationary stretch, expected at least %d (%s)" + % (name, lead, DECEL_DARK_MIN, what)) + return lead + + +# A lit deceleration ends within the producer's lead (10 ms) plus one +# shipper period (10 ms) of the stop: the gate closes when the core +# reports the hold complete, and the bytes produced ahead of the cursor +# by then ship dark. 1000 ticks is 35 ms, under 0.2 mm at the end of a +# ramp from 50 mm/s; a gate that closed before the head stopped shows +# as the whole deceleration (~2000 ticks) or more. +DECEL_LIT_MAX = 1000 + + +def check_decel_lit(name, ticks, hold, what): + """FIRE ran to the stop: the pause tier keeps the beam through the + deceleration it planned, so no dark motion precedes the hold.""" + lead = dark_lead(ticks, hold) + if lead > DECEL_LIT_MAX: + fail("[%s] %d ticks (%.0f ms) of dark motion before the stop, expected at most %d: " + "the gate closed before the head stopped (%s)" + % (name, lead, lead * 1e3 / MACHINE_TICK_HZ, DECEL_LIT_MAX, what)) + return lead + + def tick_bytes(data): """The stream with power bytes stripped (tick bytes only).""" return bytes(b for b in data if not b & 0x80) @@ -1092,42 +1217,45 @@ def main(): "(%d ticks), lit from the first step out (%d fire ticks)" % (mode, decel, dlen, accel)) - # --- rule 24: a hold verdict is held again after a resume ----------- + # --- rule 24: the verdict's pause tier ------------------------------- # One long line at 50 mm/s. Mid-move the engine's verdict goes to its - # fail tier (hold, fire blocked, no resume: an airflow fault) and the - # client takes the feed hold. A ~ then resumes the job under the - # standing verdict, which is what a button press or a sender does; - # the client must hold it again within its poll, saying so, and the - # stretch it moved in between ships dark. The clean verdict then - # resumes the hold the client took, and the rest of the line cuts lit. + # pause tier (OVERTEMP: hold, fire blocked, no resume): the client + # takes the feed hold, and the stream's gate darkens the deceleration + # into it; the latch is not written. A ~ then resumes the job under + # the standing verdict, which is what a button press or a sender + # does; the client must hold it again within its poll, saying so, + # and the stretch it moved in between ships dark. The clean verdict + # then resumes the hold the client took, and the rest of the line + # cuts lit; M2 closes the window and locks. TICK_HZ = 28160 steps = ["G90", "G21", "M3 S500", "G1 X150 F3000", ("sleep", 0.7), ("verdict", "hold"), ("wait_state", "Hold:0"), ("sleep", 0.5), ("rt", b"~"), ("sleep", 1.2), ("wait_state", "Hold:0"), - ("sleep", 0.5), ("verdict", "clean"), WAIT_IDLE, "M5"] + ("sleep", 0.5), ("verdict", "clean"), WAIT_IDLE, "M5", "M2", + ("expect_text", "laser disarmed")] data = run_session("verdict-rehold", steps, conf=DENSITY_CONF_FLOORED) text = run_session.text if "held again" not in text: fail("[verdict-rehold] the client did not say it held the job again") if "resuming" not in text: fail("[verdict-rehold] the client did not resume its own hold once the verdict cleared") + if "fire masked, job held" not in text: + fail("[verdict-rehold] the pause tier did not report the masked hold") + if "latch locked" in text.split("Pgm End")[0]: + fail("[verdict-rehold] the pause tier locked the latch") + if "ALARM" in text: + fail("[verdict-rehold] the pause tier raised an alarm") ticks = tick_bytes(data) - step = [1 if t & 0x05 else 0 for t in ticks] fire = [1 if t & 0x10 else 0 for t in ticks] - first = step.index(1) + step = [1 if t & 0x05 else 0 for t in ticks] last = len(step) - 1 - step[::-1].index(1) - holds, run = [], 0 # the stationary stretches inside the motion - for i in range(first, last + 1): - if step[i]: - if run >= 2000: - holds.append((i - run, i)) - run = 0 - else: - run += 1 + holds = holds_in(ticks) if len(holds) != 2: fail("[verdict-rehold] expected two holds in the stream, found %d: %s" % (len(holds), holds)) (_h1s, h1e), (h2s, h2e) = holds + lit_lead = check_decel_lit("verdict-rehold", ticks, holds[0], + "a pause keeps the beam through its first deceleration") between = sum(fire[h1e:h2s]) if between: fail("[verdict-rehold] FIRE while resumed under the hold verdict: %d fire ticks " @@ -1139,9 +1267,101 @@ def main(): if lit_after < 50: fail("[verdict-rehold] the resume after the clean verdict ran dark (%d fire ticks)" % lit_after) - print("PASS [verdict-rehold]: held, resumed dark for %d ticks (%.2f s), held again, " - "lit after the clear (%d fire ticks)" - % (h2s - h1e, (h2s - h1e) / float(TICK_HZ), lit_after)) + seq = latch_transitions(run_session.latch) + if seq != ["unlock", "lock"]: + fail("[verdict-rehold] latch ownership sequence %s, expected unlock (arm) and lock " + "(program end) only: a pause must not write the latch" % seq) + print("PASS [verdict-rehold]: held lit to %d ticks before the stop, resumed dark for " + "%d ticks (%.2f s), held again, lit after the clear (%d fire ticks), latch %s" + % (lit_lead, h2s - h1e, (h2s - h1e) / float(TICK_HZ), lit_after, seq)) + + # --- rule 25: the verdict's fail tier -------------------------------- + # The same line; mid-move the verdict goes to AIRFLOW. The job ends: + # window closed, latch locked, ALARM:3, the stream short and dark at + # its end, and the clean verdict that follows resumes nothing. + steps = ["G90", "G21", "M3 S500", "G1 X150 F3000", ("sleep", 0.7), + ("verdict", "fail"), ("wait_state", "Alarm", 5.0), + ("expect_text", "laser disarmed"), ("verdict", "clean"), ("sleep", 1.0), + ("rt", b"~"), ("sleep", 0.5), ("wait_state", "Alarm", 2.0), "$X"] + data = run_session("verdict-fail", steps, conf=DENSITY_CONF_FLOORED) + text = run_session.text + if "ALARM:3" not in text: + fail("[verdict-fail] the fail tier did not end the job with ALARM:3") + if "AIRFLOW" not in text: + fail("[verdict-fail] the fail tier did not name the verdict") + if "resuming" in text or "held again" in text: + fail("[verdict-fail] the fail tier was treated as a pause") + check_termination("verdict-fail", data) + line_ticks = 150.0 / 50.0 * TICK_HZ + lit = count_fire(data) + if lit > line_ticks * 0.5: + fail("[verdict-fail] %d fire ticks: the job ran on past the fail-tier verdict " + "(the whole line is %d)" % (lit, line_ticks)) + seq = latch_transitions(run_session.latch) + if seq != ["unlock", "lock"]: + fail("[verdict-fail] latch ownership sequence %s, expected unlock (arm), lock " + "(the fail tier), and nothing after" % seq) + print("PASS [verdict-fail]: AIRFLOW mid-cut ended the job with ALARM:3, %d of %d ticks " + "lit, ends dark, latch %s, ~ resumed nothing" % (lit, line_ticks, seq)) + + # --- rule 26: a sender change mid-M3 darkens the hold's decel --------- + steps = ["G90", "G21", "M3 S500", "G1 X150 F3000", ("sleep", 0.7), + ("reconnect", 0.3), ("wait_state", "Hold:0", 5.0), ("sleep", 0.5), + ("rt", b"\x18"), ("sleep", 0.5)] + data = run_session("sender-drop", steps, conf=DENSITY_CONF_FLOORED) + ticks = tick_bytes(data) + # No cycle follows the hold here, so the stream ends on the hold's + # deceleration: the stop is the tick after the last step. + step = [1 if t & 0x25 else 0 for t in ticks] + if 1 not in step: + fail("[sender-drop] no motion in the stream") + stop = len(step) - step[::-1].index(1) + if count_fire(data) < 1000: + fail("[sender-drop] the cut before the sender change ran dark (%d fire ticks)" + % count_fire(data)) + dark = check_decel_dark("sender-drop", ticks, (stop, stop), + "the gate must follow the window closed on the sender change") + seq = latch_transitions(run_session.latch) + if seq[:2] != ["unlock", "lock"]: + fail("[sender-drop] latch ownership sequence %s, expected unlock (arm), lock " + "(the sender change)" % seq) + print("PASS [sender-drop]: the sender change held the job with the decel dark from %d " + "ticks before the stop, latch %s" % (dark, seq)) + + # --- rule 27: a stale verdict holds the moment the cache expires ----- + # The engine stops publishing mid-cut. The client reads the file + # every 500 ms and its cache expires on its own clock between two + # reads: the hold must land at the expiry, not at the next read, and + # the deceleration runs lit to the stop like rule 24's, so no dark + # cut runs out in between. The engine's return resumes the cut lit. + steps = ["G90", "G21", "M3 S500", "G1 X150 F3000", ("sleep", 0.7), + ("verdict", "stale"), ("wait_state", "Hold:0", 6.0), ("sleep", 0.5), + ("verdict", "clean"), WAIT_IDLE, "M5", "M2", ("expect_text", "laser disarmed")] + data = run_session("verdict-stale", steps, conf=DENSITY_CONF_FLOORED) + text = run_session.text + if "cooling service lost" not in text: + fail("[verdict-stale] the client did not report the engine gone") + if "resuming" not in text or "restored" not in text: + fail("[verdict-stale] the client did not resume once the engine returned") + ticks = tick_bytes(data) + holds = holds_in(ticks) + if len(holds) != 1: + fail("[verdict-stale] expected one hold in the stream, found %d: %s" % (len(holds), holds)) + lit_lead = check_decel_lit("verdict-stale", ticks, holds[0], + "the hold must land at the cache's expiry, lit to the stop") + fire = [1 if t & 0x10 else 0 for t in ticks] + step = [1 if t & 0x05 else 0 for t in ticks] + last = len(step) - 1 - step[::-1].index(1) + lit_after = sum(fire[holds[0][1]:last + 1]) + if lit_after < 50: + fail("[verdict-stale] the resume after the engine's return ran dark (%d fire ticks)" % lit_after) + seq = latch_transitions(run_session.latch) + if seq != ["unlock", "lock"]: + fail("[verdict-stale] latch ownership sequence %s, expected unlock (arm) and lock " + "(program end) only" % seq) + print("PASS [verdict-stale]: the expired cache held the job lit to %d ticks (%.0f ms) " + "before the stop, lit after the return (%d fire ticks), latch %s" + % (lit_lead, lit_lead * 1e3 / MACHINE_TICK_HZ, lit_after, seq)) # --- rule 22: a jog never fires, whatever the modal spindle says ---- # The arm flow runs on the M3 (window open), the modal spindle is on