[3.5.0-rc.3] Conditional 'abort' command called unexpectedly

lycean

I upgraded from 3.4.6 to 3.5.0-rc.3 and started getting spurious aborts while docking the Z probe on my printer. After a bunch of experiments I've managed to get a minimal repro script for the problem.

Save the script below as test.g in the sys directory (or macros, it doesn't matter, but I'm assuming it's in sys).

If you execute it from the console with M98 P"test.h" then it'll work as you expect. If you put that same line in a print job (a job with just that one line will do) and start the job the second abort command will trigger when the pause starts, i.e. before the if statement is reached.

; Use probe 1 as a dummy source for values
M558 K1 P8 C"0.io6.in" H2 F1000

; Center the head before we start
G0 X{(move.axes[0].max - move.axes[0].min) / 2} Y{(move.axes[1].max - move.axes[1].min) / 2} Z50 F10000
M400

;
; First test block
;
echo "1.0 Starting test"
G91
echo "1.1 Commanding move"
G0 X50 F1000    ; ** Need to command a move for the problem to occur.
G90
G31 K1 P2000    ; ** Need to set threshold so the 'if' statement below will evaluate to true before the pause.
echo "1.2 Pausing"
G4 P1           ; ** Need a delay after the move.
echo "1.3 Setting threshold to 500"
G31 K1 P500 ; Set threshold to 500 so the 'if' statement below should be false and the 'abort' shouldn't be executed. 
echo "1.4 Testing to see if probe speed "^sensors.probes[1].speeds[0]^" is less than threshold "^sensors.probes[1].threshold
if sensors.probes[1].speeds[0] < sensors.probes[1].threshold
  abort "1.5 SHOULD NEVER FIRE: Probe speed "^sensors.probes[1].speeds[0]^" is less than threshold "^sensors.probes[1].threshold
echo "1.6 Finished test"

Output if you run the script from the console:

09/02/2024, 8:21:00 pm	M98 P"test.g"
                        1.0 Starting test
                        1.1 Commanding move
                        1.2 Pausing
09/02/2024, 8:21:03 pm	1.3 Setting threshold to 500
                        1.4 Testing to see if probe speed 1000.0 is less than threshold 500
                        1.6 Finished test

Output if you run the script from a job:

09/02/2024, 8:22:09 pm	M32 "0:/gcodes/run-test.g"
                        File 0:/gcodes/run-test.g selected for printing
                        1.0 Starting test
                        1.1 Commanding move
                        1.2 Pausing
                        Cancelled printing file 0:/gcodes/run-test.g, print time was 0h 0m
                        1.5 SHOULD NEVER FIRE: Probe speed 1000.0 is less than threshold 2000
09/02/2024, 8:22:12 pm	1.3 Setting threshold to 500
                        1.4 Testing to see if probe speed 1000.0 is less than threshold 500
                        1.6 Finished test

This is the same issue I see in probe dock/undock process, the critical bits being the move, the condition for the if being true before the pause, and the pause.

EDIT: Re-pasted test.g script to fix up the problem @OwenD pointed out, which seems to have happened copying & pasting the code.

OwenD

@lycean said in [3.5.0-rc.3] Conditional 'abort' command called unexpectedly:

if sensors. Probes[1].speeds[0] < sensors. Probes[1].threshold

Your if statement has syntax errors, whereas your echo statement is correct.

Try

if sensors.probes[1].speeds[0] < sensors.probes[1].threshold

lycean

@OwenD Thanks for pointing that out, it seems to have happened copying & pasting the code (not sure how I managed to do that...). I've re-copied the code in the original post.

OwenD

@lycean
It seems to be failing at the G31 command
You can check each command using result

G31 K1 P500
if result = 0
    echo "G31 OK"
else
    echo "G31 failed"

If you see the failed message, or no message then you have your culprit.
Not sure if it makes a difference calling G31 in a print job vs a macro
It's probably failing in both, but RRF sees it as a fatal failure when you're printing

lycean

Correct, the failure occurs at the G31, but only when the command in the if block is an abort.

The abort command works whether the script is called from a print job or from the console. You can test this by putting the line abort "This should abort" at the top of test.g and run it, either way it'll abort as expected.

If you replace the abort command with an echo command then the problem doesn't occur, i.e. replacing the if block with this:

if sensors.probes[1].speeds[0] < sensors.probes[1].threshold
  echo "1.5 SHOULD NEVER FIRE: Probe speed "^sensors.probes[1].speeds[0]^" is less than threshold "^sensors.probes[1].threshold

works fine, here's an example of the output when test.g is called from a print job:

10/02/2024, 5:56:08 pm	M32 "0:/gcodes/run-test.g"
                        File 0:/gcodes/run-test.g selected for printing
                        1.0 Starting test
                        1.1 Commanding move
                        1.2 Pausing
10/02/2024, 5:56:11 pm	1.3 Setting threshold to 500
                        1.4 Testing to see if probe speed 1000.0 is less than threshold 500
                        1.6 Finished test
                        Finished printing file 0:/gcodes/run-test.g, print time was 0h 0m

The echo didn't get executed, as you'd expect.

OwenD

@lycean
Looks like it might be an SBC thing?
I ran it on my Duet 2 stand alone mo problems (had to change IO)

Screenshot 2024-02-10 at 19-38-57 3Dprinter.png

; Use probe 1 as a dummy source for values
M558 K1 P8 C"exp.e6_stop" H2 F1000

; Center the head before we start
G0 X{(move.axes[0].max - move.axes[0].min) / 2} Y{(move.axes[1].max - move.axes[1].min) / 2} Z50 F10000
M400

;
; First test block
;
echo "1.0 Starting test"
G91
echo "1.1 Commanding move"
G0 X50 F1000    ; ** Need to command a move for the problem to occur.
G90
G31 K1 P2000    ; ** Need to set threshold so the 'if' statement below will evaluate to true before the pause.
echo "1.2 Pausing"
G4 P1           ; ** Need a delay after the move.
echo "1.3 Setting threshold to 500"
G31 K1 P500 ; Set threshold to 500 so the 'if' statement below should be false and the 'abort' shouldn't be executed. 
echo "1.4 Testing to see if probe speed "^sensors.probes[1].speeds[0]^" is less than threshold "^sensors.probes[1].threshold
if sensors.probes[1].speeds[0] < sensors.probes[1].threshold
  abort "1.5 SHOULD NEVER FIRE: Probe speed "^sensors.probes[1].speeds[0]^" is less than threshold "^sensors.probes[1].threshold
echo "1.6 Finished test"

gloomyandy

@OwenD Could be SBC or could be related to the multiple gcode stream feature, so you may not see it on a Duet2.

lycean

I'm running this stand-alone on a Duet 3 MB6HC (with a TOOL1LC board as well).

@gloomyandy That's an interesting point about the multiple gcode streams feature, I wasn't aware of that. If a second stream is simulating the job in advance it may be that the abort is actually being executed by the simulation instead of being ignored.

gloomyandy

@lycean It's not a simulation, it is running through all of the gcodes, it is just that only some of them are being executed by each stream. See: https://docs.duet3d.com/User_manual/RepRapFirmware/Multiple_motion_systems

OwenD

@gloomyandy said in [3.5.0-rc.3] Conditional 'abort' command called unexpectedly:

@OwenD Could be SBC or could be related to the multiple gcode stream feature, so you may not see it on a Duet2.

Very true.
If it's multiple stream issue the perhaps a G4 P100 before the if and abort commands would be a work around?

lycean

@gloomyandy The reason I said 'simulation' was this quote by @dc42 (from https://forum.duet3d.com/post/104962)

One of the applications for multiple GCode streams is to have the second stream reading the print file ahead of the main one and simulating it, so that it can predict a tool change or colour mix change in advance, and prepare the new tool or change the colour mix ahead of time.

Using the multiple motion streams that you pointed out requires the use of the M596 command which I'm not using, so my assumption was that it might be the simulation idea mentioned in that post.

gloomyandy

@lycean My understanding is that there are two motion systems and in the case of a print from a file there are also two gcode streams in operation (file1 and file2). These are two separate but related concepts, file1 executes movement commands via movement stream 0 while file2 executes them via movement stream 1. However some G and M commands are executed by both gcode processors (note that they are executed not simulated in that they change the actual machine state), to see which commands are executed by both file1 and file2 see the link I provided above. My understanding is that macros are executed by both file1 and file2 streams. The key question is are meta commands executed by both file streams or not. I think that they are, but perhaps @dc42 could clarify that (@droftarts I think it would be good to clarify what happens with meta commands in the documentation).

So what I think may be happening here is that your macro is being executed by file2, however it will not process the G31 commands (as no M596 command has been used to switch "general gcode processing to movement stream 1) but it will execute the meta commands in particular the if statement and the subsequent abort statement. But it will be using whatever values are already set for the threshold and offset not the ones being set in the macro (because those commands will not have been executed by file2). I think this may also explain why you need to execute a movement command and execute a delay to see the problem. I think these will delay the execution of file1 (and hence the actual execution of the G31 commands) and will be allowing file2 to "be ahead" of file1, but after file1 has executed the G31 command to set the threshold to 2000.

Note that I've not tried your example and the above is just based on my understanding of the code. There are some things I don't understand, so for instance are echo commands executed by both file1 and file2? If they are why do we not see two sets of echo output?

lycean

@gloomyandy Interesting, thanks for the information!

It certainly looks like something is evaluating the gcode ahead of the motion processing, and when the G31 is hit that evaluation follows the true path for the if statement (because that's correct given the state of the system at that instant) and then hits the abort. However, if that's the case, it shouldn't do anything - just like the echo doesn't do anything.

Hopefully someone with some more knowledge can take a peek, I just don't have the time or motivation to go pull the code and figure out how all this works.

SumoSniper

@lycean I've come up with a simple set of gcode in my thread here that I believe replicates this MMS forward evaluation issue. Seems like we are running into similar issues.

Mutiple Motion Systems & Macro Conflicts in 3.5

dc42

@lycean as @SumoSniper says, this is caused y the behaviour of multiple motion streams. See the thread he referenced.

The latest firmware binaries at https://www.dropbox.com/scl/fo/p0136wx04h8xf6ejwdnn9/h?rlkey=efrfwyb6o5tqid11gustz3uvy&dl=0 do not execute abort commands from an inactive motion stream.

lycean

@SumoSniper Thanks for pointing out your thread!

lycean

@dc42 Thanks, that's great, and I also see your suggestion in @SumoSniper's thread to get the inactive reader to skip processing problematic macros with

if state.thisInput != null & !state.thisInput.active
  M99

dc42

@lycean if you use the lates firmware at https://www.dropbox.com/scl/fo/3y4agkmfzfmqcifuecqo3/h?rlkey=j0kibs1tubm5dfj7o2vz1vbzj&dl=0 then you won't need to change your macros.