mirror of
https://github.com/openglow-org/forgefirm.git
synced 2026-10-19 02:51:42 -07:00
ScottW514
e1d1c1b84e
The soft-reset check's comment described the kernel's ramp with the
continuous formula: (f0^2 - 900^2) / (2 a) ticks, 12687 over 223 ms
at the x32 tick, and a part-way run-out at f0 * sqrt(1 - 2 (a / f0)
Q). The kernel's ramp is stepped (cnc.c, ramp_update_tasklet_fn): the
tick holds for the first 10 ms after the stop, then every 10 ms drops
by ramp_rate / 100 until it reaches the 900 Hz floor, which plays
10 ms before the stop. At 112640 Hz and 500000 Hz/s that is 5000 Hz
off every 10 ms: 24 intervals, 240 ms, about 13270 ticks, 118 ms of
the tick. The comment now says so, with the figures that follow: the
rate at a run-out is 24% of the tick with 110 ms of queue left, 38%
with 100 ms, 51% with 90 ms; the tail's mean over the 25 to 30 ms the
poll samples is 32%, 45% and 56% (61% over the 50 ms window bound),
not 21% to 56%; the 70% bound is 14 points above the slowest ramped
tail and 30 below a run-out; the time to leave running is the 100 ms
hold plus the run's end on the ramp, about 240 ms with 100 ms left,
270 ms with 110 ms, 340 ms at the floor. The evidence's ramp_ticks and
ramp_s stay the continuous figures, and the comment says they are,
about 4% and 7% under the stepped ramp's. No judge changes: the 70%
bound, the 25 ms window and the 50 ms gap stay.
The Alarm wait's failure text names a sampling stall: when the 5 ms
sampling loop runs past 2 s after the ^X, the wait has no time to
read a state, and the failure read "not in Alarm within 2 s (state
None)". It now says the state is unread because the sampling loop ran
past the 2 s. The condition is the same; the text is the change.
Proof: a compile and pyflakes 4.0.3 give no message on
forgetest/suite/motion.py, with no undefined name in forgetest or
tests. forgetest unit tests, python3 -B -m unittest discover -s tests
-p test_<name>.py, in a private PID namespace: test_manifest.py 39
OK, test_queue.py 15 OK, test_campaign.py 13 OK. Coverage lint on the
tree manifest from scripts/manifest-from-tree.py (python3 -B -m
forgetest.coverage --manifest ../tree-manifest.json --enforce):
0 uncovered, 0 empty, 0 host-tested row problems, 43 tests. Host dry
runs of the whole test against the null-sink build of the
grblHAL-glowforge default branch head ("serial_test: the scan's exempt
arguments each match once in the sources"), with the machine side
stood in for as before: with a model kernel that ramps from the
controller's cnc/stop write, the test passes, MPos X 3502.07 steps
against 3502, tail 22% of the tick; with a model kernel that ramps as
cnc.c does, 5000 Hz off every 10 ms from 110 ms of queue, the test
passes, MPos X 3496.95 steps against 3497, tail 33% of the tick, the
figure the comment gives for a run-out from 110 ms of queue.
Acceptance: the comment and the message text are inside the test's
own function, so the shared text of suite/motion.py does not change.
The fingerprint of motion.jog-roundtrip moves, and no other test's:
of the implementation hashes of the 43 catalog tests, before and
after, only that one differs.
1502 lines
75 KiB
Python
1502 lines
75 KiB
Python
# Copyright 2026 514 LLC d/b/a OpenGlow
|
|
# Written by Scott Wiederhold
|
|
# https://community.openglow.org
|
|
# SPDX-License-Identifier: MIT
|
|
|
|
"""motion.* - the motion controller under grblHAL: dry motion, no emission.
|
|
|
|
Ported from `scripts/bench/pacing_test.py` (protocol-loop pacing) and
|
|
`scripts/bench/bench_m2.py` (motion-quality bench). Every move is relative
|
|
and round-trip; the laser stays latched (the tests never touch it); the
|
|
suite is the only Grbl client while a test runs.
|
|
"""
|
|
import json
|
|
import os
|
|
import struct
|
|
import time
|
|
|
|
from ..catalog import test
|
|
from .. import baseline as _baseline
|
|
from .. import hw
|
|
from ..runner import Failed
|
|
|
|
_MOTION_COVERS = [("grblhal-glowforge", "src/**"), ("kernel-module-glowforge", "**"),
|
|
("forgectrl", "src/super.*"), ("forgectrl", "src/liveness.*")]
|
|
|
|
|
|
def controller_pid():
|
|
pids = hw.pidof("grblHAL_glowfor")
|
|
if not pids:
|
|
try:
|
|
st, m = hw.Forgectrl().get("/mode")
|
|
where = ("forgectrl reports mode=%s controller=%s" % (m.get("mode"), m.get("controller"))
|
|
if st == 200 and isinstance(m, dict) else "forgectrl /mode -> %s" % st)
|
|
except hw.HwError as e:
|
|
where = "forgectrl unreachable (%s)" % e
|
|
raise Failed("controller process not found (grblHAL_glowforge); %s" % where)
|
|
return pids[0]
|
|
|
|
|
|
def cpu_ticks(pid):
|
|
with open("/proc/%d/stat" % pid) as f:
|
|
s = f.read().split()
|
|
return int(s[13]) + int(s[14]) # utime + stime (all threads)
|
|
|
|
|
|
def cpu_percent(ctx, pid, window):
|
|
import os
|
|
hz = os.sysconf("SC_CLK_TCK")
|
|
a = cpu_ticks(pid)
|
|
ctx.sleep(window)
|
|
b = cpu_ticks(pid)
|
|
return 100.0 * (b - a) / (hz * window)
|
|
|
|
|
|
def wait_state(ctx, g, prefix, timeout):
|
|
end = time.time() + timeout
|
|
while time.time() < end:
|
|
ctx.checkpoint()
|
|
st = g.status_report()
|
|
if st["state"].startswith(prefix):
|
|
return st
|
|
time.sleep(0.1)
|
|
return None
|
|
|
|
|
|
def wait_idle(ctx, g, timeout=30.0, poll=0.05, grace=0.3):
|
|
"""Poll until Idle; returns (peak_feed_mm_min, states_seen, final_report).
|
|
An Idle report inside the first `grace` seconds counts only once a
|
|
non-Idle state was seen: a move just commanded may not have started."""
|
|
peak = 0.0
|
|
states = []
|
|
t0 = time.time()
|
|
deadline = t0 + timeout
|
|
st = None
|
|
while time.time() < deadline:
|
|
ctx.checkpoint()
|
|
st = g.status_report()
|
|
state = st["state"]
|
|
if not states or states[-1] != state:
|
|
states.append(state)
|
|
f = st.get("FS") or st.get("F")
|
|
if f:
|
|
try:
|
|
peak = max(peak, float(str(f).split(",")[0]))
|
|
except ValueError:
|
|
pass
|
|
if state.startswith("Idle") and (time.time() - t0 >= grace or len(states) > 1):
|
|
return peak, states, st
|
|
time.sleep(poll)
|
|
return peak, states + ["TIMEOUT"], st
|
|
|
|
|
|
def machine_idle(ctx, timeout=15.0):
|
|
"""The machine itself idle - the kernel has played out the stream
|
|
depth and the decel tail behind grblHAL's Idle. Every motion test ends
|
|
on this, so it hands the machine back at rest."""
|
|
ok = ctx.forgectrl.wait_idle(timeout, abort=ctx.aborted)
|
|
ctx.check(ok, "the machine did not return to idle within %.0f s of the last move", timeout)
|
|
|
|
|
|
def clean_slate(ctx, g):
|
|
st = g.status_report()
|
|
ctx.log("connect: %s", st["state"])
|
|
if any(k in st["state"] for k in ("Alarm", "Door", "Hold")):
|
|
g.realtime(0x18) # soft reset
|
|
ctx.sleep(2)
|
|
g.drain()
|
|
st = g.status_report()
|
|
if "Alarm" in st["state"]:
|
|
ctx.log("unlock: %s", g.command("$X"))
|
|
st = g.status_report()
|
|
ctx.check(st["state"].startswith("Idle"), "controller is %s, expected Idle", st["state"])
|
|
clear_error(ctx, g)
|
|
return st
|
|
|
|
|
|
def clear_error(ctx, g):
|
|
"""Clear a latched line error before the test's first move.
|
|
|
|
Soft limits are armed after a home (the driver's, since the bed has
|
|
no switches), so a jog past the bed is refused with error:15 - and
|
|
grblHAL then answers error:15 to every following G-code line, across
|
|
a fresh connection, until a blank line acknowledges it ($ commands
|
|
and the ? report are unaffected, so a sender that queries on connect
|
|
self-clears; a bare G-code stream does not). A prior test's or the
|
|
baseline hand-back's rejected jog would otherwise make this test's
|
|
first move fail with a stale error unrelated to the move. A blank
|
|
line clears it and returns ok. Harmless and idempotent at Idle."""
|
|
r = g.command("")
|
|
ctx.check(r and r[-1] == "ok" and not any(x.startswith("error") for x in r),
|
|
"the controller answered %s to a blank line at the start - not a clean parser", r)
|
|
|
|
|
|
@test("motion.pacing", title="Protocol-loop pacing (idle, parked, moving) and hold/resume position",
|
|
subsystem="motion", kind="auto", mode="grbl", est_min=1,
|
|
covers=_MOTION_COVERS, requires=["kernel.latch-locked-idle"],
|
|
steps=["Bed clear; the head needs 30 mm of free +X travel."],
|
|
description="Idle CPU is low; a job parked in a completed feed hold is coarse-paced (not "
|
|
"busy-spinning at the motion rate); active motion is tight-paced; a feed-hold "
|
|
"mid-move then resume preserves position (the feeder never starves).")
|
|
def pacing(ctx):
|
|
dist, feed = 30.0, 600.0
|
|
pid = controller_pid()
|
|
ev = ctx.evidence
|
|
ev["controller_pid"] = pid
|
|
with ctx.grbl() as g:
|
|
clean_slate(ctx, g)
|
|
g.command("M5")
|
|
g.command("G91")
|
|
idle = cpu_percent(ctx, pid, 3)
|
|
ev["idle_cpu_pct"] = round(idle, 1)
|
|
ctx.log("[1] idle CPU = %.1f%%", idle)
|
|
|
|
start = g.status_report().get("MPos")
|
|
ctx.check(start, "no MPos in the status report")
|
|
g.command("G1 X%.3f F%.0f" % (dist, feed), timeout=0.5)
|
|
ctx.sleep(0.6)
|
|
moving = cpu_percent(ctx, pid, 1.0)
|
|
st_mv = g.status_report()["state"]
|
|
ev["moving_cpu_pct"] = round(moving, 1)
|
|
ctx.log("[3] state=%s CPU during move = %.1f%%", st_mv, moving)
|
|
|
|
g.realtime(ord("!")) # feed hold
|
|
wait_state(ctx, g, "Hold", 5)
|
|
ctx.sleep(1.5) # decel completes (Hold:1 -> Hold:0)
|
|
held = g.status_report()
|
|
parked = cpu_percent(ctx, pid, 3)
|
|
ev["held_state"] = held["state"]
|
|
ev["parked_cpu_pct"] = round(parked, 1)
|
|
ctx.log("[2] %s: CPU parked in Hold = %.1f%%", held["state"], parked)
|
|
|
|
g.realtime(ord("~")) # resume
|
|
peak, states, st = wait_idle(ctx, g, 30)
|
|
ctx.check("TIMEOUT" not in states, "did not return to Idle after the resume: %s", states)
|
|
end = st.get("MPos")
|
|
moved = end[0] - start[0]
|
|
ev["moved_mm"] = round(moved, 3)
|
|
ctx.log("[4] start X=%.3f end X=%.3f moved=%.3f (expect %.1f)", start[0], end[0], moved, dist)
|
|
# return to the starting position
|
|
g.command("G1 X%.3f F%.0f" % (-dist, feed), timeout=0.5)
|
|
wait_idle(ctx, g, 30)
|
|
g.command("G90")
|
|
final = g.status_report().get("MPos")
|
|
ev["final_drift_mm"] = round(final[0] - start[0], 3) if final else None
|
|
machine_idle(ctx)
|
|
|
|
ctx.check(abs(moved - dist) < 0.05, "hold+resume lost steps: moved %.3f of %.1f mm", moved, dist)
|
|
ctx.check(parked < moving * 0.5 and parked < 8.0,
|
|
"parked Hold is not coarse-paced: %.1f%% (moving %.1f%%)", parked, moving)
|
|
ctx.check(idle < 8.0, "idle CPU %.1f%%", idle)
|
|
ctx.log("PASS: idle %.1f%%, moving %.1f%%, parked %.1f%%, hold/resume exact", idle, moving, parked)
|
|
|
|
|
|
@test("motion.jog-roundtrip", title="Motion quality: bounded jogs, max rate, diagonal, hold/resume, "
|
|
"a soft reset during a move",
|
|
subsystem="motion", kind="auto", mode="grbl", est_min=3,
|
|
covers=_MOTION_COVERS + [("forgectrl", "src/main.c")],
|
|
requires=["kernel.latch-locked-idle", "kernel.k1-k2"],
|
|
steps=["Setup: the head parked with at least 60 mm of free +X and 40 mm of free +Y travel; "
|
|
"bed clear, lid closed."],
|
|
description="Sanity jogs (X, Y 40 mm out/back at F2400), max-rate X out/back (60 mm at "
|
|
"F12000), a diagonal out/back, then a G1 with a feed-hold/resume in the middle. "
|
|
"Then a soft reset (^X) during a 60 mm G1 at F3000: the kernel ramps the motion "
|
|
"down (its tick rate falls before the run ends) and leaves running with no "
|
|
"underrun and no fault, the ring is empty after the reset, MPos matches the "
|
|
"kernel's step counters within half a step after $X, the homed mask is kept, the sender "
|
|
"is not told the position is lost, and a jog back by the MPos distance returns "
|
|
"the kernel's X counter to its start within a step. "
|
|
"No jog refused, every move returns to Idle, position drift within 0.05 mm, and "
|
|
"the head accelerometer - the supervisor's own motion witness - saw the head move "
|
|
"on every jog it could sample; the counters alone are not proof of motion.")
|
|
def jog_roundtrip(ctx):
|
|
ev = ctx.evidence
|
|
|
|
def reset_during_move(g):
|
|
"""A soft reset during a move, from rest with the head at the start:
|
|
the kernel's ramp, the position read back from its step counters,
|
|
the reference kept, and the head jogged back. The readings go to the
|
|
evidence; the failures are returned, for the caller to judge once
|
|
the head is back."""
|
|
fc = ctx.forgectrl
|
|
machine_idle(ctx)
|
|
g.drain()
|
|
spm = [grbl_setting(g, k) for k in ("$100", "$101", "$102")]
|
|
ctx.check(all(spm), "the step scales did not read back ($100 %s, $101 %s, $102 %s)", *spm)
|
|
f0 = hw.sysfs_int("cnc/step_freq")
|
|
ramp = hw.sysfs_int("cnc/ramp_rate")
|
|
ctx.check(f0 and ramp, "cnc/step_freq %s, cnc/ramp_rate %s: the kernel's tick is unreadable",
|
|
f0, ramp)
|
|
under0, faults0 = hw.sysfs_int("cnc/underruns"), hw.sysfs_read("cnc/faults")
|
|
p0 = _kernel_position()
|
|
m0 = g.status_report().get("MPos")
|
|
h0 = _port_state(fc).get("homed")
|
|
ctx.check(m0, "no MPos in the status report before the reset")
|
|
# The mask comes from the controller port's state record: $# prints
|
|
# its [HOME:...:mask] line only with $22 on, which the driver
|
|
# leaves off. The driver always holds the Z bit (the lens hold);
|
|
# without it the mask could not tell a kept reference from a
|
|
# dropped one.
|
|
ctx.check(isinstance(h0, int) and h0 & 4,
|
|
"the homed mask reads %r before the reset: the lens hold (Z, 4) is not in it, so "
|
|
"the mask cannot witness the reset", h0)
|
|
log0 = _log_offset(GRBLHAL_LOG)
|
|
rec = {"step_freq": f0, "ramp_rate": ramp, "spm": spm, "kernel_before": list(p0),
|
|
"mpos_before": list(m0), "homed_before": h0}
|
|
r = g.command("G91G1X60F3000", timeout=0.5)
|
|
ctx.check(not any(x.startswith("error") for x in r), "the 60 mm G1 was refused: %s", r)
|
|
ctx.check(wait_state(ctx, g, "Run", 2.0), "the 60 mm G1 did not start (no Run within 2 s)")
|
|
# The kernel's run starts a queue depth behind the core's; the ^X
|
|
# lands 0.3 s into it, with the head at its cruise (the move takes
|
|
# 1.2 s, its acceleration 71 ms).
|
|
ok = ctx.wait_for(lambda: hw.sysfs_read("cnc/state") == "running", 1.0, poll=0.01)
|
|
ctx.check(ok is not None, "the kernel did not start the 60 mm G1 within 1 s of Run (cnc/state %s)",
|
|
hw.sysfs_read("cnc/state"))
|
|
time.sleep(0.3)
|
|
kx = _kernel_position()
|
|
kstate = hw.sysfs_read("cnc/state")
|
|
ctx.check(kstate == "running", "the kernel was %s at the ^X: the move had ended before it", kstate)
|
|
g.realtime(0x18)
|
|
t_x = time.time()
|
|
# The stop: the kernel leaves running, polled at 5 ms. Each sample
|
|
# is the time after the ^X, the state, the bytes played and the
|
|
# bytes handed (the position record).
|
|
samples = []
|
|
while True:
|
|
st = hw.sysfs_read("cnc/state")
|
|
pos = _kernel_position()
|
|
t = time.time() - t_x
|
|
samples.append((t, st, pos[3], pos[4]))
|
|
if st != "running" or t > 1.0:
|
|
break
|
|
time.sleep(0.005)
|
|
state = None
|
|
end = t_x + 2.0
|
|
while time.time() < end:
|
|
state = g.status_report()["state"]
|
|
if state.startswith("Alarm"):
|
|
break
|
|
time.sleep(0.05)
|
|
rec.update({"t_x": round(t_x, 3), "queue_at_x": kx[4] - kx[3], "kernel_end_state": samples[-1][1],
|
|
"left_running_s": round(samples[-1][0], 4), "samples": len(samples),
|
|
"state_after_x": state})
|
|
ev["reset"] = rec
|
|
if not (state or "").startswith("Alarm"):
|
|
if (state or "").startswith("Idle"):
|
|
ctx.fail("the move had ended before the ^X: the controller is Idle with no alarm")
|
|
ctx.fail("the controller was not in Alarm within 2 s of the ^X (state %s)",
|
|
state or "unread: the 5 ms sampling loop ran past the 2 s")
|
|
|
|
# The read-back ends inside a second of the reset, and the core's
|
|
# re-init flushes what it has read: the unlock goes after both.
|
|
ctx.sleep(max(0.0, t_x + 2.0 - time.time()))
|
|
text = g.drain()
|
|
r = g.command("$X")
|
|
text += "\n".join(r) + "\n"
|
|
rec["unlock"] = r
|
|
ctx.check(r and r[-1] == "ok", "$X after the reset answered %s", r)
|
|
ctx.check(wait_state(ctx, g, "Idle", 5.0), "the controller is not Idle after $X")
|
|
machine_idle(ctx)
|
|
text += g.drain()
|
|
m1 = g.status_report().get("MPos")
|
|
p1 = _kernel_position()
|
|
h1 = _port_state(fc).get("homed")
|
|
ctx.check(m1, "no MPos in the status report after $X")
|
|
lost = [ln.strip() for ln in text.splitlines()
|
|
if ln.strip().startswith("[MSG:") and "read back" in ln]
|
|
kd = [p1[a] - p0[a] for a in range(3)]
|
|
md = [(m1[a] - m0[a]) * spm[a] for a in range(3)]
|
|
rec.update({"kernel_after": list(p1), "mpos_after": list(m1), "homed_after": h1,
|
|
"kernel_delta_steps": kd, "mpos_delta_steps": [round(v, 2) for v in md],
|
|
"ring_after": p1[4] - p1[3], "lost_messages": lost,
|
|
"readback_log": _log_lines(GRBLHAL_LOG, log0,
|
|
"soft reset: the kernel ramped the motion down")[-1:]})
|
|
|
|
# Hand back: a jog by the MPos distance (a jog carries its own G91:
|
|
# the reset restored the parser's defaults).
|
|
dx = m1[0] - m0[0]
|
|
if abs(dx) >= 0.001:
|
|
r = g.command("$J=G91X%.3fF3000" % -dx)
|
|
ctx.check(not any(x.startswith("error") for x in r), "the jog back was refused: %s", r)
|
|
_, states, _ = wait_idle(ctx, g)
|
|
ctx.check("TIMEOUT" not in states, "the jog back did not return to Idle")
|
|
machine_idle(ctx)
|
|
p2 = _kernel_position()
|
|
under1, faults1 = hw.sysfs_int("cnc/underruns"), hw.sysfs_read("cnc/faults")
|
|
rec.update({"kernel_handed_back": list(p2), "underruns": [under0, under1], "faults": [faults0, faults1]})
|
|
|
|
# The ramp: the kernel decelerated. Nothing but its ramp lowers the
|
|
# tick rate once a run is up to speed, so the bytes it played over
|
|
# the run's last 25 to 50 ms, against the tick, say whether the run
|
|
# ended at speed or decelerated. The queue at cnc/stop is about
|
|
# 110 ms of ticks: the ring holds 200 ms and the producer leads by
|
|
# 10 ms, and the core's alarm hold plays 100 ms of it at the tick
|
|
# before the driver's stop. The kernel's ramp is stepped (cnc.c,
|
|
# ramp_update_tasklet_fn): the tick holds for the first 10 ms,
|
|
# then every 10 ms it drops by ramp_rate / 100 until it reaches
|
|
# the 900 Hz floor, which plays 10 ms before the stop. At the x32
|
|
# tick of 112640 Hz and its 500000 Hz/s ramp that is 5000 Hz off
|
|
# every 10 ms: 24 intervals, 240 ms, about 13270 ticks, 118 ms of
|
|
# the tick (the ramp scales with the tick, so every mode gives the
|
|
# same fractions). So the run ends at the floor, or out of data
|
|
# part way down the ramp, on the interval its queue runs out in:
|
|
# 24% of the tick with 110 ms left, 38% with 100 ms, 51% with
|
|
# 90 ms. The tail's mean over the 25 to 30 ms the poll samples is
|
|
# higher, since it spans the intervals before: 32% with 110 ms
|
|
# left, 45% with 100 ms, 56% with 90 ms (61% over the 50 ms window
|
|
# bound), and a few percent when the run reaches the floor. A run
|
|
# that ends at the tick (a run-out with no stop) reads 100%,
|
|
# within the sampling's few percent over 25 ms. The bound is 70%:
|
|
# 14 points above the slowest ramped tail and 30 below a run-out.
|
|
# The other readings are recorded, not judged: with the ramp about
|
|
# the size of the queue, the steps that never played can be none,
|
|
# the bytes played match a run-out within a few percent, and the
|
|
# time to leave running is the 100 ms hold plus the run's end on
|
|
# the ramp: about 240 ms with 100 ms left, 270 ms with 110 ms,
|
|
# 340 ms when the run reaches the floor. The evidence's ramp_ticks
|
|
# and ramp_s are the continuous figures, (f0^2 - 900^2) / (2 a)
|
|
# and (f0 - 900) / a: 12687 ticks and 223 ms at x32, about 4% and
|
|
# 7% under the stepped ramp's.
|
|
running = [s for s in samples if s[1] == "running"]
|
|
tail = None
|
|
if running:
|
|
last = running[-1]
|
|
rec["last_running_s"] = round(last[0], 4)
|
|
before = [s for s in running if last[0] - s[0] >= 0.025]
|
|
if before:
|
|
first = before[-1]
|
|
w = last[0] - first[0]
|
|
rate = ((last[2] - first[2]) & 0xffffffff) / w
|
|
tail = {"window_s": round(w, 4), "rate_hz": round(rate), "fraction": round(rate / f0, 3)}
|
|
rec.update({"tail": tail, "ramp_s": round((f0 - 900.0) / ramp, 4),
|
|
"ramp_ticks": int((f0 * f0 - 900.0 * 900.0) / (2.0 * ramp)),
|
|
"ring_at_idle": samples[-1][3] - samples[-1][2]})
|
|
ctx.log("soft reset during the move: kernel %s %.0f ms after the ^X (queue %d ticks at the ^X, "
|
|
"ramp %d ticks over %.0f ms), tail %s; kernel delta %s steps, MPos delta %s steps, "
|
|
"homed %s -> %s, ring %d after the reset, read-back %s",
|
|
rec["kernel_end_state"], 1e3 * rec["left_running_s"], rec["queue_at_x"], rec["ramp_ticks"],
|
|
1e3 * rec["ramp_s"], tail, kd, rec["mpos_delta_steps"], h0, h1, rec["ring_after"],
|
|
rec["readback_log"] or "(no line)")
|
|
|
|
fails = []
|
|
if samples[-1][1] == "running":
|
|
fails.append("the kernel was still running 1.0 s after the ^X")
|
|
elif samples[-1][1] != "idle":
|
|
fails.append("the kernel left running into %s, not idle" % samples[-1][1])
|
|
if under1 != under0 or faults1 != faults0:
|
|
fails.append("cnc/underruns %s -> %s, cnc/faults %s -> %s across the reset"
|
|
% (under0, under1, faults0, faults1))
|
|
if tail is None:
|
|
fails.append("the kernel left running %.0f ms after the ^X with no 25 ms of its run sampled "
|
|
"after it: a stop with no ramp" % (1e3 * rec["left_running_s"]))
|
|
elif tail["window_s"] > 0.050:
|
|
fails.append("the poll did not sample the run's tail (a %.0f ms gap)" % (1e3 * tail["window_s"]))
|
|
elif tail["fraction"] > 0.70:
|
|
fails.append("the kernel's tick ran at %.0f%% of %d Hz over the run's last %.0f ms: the run "
|
|
"ended at speed, not on the ramp" % (100 * tail["fraction"], f0, 1e3 * tail["window_s"]))
|
|
if rec["ring_after"]:
|
|
fails.append("the ring still holds %d bytes after the reset: the clear did not run" % rec["ring_after"])
|
|
# The read-back is exact, and the judge allows half a step. The
|
|
# smallest miss the read-back can make is one step: the core's
|
|
# kill step for the pulse start that never came, which a position
|
|
# kept as the core counted it carries. MPos is reported to
|
|
# 0.001 mm, so the difference of two readings carries up to 0.21
|
|
# step at x32 (0.05 at x8): a correct read-back lands within
|
|
# that, a one-step miss at 0.79 step or more, and a one-step
|
|
# tolerance would let the miss land on either side of it. The
|
|
# kernel counts X_DIR set as -X, so the sign of its X count is
|
|
# the one this +X move gave it.
|
|
if abs(kd[0]) < spm[0] or md[0] <= 0:
|
|
fails.append("the move did not reach the kernel or MPos: kernel X %+d steps, MPos X %+.1f steps"
|
|
% (kd[0], md[0]))
|
|
elif abs(abs(kd[0]) - md[0]) > 0.5:
|
|
fails.append("MPos X moved %.1f steps and the kernel played %d: the position was not read back "
|
|
"from the kernel's counters" % (md[0], abs(kd[0])))
|
|
for a, name in ((1, "Y"), (2, "Z")):
|
|
if kd[a] or abs(md[a]) > 0.5:
|
|
fails.append("%s moved under an X move: kernel %+d steps, MPos %+.1f steps" % (name, kd[a], md[a]))
|
|
# The reference is kept.
|
|
if h1 != h0:
|
|
fails.append("the homed mask went %s -> %s across the reset: the reference was dropped" % (h0, h1))
|
|
if lost:
|
|
fails.append("the sender was told the position is lost: %s" % lost[-1])
|
|
if abs(p2[0] - p0[0]) > 1:
|
|
fails.append("the jog back left the kernel's X counter %+d steps from its start" % (p2[0] - p0[0]))
|
|
return fails
|
|
|
|
accel = hw.AccelSampler()
|
|
ctx.check(accel.available, "no head accelerometer found (i2c %s): the motion witness is missing",
|
|
hw.HEAD_ACCEL_I2C)
|
|
with ctx.grbl() as g, accel:
|
|
st0 = clean_slate(ctx, g)
|
|
start = st0.get("MPos")
|
|
ctx.check(start, "no MPos in the status report")
|
|
ev["start"] = start
|
|
moves = []
|
|
for name, out, back in (
|
|
("X sanity 40mm", "$J=G91X40F2400", "$J=G91X-40F2400"),
|
|
("Y sanity 40mm", "$J=G91Y40F2400", "$J=G91Y-40F2400"),
|
|
("X max-rate 60mm", "$J=G91X60F12000", "$J=G91X-60F12000"),
|
|
("diag 40mm", "$J=G91X40Y40F8000", "$J=G91X-40Y-40F8000")):
|
|
for jog in (out, back):
|
|
t0 = time.time()
|
|
r = g.command(jog)
|
|
ctx.check(not any(x.startswith("error") for x in r), "%s: jog refused: %s", name, r)
|
|
peak, states, _ = wait_idle(ctx, g)
|
|
t1 = time.time()
|
|
p2px, p2py, n = accel.p2p(t0, t1)
|
|
leg = "out" if jog == out else "back"
|
|
ctx.log("%s %s: peak %.0f mm/min, states %s; accel p2p x=%d y=%d over %d samples",
|
|
name, leg, peak, states, p2px, p2py, n)
|
|
moves.append({"name": name, "leg": leg, "peak": peak, "states": states,
|
|
"accel_p2p": [p2px, p2py], "accel_samples": n, "t0": t0, "t1": t1})
|
|
ctx.check("TIMEOUT" not in states, "%s %s did not return to Idle", name, leg)
|
|
ev["moves"] = moves
|
|
# The witness sees the ramps, not the travel: a sysfs read lands
|
|
# two or three samples in a one-second leg, and two samples on
|
|
# the constant-velocity stretch read near the idle level with the
|
|
# head in full flight (bench: 17 samples over the eight legs, a
|
|
# ramp caught on three of them). So the verdict is over the
|
|
# sequence: the head moved during the jogs (p2p over all the
|
|
# legs), and on more than one of them, never one leg alone.
|
|
p2px, p2py, n = accel.p2p(moves[0]["t0"], moves[-1]["t1"])
|
|
moving = [m for m in moves if max(m["accel_p2p"]) >= hw.ACCEL_P2P_MOVING]
|
|
ev["accel_overall"] = {"p2p": [p2px, p2py], "samples": n, "errors": accel.errors}
|
|
ev["accel_moving_legs"] = [m["name"] + " " + m["leg"] for m in moving]
|
|
ctx.log("accel over all %d legs: p2p x=%d y=%d (%d samples, %d errors); motion seen on %d legs",
|
|
len(moves), p2px, p2py, n, accel.errors, len(moving))
|
|
ctx.check(n >= 8, "the accelerometer landed only %d samples over the jogs (%d read errors): "
|
|
"the motion witness is not reading", n, accel.errors)
|
|
ctx.check(max(p2px, p2py) >= hw.ACCEL_P2P_MOVING,
|
|
"the head did not move during the jogs (accel p2p x=%d y=%d, below %d): the counters "
|
|
"ran without the gantry", p2px, p2py, hw.ACCEL_P2P_MOVING)
|
|
ctx.check(len(moving) >= 2, "the accelerometer saw motion on only %d leg(s) of %d (one jolt is "
|
|
"not a gantry moving on every jog)", len(moving), len(moves))
|
|
maxrate = max(m["peak"] for m in moves if m["name"].startswith("X max-rate"))
|
|
ev["max_rate_peak"] = maxrate
|
|
ctx.check(maxrate >= 6000, "max-rate jog peaked at only %.0f mm/min", maxrate)
|
|
|
|
# feed-hold mid-move: G1 at 600 mm/min takes 3 s for 30 mm
|
|
g.command("G91")
|
|
g.command("G1X30F600", timeout=0.5)
|
|
ctx.sleep(1.0)
|
|
g.realtime(ord("!"))
|
|
ctx.sleep(0.8)
|
|
held = g.status_report()
|
|
ev["held_state"] = held["state"]
|
|
ctx.log("after !: %s", held["state"])
|
|
g.realtime(ord("~"))
|
|
peak, states, _ = wait_idle(ctx, g)
|
|
ctx.log("after ~: states %s", states)
|
|
g.command("G1X-30F2400", timeout=0.5)
|
|
wait_idle(ctx, g)
|
|
fails = reset_during_move(g)
|
|
for why in fails:
|
|
ctx.log("soft reset: %s", why)
|
|
ctx.check(not fails, "soft reset during the move: %s", "; ".join(fails))
|
|
g.command("G90")
|
|
final = g.status_report().get("MPos")
|
|
ev["final"] = final
|
|
drift = max(abs(a - b) for a, b in zip(final[:2], start[:2]))
|
|
ev["drift_mm"] = round(drift, 3)
|
|
ctx.log("final drift %.3f mm (start %s, final %s)", drift, start, final)
|
|
machine_idle(ctx)
|
|
ctx.check("Hold" in held["state"], "feed hold did not park (state %s)", held["state"])
|
|
ctx.check(drift <= 0.05, "position drift %.3f mm", drift)
|
|
ctx.log("PASS: %d jogs, peak %.0f mm/min, hold parked, drift %.3f mm, accel p2p %d over the jogs, "
|
|
"motion on %d of %d legs", len(moves), maxrate, drift, max(p2px, p2py), len(moving), len(moves))
|
|
|
|
|
|
# ---------------------------------------------------------- microstep modes
|
|
|
|
def grbl_setting(g, key):
|
|
"""One $-setting's value from the controller, or None."""
|
|
for line in g.command(key):
|
|
if line.startswith(key + "="):
|
|
try:
|
|
return float(line[len(key) + 1:].split()[0])
|
|
except ValueError:
|
|
return None
|
|
return None
|
|
|
|
|
|
def set_xy_mode(ctx, fc, value):
|
|
"""Store xy_microsteps (empty = clear it) and wait for the GRBL
|
|
controller forgectrl restarts for it to come back configured, with
|
|
the Grbl port answering. Returns the /mode body the machine settled
|
|
on."""
|
|
if value:
|
|
st, body = fc.post("/settings", data={"xy_microsteps": value})
|
|
else:
|
|
st, body = fc.post("/settings", params={"xy_microsteps": ""})
|
|
ctx.check(st == 200, "could not set xy_microsteps=%r (%s: %s)", value or "(clear)", st, body)
|
|
mode = int(value or _baseline.XY_MODE_DEFAULT)
|
|
ctx.sleep(2.0) # the controller's stop is under way
|
|
bl = _baseline.Baseline(ctx.log, abort=ctx.run.aborted.is_set)
|
|
body = bl.wait_settled()
|
|
ctx.check(isinstance(body, dict) and body.get("controller") == "running",
|
|
"the controller did not come back after the xy_microsteps write (/mode: %s)", body)
|
|
ctx.check(_baseline.wait_controller_configured(ctx.log, body, xy_mode=mode),
|
|
"the controller came back but did not apply its x%d config", mode)
|
|
end = time.time() + _baseline.GRBL_PORT_S
|
|
while True:
|
|
ctx.checkpoint()
|
|
try:
|
|
with hw.Grbl():
|
|
return body
|
|
except OSError:
|
|
if time.time() > end:
|
|
raise Failed("the Grbl port did not answer within %d s of the restart"
|
|
% _baseline.GRBL_PORT_S)
|
|
time.sleep(1.0)
|
|
|
|
|
|
@test("motion.microstep-modes",
|
|
title="XY microstep modes: the setting drives the drivers, the scale and the tick",
|
|
subsystem="motion", kind="auto", mode="grbl", est_min=5,
|
|
covers=_MOTION_COVERS + [("forgectrl", "src/main.c"), ("forgectrl", "src/settings.*")],
|
|
requires=["motion.jog-roundtrip"],
|
|
steps=["Bed clear, lid closed; the head needs 40 mm of free +X travel."],
|
|
description="One setting, xy_microsteps, is the XY scale. For each mode it admits (8, 16, "
|
|
"32): the save restarts the idle controller; the kernel reads the mode on both "
|
|
"axes with the mode's machine tick and stop ramp; $100/$101 are the mode's and a "
|
|
"typed $100 is overwritten on the spot; a 40 mm jog out and back at the top speed "
|
|
"returns to Idle with the kernel counters, over the mode, agreeing with the "
|
|
"commanded travel, no drift, and the head accelerometer seeing the head move. "
|
|
"The setting is put back as found, with the controller restarted for it.")
|
|
def microstep_modes(ctx):
|
|
ev = ctx.evidence
|
|
fc = ctx.forgectrl
|
|
ctx.check(hw.AccelSampler().available,
|
|
"no head accelerometer found (i2c %s): the motion witness is missing", hw.HEAD_ACCEL_I2C)
|
|
was = (fc.settings() or {}).get("xy_microsteps") or ""
|
|
ev["xy_microsteps_before"] = was or "(unset)"
|
|
results = []
|
|
try:
|
|
for mode in _baseline.XY_MODES:
|
|
ctx.checkpoint()
|
|
ctx.log("--- x%d ---", mode)
|
|
set_xy_mode(ctx, fc, str(mode))
|
|
r = {"mode": mode, "sysfs": {}}
|
|
results.append(r) # in the evidence even when a check fails
|
|
for attr, want in _baseline.fixed_sysfs(mode):
|
|
if attr not in ("cnc/x_mode", "cnc/y_mode", "cnc/step_freq", "cnc/ramp_rate"):
|
|
continue
|
|
got = hw.sysfs_read(attr)
|
|
r["sysfs"][attr] = got
|
|
ctx.check(got == want, "x%d: %s reads %s, want %s", mode, attr, got, want)
|
|
spm = _baseline.xy_steps_per_mm(mode)
|
|
accel = hw.AccelSampler()
|
|
with ctx.grbl() as g, accel:
|
|
clean_slate(ctx, g)
|
|
for key in ("$100", "$101"):
|
|
v = grbl_setting(g, key)
|
|
r[key] = v
|
|
ctx.check(v is not None and abs(v - spm) < 0.001,
|
|
"x%d: %s=%s, want %.3f", mode, key, v, spm)
|
|
g.command("$100=53.333")
|
|
v = grbl_setting(g, "$100")
|
|
r["typed_100"] = v
|
|
ctx.check(v is not None and abs(v - spm) < 0.001,
|
|
"x%d: a typed $100 stuck at %s (want %.3f: the scale is the mode's)", mode, v, spm)
|
|
|
|
start = g.status_report()["MPos"]
|
|
k0 = kernel_xy_mm(ctx)
|
|
t0 = time.time()
|
|
rr = g.command("$J=G91X40F12000")
|
|
ctx.check(not any(x.startswith("error") for x in rr), "x%d: jog refused: %s", mode, rr)
|
|
peak, states, _ = wait_idle(ctx, g, 30)
|
|
ctx.check("TIMEOUT" not in states, "x%d: the jog out did not return to Idle: %s", mode, states)
|
|
# grblHAL's Idle leads the kernel by the stream depth and
|
|
# the decel tail: the counters are read once the machine
|
|
# itself is idle.
|
|
machine_idle(ctx)
|
|
out_mm = kernel_xy_mm(ctx)[0] - k0[0]
|
|
r["kernel_out_mm"] = round(out_mm, 3)
|
|
r["peak"] = peak
|
|
ctx.check(abs(out_mm - 40.0) <= 0.2,
|
|
"x%d: the kernel counters say %.3f mm for a 40 mm jog: the scale and the "
|
|
"drivers' mode disagree", mode, out_mm)
|
|
rr = g.command("$J=G91X-40F12000")
|
|
ctx.check(not any(x.startswith("error") for x in rr), "x%d: jog back refused: %s", mode, rr)
|
|
peak2, states, _ = wait_idle(ctx, g, 30)
|
|
ctx.check("TIMEOUT" not in states, "x%d: the jog back did not return to Idle: %s", mode, states)
|
|
machine_idle(ctx)
|
|
t1 = time.time()
|
|
final = g.status_report()["MPos"]
|
|
drift = abs(final[0] - start[0])
|
|
p2px, p2py, n = accel.p2p(t0, t1)
|
|
r.update({"drift_mm": round(drift, 3), "accel_p2p": [p2px, p2py], "accel_samples": n})
|
|
ctx.log("x%d: out %.3f mm by the kernel, peak %.0f/%.0f mm/min, drift %.3f mm, "
|
|
"accel p2p x=%d y=%d over %d samples",
|
|
mode, out_mm, peak, peak2, drift, p2px, p2py, n)
|
|
ctx.check(drift <= 0.05, "x%d: position drift %.3f mm", mode, drift)
|
|
ctx.check(max(peak, peak2) >= 6000, "x%d: the jog peaked at only %.0f mm/min", mode,
|
|
max(peak, peak2))
|
|
ctx.check(max(p2px, p2py) >= hw.ACCEL_P2P_MOVING,
|
|
"x%d: the head did not move during the jog (accel p2p x=%d y=%d, below %d): "
|
|
"the counters ran without the gantry", mode, p2px, p2py, hw.ACCEL_P2P_MOVING)
|
|
machine_idle(ctx)
|
|
finally:
|
|
ev["modes"] = results
|
|
set_xy_mode(ctx, fc, was)
|
|
ev["xy_microsteps_after"] = (fc.settings() or {}).get("xy_microsteps") or "(unset)"
|
|
ctx.log("PASS: %s", "; ".join("x%d: %.3f mm, drift %.3f, accel %d"
|
|
% (r["mode"], r["kernel_out_mm"], r["drift_mm"], max(r["accel_p2p"]))
|
|
for r in results))
|
|
|
|
|
|
# ---------------------------------------------------------------- liveness
|
|
|
|
@test("motion.liveness-probe", title="Supervisor motion-liveness verdict", subsystem="motion",
|
|
kind="auto", est_min=1,
|
|
covers=[("forgectrl", "src/super.c"), ("forgectrl", "src/liveness.c"), ("kernel-module-glowforge", "**")],
|
|
requires=["kernel.latch-locked-idle"],
|
|
steps=["Bed clear, lid closed: the probe jogs the head 15 mm out and back (+X first); "
|
|
"forgectrl is restarted once for a fresh probe."],
|
|
description="forgectrl's supervisor reports the head-accelerometer liveness probe as "
|
|
"verified for the running controller (the DRV8825s are not wedged); when the "
|
|
"probe was skipped at spawn, the controller is respawned once so it runs. Then "
|
|
"the regression: with every axis masked (cnc/motor_lock=15, as a bench tool "
|
|
"may leave it) forgectrl is restarted and its fresh probe must still read "
|
|
"MOTION OK - the probe unmasks the axes itself - with the head-accel p2p at "
|
|
"or above the moving threshold.")
|
|
def liveness_probe(ctx):
|
|
fc = ctx.forgectrl
|
|
ev = ctx.evidence
|
|
_liveness_verdict(ctx, fc, ev)
|
|
_liveness_masked_restart(ctx, fc, ev)
|
|
|
|
|
|
def _liveness_verdict(ctx, fc, ev):
|
|
st, m = fc.get("/mode")
|
|
ctx.check(st == 200 and isinstance(m, dict), "GET /mode -> %s", st)
|
|
ev["mode_before"] = m
|
|
ctx.log("mode: %s", m)
|
|
ctx.check(m.get("motion") != "fault", "supervisor reports motion-fault: %s", m)
|
|
if m.get("motion") != "verified":
|
|
ctx.log("probe %s at the last spawn - respawning the controller so it runs", m.get("motion"))
|
|
st, body = fc.post("/controller/stop")
|
|
ctx.check(st == 200, "POST /controller/stop -> %s", st)
|
|
ctx.sleep(2)
|
|
st, body = fc.post("/controller/start")
|
|
ctx.check(st == 200, "POST /controller/start -> %s", st)
|
|
t0 = time.time()
|
|
while time.time() - t0 < 60:
|
|
ctx.sleep(1)
|
|
st, m = fc.get("/mode")
|
|
if isinstance(m, dict) and m.get("controller") == "running":
|
|
break
|
|
ctx.sleep(3)
|
|
st, m = fc.get("/mode")
|
|
ev["mode_after"] = m
|
|
ctx.log("mode after: %s", m)
|
|
ctx.check(m.get("controller") == "running", "controller is %s", m.get("controller"))
|
|
ctx.check(m.get("motion") == "verified", "liveness is %r, expected verified", m.get("motion"))
|
|
|
|
|
|
FORGECTRL_LOG = "/data/log/forgefirm/forgectrl/forgectrl.log"
|
|
|
|
|
|
def _log_offset(path):
|
|
try:
|
|
return os.path.getsize(path)
|
|
except OSError:
|
|
return 0
|
|
|
|
|
|
def _log_lines(path, offset, needle):
|
|
try:
|
|
with open(path, "rb") as f:
|
|
f.seek(offset)
|
|
data = f.read().decode("utf-8", "replace")
|
|
except OSError:
|
|
return []
|
|
return [ln.strip() for ln in data.splitlines() if needle in ln]
|
|
|
|
|
|
def _probe_lines(path, offset):
|
|
return _log_lines(path, offset, "liveness probe:")
|
|
|
|
|
|
def _liveness_masked_restart(ctx, fc, ev):
|
|
"""The regression: a leftover motor_lock must not read as a wedge."""
|
|
ctx.check(fc.wait_idle(15, abort=ctx.aborted), "machine not idle before the masked restart")
|
|
x0 = _kernel_x_mm(ctx)
|
|
hw.sysfs_write("cnc/motor_lock", "15")
|
|
ctx.log("masked every axis (cnc/motor_lock=15); restarting forgectrl for a fresh probe")
|
|
off = _log_offset(FORGECTRL_LOG)
|
|
rc, out = hw.initd("forgectrl", "restart")
|
|
ctx.check(rc == 0, "forgectrl restart -> rc %s", rc)
|
|
m = None
|
|
t0 = time.time()
|
|
while time.time() - t0 < 150:
|
|
ctx.checkpoint()
|
|
try:
|
|
st, m = fc.get("/mode")
|
|
except hw.HwError:
|
|
m = None # the daemon is still coming up
|
|
if isinstance(m, dict) and ((m.get("controller") == "running" and m.get("motion") == "verified")
|
|
or m.get("controller") == "motion-fault"):
|
|
break
|
|
ctx.sleep(1)
|
|
# The probe's own line reaches the file through rsyslog a moment after
|
|
# the supervisor reports its verdict: wait for it, briefly.
|
|
t1 = time.time()
|
|
lines = _probe_lines(FORGECTRL_LOG, off)
|
|
while not lines and time.time() - t1 < 10:
|
|
ctx.sleep(0.5)
|
|
lines = _probe_lines(FORGECTRL_LOG, off)
|
|
for ln in lines:
|
|
ctx.log(" %s", ln.split(" INFO ", 1)[-1] if " INFO " in ln else ln[-160:])
|
|
ev["masked_restart"] = {"mode": m, "probe_lines": lines[-4:], "motor_lock_after": ctx.sysfs("cnc/motor_lock")}
|
|
ctx.check(m and m.get("controller") == "running" and m.get("motion") == "verified",
|
|
"fresh probe under a leftover mask did not verify motion: %s", m)
|
|
ctx.check(lines and "MOTION OK" in lines[0],
|
|
"the first probe after the restart was not MOTION OK: %s", lines[:1])
|
|
ctx.check(len(lines) == 1, "the probe needed the recovery ladder (%d probes) - a false dead verdict", len(lines))
|
|
ctx.check(ctx.sysfs("cnc/motor_lock") == "0", "motor_lock reads %s after the controller start (expected 0)",
|
|
ctx.sysfs("cnc/motor_lock"))
|
|
ctx.check(fc.wait_idle(15, abort=ctx.aborted), "machine not idle after the probe")
|
|
x1 = _kernel_x_mm(ctx)
|
|
ctx.log("kernel X %s -> %s mm across the probe (out and back)", x0, x1)
|
|
ctx.log("PASS: masked restart probed MOTION OK on the first try, mask cleared, controller up")
|
|
|
|
|
|
# ------------------------------------------------- the gate and the lid
|
|
|
|
def _wait_controller(ctx, fc, states, timeout, motion=None):
|
|
"""GET /mode until the controller state is one of `states` (and, for a
|
|
running one, the motion verdict is `motion` when given). Tolerates a
|
|
daemon that is still coming up. Returns the last document read."""
|
|
m = {}
|
|
t0 = time.time()
|
|
while time.time() - t0 < timeout:
|
|
ctx.checkpoint()
|
|
try:
|
|
st, m = fc.get("/mode")
|
|
except hw.HwError:
|
|
m = None
|
|
if isinstance(m, dict) and m.get("controller") in states:
|
|
if motion is None or m.get("controller") != "running" or m.get("motion") == motion:
|
|
return m
|
|
ctx.sleep(1)
|
|
return m if isinstance(m, dict) else {}
|
|
|
|
|
|
# ---------------------------------------------------------------- dead-man
|
|
|
|
def _kernel_x_mm(ctx):
|
|
pos = (ctx.forgectrl.status().get("pos") or {})
|
|
return pos.get("x")
|
|
|
|
|
|
def _return_x(ctx, delta_mm):
|
|
"""Jog back by the kernel-measured X delta (grbl's own position may be
|
|
untrusted after a kill; the kernel counters kept counting)."""
|
|
if delta_mm is None or abs(delta_mm) < 0.05:
|
|
return
|
|
with ctx.grbl() as g:
|
|
st = g.status_report()["state"]
|
|
if st.startswith("Alarm"):
|
|
g.command("$X")
|
|
g.command("$J=G91X%.3fF1200" % (-delta_mm))
|
|
wait_idle(ctx, g, 30)
|
|
machine_idle(ctx)
|
|
|
|
|
|
@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.pacing", "kernel.k1-k2"],
|
|
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 "
|
|
"locked); the process resumed from the hang recovers on a soft reset and an unlock "
|
|
"(the alarm is critical, so $X alone is refused; the reset acknowledges the "
|
|
"fault to the stream and clears the stale ring) and moves again without a "
|
|
"restart. A short SIGSTOP (100 ms, inside the kernel's 200 ms queue) mid-move: "
|
|
"no underrun, but the step producer comes back later than its lead and its "
|
|
"late events clamp; unarmed that is a warning in the controller's log and the "
|
|
"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. 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
|
|
fc = ctx.forgectrl
|
|
ev = ctx.evidence
|
|
|
|
def latch_locked():
|
|
v = hw.sysfs_int("cnc/interlock_circuit")
|
|
return v is not None and bool(v & (1 << 3))
|
|
|
|
def wait_running(timeout=30, not_pid=None):
|
|
"""A running controller; with not_pid, one other than that pid (a
|
|
killed controller can still read as running until it is reaped)."""
|
|
t0 = time.time()
|
|
while time.time() - t0 < timeout:
|
|
st, m = fc.get("/mode")
|
|
if (isinstance(m, dict) and m.get("controller") == "running" and m.get("pid")
|
|
and m.get("pid") != not_pid):
|
|
return m
|
|
ctx.sleep(0.5)
|
|
return None
|
|
|
|
# ---- 1. SIGKILL mid-move
|
|
m0 = wait_running(10)
|
|
ctx.check(m0, "controller not running")
|
|
pid0 = m0["pid"]
|
|
x0 = _kernel_x_mm(ctx)
|
|
unlocked_seen = False
|
|
with ctx.grbl() as g:
|
|
clean_slate(ctx, g)
|
|
g.command("G91")
|
|
g.command("G1X30F300", timeout=0.5)
|
|
ctx.sleep(1.0)
|
|
_os.kill(pid0, _signal.SIGKILL)
|
|
ctx.log("SIGKILL sent to controller pid %d mid-move", pid0)
|
|
t0 = time.time()
|
|
while time.time() - t0 < 15:
|
|
if not latch_locked():
|
|
unlocked_seen = True
|
|
st, m = fc.get("/mode")
|
|
if isinstance(m, dict) and m.get("controller") == "running" and m.get("pid") != pid0:
|
|
break
|
|
ctx.sleep(0.2)
|
|
m1 = wait_running(30)
|
|
respawn_s = round(time.time() - t0, 1)
|
|
ev["sigkill"] = {"old_pid": pid0, "new": m1, "respawn_s": respawn_s, "unlocked_seen": unlocked_seen}
|
|
ctx.log("after SIGKILL: respawned as %s in %s s; latch unlocked seen: %s", m1, respawn_s, unlocked_seen)
|
|
ctx.check(m1 and m1.get("pid") != pid0, "supervisor did not respawn the controller")
|
|
ctx.check(not unlocked_seen, "the latch unlocked during the kill/respawn")
|
|
ctx.check(m1.get("motion") != "fault", "motion fault after the respawn")
|
|
ctx.sleep(3)
|
|
x1 = _kernel_x_mm(ctx)
|
|
ctx.log("kernel X: %s -> %s mm", x0, x1)
|
|
_return_x(ctx, (x1 - x0) if (x0 is not None and x1 is not None) else None)
|
|
|
|
# ---- 2. SIGSTOP (hang) mid-move -> kernel underrun
|
|
m1 = wait_running(10)
|
|
pid1 = m1["pid"]
|
|
x0 = _kernel_x_mm(ctx)
|
|
underruns0 = hw.sysfs_int("cnc/underruns", 0)
|
|
ring_free_idle = hw.sysfs_int("cnc/free")
|
|
with ctx.grbl() as g:
|
|
clean_slate(ctx, g)
|
|
g.command("G91")
|
|
g.command("G1X30F300", timeout=0.5)
|
|
ctx.sleep(1.0)
|
|
_os.kill(pid1, _signal.SIGSTOP)
|
|
ctx.log("SIGSTOP sent to controller pid %d mid-move", pid1)
|
|
t0 = time.time()
|
|
kstate = None
|
|
while time.time() - t0 < 10:
|
|
kstate = hw.sysfs_read("cnc/state")
|
|
if kstate == "underrun":
|
|
break
|
|
ctx.sleep(0.05)
|
|
halt_s = round(time.time() - t0, 2)
|
|
ev["sigstop"] = {"kernel_state": kstate, "halt_s": halt_s, "latch_locked": latch_locked(),
|
|
"underruns": hw.sysfs_int("cnc/underruns", 0)}
|
|
ctx.log("after SIGSTOP: kernel %s in %s s, latch locked %s, underruns %s -> %s",
|
|
kstate, halt_s, latch_locked(), underruns0, ev["sigstop"]["underruns"])
|
|
# The controller comes back from the hang to find its stream
|
|
# faulted and the core in a critical alarm (17, motor fault). The
|
|
# core refuses an unlock until a soft reset (error 79), and the
|
|
# reset is what the stream takes as the operator's acknowledgment:
|
|
# the kernel is stopped and re-armed, the stale ring cleared, the
|
|
# producer armed again. Reset, unlock, and the controller moves
|
|
# again without a restart (the position is not trusted until a
|
|
# re-home, so the move is a jog).
|
|
_os.kill(pid1, _signal.SIGCONT)
|
|
ctx.sleep(1.0)
|
|
st = g.status_report()["state"]
|
|
ev["sigstop"]["state_after_cont"] = st
|
|
ctx.log("controller resumed: state %s", st)
|
|
ctx.check(st.startswith("Alarm"), "the resumed controller is %s, expected Alarm", st)
|
|
early = g.command("$X")
|
|
ev["sigstop"]["unlock_before_reset"] = early
|
|
ctx.log("$X before the reset: %s", early)
|
|
ctx.check(any(l.startswith("error:79") for l in early),
|
|
"$X before the reset should be refused as a critical event, got %s", early)
|
|
g.realtime(0x18)
|
|
ctx.sleep(2)
|
|
g.drain()
|
|
st = g.status_report()["state"]
|
|
ctx.log("after the soft reset: %s", st)
|
|
unlock = g.command("$X")
|
|
ev["sigstop"]["unlock_after_reset"] = unlock
|
|
ctx.log("$X after the reset: %s", unlock)
|
|
ctx.check(unlock and unlock[-1] == "ok", "$X after the reset was refused (%s)", unlock)
|
|
st = g.status_report()["state"]
|
|
ctx.check(st.startswith("Idle"), "controller is %s after the reset and unlock, expected Idle", st)
|
|
free = hw.sysfs_int("cnc/free")
|
|
ev["sigstop"]["ring_free_after_reset"] = free
|
|
ctx.log("ring after the reset: free %s (idle %s)", free, ring_free_idle)
|
|
ctx.check(free == ring_free_idle, "the reset did not clear the stale ring (free %s, idle %s)",
|
|
free, ring_free_idle)
|
|
g.command("$J=G91X-5F1200")
|
|
peak, states, st = wait_idle(ctx, g, 15)
|
|
ev["sigstop"]["recovery_states"] = states
|
|
ctx.check("TIMEOUT" not in states and not str((st or {}).get("state", "")).startswith("Alarm"),
|
|
"the controller did not move again after the reset and unlock (states %s)", states)
|
|
ctx.check(kstate == "underrun", "the ring did not drain into a kernel underrun (state %s)", kstate)
|
|
ctx.check(latch_locked(), "latch unlocked after the underrun")
|
|
m2 = wait_running(10)
|
|
ev["sigstop"]["after"] = m2
|
|
ctx.check(m2 and m2.get("pid") == pid1, "the recovered controller was replaced (%s)", m2)
|
|
ctx.sleep(3)
|
|
x1 = _kernel_x_mm(ctx)
|
|
_return_x(ctx, (x1 - x0) if (x0 is not None and x1 is not None) else None)
|
|
|
|
# ---- 2b. a short hang (inside the kernel queue): late events clamp, a warning, the move completes
|
|
m2 = wait_running(10)
|
|
pid2 = m2["pid"]
|
|
x0 = _kernel_x_mm(ctx)
|
|
underruns0 = hw.sysfs_int("cnc/underruns", 0)
|
|
log0 = _log_offset(GRBLHAL_LOG)
|
|
with ctx.grbl() as g:
|
|
clean_slate(ctx, g)
|
|
g.command("G91")
|
|
g.command("G1X30F300", timeout=0.5) # ~6 s of motion
|
|
ctx.sleep(1.0)
|
|
_os.kill(pid2, _signal.SIGSTOP)
|
|
time.sleep(0.1)
|
|
_os.kill(pid2, _signal.SIGCONT)
|
|
ctx.log("SIGSTOP 100 ms sent to controller pid %d mid-move", pid2)
|
|
peak, states, st = wait_idle(ctx, g, 30)
|
|
g.command("G90")
|
|
machine_idle(ctx) # the kernel's tail plays out behind grbl's Idle
|
|
warned = None
|
|
t0 = time.time()
|
|
while time.time() - t0 < 5 and not warned:
|
|
lines = _log_lines(GRBLHAL_LOG, log0, "late events clamped")
|
|
warned = lines[-1] if lines else None
|
|
if not warned:
|
|
ctx.sleep(0.5)
|
|
x1 = _kernel_x_mm(ctx)
|
|
ev["short_stall"] = {"states": states, "underruns": hw.sysfs_int("cnc/underruns", 0) - underruns0,
|
|
"warning": warned, "kernel_dx_mm": round((x1 - x0), 3) if (x0 is not None and x1 is not None) else None,
|
|
"state_after": (st or {}).get("state")}
|
|
ctx.log("short stall: states %s, underruns +%s, warning %r, kernel dx %s mm", states,
|
|
ev["short_stall"]["underruns"], warned, ev["short_stall"]["kernel_dx_mm"])
|
|
ctx.check("TIMEOUT" not in states and str((st or {}).get("state", "")).startswith("Idle"),
|
|
"the move did not complete after the short stall (states %s)", states)
|
|
ctx.check(ev["short_stall"]["underruns"] == 0, "the short stall drained the ring (underruns +%s)",
|
|
ev["short_stall"]["underruns"])
|
|
ctx.check(warned, "the controller did not warn about the clamped events after the short stall")
|
|
ctx.check(ev["short_stall"]["kernel_dx_mm"] is not None and abs(ev["short_stall"]["kernel_dx_mm"] - 30.0) < 0.3,
|
|
"the kernel counted %s mm for a 30 mm move after the short stall", ev["short_stall"]["kernel_dx_mm"])
|
|
ctx.check(latch_locked(), "latch unlocked after the short stall")
|
|
_return_x(ctx, (x1 - x0) if (x0 is not None and x1 is not None) else None)
|
|
|
|
# ---- 3. forgectrl restart mid-move: the move finishes, supervision retaken at idle
|
|
m2 = wait_running(10)
|
|
pid2 = m2["pid"]
|
|
x0 = _kernel_x_mm(ctx)
|
|
with ctx.grbl() as g:
|
|
clean_slate(ctx, g)
|
|
g.command("G91")
|
|
g.command("G1X30F300", timeout=0.5) # ~6 s of motion
|
|
ctx.sleep(1.0)
|
|
rc, out = hw.initd("forgectrl", "restart")
|
|
ctx.log("forgectrl restart mid-move -> rc %s", rc)
|
|
peak, states, st = wait_idle(ctx, g, 30)
|
|
ev["restart"] = {"rc": rc, "states": states}
|
|
ctx.log("move after the restart: states %s", states)
|
|
ctx.check("TIMEOUT" not in states, "the move did not finish after the forgectrl restart")
|
|
g.command("G90")
|
|
t0 = time.time()
|
|
m3 = None
|
|
while time.time() - t0 < 60:
|
|
st, m3 = fc.get("/mode")
|
|
if isinstance(m3, dict) and m3.get("controller") == "running":
|
|
break
|
|
ctx.sleep(1)
|
|
ev["restart"]["mode_after"] = m3
|
|
ctx.log("mode after restart: %s", m3)
|
|
ctx.check(m3 and m3.get("controller") == "running", "supervision not retaken after the restart: %s", m3)
|
|
ctx.check(m3.get("motion") == "verified", "motion not verified after the retake: %s", m3)
|
|
# the retake, by design: the busy controller (unmanaged, its own fd carrying
|
|
# the dead-man) finished its move; at idle the new supervisor stopped it,
|
|
# re-probed motion, and started a supervised one under the broker
|
|
ev["restart"]["replaced_at_idle"] = m3.get("pid") != pid2
|
|
ctx.log("retake: unmanaged pid %s finished the move; supervised pid %s started at idle",
|
|
pid2, m3.get("pid"))
|
|
ctx.check(latch_locked(), "latch unlocked after the restart drill")
|
|
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), 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)
|
|
|
|
|
|
# ------------------------------------------------- lid / button (the factory's)
|
|
|
|
def kernel_xy_mm(ctx):
|
|
"""The kernel's own position counters, in mm (forgectrl /status pos):
|
|
what the machine physically did, independent of what grbl believes."""
|
|
pos = (ctx.forgectrl.status().get("pos") or {})
|
|
return float(pos.get("x", 0.0)), float(pos.get("y", 0.0))
|
|
|
|
|
|
def kernel_start(ctx, timeout=15.0):
|
|
"""The kernel counters AT REST, for use as a reference point.
|
|
|
|
grblHAL reports Idle when its planner is empty; the kernel is still
|
|
playing the stream depth and the decel tail behind that. Sampling the
|
|
counters in that window records a position the head is only passing
|
|
through, and every later comparison is then measured against a
|
|
transient - which reads exactly like the failure this reference exists
|
|
to catch (a move counted but never played)."""
|
|
machine_idle(ctx, timeout)
|
|
return kernel_xy_mm(ctx)
|
|
|
|
|
|
def check_kernel_returned(ctx, ev, k0, tol_mm=0.1, tag=""):
|
|
"""After a return-to-start: the kernel counters must be back where the
|
|
job started too. grbl's own drift can read 0.000 while the head never
|
|
moved (a run the kernel did not take), which is exactly the failure
|
|
that must not pass."""
|
|
k1 = kernel_xy_mm(ctx)
|
|
kdrift = max(abs(k1[0] - k0[0]), abs(k1[1] - k0[1]))
|
|
ev[(tag + "_" if tag else "") + "kernel_drift_mm"] = round(kdrift, 3)
|
|
ctx.log("kernel counters: start (%.2f, %.2f) -> now (%.2f, %.2f), drift %.3f mm",
|
|
k0[0], k0[1], k1[0], k1[1], kdrift)
|
|
ctx.check(kdrift <= tol_mm,
|
|
"the kernel counters did not return to the job start (drift %.3f mm) - "
|
|
"the return move was counted by grbl but not played by the machine", kdrift)
|
|
|
|
|
|
class Watch:
|
|
"""Conditions over the controller's state for Context.act / wait_for
|
|
that also keep everything the controller said while they were polled
|
|
(the `[MSG:]` lines a pause or a cancel reports)."""
|
|
|
|
def __init__(self, g):
|
|
self.g = g
|
|
self.text = ""
|
|
self.last = None
|
|
|
|
def poll(self):
|
|
self.text += self.g.drain()
|
|
self.last = self.g.status_report()
|
|
return self.last
|
|
|
|
def in_state(self, prefix):
|
|
return lambda: self.poll()["state"].startswith(prefix)
|
|
|
|
def left_state(self, prefix):
|
|
return lambda: not self.poll()["state"].startswith(prefix)
|
|
|
|
|
|
def drain_text(g, seconds):
|
|
"""Everything the controller said in the next `seconds`."""
|
|
end = time.time() + seconds
|
|
text = ""
|
|
while time.time() < end:
|
|
text += g.drain()
|
|
time.sleep(0.1)
|
|
return text
|
|
|
|
|
|
GRBLHAL_LOG = "/data/log/forgefirm/grblhal/grblhal.log"
|
|
SCHED_FIFO = 1
|
|
|
|
|
|
def _thread_sched(pid):
|
|
"""(tid, policy, rt_priority) for every thread of pid. Those are fields
|
|
41 and 40 of /proc/<tid>/stat; comm can hold spaces and parentheses, so
|
|
the fields are indexed from the last ')' - rest[0] is field 3."""
|
|
out = []
|
|
for tid in sorted(os.listdir("/proc/%d/task" % pid)):
|
|
try:
|
|
with open("/proc/%d/task/%s/stat" % (pid, tid)) as f:
|
|
s = f.read()
|
|
except OSError:
|
|
continue
|
|
rest = s[s.rindex(")") + 1:].split()
|
|
if len(rest) >= 39:
|
|
out.append((tid, int(rest[38]), int(rest[37])))
|
|
return out
|
|
|
|
|
|
@test("motion.step-timing-under-load",
|
|
title="Step timing holds while userspace competes for the core",
|
|
subsystem="motion", kind="auto", mode="grbl", est_min=2,
|
|
covers=_MOTION_COVERS, requires=["kernel.latch-locked-idle", "motion.jog-roundtrip"],
|
|
steps=["Bed clear, lid closed; the head needs >= 40 mm of free +X travel."],
|
|
description="The board has one core, so the thread that stamps steps onto the pulse grid "
|
|
"has to outrank ordinary userspace: when its virtual clock slips behind wall "
|
|
"clock past the queue depth, late events clamp forward and the backlog ships "
|
|
"one step per machine tick - a burst no motor follows, while cnc/underruns "
|
|
"stays 0 because the ring never runs dry. Asserts the producer and the shipper "
|
|
"both hold SCHED_FIFO, then drives 2000 mm/min round trips against a deliberate "
|
|
"nice-5 CPU hog and requires the controller to report no clamped events.")
|
|
def step_timing_under_load(ctx):
|
|
import subprocess
|
|
|
|
ev = ctx.evidence
|
|
pid = controller_pid()
|
|
|
|
threads = _thread_sched(pid)
|
|
rt = sorted(prio for _tid, pol, prio in threads if pol == SCHED_FIFO)
|
|
ev["threads"] = len(threads)
|
|
ev["rt_priorities"] = rt
|
|
ctx.log("controller threads: %d, SCHED_FIFO priorities: %s", len(threads), rt)
|
|
ctx.check(len(rt) >= 2,
|
|
"expected the stream producer and the shipper on SCHED_FIFO, found %d of %d "
|
|
"threads at real time (%s): step timing is exposed to ordinary userspace",
|
|
len(rt), len(threads), rt)
|
|
|
|
off = _log_offset(GRBLHAL_LOG)
|
|
load = None
|
|
try:
|
|
# One SCHED_OTHER hog at the same nice as forgectrl's HTTP threads:
|
|
# the realistic competitor, and the one the fix must outrank. The
|
|
# image has no `nice` binary (BusyBox ships renice only), so the
|
|
# niceness is applied from here once the child exists, and the value
|
|
# that actually took is recorded - a hog left at nice 0 would be a
|
|
# harsher test than intended, and one left unset must not pass
|
|
# silently.
|
|
load = subprocess.Popen(["sh", "-c", "while :; do :; done"],
|
|
stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL)
|
|
try:
|
|
os.setpriority(os.PRIO_PROCESS, load.pid, 5)
|
|
hog_nice = os.getpriority(os.PRIO_PROCESS, load.pid)
|
|
except OSError as exc:
|
|
hog_nice = None
|
|
ctx.log("could not set the hog niceness: %s", exc)
|
|
ev["hog_nice"] = hog_nice
|
|
ctx.check(hog_nice == 5, "CPU hog is at nice %s, expected 5", hog_nice)
|
|
ctx.log("CPU hog started (pid %d, nice %s)", load.pid, hog_nice)
|
|
with ctx.grbl() as g:
|
|
clean_slate(ctx, g)
|
|
ctrl0 = cpu_ticks(pid)
|
|
t0 = time.time()
|
|
legs = 0
|
|
for _i in range(10):
|
|
ctx.checkpoint()
|
|
for jog in ("$J=G91X40F2000", "$J=G91X-40F2000"):
|
|
r = g.command(jog)
|
|
ctx.check(not any(x.startswith("error") for x in r),
|
|
"jog refused under load: %s", r)
|
|
_peak, states, _ = wait_idle(ctx, g, 30)
|
|
ctx.check("TIMEOUT" not in states, "a leg did not return to Idle under load")
|
|
legs += 1
|
|
elapsed = time.time() - t0
|
|
hz = os.sysconf("SC_CLK_TCK")
|
|
ev["legs"] = legs
|
|
ev["motion_s"] = round(elapsed, 1)
|
|
ev["controller_cpu_pct"] = round(100.0 * (cpu_ticks(pid) - ctrl0) / (hz * elapsed), 1)
|
|
ctx.log("%d legs in %.1f s, controller CPU %.1f %%",
|
|
legs, elapsed, ev["controller_cpu_pct"])
|
|
machine_idle(ctx)
|
|
finally:
|
|
if load is not None:
|
|
load.kill()
|
|
load.wait()
|
|
ctx.log("CPU hog stopped")
|
|
|
|
clamped = _log_lines(GRBLHAL_LOG, off, "late events clamped")
|
|
ev["clamp_lines"] = clamped
|
|
ctx.check(not clamped,
|
|
"step generation was starved while userspace competed for the core: %s",
|
|
"; ".join(clamped))
|
|
ctx.log("PASS: %d legs at 2000 mm/min against a nice-5 CPU hog, no clamped events",
|
|
ev["legs"])
|
|
|
|
|
|
# ------------------------------------------------- motor release
|
|
|
|
HOLD_CURRENTS = ("33", "5") # pic/x_step_current, pic/y_step_current at idle
|
|
|
|
|
|
def _step_currents():
|
|
return (hw.sysfs_read("pic/x_step_current"), hw.sysfs_read("pic/y_step_current"))
|
|
|
|
|
|
def _rail_lines():
|
|
"""How many times the kernel has logged the 40 V supply going on or off."""
|
|
rc, out = hw.run(["dmesg"])
|
|
if rc != 0:
|
|
return -1
|
|
return sum(1 for line in out.splitlines() if "40V on" in line or "40V off" in line)
|
|
|
|
|
|
def _kernel_position():
|
|
"""The kernel's position record: (x, y, z) in steps, then the bytes it
|
|
has played and the bytes it was handed. Nothing moves without the last
|
|
two moving, which makes them the witness for "nothing was shipped": the
|
|
head accelerometer cannot say it, since the rotors relax off their held
|
|
microstep when the drivers let go, when the currents drop to hold, and at
|
|
a reset, and the head feels each of those."""
|
|
with open(hw.sysfs_root() + "cnc/position", "rb") as f:
|
|
raw = f.read(32)
|
|
return struct.unpack_from("<3i", raw, 0) + struct.unpack_from("<2I", raw, 12)
|
|
|
|
|
|
def _refused(ctx, g, line):
|
|
"""Send a line that must be refused; acknowledge the parser error it
|
|
leaves (clear_error has the why) and return the error."""
|
|
r = g.command(line)
|
|
err = next((x for x in r if x.startswith("error")), None)
|
|
if err is not None:
|
|
g.command("")
|
|
return err
|
|
|
|
|
|
def _drop_reference(ctx, fc):
|
|
"""A false home is not left behind: a fresh controller starts unhomed."""
|
|
fc.post("/controller/stop")
|
|
_wait_controller(ctx, fc, ("stopped", "standby"), 30)
|
|
fc.post("/controller/start")
|
|
m = _wait_controller(ctx, fc, ("running",), 120, motion="verified")
|
|
ctx.check(m.get("controller") == "running", "the controller did not come back: %s", m)
|
|
|
|
|
|
@test("motion.release", title="Motor release: nothing moves a released gantry, only the operator energizes it",
|
|
subsystem="motion", kind="auto", hardware="takeover", mode="grbl", est_min=8,
|
|
covers=_MOTION_COVERS + [("forgectrl", "src/status.*"), ("forgectrl", "src/wizdark.*")],
|
|
requires=["motion.jog-roundtrip"],
|
|
steps=["Bed clear; the head needs 50 mm of free travel each way on X and Y. Nobody touches the gantry."],
|
|
description="$MD releases X and Y by taking their step currents to 0, with the 40 V rail "
|
|
"untouched (no supply line in the kernel log, cnc/state idle, no fault), drops the "
|
|
"X and Y reference and locks the machine in alarm. While released a jog, a G0 and "
|
|
"$X are refused, a soft reset does not unlock it, and forgectrl refuses a switch "
|
|
"to cloud mode; the kernel's position record "
|
|
"is the witness that nothing was shipped (no step and no byte played), and the head "
|
|
"accelerometer stays under the moving threshold in the window after the release. "
|
|
"$ME energizes with no fault. The drivers are then proven alive the way the machine "
|
|
"proves it to itself: the Setup motion check runs the liveness probe on the held "
|
|
"device and the witnessed 50 mm jogs.")
|
|
def motor_release(ctx):
|
|
from .setup_dark import run_check
|
|
|
|
ev = ctx.evidence
|
|
fc = hw.Forgectrl()
|
|
accel = hw.AccelSampler()
|
|
ctx.check(accel.available, "no head accelerometer found (i2c %s): the motion witness is missing",
|
|
hw.HEAD_ACCEL_I2C)
|
|
rail0 = _rail_lines()
|
|
ctx.check(rail0 >= 0, "the kernel log is unreadable: the rail witness is missing")
|
|
with ctx.grbl() as g, accel:
|
|
clean_slate(ctx, g)
|
|
r = g.command("$MD")
|
|
ctx.check(not any(x.startswith("error") for x in r), "$MD refused at idle: %s", r)
|
|
text = "\n".join(r) + drain_text(g, 1.0)
|
|
ev["released_currents"] = list(_step_currents())
|
|
ev["state_released"] = g.status_report()["state"]
|
|
ev["kernel_state_released"] = hw.sysfs_read("cnc/state")
|
|
ev["faults_released"] = hw.sysfs_int("cnc/faults")
|
|
ev["homed_axes_released"] = fc.status().get("homed_axes")
|
|
ctx.log("$MD: step currents %s, %s, cnc/state %s, faults %s, homed_axes %s",
|
|
ev["released_currents"], ev["state_released"], ev["kernel_state_released"],
|
|
ev["faults_released"], ev["homed_axes_released"])
|
|
ctx.check(ev["released_currents"] == ["0", "0"],
|
|
"the step currents read %s after $MD, not 0 and 0", ev["released_currents"])
|
|
ctx.check(ev["state_released"].startswith("Alarm"), "not locked in alarm: %s", ev["state_released"])
|
|
ctx.check(ev["kernel_state_released"] == "idle", "the kernel left idle: %s", ev["kernel_state_released"])
|
|
ctx.check(ev["faults_released"] == 0, "a driver fault on release: %s", ev["faults_released"])
|
|
ctx.check(not (ev["homed_axes_released"] or 0) & 3, "X or Y still referenced while released")
|
|
ctx.check("Motors released" in text, "the sender was not told the motors are released")
|
|
|
|
# The rotors have relaxed by now: from here on the head is still.
|
|
ctx.sleep(1.0)
|
|
k0 = _kernel_position()
|
|
t0 = time.time()
|
|
refusals = {}
|
|
for line in ("$J=G91X10F2400", "G0X10", "$X"):
|
|
refusals[line] = _refused(ctx, g, line)
|
|
ctx.check(refusals[line], "%s was accepted while the motors are released", line)
|
|
ctx.sleep(1.0)
|
|
p2px, p2py, n = accel.p2p(t0)
|
|
ev["released_accel_p2p"] = [p2px, p2py, n]
|
|
ctx.check(n > 0, "no accelerometer samples in the released window")
|
|
ctx.check(max(p2px, p2py) < hw.ACCEL_P2P_MOVING,
|
|
"the head moved while released (accel p2p x=%d y=%d)", p2px, p2py)
|
|
g.realtime(0x18)
|
|
ctx.sleep(2)
|
|
g.drain()
|
|
refusals["^X then $X"] = _refused(ctx, g, "$X")
|
|
ctx.check(refusals["^X then $X"], "a soft reset and $X unlocked a released machine")
|
|
ev["state_after_reset"] = g.status_report()["state"]
|
|
ctx.check(ev["state_after_reset"].startswith("Alarm"),
|
|
"a soft reset unlocked a released machine: %s", ev["state_after_reset"])
|
|
k1 = _kernel_position()
|
|
ev["refusals"] = refusals
|
|
ev["kernel_position"] = [list(k0), list(k1)]
|
|
ctx.log("refused while released: %s; accel p2p x=%d y=%d over %d samples; kernel record %s -> %s",
|
|
refusals, p2px, p2py, n, k0, k1)
|
|
ctx.check(k1 == k0, "the kernel played something while released: %s -> %s", k0, k1)
|
|
|
|
# forgectrl reads the release too: cloud homing moves the head, so the
|
|
# switch is refused (for the release where cloud mode is enabled, for
|
|
# cloud mode being off where it is not; the mode stays either way).
|
|
st, body = fc.post("/mode", data={"controller": "cloud"})
|
|
text = body if isinstance(body, str) else json.dumps(body)
|
|
cloud_on = str(fc.settings().get("cloud_enabled", "")).lower() in ("1", "true", "yes", "on")
|
|
ev["mode_cloud_released"] = {"status": st, "body": text, "cloud_enabled": cloud_on}
|
|
ctx.log("POST /mode controller=cloud while released -> %s %s", st, text)
|
|
ctx.check(st == 409, "a switch to cloud mode while released -> %s, expected 409", st)
|
|
if cloud_on:
|
|
ctx.check("released" in text, "the refusal does not name the release: %r", text)
|
|
ctx.check(fc.get("/mode")[1].get("mode") == "grbl", "the mode changed under a released gantry")
|
|
ctx.check(_step_currents() == ("0", "0"),
|
|
"something energized the motors: step currents %s", _step_currents())
|
|
|
|
r = g.command("$ME")
|
|
ctx.check(not any(x.startswith("error") for x in r), "$ME refused: %s", r)
|
|
ctx.sleep(0.5)
|
|
ev["energized_currents"] = list(_step_currents())
|
|
ev["faults_energized"] = hw.sysfs_int("cnc/faults")
|
|
ev["state_energized"] = g.status_report()["state"]
|
|
ctx.check(tuple(ev["energized_currents"]) == HOLD_CURRENTS,
|
|
"the step currents read %s after $ME, not the hold currents", ev["energized_currents"])
|
|
ctx.check(ev["faults_energized"] == 0, "a driver fault on energize: %s", ev["faults_energized"])
|
|
ctx.check(ev["state_energized"].startswith("Idle"), "not idle after $ME: %s", ev["state_energized"])
|
|
|
|
# The drivers are alive: the machine's own witness says so. The liveness
|
|
# probe is built for the accelerometer (a slow, rough move sampled for
|
|
# seconds); a quick smooth jog is not, and reads as nothing half the time.
|
|
ctx.notice("The head moves 50 mm each way on X and on Y. Keep the bed clear.")
|
|
last = run_check(ctx, "motion", lambda p: "Continue" if p.get("id") == "jogs" else None, 420)
|
|
ctx.clear_notice()
|
|
res = last.get("result") or {}
|
|
ev["probe"] = res.get("probe")
|
|
ev["moves"] = res.get("moves")
|
|
ctx.log("after energize: probe '%s', moves %s", res.get("probe"),
|
|
{k: v.get("witnessed") for k, v in (res.get("moves") or {}).items()})
|
|
ctx.check(res.get("probe") and last.get("result") is not None and not last.get("error"),
|
|
"the motion check did not complete after the energize: %s", last.get("error") or last)
|
|
for name in ("+X", "-X", "+Y", "-Y"):
|
|
m = (res.get("moves") or {}).get(name) or {}
|
|
ctx.check(m.get("witnessed") is True,
|
|
"the %s jog was not witnessed after the energize: the drivers did not come back (%s)", name, m)
|
|
ok = ctx.wait_for(lambda: (fc.get("/mode")[1] or {}).get("local") is False
|
|
and (fc.get("/mode")[1] or {}).get("controller") == "running", 90)
|
|
ctx.check(ok is not None, "the controller is not back in its normal posture")
|
|
ev["rail_lines"] = [rail0, _rail_lines()]
|
|
ctx.check(ev["rail_lines"][0] == ev["rail_lines"][1],
|
|
"the kernel logged the 40 V supply changing across a release: %s", ev["rail_lines"])
|
|
machine_idle(ctx)
|
|
ctx.log("PASS: released with the rail untouched, every motion refused and nothing shipped, "
|
|
"energized with no fault, and the liveness probe and the witnessed jogs say the drivers are alive")
|
|
|
|
|
|
def _port_state(fc):
|
|
st, body = fc.get("/motion/state")
|
|
if st != 200 or not isinstance(body, dict):
|
|
raise hw.HwError("forgectrl /motion/state -> %s %s" % (st, body))
|
|
return body
|
|
|
|
|
|
def _port_idle(ctx, fc, timeout=30.0):
|
|
"""The port's own word that its jog is over. The suite's Grbl client
|
|
sends no line while a port jog runs: a line from it is what cancels one."""
|
|
ok = ctx.wait_for(lambda: (lambda s: s["state"] == "Idle" and not s["port_jog"])(_port_state(fc)),
|
|
timeout, poll=0.1)
|
|
ctx.check(ok is not None, "the port jog did not end: %s", _port_state(fc))
|
|
machine_idle(ctx)
|