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