[3.5b4] Homing process issues unwanted 'abort' command

Diamondback

Hello,

I've had this issue since a while on various 3.5 betas, but never got around to reporting it (can't remember when it started, sorry )
My RRF automatically issues an abort command in my homing sequence IF the homing is part of a print job. It works fine when I manually trigger it.
So my first hunch would be something again about macro hierachy depth or something, but replicating the same depth without making it a print job still works fine...
Here's the executed gcode, this is a minimalized print job that is executed as such and triggers the behavior every single time for me.

print-file gcode:

M98 P"/macros/Misc/PrePrintCalibrate"

PrePrintCalibrate:

echo "Pre-Print Calibration"
echo "Checking Homing Status"
M98 P"homeall.g"
echo "Ensuring no active tool"
T-1

echo "Starting Bed Mesh Process"
echo "Setting bed mesh to default values"
M557 X{global.minXMesh, global.maxXMesh} Y{global.minYMesh, global.maxYMesh} S{global.meshPointSpacing}  ; define default mesh grid

echo "Starting bed.g macro..."
G32

homeall.g:

echo "Executing homeall.g"

M98 P"homew.g"	                ; Home Wiper height
M98 P"homed.g"		        ; Home Wiper disk
M98 P"homey.g"			; Home Y
M98 P"homex.g"			; Home X 
M98 P"homez.g"			; Home Z
M98 P"homec.g"			; Home C (ToolHead)

homew.g:

echo "Executing homew.g"

G91
M400
M913 W10		; C MOTOR TO 60% CURRENT
G1 H2 W-26 F2000
G92 W-1
G90
M400
M913 W100			; C MOTORS TO 100% CURRENT

homed.g:

echo "Executing homed.g"

M400
G92 D0

homey.g:

echo "Executing homey.g"

G91               ; relative positioning
G1 Z5 F2100 H2    ; lift Z relative to current position
G1 H1 Y-500 F10000 ; move quickly to Y axis endstop and stop there (first pass)
G1 Y5 F10000       ; go back a few mm
G1 H1 Y-500 F360  ; move slowly to Y axis endstop once more (second pass)
G90               ; absolute positioning

homex.g:

echo "Executing homex.g"

G91               ; relative positioning
G1 Z5 F2100 H2    ; lift Z relative to current position
G1 H1 X400 F10000 ; move quickly to X axis endstop and stop there (first pass)
G1 X-5 F10000       ; go back a few mm
G1 H1 X400 F360  ; move slowly to X axis endstop once more (second pass)
G90               ; absolute positioning

homez.g:

echo "Executing homez.g"

G90 ; absolute positioning
G1 X0 Y0 F15000 ; go to first probe point

M558 K0 P{global.zProbeType} C{global.zProbePin} H{global.zProbeDiveHeightMesh} F{global.zProbeSpeedFeedLevel} T{global.zProbeSpeedTravel}  ; set Z probe dive height + speeds
G31 K0 X0 Y0 Z0 P{global.zProbeTriggerValue} ; set Z probe trigger value, offset and trigger height
G30 K0 ; home Z by probing the bed
M558 K0 P{global.zProbeType} C{global.zProbePin} H{global.zProbeDiveHeightMesh} F{global.zProbeSpeedFeed} T{global.zProbeSpeedTravel}  ; set Z probe dive height + speeds
G31 K0 X0 Y0 Z0 P{global.zProbeTriggerValue} ; set Z probe trigger value, offset and trigger height
G30 K0 ; home Z by probing the bed
G91 ; relative positioning
G1 Z10 F{global.zProbeSpeedFeedLevel}

homec.g:

echo "Executing homec.g"
	
G91
M400
M913 C60		; C MOTOR TO 60% CURRENT
G1 H2 C-300 F10000
G92 C0
G90
M400
M913 C100			; C MOTORS TO 100% CURRENT

M98 P"/macros/Toolchanging/Coupler - Unlock"		; open coupler

Weirdly enough, with all the prints it shows that the abort is triggered seemingly randomly within the homing sequence, it changes "position" each test more or less.

Here's what a relevant console looks like:

Here's an M122 after it cancelled in case that has any merit...

M122
=== Diagnostics ===
RepRapFirmware for Duet 3 MB6HC version 3.5.0-beta.4 (2023-06-08 23:41:30) running on Duet 3 MB6HC v1.02 or later (standalone mode)
Board ID: 08DJM-9P63L-DJ3T0-6J1F4-3S06S-9A1V9
Used output buffers: 3 of 40 (31 max)
=== RTOS ===
Static ram: 155012
Dynamic ram: 132568 of which 0 recycled
Never used RAM 29524, free system stack 143 words
Tasks: NETWORK(1,ready,38.3%,182) ETHERNET(5,nWait,0.3%,317) ACCEL(6,nWait,0.0%,348) HEAT(3,nWait,0.0%,323) Move(4,nWait,0.0%,216) CanReceiv(6,nWait,0.0%,794) CanSender(5,nWait,0.0%,335) CanClock(7,delaying,0.0%,351) TMC(4,nWait,8.7%,59) MAIN(1,running,52.7%,137) IDLE(0,ready,0.0%,30), total 100.0%
Owned mutexes:
=== Platform ===
Last reset 00:06:38 ago, cause: software
Last software reset at 2023-07-11 21:22, reason: User, Gcodes spinning, available RAM 29764, slot 2
Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00400000 BFAR 0x00000000 SP 0x00000000 Task MAIN Freestk 0 n/a
Error status: 0x00
MCU temperature: min 43.8, current 44.7, max 44.9
Supply voltage: min 23.6, current 23.8, max 23.9, under voltage events: 0, over voltage events: 0, power good: yes
12V rail voltage: min 12.2, current 12.3, max 12.5, under voltage events: 0
Heap OK, handles allocated/used 495/389, heap memory allocated/used/recyclable 24576/23948/1428, gc cycles 61
Events: 0 queued, 0 completed
Driver 0: standstill, SG min 0, mspos 136, reads 23621, writes 17 timeouts 0
Driver 1: standstill, SG min 0, mspos 552, reads 23621, writes 17 timeouts 0
Driver 2: standstill, SG min 0, mspos 616, reads 23622, writes 17 timeouts 0
Driver 3: standstill, SG min 0, mspos 136, reads 23622, writes 17 timeouts 0
Driver 4: standstill, SG min 0, mspos 952, reads 23618, writes 21 timeouts 0
Driver 5: standstill, SG min 0, mspos 296, reads 23622, writes 17 timeouts 0
Date/time: 2023-07-11 21:29:04
Slowest loop: 13.85ms; fastest: 0.04ms
=== Storage ===
Free file entries: 19
SD card 0 detected, interface speed: 25.0MBytes/sec
SD card longest read time 0.8ms, write time 2.5ms, max retries 0
=== Move ===
DMs created 125, segments created 9, maxWait 182660ms, bed compensation in use: mesh, height map offset 0.000, ebfmin 0.00, ebfmax 0.00
no step interrupt scheduled
=== DDARing 0 ===
Scheduled moves 558, completed 558, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== DDARing 1 ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== Heat ===
Bed heaters 0 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1, chamber heaters -1 -1 -1 -1, ordering errs 0
=== GCodes ===
Movement locks held by null, null
HTTP is idle in state(s) 0
Telnet is idle in state(s) 0
File is idle in state(s) 0
USB is idle in state(s) 0
Aux is idle in state(s) 0
Trigger is idle in state(s) 0
Queue is idle in state(s) 0
LCD is idle in state(s) 0
SBC is idle in state(s) 0
Daemon is doing "G4 P500" in state(s) 0 0, running macro
Aux2 is idle in state(s) 0
Autopause is idle in state(s) 0
File2 is idle in state(s) 0
Queue2 is idle in state(s) 0
Q0 segments left 0, axes/extruders owned 0x0000000
Code queue 0 is empty
Q1 segments left 0, axes/extruders owned 0x0000000
Code queue 1 is empty
=== Filament sensors ===
Extruder 0: no data received
Extruder 1: no data received
Extruder 2: no data received
Extruder 3: no data received
=== CAN ===
Messages queued 4171, received 8749, lost 0, boc 0
Longest wait 1ms for reply type 6018, peak Tx sync delay 111, free buffers 50 (min 49), ts 1995/1994/0
Tx timeouts 0,0,0,0,0,0
=== Network ===
Slowest loop: 36.21ms; fastest: 0.03ms
Responder states: MQTT(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0) Telnet(0)
HTTP sessions: 1 of 8
= Ethernet =
Interface state: active
Error counts: 0 0 0 1 0 0
Socket states: 5 2 2 2 2 0 0 0
= WiFi =
Interface state: disabled
Module is disabled
Failed messages: pending 0, notready 0, noresp 0
Socket states: 0 0 0 0 0 0 0 0
=== Multicast handler ===
Responder is inactive, messages received 0, responses 0

Everything works fine with the print job if i remove the homing from it and just home manually before...

Any ideas?

Diamondback

Anyone? @dc42 ?

Phaedrux

@Diamondback said in [3.5b4] Homing process issues unwanted 'abort' command:

M98 P"homeall.g"

Does it still happen if you use G28 instead of calling it with M98?

Diamondback

@Phaedrux That actually works fine That's very helpful already, but why does this happen? It used to work fine but the regression happened with one of the 3.5 betas...
Does this have potential consequences for other macro calls?

gloomyandy

@Diamondback What board are you using? What version of RRF (the output from M122 would probably be useful).

Diamondback

@gloomyandy

=== Diagnostics ===
RepRapFirmware for Duet 3 MB6HC version 3.5.0-beta.4 (2023-06-08 23:41:30) running on Duet 3 MB6HC v1.02 or later (standalone mode)
Board ID: 08DJM-9P63L-DJ3T0-6J1F4-3S06S-9A1V9
Used output buffers: 3 of 40 (40 max)
=== RTOS ===
Static ram: 155012
Dynamic ram: 133920 of which 0 recycled
Never used RAM 27692, free system stack 117 words
Tasks: NETWORK(1,ready,136.5%,165) ETHERNET(5,nWait,19.8%,115) ACCEL(6,nWait,0.0%,348) HEAT(3,nWait,6.3%,323) Move(4,nWait,187.8%,210) CanReceiv(6,nWait,10.3%,769) CanSender(5,nWait,1.8%,326) CanClock(7,delaying,1.7%,349) TMC(4,nWait,128.2%,59) MAIN(1,running,47.7%,137) IDLE(0,ready,0.4%,30), total 540.6%
Owned mutexes:
=== Platform ===
Last reset 196:22:54 ago, cause: power up
Last software reset at 2023-07-27 13:42, reason: User, Gcodes spinning, available RAM 27548, slot 2
Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00400000 BFAR 0x00000000 SP 0x00000000 Task MAIN Freestk 0 n/a
Error status: 0x04
MCU temperature: min 20.8, current 44.6, max 48.0
Supply voltage: min 23.3, current 23.6, max 24.0, under voltage events: 0, over voltage events: 0, power good: yes
12V rail voltage: min 12.1, current 12.3, max 12.5, under voltage events: 0
Heap OK, handles allocated/used 495/415, heap memory allocated/used/recyclable 24576/24092/1072, gc cycles 90579
Events: 0 queued, 0 completed
Driver 0: standstill, SG min 0, mspos 456, reads 20344, writes 403 timeouts 0
Driver 1: standstill, SG min 0, mspos 200, reads 20344, writes 403 timeouts 0
Driver 2: ok, SG min 0, mspos 382, reads 20340, writes 407 timeouts 0
Driver 3: ok, SG min 0, mspos 275, reads 20341, writes 407 timeouts 0
Driver 4: standstill, SG min 0, mspos 520, reads 20193, writes 555 timeouts 0
Driver 5: standstill, SG min 0, mspos 456, reads 20345, writes 403 timeouts 0
Date/time: 2023-08-08 15:06:55
Slowest loop: 221.89ms; fastest: 0.04ms
=== Storage ===
Free file entries: 13
SD card 0 detected, interface speed: 25.0MBytes/sec
SD card longest read time 3.2ms, write time 147.5ms, max retries 0
=== Move ===
DMs created 125, segments created 29, maxWait 87145020ms, bed compensation in use: mesh, height map offset 0.000, ebfmin 0.00, ebfmax 0.00
next step interrupt due in 125 ticks, disabled
=== DDARing 0 ===
Scheduled moves 89768, completed 89743, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 5], CDDA state 3
=== DDARing 1 ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== Heat ===
Bed heaters 0 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1, chamber heaters -1 -1 -1 -1, ordering errs 0
Heater 0 is on, I-accum = 0.0
Heater 4 is on, I-accum = 0.0
=== GCodes ===
Movement locks held by null, null
HTTP is idle in state(s) 0
Telnet is idle in state(s) 0
File is idle in state(s) 3
USB is idle in state(s) 0
Aux is idle in state(s) 0
Trigger is idle in state(s) 0
Queue is idle in state(s) 0
LCD is idle in state(s) 0
SBC is idle in state(s) 0
Daemon is doing "M150 R0 U0 B0 P0 S64 F0" in state(s) 0 0 0 0 0, running macro
Aux2 is idle in state(s) 0
Autopause is idle in state(s) 0
File2 is doing "M0" in state(s) 0 0, running macro, sync state 1
Queue2 is idle in state(s) 0
Q0 segments left 1, axes/extruders owned 0x10000007
Queue 0 has 'M150 R0 U0 B0 P0 S64 F0' for move 89751
Queue 0 has 'M150 R0 U0 B0 P0 S64 F0' for move 89757
Queue 0 has 'M150 R0 U0 B0 P0 S64 F0' for move 89763
Q1 segments left 0, axes/extruders owned 0x0000000
Code queue 1 is empty
=== Filament sensors ===
Extruder 0: no data received
Extruder 1: no data received
Extruder 2: no data received
Extruder 3: no data received
=== CAN ===
Messages queued 9605379, received 14701227, lost 0, boc 0
Longest wait 2ms for reply type 6013, peak Tx sync delay 24761, free buffers 50 (min 48), ts 3534871/3534870/0
Tx timeouts 0,0,0,0,0,0
=== Network ===
Slowest loop: 3684.59ms; fastest: 0.03ms
Responder states: MQTT(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0) Telnet(0)
HTTP sessions: 1 of 8
= Ethernet =
Interface state: active
Error counts: 0 0 0 1 0 0
Socket states: 5 5 2 2 2 0 0 0
= WiFi =
Interface state: disabled
Module is disabled
Failed messages: pending 0, notready 0, noresp 0
Socket states: 0 0 0 0 0 0 0 0
=== Multicast handler ===
Responder is inactive, messages received 0, responses 0