diff --git a/forgetest/forgetest/suite/cooling.py b/forgetest/forgetest/suite/cooling.py index cfecd5f..d2584f2 100644 --- a/forgetest/forgetest/suite/cooling.py +++ b/forgetest/forgetest/suite/cooling.py @@ -1390,3 +1390,89 @@ def fan_duty_readback(ctx): idle = {k: hw.sysfs_int(k) for k in run} ev["idle_duties"] = idle ctx.log("duties at idle: %s", idle) + + +@test("cooling.fail-tier-stop", title="A fail-tier verdict ends the controller: CRASH stops motion, " + "locks the laser, and the supervisor restarts the controller", + subsystem="cooling", kind="operator", mode="grbl", est_min=4, + covers=_COOL_COVERS + [("forgectrl", "src/super.*")], + requires=["cooling.crash-watch-plumbing", "motion.deadman"], actions=["button"], + steps=["Bed clear, lid closed, 40 mm of free +X travel. Nothing fires: the job is dark (S0).", + "Press the physical button when it lights white, once. The head moves and stops on " + "its own; the controller restarts."], + description="The engine's fail tiers (a lid IR fire signal, a head crash signal) do not " + "leave the job to the controller: after the kernel writes (motion stopped, the " + "latch locked) the engine ends the controller through the supervisor, which " + "starts it again, so no run start can relight what was locked and the sender " + "sees the job end. Provable without emission or a physical crash: the crash " + "watch's thresholds at their lowest (1) make the head's own move trip the abort " + "generator inside an armed, dark (S0) job. Expected: the engine logs the crash " + "signal, the supervisor logs the stop and starts a new controller (new pid), the " + "latch is locked, the kernel idle, no emission, and the thresholds are put back.") +def fail_tier_stop(ctx): + from .laser import prepare, stream, sample + from .motion import FORGECTRL_LOG, _log_lines, _log_offset + fc = ctx.forgectrl + ev = ctx.evidence + before = fc.settings() + orig = {k: before.get(k, "") for k in CRASH_KEYS} + ev["orig"] = orig + ctx.check(fc.wait_idle(15, abort=ctx.aborted), "machine not idle at the start") + st, m0 = fc.get("/mode") + ctx.check(st == 200 and isinstance(m0, dict) and m0.get("controller") == "running", "controller not running: %s", m0) + pid0 = m0.get("pid") + _set_gates(ctx, fc, {k: "1" for k in CRASH_KEYS}) + off = _log_offset(FORGECTRL_LOG) + t_arm = None + try: + try: + with ctx.grbl() as g: + prepare(ctx, g) + ctx.ready("DARK JOB (S0, nothing fires). Bed clear with 40 mm of free +X travel, lid closed. " + "The head moves 20 mm and the controller restarts on its own.") + stream(g, ["G91", "G21", "M3 S0", "G4 P1", "G1 X20 F1200", "G1 X-20 F1200", "M5", "G90", "M2"]) + ctx.arm_press() + t_arm = ctx.wait_for(lambda: bool((sample(ctx) or {}).get("armed")), 240) + ctx.clear_notice() + ctx.check(t_arm is not None, "the window never opened (arm refused, or no press)") + t0 = time.time() + tripped = ctx.wait_for(lambda: _cool(fc).get("verdict") == "CRASH" + or (fc.get("/mode")[1] or {}).get("pid") not in (None, pid0), 30) + ctx.log("the crash tier tripped after %s s", tripped) + except (hw.HwError, OSError) as e: + ctx.log("the Grbl connection ended with the restart: %s", e) + t_kill = time.time() + m1 = None + while time.time() - t_kill < 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) + # the daemon's lines reach the log file through syslog, a moment + # after the events they name + ctx.wait_for(lambda: bool(_log_lines(FORGECTRL_LOG, off, "HEAD CRASH SIGNAL")) + and bool(_log_lines(FORGECTRL_LOG, off, "head crash signal - the controller is stopped")), 15) + engine = _log_lines(FORGECTRL_LOG, off, "HEAD CRASH SIGNAL") + super_ = _log_lines(FORGECTRL_LOG, off, "head crash signal - the controller is stopped") + smp = sample(ctx) + ilk = hw.sysfs_int("cnc/interlock_circuit") + ev["result"] = {"mode_after": m1, "engine_lines": [ln[-160:] for ln in engine[-2:]], + "super_lines": [ln[-160:] for ln in super_[-2:]], + "emission": smp and smp["emission"], "kernel": smp and smp["kstate"], + "latch_locked": ilk is not None and bool(ilk & (1 << 3))} + ctx.log("after the crash tier: %s", ev["result"]) + ctx.check(engine, "the engine did not log the crash signal") + ctx.check(super_, "the supervisor did not log the fail-tier stop") + ctx.check(m1 and m1.get("pid") != pid0, "the controller was not stopped and started again: %s", m1) + ctx.check(ev["result"]["latch_locked"], "latch not locked after the crash tier") + ctx.check(not (smp and smp["emission"]), "emission during a dark job: %s", smp and smp["emission"]) + ctx.check(fc.wait_idle(30, abort=ctx.aborted), "machine not idle after the restart") + finally: + fc.wait_idle(30, abort=ctx.aborted) + st, body = fc.post("/settings", params=orig) + ctx.log("restore thresholds: POST /settings %s -> %s", orig, st) + after = fc.settings() + ctx.check(all(after.get(k, "") == orig[k] for k in CRASH_KEYS), + "thresholds not restored: %s", {k: after.get(k) for k in CRASH_KEYS}) + ctx.log("PASS: the crash tier stopped the job, locked the latch, and the supervisor restarted " + "the controller (pid %s -> %s)", pid0, m1 and m1.get("pid")) diff --git a/forgetest/forgetest/suite/laser.py b/forgetest/forgetest/suite/laser.py index 3e7d4cf..53371a5 100644 --- a/forgetest/forgetest/suite/laser.py +++ b/forgetest/forgetest/suite/laser.py @@ -252,6 +252,26 @@ def kill_trail(ctx, t0, seconds=5.0): return trail +def kill_fast_trail(t0, seconds=1.5): + """The latch and the kernel state read from sysfs every few + milliseconds after a kill: the supervisor's own reaction, which the + HTTP samples of kill_trail cannot resolve. A controller death is a + signal to the supervisor, not a poll, so the relock lands within + milliseconds; the kernel leaves running once its stop ramp is done.""" + locked_at = stopped_at = None + end = t0 + seconds + while time.time() < end and (locked_at is None or stopped_at is None): + now = time.time() - t0 + ilk = hw.sysfs_int("cnc/interlock_circuit") + if locked_at is None and ilk is not None and ilk & IL_LASER_LATCH: + locked_at = round(now, 3) + st = hw.sysfs_read("cnc/state") + if stopped_at is None and st is not None and st != "running": + stopped_at = round(now, 3) + time.sleep(0.005) + return {"latch_locked_at_s": locked_at, "kernel_stopped_at_s": stopped_at} + + def judge_kill(ctx, trail, what): """(first zero, tail stayed zero, kernel stopped running) from a trail.""" for t in trail: @@ -715,7 +735,9 @@ def disarm_in_hold(ctx): "SIGTERM, so emission drops within 2.5 s and stays 0, the kernel is not running, " "and the restart is a separate operator-judged step. Unexpected: mid-burn SIGKILL " "of the controller - the supervisor's exit safing must end the fire tail inside " - "the ring's in-flight window, leave the latch locked, and respawn the controller.") + "the ring's in-flight window, leave the latch locked, and respawn the controller. " + "The death is a signal to the supervisor, not a poll: the latch relocks within " + "300 ms of the kill and the kernel is out of running within a second.") def armed_kill(ctx): ev = ctx.evidence fc = ctx.forgectrl @@ -769,13 +791,20 @@ def armed_kill(ctx): ctx.log("emission live (%s) - SIGKILL controller pid %s NOW", smp["emission"], pid) t_kill = time.time() _os.kill(pid, _signal.SIGKILL) + fast = kill_fast_trail(t_kill) trail = kill_trail(ctx, t_kill) + ctx.log("after the kill (sysfs): %s", fast) zero_at, tail_zero, not_running = judge_kill(ctx, trail, "kill") ilk = hw.sysfs_int("cnc/interlock_circuit") locked = ilk is not None and bool(ilk & (1 << 3)) ev["sigkill"] = {"pid": pid, "zero_at_s": zero_at, "tail_zero": tail_zero, - "kernel_not_running": not_running, "latch_locked": locked, "trail": trail} + "kernel_not_running": not_running, "latch_locked": locked, "trail": trail, + "fast": fast} ctx.log("latch locked after the kill: %s", locked) + ctx.check(fast["latch_locked_at_s"] is not None and fast["latch_locked_at_s"] < 0.3, + "the latch was not locked within 300 ms of the kill: %s", fast) + ctx.check(fast["kernel_stopped_at_s"] is not None and fast["kernel_stopped_at_s"] < 1.0, + "the kernel was still running 1 s after the kill: %s", fast) ctx.check(zero_at is not None and zero_at < 2.5, "emission did not drop within 2.5 s of the kill (first 0 at %s)", zero_at) ctx.check(tail_zero, "emission returned after the kill") diff --git a/forgetest/forgetest/suite/motion.py b/forgetest/forgetest/suite/motion.py index 150d1fb..a5b735d 100644 --- a/forgetest/forgetest/suite/motion.py +++ b/forgetest/forgetest/suite/motion.py @@ -753,11 +753,14 @@ def _return_x(ctx, delta_mm): machine_idle(ctx) -@test("motion.deadman", title="Dead-man: controller kill, controller hang, forgectrl restart mid-move", - subsystem="motion", kind="auto", mode="grbl", est_min=4, +@test("motion.deadman", title="Dead-man: controller kill, controller hang, forgectrl restart mid-move, " + "a kill during the web-service homing", + subsystem="motion", kind="auto", mode="grbl", est_min=6, covers=_MOTION_COVERS + [("forgectrl", "src/main.c"), ("forgectrl", "init/**")], requires=["motion.cancel-abort", "kernel.k1-k2"], - steps=["Bed clear; the head needs 40 mm of free +X travel and must not be at the left rail."], + steps=["Bed clear; the head needs 40 mm of free +X travel and must not be at the left rail. " + "With cloud mode enabled the test also homes through the web service and kills the " + "controller mid-homing (about a minute); the head ends wherever the homing was."], description="SIGKILL of the controller mid-move: the supervisor reaps it, safes (cnc/stop, " "latch relocked - it never unlocked), and respawns within seconds. SIGSTOP (a " "hang) mid-move: the ring drains into a kernel underrun (fast halt, latch " @@ -770,7 +773,10 @@ def _return_x(ctx, delta_mm): "move completes with every step (the armed case faults, proven on the host). " "forgectrl restart mid-move: the busy controller finishes the move unmanaged " "and the new daemon retakes supervision at idle. After each drill the head is " - "jogged back by the kernel-measured distance.") + "jogged back by the kernel-measured distance. SIGKILL during $H (the web-service " + "homing, with cloud mode enabled): the homing runner the controller left behind " + "is ended before the respawn, the kernel is idle when the new controller starts, " + "and the pulse device has one controller on it.") def deadman(ctx): import os as _os import signal as _signal @@ -978,8 +984,155 @@ def deadman(ctx): x1 = _kernel_x_mm(ctx) _return_x(ctx, (x1 - x0) if (x0 is not None and x1 is not None) else None) machine_idle(ctx) + + # ---- 4. SIGKILL during $H: the homing runner is ended, the kernel idle, one writer + homing_kill(ctx, wait_running) + ctx.log("PASS: kill respawned in %s s, hang -> underrun in %s s, short stall warned and completed, " - "restart retook supervision (pid %s)", respawn_s, halt_s, m3.get("pid")) + "restart retook supervision (pid %s), the kill during $H ended the runner (%s)", + respawn_s, halt_s, m3.get("pid"), ev.get("homing_kill", {}).get("runner_gone_s", "skipped")) + + +def _pulse_holders(): + """The processes holding the pulse device open, by name.""" + out = [] + for pid in os.listdir("/proc"): + if not pid.isdigit(): + continue + try: + for fd in os.listdir("/proc/%s/fd" % pid): + if os.readlink("/proc/%s/fd/%s" % (pid, fd)) == "/dev/glowforge": + with open("/proc/%s/comm" % pid) as f: + out.append(f.read().strip()) + break + except OSError: + continue + return out + + +def homing_kill(ctx, wait_running): + """SIGKILL the GRBL controller while gfhome (the web-service homing + runner, its own process group on the inherited pulse fd) is moving + the head. The supervisor must end the runner before it starts another + controller, or two processes write the ring. Skipped when cloud mode + is not enabled on the machine (the runner needs the service).""" + import os as _os + import signal as _signal + fc = ctx.forgectrl + ev = ctx.evidence + before = fc.settings() + if str(before.get("cloud_enabled", "")).lower() not in ("1", "true", "yes", "on"): + ctx.log("kill during $H: skipped, cloud mode is not enabled on this machine") + return + hm = before.get("homing_mode", "") + ev["homing_kill"] = {"homing_mode": hm} + if hm != "gfcloud": + st, body = fc.post("/settings", data={"homing_mode": "gfcloud"}) + ctx.check(st == 200, "homing_mode=gfcloud -> %s %s", st, body) + try: + m4 = wait_running(10) + ctx.check(m4, "controller not running before the homing drill") + pid4 = m4["pid"] + off = _log_offset(FORGECTRL_LOG) + runner_up = None + try: + with ctx.grbl() as g: + clean_slate(ctx, g) + g.send_raw(b"$H\n") + runner_up = ctx.wait_for(lambda: bool(hw.pidof("gfhome.py")), 30) + ctx.check(runner_up is not None, "the homing runner never started for $H") + ctx.sleep(3.0) # into the session: the runner drives the head + ctx.log("SIGKILL sent to controller pid %d during $H (runner pid %s)", + pid4, hw.pidof("gfhome.py")) + _os.kill(pid4, _signal.SIGKILL) + except (hw.HwError, OSError) as e: + ctx.log("the Grbl connection ended with the kill: %s", e) + t_kill = time.time() + gone_s = ctx.wait_for(lambda: not hw.pidof("gfhome.py"), 15) + ev["homing_kill"]["runner_gone_s"] = gone_s + ctx.check(gone_s is not None, "the homing runner outlived its controller") + m5 = None + while time.time() - t_kill < 60: + st, m5 = fc.get("/mode") + if isinstance(m5, dict) and m5.get("controller") == "running" and m5.get("pid") != pid4: + break + ctx.sleep(0.5) + kstate = hw.sysfs_read("cnc/state") + holders = _pulse_holders() + lines = _log_lines(FORGECTRL_LOG, off, "homing runner") + halted = _log_lines(FORGECTRL_LOG, off, "halting it") + ev["homing_kill"].update({"respawn_s": round(time.time() - t_kill, 1), "mode_after": m5, + "kernel_state_at_respawn": kstate, "pulse_holders": holders, + "super_lines": [ln[-160:] for ln in lines[-3:]]}) + ctx.log("kill during $H: runner gone in %s s, respawned as %s, kernel %s, pulse held by %s", + gone_s, m5 and m5.get("pid"), kstate, holders) + ctx.check(m5 and m5.get("pid") != pid4, "no respawn after the kill during $H: %s", m5) + ctx.check(lines, "the supervisor did not log the runner's end") + ctx.check(not halted, "the kernel had to be halted for the respawn: %s", halted[-1:]) + ctx.check(kstate in ("idle", "disabled"), "the kernel was %s when the new controller started", kstate) + ctx.check("gfhome.py" not in holders and holders.count("grblHAL_glowfor") <= 1, + "more than one controller on the pulse device: %s", holders) + ctx.check(fc.wait_idle(15, abort=ctx.aborted), "machine not idle after the drill") + finally: + if hm != "gfcloud": + st, body = (fc.post("/settings", params={"homing_mode": ""}) if not hm + else fc.post("/settings", data={"homing_mode": hm})) + ctx.log("restore homing_mode=%r -> %s", hm, st) + + +@test("motion.respawn-gate", title="A respawn waits for the lid the way a first spawn does", + subsystem="motion", kind="operator", mode="grbl", est_min=2, + covers=_MOTION_COVERS, requires=["motion.deadman", "motion.gate-waits-for-lid"], actions=["lid"], + steps=["Bed clear. Open the lid when told and close it when told; nothing moves."], + description="The enclosure check runs before every controller spawn, respawns included. " + "With the lid open, the controller is killed: the supervisor safes the machine " + "(latch locked), reports waiting with why naming the lid, and starts no controller " + "while the lid stays open. When the lid closes the controller comes back verified, " + "without a second motion probe (the probe is once per broker hold).") +def respawn_gate(ctx): + import os as _os + import signal as _signal + fc = ctx.forgectrl + ev = ctx.evidence + ctx.check(fc.wait_idle(15, abort=ctx.aborted), "machine not idle at the start") + st, m0 = fc.get("/mode") + ctx.check(st == 200 and isinstance(m0, dict) and m0.get("controller") == "running", "controller not running: %s", m0) + pid0 = m0.get("pid") + off = _log_offset(FORGECTRL_LOG) + ctx.act("lid", "open") + try: + ctx.sleep(1.0) + _os.kill(pid0, _signal.SIGKILL) + t_kill = time.time() + ctx.log("SIGKILL sent to controller pid %d with the lid open", pid0) + waited = ctx.wait_for(lambda: (fc.get("/mode")[1] or {}).get("controller") == "waiting", 15) + st, m1 = fc.get("/mode") + ev["after_kill"] = {"waiting_s": waited, "mode": m1} + ctx.log("mode %.1f s after the kill: %s", time.time() - t_kill, m1) + ctx.check(waited is not None, "the supervisor did not report waiting for the lid: %s", m1) + ctx.check("lid" in (m1.get("why") or ""), "why does not name the lid: %r", m1.get("why")) + ilk = hw.sysfs_int("cnc/interlock_circuit") + ctx.check(ilk is not None and ilk & (1 << 3), "latch not locked after the kill") + ctx.sleep(4.0) + st, m2 = fc.get("/mode") + ctx.check(isinstance(m2, dict) and m2.get("controller") == "waiting" and not m2.get("pid"), + "the wait did not hold with the lid open: %s", m2) + finally: + ctx.act("lid", "close") + t_close = time.time() + came = ctx.wait_for(lambda: ((fc.get("/mode")[1] or {}).get("controller") == "running" + and (fc.get("/mode")[1] or {}).get("pid") != pid0), 60) + st, m3 = fc.get("/mode") + ev["after_close"] = {"running_s": came, "mode": m3} + ctx.log("mode %.1f s after the lid closed: %s", time.time() - t_close, m3) + ctx.check(came is not None and m3.get("motion") == "verified", + "the controller did not come back verified after the lid closed: %s", m3) + lines = _probe_lines(FORGECTRL_LOG, off) + ev["probe_lines"] = lines[-2:] + ctx.check(not lines, "the motion probe ran again for the respawn: %s", lines[:1]) + ctx.check(fc.wait_idle(15, abort=ctx.aborted), "machine not idle at the end") + ctx.log("PASS: the respawn waited %.1f s for the lid, then came back verified in %.1f s with no probe", + t_close - t_kill, came) @test("motion.soft-limits", title="After a home the bed is the X/Y envelope",