Pausing during a macro and resuming, same macro is run again?

tristanryerparke

I have had some issues when pausing a printing file that was performing a macro at the time of pause. The macro finishes as usual and then the job is paused. Then when resuming, that same macro is run AGAIN before continuing on to the rest of the file. I understand that for files consisting of mostly G0/G1 commands, this re-running of the last command would be no issue, but for long macros and macros which physically toggle something (in my case pick up an attachment on the toolhead) it can be catastrophic if the macro is run again.
I've had this issue since I got into using the duet3 on rrf3.1.0.

Here is a test case:
File in gcodes directory: "pause_macro_issue.nc"
Contents:

M98 P"0:/macros/pretendMacro1.g"
G4 S0.5
M98 P"0:/macros/pretendMacro2.g"
G4 S0.5
M98 P"0:/macros/pretendMacro3.g"
G4 S0.5

pretendMacro1.g:

G4 S0.5
M118 P0 S"Part 1 of pretendMacro1" L1
G4 S0.5
M118 P0 S"Part 2 of pretendMacro1" L1
G4 S0.5
M118 P0 S"Part 3 of pretendMacro1" L1
G4 S0.5
M118 P0 S"Part 4 of pretendMacro1" L1

pretendMacro2.g:

G4 S0.5
M118 P0 S"Part 1 of pretendMacro2" L1
G4 S0.5
M118 P0 S"Part 2 of pretendMacro2" L1
G4 S0.5
M118 P0 S"Part 3 of pretendMacro2" L1
G4 S0.5
M118 P0 S"Part 4 of pretendMacro2" L1

pretendMaco3.g:

G4 S0.5
M118 P0 S"Part 1 of pretendMacro3" L1
G4 S0.5
M118 P0 S"Part 2 of pretendMacro3" L1
G4 S0.5
M118 P0 S"Part 3 of pretendMacro3" L1
G4 S0.5
M118 P0 S"Part 4 of pretendMacro3" L1

Logfile output:

2021-04-25 08:00:46 File 0:/gcodes/pause_macro_issue.nc selected for printing
2021-04-25 08:00:46 Part 1 of pretendMacro1
2021-04-25 08:00:47 Part 2 of pretendMacro1
2021-04-25 08:00:47 Part 3 of pretendMacro1
2021-04-25 08:00:48 Part 4 of pretendMacro1
2021-04-25 08:00:49 Part 1 of pretendMacro2
2021-04-25 08:00:50 Part 2 of pretendMacro2
2021-04-25 08:00:50 Part 3 of pretendMacro2
2021-04-25 08:00:51 Part 4 of pretendMacro2
2021-04-25 08:00:51 Printing paused at X1040.5 Y-1284.0 Z0.0 A90.0 B0.0
2021-04-25 08:01:01 Printing resumed
2021-04-25 08:01:01 Printing resumed
2021-04-25 08:01:02 Part 1 of pretendMacro2
2021-04-25 08:01:02 Part 2 of pretendMacro2
2021-04-25 08:01:03 Part 3 of pretendMacro2
2021-04-25 08:01:03 Part 4 of pretendMacro2
2021-04-25 08:01:04 Part 1 of pretendMacro3
2021-04-25 08:01:05 Part 2 of pretendMacro3
2021-04-25 08:01:05 Part 3 of pretendMacro3
2021-04-25 08:01:06 Part 4 of pretendMacro3
2021-04-25 08:01:07 Done printing file
2021-04-25 08:01:07 Done printing file
2021-04-25 08:01:07 Finished printing file 0:/gcodes/pause_macro_issue.nc, print time was 0h 0m

It can be seen from the printout that pretendMacro2.g is run twice.
For now I'm trying to think of a conditional solution in my macros to just ignore the second run... But I feel as if this shouldn't be happening.
If this isn't a bug, is there a way to avoid this issue?
Cheers,
T

M112:

m122
=== Diagnostics ===
RepRapFirmware for Duet 3 MB6HC version 3.3beta3.1 (2021-04-26 11:17:17) running on Duet 3 MB6HC v1.01 or later (SBC mode)
Board ID: 08DJM-956L2-G43S8-6J9D6-3S46R-KU2AD
Used output buffers: 5 of 40 (20 max)
=== RTOS ===
Static ram: 150600
Dynamic ram: 61752 of which 0 recycled
Never used RAM 92984, free system stack 200 words
Tasks: SBC(ready,7.7%,310) HEAT(delaying,0.0%,365) Move(notifyWait,0.0%,300) CanReceiv(notifyWait,0.0%,907) CanSender(notifyWait,0.0%,373) CanClock(delaying,0.0%,353) TMC(notifyWait,7.7%,93) MAIN(running,84.2%,1264) IDLE(ready,0.3%,29), total 100.0%
Owned mutexes: HTTP(MAIN)
=== Platform ===
Last reset 00:00:31 ago, cause: software
Last software reset at 2021-04-25 08:15, reason: User, GCodes spinning, available RAM 92768, slot 0
Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x0044a000 BFAR 0x00000000 SP 0x00000000 Task SBC Freestk 0 n/a
Error status: 0x00
Aux0 errors 0,0,0
Aux1 errors 0,0,0
Step timer max interval 185
MCU temperature: min 58.1, current 58.3, max 58.4
Supply voltage: min 24.1, current 24.1, max 24.1, under voltage events: 0, over voltage events: 0, power good: yes
12V rail voltage: min 12.1, current 12.1, max 12.1, under voltage events: 0
Heap OK, handles allocated/used 99/1, heap memory allocated/used/recyclable 2048/10/0, gc cycles 0
Driver 0: position 0, standstill, reads 44901, writes 19 timeouts 0, SG min/max 0/0
Driver 1: position 0, standstill, reads 44904, writes 16 timeouts 0, SG min/max 0/0
Driver 2: position 0, standstill, reads 44907, writes 14 timeouts 0, SG min/max 0/0
Driver 3: position 0, standstill, reads 44907, writes 14 timeouts 0, SG min/max 0/0
Driver 4: position 0, standstill, reads 44907, writes 14 timeouts 0, SG min/max 0/0
Driver 5: position 0, standstill, reads 44910, writes 11 timeouts 0, SG min/max 0/0
Date/time: 2021-04-25 08:15:55
Slowest loop: 74.73ms; fastest: 0.03ms
=== Storage ===
Free file entries: 10
SD card 0 not detected, interface speed: 37.5MBytes/sec
SD card longest read time 0.0ms, write time 0.0ms, max retries 0
=== Move ===
DMs created 125, maxWait 0ms, bed compensation in use: none, comp offset 0.000
=== MainDDARing ===
Scheduled moves 0, completed moves 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== AuxDDARing ===
Scheduled moves 0, completed moves 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== Heat ===
Bed heaters = -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1, chamberHeaters = -1 -1 -1 -1
=== GCodes ===
Segments left: 0
Movement lock held by null
HTTP* is doing "M122" 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 idle in state(s) 0
Aux2 is idle in state(s) 0
Autopause is idle in state(s) 0
Code queue is empty.
=== CAN ===
Messages queued 172, send timeouts 0, received 13, lost 0, longest wait 1ms for reply type 6043, peak Tx sync delay 14789, free buffers 49 (min 48)
=== SBC interface ===
State: 4, failed transfers: 0
Last transfer: 3ms ago
RX/TX seq numbers: 1056/1056
SPI underruns 0, overruns 0
Number of disconnects: 0, IAP RAM available 0x2c8fc
Buffer RX/TX: 0/0-0
=== Duet Control Server ===
Duet Control Server v3.3-b3
Code buffer space: 4096
Configured SPI speed: 8000000 Hz
Full transfers per second: 34.81
Codes per second: 3.39
Maximum length of RX/TX data transfers: 4912/448

OwenD

what is in your pause.g and resume.g?
How are you pausing? button or gcode?

tristanryerparke

@owend pause.g and resume.g just have comments in them. Pausing via button on status page.

dc42

@tristanryerparke said in Pausing during a macro and resuming, same macro is run again?:

I have had some issues when pausing a printing file that was performing a macro at the time of pause. The macro finishes as usual and then the job is paused. Then when resuming, that same macro is run AGAIN before continuing on to the rest of the file.

When RRF is running in standalone mode, pausing is not possible during execution of a macro, so a pause command will be delayed until the macro has finished. I guess that Duet Control Server doesn't replicate this behaviour. I'll ask @chrishamm to take a look.

chrishamm

@tristanryerparke Thanks for reporting this. I can confirm this is a problem in DSF which will be fixed in the upcoming v3.3-RC1.