From 5802983cb6400f65fbba61a104981f25102a0735 Mon Sep 17 00:00:00 2001 From: Luca Toniolo <10792599+grandixximo@users.noreply.github.com> Date: Sun, 11 Oct 2026 09:49:45 +1100 Subject: [PATCH 1/6] tests: add probe-queue-not-empty for the AUTO read-ahead race (#3650) Runs 100 G38.2 probes in AUTO mode and fails on "Queue is not empty after probing". A test-only comp busy waits between motion-command-handler and motion-controller, so task often sees motion idle right after the probe was queued. Fails without af6b5b75ca, passes with it. --- tests/probe-queue-not-empty/README | 15 ++++ tests/probe-queue-not-empty/checkresult | 3 + tests/probe-queue-not-empty/postgui.hal | 1 + tests/probe-queue-not-empty/probe.hal | 14 ++++ tests/probe-queue-not-empty/servo_delay.comp | 19 +++++ tests/probe-queue-not-empty/simpockets.tbl | 1 + tests/probe-queue-not-empty/skip | 4 + tests/probe-queue-not-empty/test-ui.py | 66 +++++++++++++++ tests/probe-queue-not-empty/test.ini | 86 ++++++++++++++++++++ tests/probe-queue-not-empty/test.ngc | 14 ++++ tests/probe-queue-not-empty/test.sh | 5 ++ 11 files changed, 228 insertions(+) create mode 100644 tests/probe-queue-not-empty/README create mode 100755 tests/probe-queue-not-empty/checkresult create mode 100644 tests/probe-queue-not-empty/postgui.hal create mode 100644 tests/probe-queue-not-empty/probe.hal create mode 100644 tests/probe-queue-not-empty/servo_delay.comp create mode 100644 tests/probe-queue-not-empty/simpockets.tbl create mode 100755 tests/probe-queue-not-empty/skip create mode 100755 tests/probe-queue-not-empty/test-ui.py create mode 100644 tests/probe-queue-not-empty/test.ini create mode 100644 tests/probe-queue-not-empty/test.ngc create mode 100755 tests/probe-queue-not-empty/test.sh diff --git a/tests/probe-queue-not-empty/README b/tests/probe-queue-not-empty/README new file mode 100644 index 00000000000..864928f02a2 --- /dev/null +++ b/tests/probe-queue-not-empty/README @@ -0,0 +1,15 @@ +Runs 100 G38.2 probes in AUTO mode and fails on "Queue is not empty +after probing" (#3650). + +After a probe, read-ahead waits for the EMC_TASK_PLAN_SYNCH that follows +it, then reads the next line, whose read_inputs() wants an empty motion +queue. Motion acknowledges the probe command in motion-command-handler +but only updates the queue depth and in-position flag in +motion-controller. A status snapshot taken in between still shows motion +idle, so the SYNCH completes at once, and if the next snapshot shows the +probe in the queue, read_inputs() fails. + +That gap is normally a few microseconds wide. probe.hal puts servo_delay +between the two functions, a busy wait that varies on each servo period, +so about half of the probes see it. Task must not clear the read-ahead +wait while the queue it is about to check is not empty. diff --git a/tests/probe-queue-not-empty/checkresult b/tests/probe-queue-not-empty/checkresult new file mode 100755 index 00000000000..acfd40f1b32 --- /dev/null +++ b/tests/probe-queue-not-empty/checkresult @@ -0,0 +1,3 @@ +#!/bin/sh +# Test passes if test-ui.py returns successfully +exit 0 diff --git a/tests/probe-queue-not-empty/postgui.hal b/tests/probe-queue-not-empty/postgui.hal new file mode 100644 index 00000000000..a0ab5529dec --- /dev/null +++ b/tests/probe-queue-not-empty/postgui.hal @@ -0,0 +1 @@ +net done-count <= motion.analog-out-00 => test-ui.done-count diff --git a/tests/probe-queue-not-empty/probe.hal b/tests/probe-queue-not-empty/probe.hal new file mode 100644 index 00000000000..17810d04c34 --- /dev/null +++ b/tests/probe-queue-not-empty/probe.hal @@ -0,0 +1,14 @@ +# the probe trips when Z goes below -0.5 +loadrt comp names=probe-comp +addf probe-comp servo-thread +net Zpos => probe-comp.in0 +setp probe-comp.in1 -0.5 +net probe probe-comp.out => motion.probe-input + +# Stall the servo thread for a varying time between the command handler +# and the controller, as preemption or a latency spike would. Motion +# has then acknowledged a new command while its status still shows the +# old queue depth. +loadrt servo_delay +addf servo-delay.0 servo-thread 2 +setp servo-delay.0.max-ns 200000 diff --git a/tests/probe-queue-not-empty/servo_delay.comp b/tests/probe-queue-not-empty/servo_delay.comp new file mode 100644 index 00000000000..df01bbb39d9 --- /dev/null +++ b/tests/probe-queue-not-empty/servo_delay.comp @@ -0,0 +1,19 @@ +component servo_delay "Busy wait for a varying time on each run, to widen the gap between two functions"; +pin in uint max_ns = 0 "Upper bound of the wait in ns, 0 disables it"; +param rw uint step_ns = 7919 "Amount the wait grows by on each run, modulo max-ns"; +variable rtapi_uint wait_ns; +option period no; +function _; +license "GPL"; +author "Luca Toniolo"; +;; +FUNCTION(_) { + rtapi_sint end; + + if (max_ns == 0) + return; + wait_ns = (wait_ns + step_ns) % max_ns; + end = rtapi_get_time() + (rtapi_sint)wait_ns; + while (rtapi_get_time() < end) + ; +} diff --git a/tests/probe-queue-not-empty/simpockets.tbl b/tests/probe-queue-not-empty/simpockets.tbl new file mode 100644 index 00000000000..0bdf35afecc --- /dev/null +++ b/tests/probe-queue-not-empty/simpockets.tbl @@ -0,0 +1 @@ +T1 P1 Z0.0 D0.0 ; diff --git a/tests/probe-queue-not-empty/skip b/tests/probe-queue-not-empty/skip new file mode 100755 index 00000000000..a12f31a77c2 --- /dev/null +++ b/tests/probe-queue-not-empty/skip @@ -0,0 +1,4 @@ +#!/bin/sh +# Builds a realtime component with halcompile, which needs the build +# tools present. Skip when testing installed packages. +[ -z "$SYSTEM_BUILD" ] diff --git a/tests/probe-queue-not-empty/test-ui.py b/tests/probe-queue-not-empty/test-ui.py new file mode 100755 index 00000000000..a8b7e868fd2 --- /dev/null +++ b/tests/probe-queue-not-empty/test-ui.py @@ -0,0 +1,66 @@ +#!/usr/bin/env python3 + +import linuxcnc +import linuxcnc_util +import hal + +import time +import sys +import os + +c = linuxcnc.command() +s = linuxcnc.stat() +e = linuxcnc.error_channel() +l = linuxcnc_util.LinuxCNC(command=c, status=s, error=e) + +h = hal.component("test-ui") +h.newpin("done-count", hal.Type.REAL, hal.Dir.IN) +h.ready() +os.system("halcmd source ./postgui.hal") + +c.state(linuxcnc.STATE_ESTOP_RESET) +c.state(linuxcnc.STATE_ON) +c.home(0) +c.home(1) +c.home(2) +l.wait_for_home([1, 1, 1, 0, 0, 0, 0, 0, 0]) +c.mode(linuxcnc.MODE_AUTO) +c.wait_complete() + +c.program_open('test.ngc') +c.auto(linuxcnc.AUTO_RUN, 0) + +start = time.time() +while True: + s.poll() + if s.interp_state != linuxcnc.INTERP_IDLE: + break + if time.time() - start > 10: + sys.stderr.write("timeout waiting for the program to start\n") + sys.exit(1) + time.sleep(0.001) + +errors = [] +while True: + err = e.poll() + if err: + errors.append(err[1]) + s.poll() + if s.interp_state == linuxcnc.INTERP_IDLE: + break + if time.time() - start > 60: + sys.stderr.write("timeout waiting for the program to finish\n") + sys.exit(1) + time.sleep(0.05) + +err = e.poll() +while err: + errors.append(err[1]) + err = e.poll() + +for msg in errors: + sys.stderr.write("error: %s\n" % msg) +sys.stderr.write("probes done: %d\n" % h["done-count"]) +if errors or h["done-count"] != 100: + sys.exit(1) +sys.exit(0) diff --git a/tests/probe-queue-not-empty/test.ini b/tests/probe-queue-not-empty/test.ini new file mode 100644 index 00000000000..346951d7590 --- /dev/null +++ b/tests/probe-queue-not-empty/test.ini @@ -0,0 +1,86 @@ +[EMC] +VERSION = 1.1 +DEBUG = 0x0 + +[DISPLAY] +DISPLAY = ./test-ui.py + +[TASK] +TASK = milltask +CYCLE_TIME = 0.001 + +[RS274NGC] +PARAMETER_FILE = sim.var + +[EMCMOT] +EMCMOT = motmod +COMM_TIMEOUT = 4.0 +BASE_PERIOD = 0 +SERVO_PERIOD = 1000000 + +[EMCIO] +TOOL_TABLE = simpockets.tbl + +[HAL] +HALFILE = LIB:core_sim.hal +HALFILE = probe.hal + +[TRAJ] +NO_FORCE_HOMING = 1 +COORDINATES = X Y Z +LINEAR_UNITS = inch +ANGULAR_UNITS = degree +DEFAULT_LINEAR_VELOCITY = 10 +MAX_LINEAR_VELOCITY = 100 + +[KINS] +KINEMATICS = trivkins +JOINTS = 3 + +[AXIS_X] +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 + +[JOINT_0] +TYPE = LINEAR +HOME = 0.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +FERROR = 0.050 +MIN_FERROR = 0.010 + +[AXIS_Y] +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 + +[JOINT_1] +TYPE = LINEAR +HOME = 0.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +FERROR = 0.050 +MIN_FERROR = 0.010 + +[AXIS_Z] +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 + +[JOINT_2] +TYPE = LINEAR +HOME = 0.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +FERROR = 0.050 +MIN_FERROR = 0.010 diff --git a/tests/probe-queue-not-empty/test.ngc b/tests/probe-queue-not-empty/test.ngc new file mode 100644 index 00000000000..eca2d6bd19f --- /dev/null +++ b/tests/probe-queue-not-empty/test.ngc @@ -0,0 +1,14 @@ +G20 G90 G94 +G0 Z0 +# = 0 +o100 while [# LT 100] + G0 Z-0.4 + G38.2 Z-1 F600 + # = [# + 1] +o100 endwhile +o110 if [[#5070 NE 1] OR [ABS[#5063 + 0.5] GT 0.02]] + (abort, bad probe result Z#5063 success #5070) +o110 endif +G0 Z0 +M68 E0 Q# +M2 diff --git a/tests/probe-queue-not-empty/test.sh b/tests/probe-queue-not-empty/test.sh new file mode 100755 index 00000000000..f9f8e26a874 --- /dev/null +++ b/tests/probe-queue-not-empty/test.sh @@ -0,0 +1,5 @@ +#!/bin/bash +set -e + +halcompile --install servo_delay.comp >/dev/null +linuxcnc -r test.ini From 303e280cc73f741221788cf4a6571067bf6670ef Mon Sep 17 00:00:00 2001 From: Luca Toniolo <10792599+grandixximo@users.noreply.github.com> Date: Sun, 11 Oct 2026 12:48:30 +1100 Subject: [PATCH 2/6] tests: probe-queue-not-empty: wait for machine on and each home The test sent the home commands right after the machine-on command, all three at once. Wait until the machine is on, and home one joint at a time, since a home command is refused while another joint homes. --- tests/probe-queue-not-empty/test-ui.py | 26 ++++++++++++++++++++------ 1 file changed, 20 insertions(+), 6 deletions(-) diff --git a/tests/probe-queue-not-empty/test-ui.py b/tests/probe-queue-not-empty/test-ui.py index a8b7e868fd2..10a9c9632ef 100755 --- a/tests/probe-queue-not-empty/test-ui.py +++ b/tests/probe-queue-not-empty/test-ui.py @@ -1,7 +1,6 @@ #!/usr/bin/env python3 import linuxcnc -import linuxcnc_util import hal import time @@ -11,19 +10,34 @@ c = linuxcnc.command() s = linuxcnc.stat() e = linuxcnc.error_channel() -l = linuxcnc_util.LinuxCNC(command=c, status=s, error=e) h = hal.component("test-ui") h.newpin("done-count", hal.Type.REAL, hal.Dir.IN) h.ready() os.system("halcmd source ./postgui.hal") +def wait_for(what, done): + start = time.time() + while True: + s.poll() + if done(): + return + if time.time() - start > 10: + sys.stderr.write("timeout waiting for %s\n" % what) + sys.exit(1) + time.sleep(0.05) + c.state(linuxcnc.STATE_ESTOP_RESET) +c.wait_complete() c.state(linuxcnc.STATE_ON) -c.home(0) -c.home(1) -c.home(2) -l.wait_for_home([1, 1, 1, 0, 0, 0, 0, 0, 0]) +c.wait_complete() +wait_for("machine on", lambda: s.task_state == linuxcnc.STATE_ON) + +# one joint at a time: a home command while another joint homes is refused +for joint in range(3): + c.home(joint) + wait_for("joint %d homed" % joint, lambda: s.homed[joint] + and not any(j["homing"] for j in s.joint[:3])) c.mode(linuxcnc.MODE_AUTO) c.wait_complete() From 0c6e61cab2ecbea6ed92c3af486fdb3b8bd19496 Mon Sep 17 00:00:00 2001 From: Luca Toniolo <10792599+grandixximo@users.noreply.github.com> Date: Sun, 11 Oct 2026 12:18:03 +1100 Subject: [PATCH 3/6] motion, task: report motion busy until the controller has acted on a command Motion echoes a command in motion-command-handler, but motion-controller acts on it: it queues the move, enables the machine, switches mode, and then publishes the queue depth and state. A status read between the two shows the command taken and motion idle, so task takes motion as done. After a G38 move the SYNCH then finishes at once and the next line reads the result of the probe before, or fails with "Queue is not empty after probing" (#3650), and wait_complete() returns before the machine is on or in auto mode. Record the heartbeat at which each command is echoed, and report motion busy until the heartbeat has moved past it, that is until the controller has run once after taking the command. motion-logger has no controller and counts each command as acted on. Both heartbeat fields are rtapi_u64, the RTAPI type for headers RT code includes. --- src/emc/motion-logger/motion-logger.c | 2 ++ src/emc/motion/command.c | 1 + src/emc/motion/motion.c | 1 + src/emc/motion/motion.h | 7 +++++-- src/emc/task/taskintf.cc | 5 +++++ 5 files changed, 14 insertions(+), 2 deletions(-) diff --git a/src/emc/motion-logger/motion-logger.c b/src/emc/motion-logger/motion-logger.c index 36b77e54528..a499764cbb3 100644 --- a/src/emc/motion-logger/motion-logger.c +++ b/src/emc/motion-logger/motion-logger.c @@ -708,6 +708,8 @@ int main(int argc, char* argv[]) { update_joint_status(); + /* there is no controller here, so count the command as acted on */ + emcmotStatus->commandHeartbeat = emcmotStatus->heartbeat++; emcmotStatus->commandEcho = c->command; emcmotStatus->commandNumEcho = c->commandNum; emcmotStatus->commandStatus = EMCMOT_COMMAND_OK; diff --git a/src/emc/motion/command.c b/src/emc/motion/command.c index 07f89dcb890..d9cded5f081 100644 --- a/src/emc/motion/command.c +++ b/src/emc/motion/command.c @@ -434,6 +434,7 @@ void emcmotCommandHandler_locked(void *arg, long servo_period) emcmotInternal->head++; /* got a new command-- echo command and number... */ + emcmotStatus->commandHeartbeat = emcmotStatus->heartbeat; emcmotStatus->commandEcho = emcmotCommand->command; emcmotStatus->commandNumEcho = emcmotCommand->commandNum; diff --git a/src/emc/motion/motion.c b/src/emc/motion/motion.c index 30ce42a6315..fa4472f5f9c 100644 --- a/src/emc/motion/motion.c +++ b/src/emc/motion/motion.c @@ -869,6 +869,7 @@ static int init_comm_buffers(void) emcmotStatus->head = 0; emcmotStatus->commandEcho = 0; emcmotStatus->commandNumEcho = 0; + emcmotStatus->commandHeartbeat = 0; emcmotStatus->commandStatus = 0; /* init more stuff */ diff --git a/src/emc/motion/motion.h b/src/emc/motion/motion.h index 7f3572eda73..f77d0aab4d4 100644 --- a/src/emc/motion/motion.h +++ b/src/emc/motion/motion.h @@ -584,9 +584,12 @@ Suggestion: Split this in to an Error and a Status flag register.. typedef struct emcmot_status_t { unsigned char head; /* flag count for mutex detect */ - /* these three are updated only when a new command is handled */ + /* these four are updated only when a new command is handled */ cmd_code_t commandEcho; /* echo of input command */ int commandNumEcho; /* echo of input command number */ + rtapi_u64 commandHeartbeat; /* heartbeat when the command was echoed: + the controller has acted on the command + once heartbeat has moved past it */ cmd_status_t commandStatus; /* result of most recent command */ /* these are config info, updated when a command changes them */ double feed_scale; /* velocity scale factor for all motion but rapids */ @@ -638,7 +641,7 @@ Suggestion: Split this in to an Error and a Status flag register.. /*! \todo FIXME - all structure members beyond this point are in limbo */ /* dynamic status-- changes every cycle */ - uint64_t heartbeat; /* Incremented every time the motion controller is done. */ + rtapi_u64 heartbeat; /* Incremented every time the motion controller is done. */ int config_num; /* incremented whenever configuration changed. */ int id; /* id for executing motion */ diff --git a/src/emc/task/taskintf.cc b/src/emc/task/taskintf.cc index 049ae4d26d4..54229b10d56 100644 --- a/src/emc/task/taskintf.cc +++ b/src/emc/task/taskintf.cc @@ -2171,6 +2171,11 @@ int emcMotionUpdate(EMC_MOTION_STAT * stat) } else if (stat->traj.status == RCS_STATUS::EXEC) { exec = 1; } + // what the controller makes of the last command (queue depth, in + // position, enable) shows only once it has run after taking it + if (emcmotStatus.heartbeat <= emcmotStatus.commandHeartbeat) { + exec = 1; + } if (error) { stat->status = RCS_STATUS::ERROR; From 9fc750c1b384ec2007119b397f67137ada75b402 Mon Sep 17 00:00:00 2001 From: Luca Toniolo <10792599+grandixximo@users.noreply.github.com> Date: Sun, 11 Oct 2026 12:18:03 +1100 Subject: [PATCH 4/6] task: keep motion busy when a status read fails after a command emcMotionUpdate() returns early when the status or config read fails, which happens while motion-controller runs, and leaves the motion status as it was. Right after a command that copy predates it, and with a probe just queued it says motion is done. Report motion busy until a read that has seen the command succeeds. --- src/emc/task/taskintf.cc | 16 ++++++++++++++-- 1 file changed, 14 insertions(+), 2 deletions(-) diff --git a/src/emc/task/taskintf.cc b/src/emc/task/taskintf.cc index 54229b10d56..8080dd92ca1 100644 --- a/src/emc/task/taskintf.cc +++ b/src/emc/task/taskintf.cc @@ -2073,6 +2073,18 @@ int emcSpindleUpdate(EMC_SPINDLE_STAT stat[], int num_spindles){ return 0; } +// A failed read leaves stat as it was. If that copy is older than the +// last command sent, motion may already be running it, so do not report +// it done: a probe just queued would look finished. +static int emcMotionUpdateFailed(EMC_MOTION_STAT * stat) +{ + if (stat->status == RCS_STATUS::DONE && + stat->echo_serial_number != emcmotCommand.commandNum) { + stat->status = RCS_STATUS::EXEC; + } + return -1; +} + int emcMotionUpdate(EMC_MOTION_STAT * stat) { int r1, r2, r3, r4; @@ -2083,12 +2095,12 @@ int emcMotionUpdate(EMC_MOTION_STAT * stat) // read the emcmot status if (0 != usrmotReadEmcmotStatus(&emcmotStatus)) { - return -1; + return emcMotionUpdateFailed(stat); } new_config = 0; if (emcmotStatus.config_num != emcmotConfig.config_num) { if (0 != usrmotReadEmcmotConfig(&emcmotConfig)) { - return -1; + return emcMotionUpdateFailed(stat); } new_config = 1; } From 7ad67f6ecd3a34cea21ec1fb8431c8c1900fac54 Mon Sep 17 00:00:00 2001 From: Luca Toniolo <10792599+grandixximo@users.noreply.github.com> Date: Sun, 11 Oct 2026 12:18:40 +1100 Subject: [PATCH 5/6] tests: add stale-motion-status Probe at alternating heights, and check that the machine is on and in auto mode once wait_complete() returns. late-controller runs the controller a 50 ms servo period after the command handler, slow-controller uses kinematics that make the controller take most of the servo period, so that status reads fail. Both fail on master, and each needs one of the two changes before. --- tests/stale-motion-status/README | 22 +++++ .../late-controller/checkresult | 3 + .../late-controller/postgui.hal | 1 + .../late-controller/probe.hal | 12 +++ .../late-controller/simpockets.tbl | 1 + .../late-controller/test-ui.py | 1 + .../late-controller/test.ini | 90 ++++++++++++++++++ .../late-controller/test.ngc | 1 + .../late-controller/test.sh | 4 + tests/stale-motion-status/postgui.hal | 1 + tests/stale-motion-status/simpockets.tbl | 1 + .../slow-controller/checkresult | 3 + .../slow-controller/postgui.hal | 1 + .../slow-controller/probe.hal | 11 +++ .../slow-controller/simpockets.tbl | 1 + .../stale-motion-status/slow-controller/skip | 4 + .../slow-controller/slowkins.comp | 93 ++++++++++++++++++ .../slow-controller/test-ui.py | 1 + .../slow-controller/test.ini | 90 ++++++++++++++++++ .../slow-controller/test.ngc | 1 + .../slow-controller/test.sh | 5 + tests/stale-motion-status/test-ui.py | 95 +++++++++++++++++++ tests/stale-motion-status/test.ngc | 16 ++++ 23 files changed, 458 insertions(+) create mode 100644 tests/stale-motion-status/README create mode 100755 tests/stale-motion-status/late-controller/checkresult create mode 120000 tests/stale-motion-status/late-controller/postgui.hal create mode 100644 tests/stale-motion-status/late-controller/probe.hal create mode 120000 tests/stale-motion-status/late-controller/simpockets.tbl create mode 120000 tests/stale-motion-status/late-controller/test-ui.py create mode 100644 tests/stale-motion-status/late-controller/test.ini create mode 120000 tests/stale-motion-status/late-controller/test.ngc create mode 100755 tests/stale-motion-status/late-controller/test.sh create mode 100644 tests/stale-motion-status/postgui.hal create mode 100644 tests/stale-motion-status/simpockets.tbl create mode 100755 tests/stale-motion-status/slow-controller/checkresult create mode 120000 tests/stale-motion-status/slow-controller/postgui.hal create mode 100644 tests/stale-motion-status/slow-controller/probe.hal create mode 120000 tests/stale-motion-status/slow-controller/simpockets.tbl create mode 100755 tests/stale-motion-status/slow-controller/skip create mode 100644 tests/stale-motion-status/slow-controller/slowkins.comp create mode 120000 tests/stale-motion-status/slow-controller/test-ui.py create mode 100644 tests/stale-motion-status/slow-controller/test.ini create mode 120000 tests/stale-motion-status/slow-controller/test.ngc create mode 100755 tests/stale-motion-status/slow-controller/test.sh create mode 100755 tests/stale-motion-status/test-ui.py create mode 100644 tests/stale-motion-status/test.ngc diff --git a/tests/stale-motion-status/README b/tests/stale-motion-status/README new file mode 100644 index 00000000000..1b12ac0a5b6 --- /dev/null +++ b/tests/stale-motion-status/README @@ -0,0 +1,22 @@ +Task must not take a motion status from before a command as current. + +Motion acknowledges a command in motion-command-handler and acts on it +later, in motion-controller: it queues the move, enables the machine, +switches mode. A status read in between, or a failed read that leaves +task with its copy from before the command, shows motion idle. Task +then finishes the command too soon: wait_complete() returns before the +machine is on or in auto mode, and the line after a G38 move takes the +result of the probe before, or fails with "Queue is not empty after +probing" (#3650). + +Both tests check that the machine is on and in auto mode once +wait_complete() returns, then probe at alternating heights and fail if +a probe reads the height of the one before. + +late-controller runs motion-controller before motion-command-handler, +so a whole servo period passes between the two. The period is 50 ms, +longer than the var file write task does when it synchs after a probe. + +slow-controller uses kinematics that busy wait, so motion-controller +takes most of the servo period and status reads by task often fail +while it runs. diff --git a/tests/stale-motion-status/late-controller/checkresult b/tests/stale-motion-status/late-controller/checkresult new file mode 100755 index 00000000000..acfd40f1b32 --- /dev/null +++ b/tests/stale-motion-status/late-controller/checkresult @@ -0,0 +1,3 @@ +#!/bin/sh +# Test passes if test-ui.py returns successfully +exit 0 diff --git a/tests/stale-motion-status/late-controller/postgui.hal b/tests/stale-motion-status/late-controller/postgui.hal new file mode 120000 index 00000000000..d5ae19df5df --- /dev/null +++ b/tests/stale-motion-status/late-controller/postgui.hal @@ -0,0 +1 @@ +../postgui.hal \ No newline at end of file diff --git a/tests/stale-motion-status/late-controller/probe.hal b/tests/stale-motion-status/late-controller/probe.hal new file mode 100644 index 00000000000..9f2ad8d04c6 --- /dev/null +++ b/tests/stale-motion-status/late-controller/probe.hal @@ -0,0 +1,12 @@ +# the probe trips when Z goes below the height set with M68 E1 +loadrt comp names=probe-comp +addf probe-comp servo-thread +net Zpos => probe-comp.in0 +net probe-height motion.analog-out-01 => probe-comp.in1 +net probe probe-comp.out => motion.probe-input + +# Run the controller before the command handler, so that motion +# acknowledges a command a whole servo period before the controller +# acts on it. +delf motion-command-handler servo-thread +addf motion-command-handler servo-thread 2 diff --git a/tests/stale-motion-status/late-controller/simpockets.tbl b/tests/stale-motion-status/late-controller/simpockets.tbl new file mode 120000 index 00000000000..84a56f68b93 --- /dev/null +++ b/tests/stale-motion-status/late-controller/simpockets.tbl @@ -0,0 +1 @@ +../simpockets.tbl \ No newline at end of file diff --git a/tests/stale-motion-status/late-controller/test-ui.py b/tests/stale-motion-status/late-controller/test-ui.py new file mode 120000 index 00000000000..15b94027b91 --- /dev/null +++ b/tests/stale-motion-status/late-controller/test-ui.py @@ -0,0 +1 @@ +../test-ui.py \ No newline at end of file diff --git a/tests/stale-motion-status/late-controller/test.ini b/tests/stale-motion-status/late-controller/test.ini new file mode 100644 index 00000000000..2e800bf4986 --- /dev/null +++ b/tests/stale-motion-status/late-controller/test.ini @@ -0,0 +1,90 @@ +[TEST] +PROBES = 4 +FEED = 6 + +[EMC] +VERSION = 1.1 +DEBUG = 0x0 + +[DISPLAY] +DISPLAY = ./test-ui.py + +[TASK] +TASK = milltask +CYCLE_TIME = 0.001 + +[RS274NGC] +PARAMETER_FILE = sim.var + +[EMCMOT] +EMCMOT = motmod +COMM_TIMEOUT = 4.0 +BASE_PERIOD = 0 +SERVO_PERIOD = 50000000 + +[EMCIO] +TOOL_TABLE = simpockets.tbl + +[HAL] +HALFILE = LIB:core_sim.hal +HALFILE = probe.hal + +[TRAJ] +NO_FORCE_HOMING = 1 +COORDINATES = X Y Z +LINEAR_UNITS = inch +ANGULAR_UNITS = degree +DEFAULT_LINEAR_VELOCITY = 10 +MAX_LINEAR_VELOCITY = 100 + +[KINS] +KINEMATICS = trivkins +JOINTS = 3 + +[AXIS_X] +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 + +[JOINT_0] +TYPE = LINEAR +HOME = 0.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +FERROR = 0.050 +MIN_FERROR = 0.010 + +[AXIS_Y] +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 + +[JOINT_1] +TYPE = LINEAR +HOME = 0.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +FERROR = 0.050 +MIN_FERROR = 0.010 + +[AXIS_Z] +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 + +[JOINT_2] +TYPE = LINEAR +HOME = 0.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +FERROR = 0.050 +MIN_FERROR = 0.010 diff --git a/tests/stale-motion-status/late-controller/test.ngc b/tests/stale-motion-status/late-controller/test.ngc new file mode 120000 index 00000000000..45526095ca3 --- /dev/null +++ b/tests/stale-motion-status/late-controller/test.ngc @@ -0,0 +1 @@ +../test.ngc \ No newline at end of file diff --git a/tests/stale-motion-status/late-controller/test.sh b/tests/stale-motion-status/late-controller/test.sh new file mode 100755 index 00000000000..1f7aa8c808a --- /dev/null +++ b/tests/stale-motion-status/late-controller/test.sh @@ -0,0 +1,4 @@ +#!/bin/bash +set -e + +linuxcnc -r test.ini diff --git a/tests/stale-motion-status/postgui.hal b/tests/stale-motion-status/postgui.hal new file mode 100644 index 00000000000..b3e0f7b7e58 --- /dev/null +++ b/tests/stale-motion-status/postgui.hal @@ -0,0 +1 @@ +net finished <= motion.analog-out-00 => test-ui.finished diff --git a/tests/stale-motion-status/simpockets.tbl b/tests/stale-motion-status/simpockets.tbl new file mode 100644 index 00000000000..0bdf35afecc --- /dev/null +++ b/tests/stale-motion-status/simpockets.tbl @@ -0,0 +1 @@ +T1 P1 Z0.0 D0.0 ; diff --git a/tests/stale-motion-status/slow-controller/checkresult b/tests/stale-motion-status/slow-controller/checkresult new file mode 100755 index 00000000000..acfd40f1b32 --- /dev/null +++ b/tests/stale-motion-status/slow-controller/checkresult @@ -0,0 +1,3 @@ +#!/bin/sh +# Test passes if test-ui.py returns successfully +exit 0 diff --git a/tests/stale-motion-status/slow-controller/postgui.hal b/tests/stale-motion-status/slow-controller/postgui.hal new file mode 120000 index 00000000000..d5ae19df5df --- /dev/null +++ b/tests/stale-motion-status/slow-controller/postgui.hal @@ -0,0 +1 @@ +../postgui.hal \ No newline at end of file diff --git a/tests/stale-motion-status/slow-controller/probe.hal b/tests/stale-motion-status/slow-controller/probe.hal new file mode 100644 index 00000000000..dbbe98e437e --- /dev/null +++ b/tests/stale-motion-status/slow-controller/probe.hal @@ -0,0 +1,11 @@ +# the probe trips when Z goes below the height set with M68 E1 +loadrt comp names=probe-comp +addf probe-comp servo-thread +net Zpos => probe-comp.in0 +net probe-height motion.analog-out-01 => probe-comp.in1 +net probe probe-comp.out => motion.probe-input + +# Make the controller take most of the servo period, so that status +# reads by task often fail while it runs. +addf slowkins.arm servo-thread 1 +setp slowkins.wait-ns 700000 diff --git a/tests/stale-motion-status/slow-controller/simpockets.tbl b/tests/stale-motion-status/slow-controller/simpockets.tbl new file mode 120000 index 00000000000..84a56f68b93 --- /dev/null +++ b/tests/stale-motion-status/slow-controller/simpockets.tbl @@ -0,0 +1 @@ +../simpockets.tbl \ No newline at end of file diff --git a/tests/stale-motion-status/slow-controller/skip b/tests/stale-motion-status/slow-controller/skip new file mode 100755 index 00000000000..a12f31a77c2 --- /dev/null +++ b/tests/stale-motion-status/slow-controller/skip @@ -0,0 +1,4 @@ +#!/bin/sh +# Builds a realtime component with halcompile, which needs the build +# tools present. Skip when testing installed packages. +[ -z "$SYSTEM_BUILD" ] diff --git a/tests/stale-motion-status/slow-controller/slowkins.comp b/tests/stale-motion-status/slow-controller/slowkins.comp new file mode 100644 index 00000000000..0025d944fec --- /dev/null +++ b/tests/stale-motion-status/slow-controller/slowkins.comp @@ -0,0 +1,93 @@ +component slowkins "Identity kinematics for X Y Z that busy wait in kinematicsForward once per servo period"; +pin out bool dummy = 1; // halcompile requires at least one pin +function arm "Let the next kinematicsForward call busy wait"; +option singleton yes; +option extra_setup; +option period no; +license "GPL"; +author "Luca Toniolo"; +;; +#include + +static struct haldata { + hal_uint_t wait_ns; + int armed; +} *haldata; + +EXTRA_SETUP() { + (void)__comp_inst; + (void)prefix; + (void)extra_arg; + + if (comp_id < 0) + return -1; + haldata = hal_malloc(sizeof(struct haldata)); + if (!haldata) + return -1; + return hal_param_new_uint(comp_id, HAL_RW, &haldata->wait_ns, 0, + "slowkins.wait-ns"); +} + +/* motion calls kinematicsForward twice per period in free mode; one wait + per period keeps the controller inside the period */ +FUNCTION(arm) { + (void)__comp_inst; + haldata->armed = 1; +} + +KINS_NOT_SWITCHABLE +EXPORT_SYMBOL(kinematicsType); +EXPORT_SYMBOL(kinematicsInverse); +EXPORT_SYMBOL(kinematicsJacobian); +EXPORT_SYMBOL(kinematicsForward); + +KINEMATICS_TYPE kinematicsType() +{ + return KINEMATICS_IDENTITY; +} + +int kinematicsForward(const double *j, EmcPose *pos, + const KINEMATICS_FORWARD_FLAGS *fflags, + KINEMATICS_INVERSE_FLAGS *iflags) +{ + (void)fflags; + (void)iflags; + if (haldata->armed) { + rtapi_sint end = rtapi_get_time() + (rtapi_sint)hal_get_uint(haldata->wait_ns); + haldata->armed = 0; + while (rtapi_get_time() < end) + ; + } + pos->tran.x = j[0]; + pos->tran.y = j[1]; + pos->tran.z = j[2]; + pos->a = pos->b = pos->c = 0; + pos->u = pos->v = pos->w = 0; + return 0; +} + +int kinematicsInverse(const EmcPose *pos, double *j, + const KINEMATICS_INVERSE_FLAGS *iflags, + KINEMATICS_FORWARD_FLAGS *fflags) +{ + (void)iflags; + (void)fflags; + j[0] = pos->tran.x; + j[1] = pos->tran.y; + j[2] = pos->tran.z; + return 0; +} + +int kinematicsJacobian(const double *j, const EmcPose *pos, + double jac[EMCMOT_MAX_JOINTS][EMCMOT_MAX_AXIS], + const KINEMATICS_INVERSE_FLAGS *iflags) +{ + (void)j; + (void)pos; + (void)iflags; + memset(jac, 0, sizeof(double) * EMCMOT_MAX_JOINTS * EMCMOT_MAX_AXIS); + jac[0][0] = 1; + jac[1][1] = 1; + jac[2][2] = 1; + return 0; +} diff --git a/tests/stale-motion-status/slow-controller/test-ui.py b/tests/stale-motion-status/slow-controller/test-ui.py new file mode 120000 index 00000000000..15b94027b91 --- /dev/null +++ b/tests/stale-motion-status/slow-controller/test-ui.py @@ -0,0 +1 @@ +../test-ui.py \ No newline at end of file diff --git a/tests/stale-motion-status/slow-controller/test.ini b/tests/stale-motion-status/slow-controller/test.ini new file mode 100644 index 00000000000..d4644a2b791 --- /dev/null +++ b/tests/stale-motion-status/slow-controller/test.ini @@ -0,0 +1,90 @@ +[TEST] +PROBES = 300 +FEED = 300 + +[EMC] +VERSION = 1.1 +DEBUG = 0x0 + +[DISPLAY] +DISPLAY = ./test-ui.py + +[TASK] +TASK = milltask +CYCLE_TIME = 0.001 + +[RS274NGC] +PARAMETER_FILE = sim.var + +[EMCMOT] +EMCMOT = motmod +COMM_TIMEOUT = 4.0 +BASE_PERIOD = 0 +SERVO_PERIOD = 1000000 + +[EMCIO] +TOOL_TABLE = simpockets.tbl + +[HAL] +HALFILE = LIB:core_sim.hal +HALFILE = probe.hal + +[TRAJ] +NO_FORCE_HOMING = 1 +COORDINATES = X Y Z +LINEAR_UNITS = inch +ANGULAR_UNITS = degree +DEFAULT_LINEAR_VELOCITY = 10 +MAX_LINEAR_VELOCITY = 100 + +[KINS] +KINEMATICS = slowkins +JOINTS = 3 + +[AXIS_X] +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 + +[JOINT_0] +TYPE = LINEAR +HOME = 0.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +FERROR = 0.050 +MIN_FERROR = 0.010 + +[AXIS_Y] +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 + +[JOINT_1] +TYPE = LINEAR +HOME = 0.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +FERROR = 0.050 +MIN_FERROR = 0.010 + +[AXIS_Z] +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 + +[JOINT_2] +TYPE = LINEAR +HOME = 0.0 +MAX_VELOCITY = 100 +MAX_ACCELERATION = 10000.0 +MIN_LIMIT = -40.0 +MAX_LIMIT = 40.0 +FERROR = 0.050 +MIN_FERROR = 0.010 diff --git a/tests/stale-motion-status/slow-controller/test.ngc b/tests/stale-motion-status/slow-controller/test.ngc new file mode 120000 index 00000000000..45526095ca3 --- /dev/null +++ b/tests/stale-motion-status/slow-controller/test.ngc @@ -0,0 +1 @@ +../test.ngc \ No newline at end of file diff --git a/tests/stale-motion-status/slow-controller/test.sh b/tests/stale-motion-status/slow-controller/test.sh new file mode 100755 index 00000000000..14a77f5bc36 --- /dev/null +++ b/tests/stale-motion-status/slow-controller/test.sh @@ -0,0 +1,5 @@ +#!/bin/bash +set -e + +halcompile --install slowkins.comp >/dev/null +linuxcnc -r test.ini diff --git a/tests/stale-motion-status/test-ui.py b/tests/stale-motion-status/test-ui.py new file mode 100755 index 00000000000..0682db249dc --- /dev/null +++ b/tests/stale-motion-status/test-ui.py @@ -0,0 +1,95 @@ +#!/usr/bin/env python3 + +import linuxcnc +import hal + +import time +import sys +import os + +c = linuxcnc.command() +s = linuxcnc.stat() +e = linuxcnc.error_channel() + +h = hal.component("test-ui") +h.newpin("finished", hal.Type.REAL, hal.Dir.IN) +h.ready() +os.system("halcmd source ./postgui.hal") + +failures = [] + +def settle(what, done): + """wait_complete() must not return before the command took effect; + note it if it did, then wait for it so the rest still runs""" + s.poll() + if done(): + return + failures.append("wait_complete() returned before " + what) + start = time.time() + while not done(): + if time.time() - start > 60: + sys.stderr.write("timeout waiting for %s\n" % what) + sys.exit(1) + time.sleep(0.05) + s.poll() + +c.state(linuxcnc.STATE_ESTOP_RESET) +c.wait_complete(60) +c.state(linuxcnc.STATE_ON) +c.wait_complete(60) +settle("the machine was on", lambda: s.task_state == linuxcnc.STATE_ON) + +# one joint at a time: a home command while another joint homes is refused +for joint in range(3): + c.home(joint) + start = time.time() + while True: + s.poll() + if s.homed[joint] and not any(j["homing"] for j in s.joint[:3]): + break + if time.time() - start > 60: + sys.stderr.write("timeout homing joint %d\n" % joint) + sys.exit(1) + time.sleep(0.05) + +c.mode(linuxcnc.MODE_AUTO) +c.wait_complete(60) +settle("auto mode was on", lambda: s.task_mode == linuxcnc.MODE_AUTO + and s.motion_mode == linuxcnc.TRAJ_MODE_COORD) + +c.program_open('test.ngc') +c.auto(linuxcnc.AUTO_RUN, 0) + +start = time.time() +while True: + s.poll() + if s.interp_state != linuxcnc.INTERP_IDLE: + break + if time.time() - start > 60: + sys.stderr.write("timeout waiting for the program to start\n") + sys.exit(1) + time.sleep(0.001) + +errors = [] +while True: + err = e.poll() + if err: + errors.append(err[1]) + s.poll() + if s.interp_state == linuxcnc.INTERP_IDLE: + break + if time.time() - start > 600: + sys.stderr.write("timeout waiting for the program to finish\n") + sys.exit(1) + time.sleep(0.05) + +err = e.poll() +while err: + errors.append(err[1]) + err = e.poll() + +for msg in failures + errors: + sys.stderr.write("error: %s\n" % msg) +if h["finished"] != 1: + sys.stderr.write("the program did not finish\n") +sys.exit(1 if failures or errors or h["finished"] != 1 else 0) diff --git a/tests/stale-motion-status/test.ngc b/tests/stale-motion-status/test.ngc new file mode 100644 index 00000000000..ceeea2d276e --- /dev/null +++ b/tests/stale-motion-status/test.ngc @@ -0,0 +1,16 @@ +G20 G90 G94 +G0 Z0 +# = 0 +o100 while [# LT #<_ini[test]probes>] + # = [-0.45 - 0.1 * [# MOD 2]] + M68 E1 Q# + G0 Z-0.4 + G38.2 Z-1 F#<_ini[test]feed> + o110 if [ABS[#5063 - #] GT 0.02] + (abort, probe # read Z#5063, it tripped at Z#) + o110 endif + # = [# + 1] +o100 endwhile +G0 Z0 +M68 E0 Q1 +M2 From 72afaac66ff87c8620a27a1d873474c1576a6daf Mon Sep 17 00:00:00 2001 From: Luca Toniolo <10792599+grandixximo@users.noreply.github.com> Date: Sat, 17 Oct 2026 16:15:15 +1100 Subject: [PATCH 6/6] tests: stale-motion-status: slow the controller only once task is up At startup task reads the motion status once a second and gives up after ten tries. The tries come at the same point of the servo period each time, so with slowkins keeping the controller busy for most of the period from load on, all ten could miss the free part of the period: "can't read motion status" under load (#4669). With a wait of 99% of the period from load the startup failed that way in some runs. slow-controller now sets the wait once task has handled its first command. The commands after it still run with the controller busy for most of the period, and pass with a wait of 99% too. --- tests/stale-motion-status/README | 3 ++- tests/stale-motion-status/slow-controller/probe.hal | 6 +++--- tests/stale-motion-status/test-ui.py | 4 ++++ 3 files changed, 9 insertions(+), 4 deletions(-) diff --git a/tests/stale-motion-status/README b/tests/stale-motion-status/README index 1b12ac0a5b6..993a1643a0d 100644 --- a/tests/stale-motion-status/README +++ b/tests/stale-motion-status/README @@ -19,4 +19,5 @@ longer than the var file write task does when it synchs after a probe. slow-controller uses kinematics that busy wait, so motion-controller takes most of the servo period and status reads by task often fail -while it runs. +while it runs. The wait starts once task is up: its startup reads the +status only once a second and gives up after ten tries. diff --git a/tests/stale-motion-status/slow-controller/probe.hal b/tests/stale-motion-status/slow-controller/probe.hal index dbbe98e437e..0c0e3c6ba81 100644 --- a/tests/stale-motion-status/slow-controller/probe.hal +++ b/tests/stale-motion-status/slow-controller/probe.hal @@ -5,7 +5,7 @@ net Zpos => probe-comp.in0 net probe-height motion.analog-out-01 => probe-comp.in1 net probe probe-comp.out => motion.probe-input -# Make the controller take most of the servo period, so that status -# reads by task often fail while it runs. +# Let the controller take most of the servo period, so that status reads +# by task often fail while it runs. test-ui.py sets slowkins.wait-ns once +# task is up: at startup task reads the status only once a second. addf slowkins.arm servo-thread 1 -setp slowkins.wait-ns 700000 diff --git a/tests/stale-motion-status/test-ui.py b/tests/stale-motion-status/test-ui.py index 0682db249dc..7387363da4a 100755 --- a/tests/stale-motion-status/test-ui.py +++ b/tests/stale-motion-status/test-ui.py @@ -35,6 +35,10 @@ def settle(what, done): c.state(linuxcnc.STATE_ESTOP_RESET) c.wait_complete(60) +# slow-controller: task is up, from now on the controller takes most of +# the servo period +if hal.component_exists("slowkins"): + hal.set_p("slowkins.wait-ns", "700000") c.state(linuxcnc.STATE_ON) c.wait_complete(60) settle("the machine was on", lambda: s.task_state == linuxcnc.STATE_ON)