Pause/resume issues in 3.5.0rc3+5?

NeoDue

@Exerqtor Hm. My printer is running rc3+ date 2024-02-27 here, and filament run-out detection. manual load via PanelDue and resume works perfectly fine.

In case it helps, here are my pause/resume config files:

; pause.g
; Called when a print from SD card is paused

M400                     ; finish active moves 
G10                      ; retract
G91                      ; relative Positioning
G1 Z5 F360               ; move bed 5mm down
G90                      ; absolute positioning
G1 H2 X{move.axes[0].min} U{move.axes[3].max} Y{move.axes[1].min} F6000    ; move heads to X=min/U=max and Y=min

; resume.g
; called before a print from SD card is resumed

G1 R1 X0 Y0 Z5 F6000     ; move print head 5mm over last position saved in slot 1 
G1 R1 X0 Y0 Z0           ; move bed up 5mm.
M400                     ; finish active moves
G11                      ; unretract if retracted

Exerqtor

@NeoDue Thx for your feedback, but you're running a somewhat older version of 3.5.0 rc3 than I am. Please try these binaries and check if it still works.

I just tried another print with a manual filamentchange (who worked on on 3.5.0b4) and this make the machine stuck in a loop.

I've got the machine setup to automatically purge(if "ok") & resume the print once i click "ok" or "skip" in when M600 is called (I'll post the macros farther down in the post).

This is the way it's supposed to work (and have worked until recently):

M600 in the job g-code and filament-change.g gets run (look farther down for contence of filament-change.g).
The printer goes into the filament change position and a M291 S4 message with "OK" & "SKIP" get's displayed.
"OK" is pressed it will extrude(purge) "n" amount of filament, dim the chamber lights back down, change global.FilamentCHG to true and the that's the end of filament--change.g.
If "SKIP" is pressed no filament will get extruded(purged), dim the chamber lights back down, change global.FilamentCHG to true and the that's the end of filament--change.g.
The following condition in daemon.g get's ran:

  ; Resume after filament change
  if exists(global.FilamentCHG)
    if global.FilamentCHG = true && state.status = "paused"
      M24                                                                      ; Resume the pause automatically now that the manual filament change is done
      set global.FilamentCHG = false

M24 gets sent by daemon.g and resume.g gets ran and the print continues(look farther down for contence of resume.g).

This is what happens now:

M600 in the job g-code and filament-change.g gets run (look farther down for contence of filament-change.g).
The printer goes into the filament change position and a M291 S4 message with "OK" & "SKIP" get's displayed.
"OK" is pressed it will extrude(purge) "n" amount of filament, dim the chamber lights back down, change global.FilamentCHG to true and the that's the end of filament-change.g.
If "SKIP" is pressed no filament will get extruded(purged), dim the chamber lights back down, change global.FilamentCHG to true and the that's the end of filament--change.g.
The following condition in daemon.g get's ran:

  ; Resume after filament change
  if exists(global.FilamentCHG)
    if global.FilamentCHG = true && state.status = "paused"
      M24                                                                      ; Resume the pause automatically now that the manual filament change is done
      set global.FilamentCHG = false

M24 gets sent by daemon.g and resume.g gets ran and the print head returns over the point where it stopped printing but DON'T lower the nozzle down to the buildplate again.
Hovers over the buildplate for a split second and filament-change.g get's ran again, and hence it's stuck in a loop no matter if i press "OK" or "SKIP". The only way i can break the cycle is to power toggle the machine.

Here is the event log from the failed filament change/resumes:

2024-04-01 12:21:01 [warn] Started printing file 0:/gcodes/BFI/[a]_BFI_Front_with_Logo_M3_Symmetrical_x2_0.2mm_ABS_0.4n_21m8s.gcode
2024-04-01 12:21:03 [warn] M150 sent for logo : yellow
2024-04-01 12:21:03 [warn] M150 sent for nozzle : yellow
2024-04-01 12:21:04 [warn] M150 sent for logo : teal
2024-04-01 12:21:04 [warn] M150 sent for nozzle : bright_white
2024-04-01 12:21:32 [warn] M150 sent for logo : green
2024-04-01 12:21:32 [warn] M150 sent for nozzle : bright_white
2024-04-01 12:21:46 [warn] 9 points probed, min error -0.014, max error 0.013, mean -0.004, deviation 0.008
Height map saved to file 0:/sys/heightmap.csv
2024-04-01 12:21:47 [warn] M150 sent for logo : dim_gray
2024-04-01 12:21:47 [warn] M150 sent for nozzle : dim_red
2024-04-01 12:21:48 [warn] M150 sent for logo : yellow
2024-04-01 12:21:48 [warn] M150 sent for nozzle : yellow
2024-04-01 12:22:13 [warn] M150 sent for logo : light_blue
2024-04-01 12:22:13 [warn] M150 sent for nozzle : bright_white
2024-04-01 12:22:23 [warn] M150 sent for logo : red
2024-04-01 12:22:23 [warn] M150 sent for nozzle : bright_white
2024-04-01 12:24:51 [warn] Resume state saved
2024-04-01 12:26:46 [warn] Printing paused for filament change at X174.6 Y157.6 Z0.2
2024-04-01 12:26:48 [warn] Printing resumed
2024-04-01 12:26:48 [warn] Resume state saved
2024-04-01 12:27:20 [warn] Printing paused for filament change at X174.6 Y157.6 Z5.2
2024-04-01 12:27:21 [warn] Printing resumed
2024-04-01 12:27:21 [warn] Resume state saved
2024-04-01 12:27:38 [warn] Printing paused for filament change at X174.6 Y157.6 Z10.2
2024-04-01 12:27:40 [warn] Printing resumed
2024-04-01 12:27:40 [warn] Resume state saved
2024-04-01 12:29:17 [warn] Printing paused for filament change at X174.6 Y157.6 Z15.2
2024-04-01 12:29:18 [warn] Error: M0: Pause the print before attempting to cancel it
2024-04-01 12:29:19 [warn] Printing resumed
2024-04-01 12:29:19 [warn] Resume state saved
2024-04-01 12:29:22 [warn] Error: M0: Pause the print before attempting to cancel it
2024-04-01 12:32:34 [warn] HTTP client 192.168.10.1xx login succeeded (session key 4247479220)
2024-04-01 12:34:00 [warn] Printing paused for filament change at X174.6 Y157.6 Z20.2
2024-04-01 12:34:02 [warn] Printing resumed
2024-04-01 12:34:02 [warn] Resume state saved
2024-04-01 13:02:00 [warn] Warning: VIN under-voltage event (8.6V)
power up + 00:00:03 [info] Event logging started at level warn
power up + 00:00:03 [info] Running: Duet 3 Mini5plus WiFi: 3.5.0-rc.3+5 (2024-03-27 11:34:04)
power up + 00:00:04 [warn] WiFi module started
power up + 00:00:04 [warn] M150 sent for logo : n/a
power up + 00:00:04 [warn] M150 sent for nozzle : n/a
power up + 00:00:04 [warn] M150 sent for logo : n/a
power up + 00:00:04 [warn] M150 sent for nozzle : n/a
power up + 00:00:09 [warn] WiFi module is connected to access point RV32-IOT2G, IP address 192.168.10.x
power up + 00:00:10 [warn] HTTP client 192.168.10.xx login succeeded (session key 3077884437)
2024-04-01 13:02:19 [warn] Date and time set at power up + 00:00:10

The [warn] Error: M0: Pause the print before attempting to cancel it errors got thrown because I tried pressing cancel in PD & DWC after pressing "OK" / "SKIP" btw.

; /sys/filament-change.g  v2.2
; Called when M600 is sent
; Used to do a filament change while printing

;---/
; -/--/--/--/--/--/--/--/--/--/--/--/--/--/--/--/--
; THIS MACRO ONLY WORKS WITH RRF 3.5.0b1 AND LATER!!
;--/--/--/--/--/--/--/--/--/--/--/--/--/--/--/--/--
;-/

; ====================---------------------------------------------------------
; Settings section
; ====================

; Will not be used if you're using a "goto" macro
var x = 40                                                                     ; The X axis location where you want the hotend to "park" while changing filament
var y = 0                                                                      ; The Y axis location where you want the hotend to "park" while changing filament

var spd = 15000                                                                ; The speed of which you want the hotend to move to the "park" location

var lift = 20                                                                  ; The Z clearance you want your nozzle to have from the print while changing filament

var lights = true                                                              ; true / false depending if you have chamber lights or not that you want to turn on
; If you don't have lights you want to turn on don't mess with these
var io = 0                                                                     ; The GPIO port number (set by M950) for the lights you want to turn on
var pwm = 1                                                                    ; The PWM to be set on the GPIO port above, 0=off 1=full power
  
var purge = 60                                                                 ; The amount of filament your hotend need to purge for a clean filament/color change

; Will be swaped out with global.unload_length if you have that defined!
var unload = 12                                                                ; The length of which filament have to be retracted to clear the meltzone
 
; Don't touch anyting beyond this point(unless you know what you're doing)!!
; ====================---------------------------------------------------------


if exists(global.unload_length)
  set var.unload = global.unload_length

var pwm_res = state.gpOut[{var.io}].pwm                                        ; Store the PWM from the PPIO port so that it can be returned after changing filament
if var.lights
  M42 P{var.io} S{var.pwm}                                                     ; Turn on the lights

if fileexists("/sys/lib/beep/l.g")
  M98 P"/sys/lib/beep/l.g"                                                     ; Long beep

M400                                                                           ; Wait for moves to finish
G91                                                                            ; Relative positioning
M83                                                                            ; Extruder relative positioning
G10                                                                            ; Retraction
G1 Z1.00 X20.0 Y20.0 F20000                                                    ; Short quick move to disengage from print
  
G1 Z{var.lift - 1} F800                                                        ; Go to spesified Z clearance

if !fileexists("/sys/lib/goto/front_right.g")
  G90                                                                          ; Absolute positioning
  G1 X{var.x} Y{var.y} F{var.spd}                                              ; Move the nozzle to the location defined in the settings section
if fileexists("/sys/lib/goto/front_right.g")
  M98 P"/sys/lib/goto/front_right.g" {var.spd}                                 ; Move to front right for filament change
  
  
G1 E2 F800                                                                     ; Extrude slightly to help form a nice tip on the filament
G1 E{-(var.unload)} F800                                                       ; Retract filament from the meltzone
M400                                                                           ; Wait for moves to finish

if fileexists("/sys/lib/beep/xl.g")
  M98 P"/sys/lib/beep/xl.g"                                                    ; Extra long beep

M291 S4 R"Manual Filament Change" P"Change & prime filament, then press OK." K{"OK","SKIP",}
; "OK"
if input = 0
  G1 E{var.purge} F200                                                         ; Purge filament
; "SKIP"
if input = 1
  G1 E{var.unload} F800                                                        ; Extrude filament back to the meltzone  

M400                                                                           ; Wait for moves to finish
if var.lights
  M42 P{var.io} S{var.pwm_res}                                                 ; Return lights to previous state

if !exists(global.FilamentCHG)
  global FilamentCHG = true
else
  set global.FilamentCHG = true

; resume.g
; Called before a print from SD card is resumed

G1 R1 X0 Y0 Z5 F15000                                                          ; Go to 5mm above position of the last print move
G1 R1 X0 Y0                                                                    ; Go back to the last print move
M83                                                                            ; Relative extruder moves

NeoDue

@Exerqtor Will do, but probably not before the weekend - I have to finish a longer print first.

In the meantime, I will try to understand that complicated filament change logic of yours...

Offtopic and just to understand: why the heck do you use daemon.g to restart the print instead of simply using filament-change.g to handle everything, including the decision to resume the print?

Exerqtor

@NeoDue said in Pause/resume issues in 3.5.0rc3+5?:

@Exerqtor ~~Will do, but probably not before the weekend - I have to finish a longer print first.~~

In the meantime, I will try to understand that complicated filament change logic of yours...

Offtopic and just to understand: why the heck do you use daemon.g to restart the print instead of simply using filament-change.g to handle everything, including the decision to resume the print?

It's talked about in this thread from about this time last year lol. It might be that RRF has changed it's behaviour in regard to how the states and resume is dealt with on filament change by now that I haven't picked up on. But if you skim through that thread you will see what I/we wanted to achieve.

NeoDue

@Exerqtor Thanks for the link! I faintly remember reading it while I worked on my setup... and that it was the reason for deciding that a manual filament change is perfectly fine for now

But @dc42's information in there that M24 within filament-change.g is not allowed is the answer to my question.

Edit: one thought however: I do not use M600 or such, but I do use a custom filament load macro (not named "filament-change.g") - which is however called by hand via pressing the corresponding Macro button in the PanelDue. When the filament is loaded, I press resume manually - which also works, at least for my firmware version. Did you already try to narrow down the issue, e.g. by calling your filament change macro manually / replacing M24 with a manual call etc?

Exerqtor

@NeoDue Well it's happening in two different scenarios for me now at least, one from the printer being paused by a filament runout, and one from a filament change.

And since i'm not using filament-error.g the filament runout is pretty much just a regular pause but with a runout flag.

So i'm quite sure it's something under the hood of RRF's thats broken and causing this 😅

NeoDue

@Exerqtor Yes, but it might help the devs if you can tell them for example "step x works if I start the macro manually but if I let M600 start it it fails" or such, hence the question. You do have a rather complex routine there

gloomyandy

@Exerqtor We are currently investigating a problem with pause/resume in the latest builds of RRF. I suspect this may be what is causing this problem. You may want to hold off any further investigations until we have a fix for that problem available.

Exerqtor

@gloomyandy Glad to hear my assumptions were right 😆 I'll avoid anything pause/resume related until then lol

Is it related to the commits made for fixing pause/resume issues made in the 3.5-mms-changes branch? I don't think I had any issues before MMS got merged with 3.5-dev 🤔

gloomyandy

@Exerqtor MMS has been present in pretty much all of the 3.5 releases.

Exerqtor

@gloomyandy Yeah I know, I meant the 3.5-mms-changes branch David made March first and the commits made to that branch March 4th [1] & [2] related to resume after pause. I stated the wrong branch name in the previous post(edited it by now).

dc42

@Exerqtor please try the 3.5.0-rc.3+6 build at https://www.dropbox.com/scl/fo/x7ec0sg11a2zrevxoj3j8/h?rlkey=pcdfiv72z0dkkrbv5i8cem5fd&dl=0.

dc42

@Exerqtor oops, that's the wrong firmware build. Give me a few minutes to correct it.

dc42

@Exerqtor I've updated those files.

Exerqtor

@dc42
Aaah i just did a test with the first ones you supplied there and was about to repport that the issue is persistent.

I'll try the NEWER ones after dinner and report back!

@dc42 Naah that build is borked! Now Z won't even move after homing. Or if i try to move the bed from PD / DWC nothing happens.

The printer reported Z0.54 after homing, and if i try to lower Z with 5mm the reported Z-height changes to 5.54 but no actual movement.

Don't know if M122 reports will help any, but here they are:

=== Diagnostics ===
RepRapFirmware for Duet 3 Mini 5+ version 3.5.0-rc.3+6 (2024-04-02 14:34:06) running on Duet 3 Mini5plus WiFi (standalone mode)
Board ID: XNHXF-HR6KL-K65J0-409N2-K9W1Z-RV2MZ
Used output buffers: 29 of 40 (40 max)
=== RTOS ===
Static ram: 103232
Dynamic ram: 126672 of which 12 recycled
Never used RAM 8380, free system stack 135 words
Tasks: NETWORK(2,nWait 7,16.1%,229) HEAT(3,nWait 6,0.0%,351) Move(4,nWait 6,0.0%,256) CanReceiv(6,nWait 1,0.1%,797) CanSender(5,nWait 7,0.0%,336) CanClock(7,delaying,0.0%,339) TMC(4,nWait 6,0.8%,68) MAIN(1,running,81.2%,654) IDLE(0,ready,0.9%,30) AIN(4,delaying,0.8%,260), total 100.0%
Owned mutexes: WiFi(NETWORK)
=== Platform ===
Last reset 00:19:21 ago, cause: software
Last software reset at 2024-04-02 15:40, reason: User, Gcodes spinning, available RAM 11360, slot 1
Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00489000 BFAR 0xe000ed38 SP 0x00000000 Task MAIN Freestk 0 n/a
Error status: 0x04
Aux0 errors 0,0,0
MCU revision 3, ADC conversions started 1161890, completed 1161890, timed out 0, errs 0
MCU temperature: min 39.6, current 43.6, max 47.8
Supply voltage: min 2.8, current 24.1, max 24.4, under voltage events: 0, over voltage events: 0, power good: yes
Heap OK, handles allocated/used 99/43, heap memory allocated/used/recyclable 2048/1500/940, gc cycles 264
Events: 0 queued, 0 completed
Driver 0: standstill, SG min 0, read errors 0, write errors 0, ifcnt 32, reads 61101, writes 32, timeouts 0, DMA errors 0, CC errors 0
Driver 1: standstill, SG min 0, read errors 0, write errors 0, ifcnt 32, reads 61101, writes 32, timeouts 0, DMA errors 0, CC errors 0
Driver 2: standstill, SG min 0, read errors 0, write errors 0, ifcnt 22, reads 61111, writes 22, timeouts 0, DMA errors 0, CC errors 0
Driver 3: standstill, SG min 0, read errors 0, write errors 0, ifcnt 21, reads 61111, writes 21, timeouts 0, DMA errors 0, CC errors 0
Driver 4: standstill, SG min 0, read errors 0, write errors 0, ifcnt 21, reads 61112, writes 21, timeouts 0, DMA errors 0, CC errors 0
Driver 5: not present
Driver 6: not present
Date/time: 2024-04-02 16:36:25
Cache data hit count 2117861953
Slowest loop: 164.57ms; fastest: 0.13ms
=== Storage ===
Free file entries: 16
SD card 0 detected, interface speed: 22.5MBytes/sec
SD card longest read time 7.6ms, write time 8.1ms, max retries 0
=== Move ===
DMs created 83, segments created 11, maxWait 737572ms, bed compensation in use: none, height map offset 0.000, max steps late 1, min interval 0, bad calcs 0, ebfmin 0.00, ebfmax 0.00
no step interrupt scheduled
Moves shaped first try 5, on retry 0, too short 0, wrong shape 4, maybepossible 0
=== DDARing 0 ===
Scheduled moves 25, completed 25, 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, chamber heaters -1 -1 -1 -1, ordering errs 0
Heater 0 is on, I-accum = 0.4
Heater 1 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) 0
USB is idle in state(s) 0
Aux is idle in state(s) 0 0 0 0 0, running macro
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 P250" 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 0x0000807
Code queue 0 is empty
Q1 segments left 0, axes/extruders owned 0x0000000
Code queue 1 is empty
=== Filament sensors ===
check 0 clear 0
Extruder 0 sensor: no filament
=== CAN ===
Messages queued 10493, received 23836, lost 0, errs 1307, boc 0
Longest wait 2ms for reply type 6031, peak Tx sync delay 8139, free buffers 26 (min 25), ts 5810/5808/0
Tx timeouts 0,0,1,0,0,0 last cancelled message type 30 dest 127
=== Network ===
Slowest loop: 201.24ms; fastest: 0.00ms
Responder states: MQTT(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0)
HTTP sessions: 2 of 8
=== WiFi ===
Interface state: active
Module is connected to access point 
Failed messages: pending 0, notrdy 1, noresp 1
Firmware version 2.1beta7
MAC address c4:5b:be:ce:91:93
Module reset reason: Power up, Vcc 3.37, flash size 2097152, free heap 36232
WiFi IP address 192.168.10.x
Signal strength -54dBm, channel 6, mode 802.11n, reconnections 0
Clock register 00002001
Socket states: 0 0 0 0 0 0 0 0
M122 B121
Diagnostics for board 121:
Duet TOOL1LC rev 1.1 or later firmware version 3.5.0-rc.3+6 (2024-04-02 12:49:31)
Bootloader ID: SAMC21 bootloader version 2.8 (2023-07-25)
All averaging filters OK
Never used RAM 3928, free system stack 134 words
Tasks: Move(3,nWait 7,0.0%,135) HEAT(2,nWait 6,0.4%,105) CanAsync(5,nWait 4,0.0%,51) CanRecv(3,nWait 1,0.0%,71) CanClock(5,nWait 1,0.0%,59) ACCEL(3,nWait 6,0.0%,53) TMC(2,nWait 6,3.4%,53) MAIN(1,running,91.2%,315) IDLE(0,ready,0.0%,27) AIN(2,delaying,4.9%,112), total 100.0%
Owned mutexes:
Last reset 00:19:29 ago, cause: power up
Last software reset at 2024-03-12 16:55, reason: StackOverflow, available RAM 2968, slot 0
Software reset code 0x0100 ICSR 0x0042600e SP 0x20007f34 Task Move Freestk 3342 ok
Stack: 20004a80 20004ab4 0001cf33 20004c98 20004938 00000000 0001c011 20003320 fffffffd a5a5a5a5 00000000 20007f8c 00000000 20007f8c 0001cc97 00000000 200017c4 20001748 0001c4d7 20001748 200017c4 00000032 454c4449 00022700 0001ac77 200018e0 200018e0
Driver 0: pos 0, 568.8 steps/mm, standstill, SG min 0, read errors 0, write errors 0, ifcnt 11, reads 60547, writes 11, timeouts 0, DMA errors 0, CC errors 0, steps req 0 done 0
Moves scheduled 0, completed 0, in progress 0, hiccups 0, segs 0, step errors 0, maxLate 0 maxPrep 0, maxOverdue 0, maxInc 0, mcErrs 0, gcmErrs 0, ebfmin 0.00 max 0.00
Peak sync jitter -2/9, peak Rx sync delay 219, resyncs 0/0, no timer interrupt scheduled
VIN voltage: min 23.7, current 24.7, max 24.9
MCU temperature: min 65.2C, current 71.7C, max 71.7C
Last sensors broadcast 0x00000012 found 2 15 ticks ago, 0 ordering errs, loop time 0
CAN messages queued 24032, send timeouts 0, received 10573, lost 0, errs 0, boc 0, free buffers 18, min 18, error reg 0
dup 0, oos 0/0/0/0, bm 0, wbm 0, rxMotionDelay 0
Accelerometer: LIS3DH, status: 00
I2C bus errors 0, naks 3, contentions 0, other errors 0
=== Filament sensors ===
Interrupt 5726621 to 0us, poll 4 to 1432us
Driver 0: ok

I just saw that the printer state is permanently "Busy" now after trying to home & lower Z. Dispite the printer not doing anything.

dc42

@Exerqtor I'm sorry about that, I'm about to run a print to test the correction.

Exerqtor

@dc42 Nothing to say sorry for, it's a pre-release afterall

dc42

@Exerqtor I've updated the files, same link as before. A remaining issue I have noticed is that when resuming after a pause there is a slight delay between restoring the XYZ position and starting printing again. I think I know the reason for that and I'll look into it tomorrow.

Exerqtor

@dc42 Okok, I'll pull them, try one least time and report back before hitting the bunk.

A little bit off topic, but: I don't know if this is expected behaviour or (or when it got introduced), but for some reason this command:

M291 S4 R"Bed tramming" P"Are you sure you want to tram the bed?" K{"YES","CANCEL",}

Don't end up posting a message on PD, just DWC.

And I can confirm that the resume now works again, and that the Z-issues is resolved. I didn't notice any delay between between restoring the XYZ position and starting printing again though, at least not more than it's "allways" been.

dc42

@Exerqtor which version of PanelDueFirmware are you using?