[3.5.0-rc.3+5] [bug] nested while job Illegal para letter '.'

timschneider

Hi @chrishamm today I had the following bug while porting a jobfile with meta commands from duet2 in standalone to an duet3 in sbc mode.

the following will work in standalone mode

if !inputs[state.thisInput].active
  M99

var x = 0
var y = 1

var N = 5

while var.x < var.y
  var i = 0
  while var.i < var.N
    echo "var.i = " ^ var.i
    echo "var.N = " ^ var.N

    if var.i > 2
      set var.N = var.i
    if var.i > 5
      break
    set var.i = var.i + 1

  set var.x = var.x + 1

and will fail in sbc mode

Feb 29 21:11:01 Meltingplot-MBL-480-vaswsq DuetControlServer[405]: [info] var.i = 0
Feb 29 21:11:01 Meltingplot-MBL-480-vaswsq DuetControlServer[405]: [info] var.N = 5
Feb 29 21:11:02 Meltingplot-MBL-480-vaswsq DuetControlServer[405]: [error] in job file (channel File) line : Illegal parameter letter '.'
Feb 29 21:11:02 Meltingplot-MBL-480-vaswsq DuetControlServer[405]: [error] DuetAPI.CodeParserException: Illegal parameter letter '.'
Feb 29 21:11:02 Meltingplot-MBL-480-vaswsq DuetControlServer[405]:    DuetAPI.CodeParserException: Illegal parameter letter '.'
Feb 29 21:11:02 Meltingplot-MBL-480-vaswsq DuetControlServer[405]:    at DuetAPI.Commands.Code.AddParameter(Code code, Char letter, String value, Boolean isQuoted, Boolean isSingleParameter) in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetAPI/Commands/Code/Parser.cs:line 746
Feb 29 21:11:02 Meltingplot-MBL-480-vaswsq DuetControlServer[405]:    at DuetAPI.Commands.Code.ParseAsync(Stream stream, Code result, CodeParserBuffer buffer, CancellationToken cancellationToken) in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetAPI/Commands/Code/ParserAsync.cs:line 725
Feb 29 21:11:02 Meltingplot-MBL-480-vaswsq DuetControlServer[405]:    at DuetControlServer.Files.CodeFile.ReadCodeAsync(Code sharedCode) in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetControlServer/Files/CodeFile.cs:line 221
Feb 29 21:11:02 Meltingplot-MBL-480-vaswsq DuetControlServer[405]:    at DuetControlServer.Files.JobProcessor.DoFilePrint(CodeFile file) in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetControlServer/Files/JobProcessor.cs:line 344
Feb 29 21:12:07 Meltingplot-MBL-480-vaswsq systemd[1]: Stopping Duet Control Server...

with a small modifikation of the code {...}

if !inputs[state.thisInput].active
  M99

var x = 0
var y = 1

var N = 5

while {var.x < var.y}
  var i = 0
  while {var.i < var.N}
    echo "var.i = " ^ var.i
    echo "var.N = " ^ var.N

    if {var.i > 2}
      set var.N = var.i
    if var.i > 5
      break
    set var.i = var.i + 1

  set var.x = var.x + 1

the output is the following:

M122

M122
=== Diagnostics ===
RepRapFirmware for Duet 3 MB6HC version 3.5.0-rc.3+5 (2024-02-21 14:58:54) running on Duet 3 MB6HC v1.02 or later (SBC mode)
Board ID: 08DJM-9P63L-DJ3T8-6JKD4-3SJ6K-9A77A
Used output buffers: 1 of 40 (17 max)
=== RTOS ===
Static ram: 155208
Dynamic ram: 88620 of which 4112 recycled
Never used RAM 94788, free system stack 125 words
Tasks: SBC(2,ready,0.9%,406) HEAT(3,nWait 1,0.0%,327) Move(4,nWait 6,0.0%,235) CanReceiv(6,nWait 1,0.0%,940) CanSender(5,nWait 7,0.0%,334) CanClock(7,delaying,0.0%,334) TMC(4,nWait 6,8.8%,56) MAIN(2,running,90.0%,103) IDLE(0,ready,0.2%,30), total 100.0%
Owned mutexes: HTTP(MAIN)
=== Platform ===
Last reset 00:09:43 ago, cause: power up
Last software reset at 2024-02-29 20:53, reason: User, Gcodes spinning, available RAM 94812, slot 0
Software reset code 0x6003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00400000 BFAR 0x00000000 SP 0x00000000 Task SBC Freestk 0 n/a
Error status: 0x00
MCU temperature: min 25.8, current 34.0, max 34.2
Supply voltage: min 0.4, current 24.1, max 24.2, under voltage events: 0, over voltage events: 0, power good: yes
12V rail voltage: min 0.1, current 12.3, max 12.8, under voltage events: 0
Heap OK, handles allocated/used 99/4, heap memory allocated/used/recyclable 2048/536/432, gc cycles 0
Events: 0 queued, 0 completed
Driver 0: standstill, SG min 0, mspos 40, reads 60308, writes 27 timeouts 0
Driver 1: standstill, SG min 0, mspos 360, reads 60309, writes 27 timeouts 0
Driver 2: standstill, SG min 0, mspos 8, reads 60315, writes 21 timeouts 0
Driver 3: standstill, SG min 0, mspos 8, reads 60315, writes 21 timeouts 0
Driver 4: standstill, SG min 0, mspos 8, reads 60315, writes 21 timeouts 0
Driver 5: standstill, SG min 0, mspos 4, reads 60317, writes 19 timeouts 0
Date/time: 2024-02-29 21:19:04
Slowest loop: 64.73ms; fastest: 0.06ms
=== Storage ===
Free file entries: 20
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, segments created 17, maxWait 498358ms, 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 4, on retry 0, too short 0, wrong shape 34, maybepossible 0
=== DDARing 0 ===
Scheduled moves 40, completed 40, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 1], 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 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 0, running macro
Aux2 is idle in state(s) 0
Autopause is idle in state(s) 0
File2* is idle in state(s) 0, sync state 2
Queue2 is idle in state(s) 0
Q0 segments left 0, axes/extruders owned 0x0000003
Code queue 0 is empty
Q1 segments left 0, axes/extruders owned 0x0000000
Code queue 1 is empty
=== Filament sensors ===
check 633993 clear 4462564
Extruder 0: pos 2160.00, errs: frame 0 parity 0 ovrun 0 pol 0 ovdue 0
=== CAN ===
Messages queued 5175, received 0, lost 0, errs 2753656, boc 0
Longest wait 0ms for reply type 0, peak Tx sync delay 0, free buffers 50 (min 50), ts 2916/0/0
Tx timeouts 0,0,2915,0,0,2258 last cancelled message type 30 dest 127
=== SBC interface ===
Transfer state: 5, failed transfers: 0, checksum errors: 0
RX/TX seq numbers: 15981/15981
SPI underruns 0, overruns 0
State: 5, disconnects: 1, timeouts: 1 total, 1 by SBC, IAP RAM available 0x255b4
Buffer RX/TX: 0/0-0, open files: 0
=== Duet Control Server ===
Duet Control Server version 3.5.0-rc.3+5 (2024-02-21 14:42:00, 32-bit)
Failed to deserialize the following properties:
- MoveSegmentation -> Int32 from 2.0
Daemon:
>> Doing macro daemon.g, started by system
Code buffer space: 4096
Configured SPI speed: 8000000Hz, TfrRdy pin glitches: 0
Full transfers per second: 38.68, max time between full transfers: 47.4ms, max pin wait times: 38.1ms/3.3ms
Codes per second: 0.97
Maximum length of RX/TX data transfers: 4445/296

chrishamm

@timschneider Thanks, fixed. This bug only showed up if meta G-code with while loops was used in job files.

timschneider

@chrishamm thank you for working on the bug that fast!

I've just installed rc.3+6 and tried to retest the above code, but now something else went wrong.

but the initial problem is solved.

and now to the new problem

Mar 01 14:04:34 Meltingplot-MBL-480-vaswsq DuetControlServer[2500]: [debug] Evaluation result: (true) = True
Mar 01 14:04:34 Meltingplot-MBL-480-vaswsq DuetControlServer[2500]: [error] in file daemon.g line 2: Illegal parameter letter '='
Mar 01 14:04:34 Meltingplot-MBL-480-vaswsq DuetControlServer[2500]: [error] DuetAPI.CodeParserException: Illegal parameter letter '='
Mar 01 14:04:34 Meltingplot-MBL-480-vaswsq DuetControlServer[2500]:    DuetAPI.CodeParserException: Illegal parameter letter '='
Mar 01 14:04:34 Meltingplot-MBL-480-vaswsq DuetControlServer[2500]:    at DuetAPI.Commands.Code.AddParameter(Code code, Char letter, String value, Boolean isQuoted, Boolean isSingleParameter) in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetAPI/Commands/Code/Parser.cs:line 726
Mar 01 14:04:34 Meltingplot-MBL-480-vaswsq DuetControlServer[2500]:    at DuetAPI.Commands.Code.ParseAsync(Stream stream, Code result, CodeParserBuffer buffer, CancellationToken cancellationToken) in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetAPI/Commands/Code/ParserAsync.cs:line 725
Mar 01 14:04:34 Meltingplot-MBL-480-vaswsq DuetControlServer[2500]:    at DuetControlServer.Files.CodeFile.ReadCodeAsync(Code sharedCode) in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetControlServer/Files/CodeFile.cs:line 232
Mar 01 14:04:34 Meltingplot-MBL-480-vaswsq DuetControlServer[2500]:    at DuetControlServer.Files.MacroFile.ReadCodeAsync() in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetControlServer/Files/MacroFile.cs:line 260
Mar 01 14:04:34 Meltingplot-MBL-480-vaswsq DuetControlServer[2500]:    at DuetControlServer.Files.MacroFile.Run() in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetControlServer/Files/MacroFile.cs:line 311

part of daemon.g

while true
  if exists(global.initial_temp) == false
    global initial_temp = 0

this will also fail

part of daemon.g

while true
  if !exists(global.initial_temp)
    global initial_temp = 0

the above error is in the daemon.g, but it can be recreated in a macro.

echo "0"
if !exists(global.initial_temp)
  echo "1"
else
  echo "2"
echo "3"

The output in the console

1.3.2024, 15:09:53 	M98 P"0:/macros/test-sbc-4"
1.3.2024, 15:09:52 	0

and the same in the job processor

content of print_end

G10                                 ; Retract the filament

G10 P0 R0 S0                        ; disable hotend
M140 S0 R0                          ; set bed heater to 0°
M140 P0 S-273.1                     ; disable bed heater
T-1                                 ; deselect all tools

if exists(global.clearanceHeight) && move.axes[2].homed
  G90                                     ; absolute positioning
  G1 Z{max(20,global.clearanceHeight)}    ; lift z to clearance height 

G28 X Y                             ; home x and y

if (sensors.gpIn[2].value == 1 && sensors.gpIn[3].value == 1 )
  G91                               ; relative 
  if move.axes[2].homed
    G1 Z100 F1250                     ; lift z  ; move only if both doors are closed

G90
;G1 Z{move.axes[2].max-5} F1250        ; lift z
G1 X{move.axes[0].max}              ; move gantry away from camera

;M84                                ; turn off motors
M107                                ; Turn off fans

chrishamm

@timschneider I just wanted to edit my post and say that I've discovered something else. I'm looking into it.

chrishamm

@timschneider I've got another bug fix ready in case you want to try it.

timschneider

@chrishamm
thank you for the fix !

the main problem is fixed now, but idk if there is another one.
If started as a job file it will never terminate, even with an explicit M0 at the end of the .gcode file.

Mar 06 11:38:42 X: [debug] HTTP: Finished code M23 "0:/macros/test-sbc-3.gcode" => File 0:/macros/test-sbc-3.gcode selected for printing
Mar 06 11:38:42 X: [debug] IPC#14: Connection closed
Mar 06 11:38:42 X: [debug] Requesting update of key job, seq 1 -> 3
Mar 06 11:38:42 X: [debug] Updated key job
Mar 06 11:38:44 X: [debug] Requesting update of key inputs, seq 30 -> 31
Mar 06 11:38:44 X: [debug] Updated key inputs
Mar 06 11:38:44 X: [debug] Requesting update of key inputs, seq 31 -> 32
Mar 06 11:38:44 X: [debug] Updated key inputs
Mar 06 11:38:52 X: [debug] Got new UNIX connection via IPC#15, checking permissions...
Mar 06 11:38:52 X: [debug] IPC#15: Granting full DSF permissions to external plugin
Mar 06 11:38:52 X: [debug] Command processor added for IPC#15
Mar 06 11:38:52 X: [debug] IPC#15: Received command SimpleCode
Mar 06 11:38:52 X: [debug] HTTP: Starting code M24
Mar 06 11:38:52 X: [debug] Processing M24
Mar 06 11:38:52 X: [debug] HTTP: Sent M24, remaining space 1512, needed 24
Mar 06 11:38:52 X: [info] Starting macro file start.g on channel File
Mar 06 11:38:52 X: [debug] File: Starting code ; start.g  (macro code)
Mar 06 11:38:52 X: [debug] File: Starting code ; is run when you start a print from SD card. Runs immediately before any slicer created gcode (macro code)
Mar 06 11:38:52 X: [debug] Processing ; start.g
Mar 06 11:38:52 X: [debug] File: Starting code M98 P"0:/sys/meltingplot/check_doors_closed" (macro code)
Mar 06 11:38:52 X: [debug] Processing ; is run when you start a print from SD card. Runs immediately before any slicer created gcode
Mar 06 11:38:52 X: [debug] Processing M98 P"0:/sys/meltingplot/check_doors_closed"
Mar 06 11:38:52 X: [debug] File: Finished code ; start.g
Mar 06 11:38:52 X: [debug] File: Finished code ; is run when you start a print from SD card. Runs immediately before any slicer created gcode
Mar 06 11:38:52 X: [debug] File: Sent M98 P"0:/sys/meltingplot/check_doors_closed", remaining space 1464, needed 72
Mar 06 11:38:52 X: [info] Starting macro file start.g on channel File2
Mar 06 11:38:52 X: [debug] File2: Starting code ; start.g  (macro code)
Mar 06 11:38:52 X: [debug] File2: Starting code ; is run when you start a print from SD card. Runs immediately before any slicer created gcode (macro code)
Mar 06 11:38:52 X: [debug] Processing ; start.g
Mar 06 11:38:52 X: [debug] Processing ; is run when you start a print from SD card. Runs immediately before any slicer created gcode
Mar 06 11:38:52 X: [debug] File2: Finished code ; start.g
Mar 06 11:38:52 X: [debug] File2: Finished code ; is run when you start a print from SD card. Runs immediately before any slicer created gcode
Mar 06 11:38:52 X: [debug] File2: Starting code M98 P"0:/sys/meltingplot/check_doors_closed" (macro code)
Mar 06 11:38:52 X: [debug] Processing M98 P"0:/sys/meltingplot/check_doors_closed"
Mar 06 11:38:52 X: [debug] File2: Sent M98 P"0:/sys/meltingplot/check_doors_closed", remaining space 1464, needed 72
Mar 06 11:38:52 X: [info] Starting macro file 0:/sys/meltingplot/check_doors_closed on channel File
Mar 06 11:38:52 X: [debug] File: ==> Starting code M98 P"0:/sys/meltingplot/check_doors_closed"
Mar 06 11:38:52 X: [debug] HTTP: Finished code M24 =>
Mar 06 11:38:52 X: [info] Starting file print
Mar 06 11:38:52 X: [debug] IPC#15: Connection closed
Mar 06 11:38:52 X: [info] Starting macro file 0:/sys/meltingplot/check_doors_closed on channel File2
Mar 06 11:38:52 X: [debug] File2: ==> Starting code M98 P"0:/sys/meltingplot/check_doors_closed"
Mar 06 11:38:52 X: [debug] Evaluating While block
Mar 06 11:38:52 X: [debug] Evaluating While block
Mar 06 11:38:52 X: [debug] Evaluating (sensors.gpIn[2].value == 0 || sensors.gpIn[3].value == 0 ) on channel File
Mar 06 11:38:52 X: [debug] Evaluating (sensors.gpIn[2].value == 0 || sensors.gpIn[3].value == 0 ) on channel File2
Mar 06 11:38:52 X: [debug] Evaluation result: ((sensors.gpIn[2].value == 0 || sensors.gpIn[3].value == 0 )) = False
Mar 06 11:38:52 X: [debug] Evaluation result: ((sensors.gpIn[2].value == 0 || sensors.gpIn[3].value == 0 )) = False
Mar 06 11:38:52 X: [debug] End of While block
Mar 06 11:38:52 X: [debug] End of While block
Mar 06 11:38:52 X: [debug] Finished codes from macro file 0:/sys/meltingplot/check_doors_closed
Mar 06 11:38:52 X: [info] Finished macro file 0:/sys/meltingplot/check_doors_closed
Mar 06 11:38:52 X: [debug] Finished codes from macro file 0:/sys/meltingplot/check_doors_closed
Mar 06 11:38:52 X: [info] Finished macro file 0:/sys/meltingplot/check_doors_closed
Mar 06 11:38:52 X: [debug] File: ==> Unfinished starting code: M98 P"0:/sys/meltingplot/check_doors_closed"
Mar 06 11:38:52 X: [debug] File: Finished code M98 P"0:/sys/meltingplot/check_doors_closed"
Mar 06 11:38:52 X: [debug] Requesting update of key inputs, seq 32 -> 36
Mar 06 11:38:52 X: [debug] Finished codes from macro file start.g
Mar 06 11:38:52 X: [info] Finished macro file start.g
Mar 06 11:38:52 X: [debug] File: Disposing macro file 0:/sys/meltingplot/check_doors_closed
Mar 06 11:38:52 X: [debug] File2: ==> Unfinished starting code: M98 P"0:/sys/meltingplot/check_doors_closed"
Mar 06 11:38:52 X: [debug] File2: Disposing macro file 0:/sys/meltingplot/check_doors_closed
Mar 06 11:38:52 X: [debug] File2: Finished code M98 P"0:/sys/meltingplot/check_doors_closed"
Mar 06 11:38:52 X: [debug] Finished codes from macro file start.g
Mar 06 11:38:52 X: [info] Finished macro file start.g
Mar 06 11:38:52 X: [debug] File: Disposing macro file start.g
Mar 06 11:38:52 X: [debug] Evaluating If block
Mar 06 11:38:52 X: [debug] Evaluating !inputs[state.thisInput].active on channel File
Mar 06 11:38:52 X: [debug] Updated key inputs
Mar 06 11:38:52 X: [debug] Requesting update of key job, seq 3 -> 4
Mar 06 11:38:52 X: [debug] File2: Disposing macro file start.g
Mar 06 11:38:52 X: [debug] Evaluating If block
Mar 06 11:38:52 X: [debug] Evaluating !inputs[state.thisInput].active on channel File2
Mar 06 11:38:52 X: [debug] Evaluation result: (!inputs[state.thisInput].active) = False
Mar 06 11:38:52 X: [debug] Updated key job
Mar 06 11:38:52 X: [debug] End of If block
Mar 06 11:38:52 X: [debug] File: Starting code var x = 0
Mar 06 11:38:52 X: [debug] File: Starting code var y = 1
Mar 06 11:38:52 X: [debug] File: Starting code var N = 5
Mar 06 11:38:52 X: [debug] Processing var x = 0
Mar 06 11:38:52 X: [debug] Setting variable var.x to 0 on channel File
Mar 06 11:38:52 X: [debug] Evaluation result: (!inputs[state.thisInput].active) = True
Mar 06 11:38:52 X: [debug] File2: Starting code M0
Mar 06 11:38:52 X: [debug] Processing M0
Mar 06 11:38:52 X: [debug] End of If block
Mar 06 11:38:52 X: [debug] File2: Starting code var x = 0
Mar 06 11:38:52 X: [debug] File2: Starting code var y = 1
Mar 06 11:38:52 X: [debug] File2: Starting code var N = 5
Mar 06 11:38:52 X: [debug] Set variable var.x to 0
Mar 06 11:38:52 X: [debug] Processing var y = 1
Mar 06 11:38:52 X: [debug] Setting variable var.y to 1 on channel File
Mar 06 11:38:52 X: [debug] File: Finished code var x = 0 =>
Mar 06 11:38:52 X: [debug] Set variable var.y to 1
Mar 06 11:38:52 X: [debug] Processing var N = 5
Mar 06 11:38:52 X: [debug] File: Finished code var y = 1 =>
Mar 06 11:38:52 X: [debug] Setting variable var.N to 5 on channel File
Mar 06 11:38:52 X: [debug] Set variable var.N to 5
Mar 06 11:38:52 X: [debug] Evaluating While block
Mar 06 11:38:52 X: [debug] Evaluating var.x < var.y on channel File
Mar 06 11:38:52 X: [debug] File: Finished code var N = 5 =>
Mar 06 11:38:52 X: [debug] Evaluation result: (var.x < var.y) = True
Mar 06 11:38:52 X: [debug] File: Starting code var i = 0
Mar 06 11:38:52 X: [debug] Processing var i = 0
Mar 06 11:38:52 X: [debug] Setting variable var.i to 0 on channel File
Mar 06 11:38:52 X: [debug] Set variable var.i to 0
Mar 06 11:38:52 X: [debug] Evaluating While block
Mar 06 11:38:52 X: [debug] File: Finished code var i = 0 =>
Mar 06 11:38:52 X: [debug] Evaluating var.i < var.N on channel File
Mar 06 11:38:52 X: [debug] Requesting update of key inputs, seq 36 -> 44
Mar 06 11:38:52 X: [debug] Evaluation result: (var.i < var.N) = True
Mar 06 11:38:52 X: [debug] File: Starting code echo "var.i = " ^ var.i
Mar 06 11:38:52 X: [debug] Processing echo "var.i = " ^ var.i
Mar 06 11:38:52 X: [debug] Evaluating "var.i = " ^ var.i on channel File
Mar 06 11:38:52 X: [debug] File: Starting code echo "var.N = " ^ var.N
Mar 06 11:38:52 X: [debug] Updated key inputs
Mar 06 11:38:52 X: [debug] Processing echo "var.N = " ^ var.N
Mar 06 11:38:52 X: [debug] Evaluating "var.N = " ^ var.N on channel File
Mar 06 11:38:52 X: [info] var.i = 0
Mar 06 11:38:52 X: [debug] File: Finished code echo "var.i = " ^ var.i => var.i = 0
Mar 06 11:38:52 X: [info] var.N = 5
Mar 06 11:38:52 X: [debug] Evaluating If block
Mar 06 11:38:52 X: [debug] Evaluating var.i > 2 on channel File
Mar 06 11:38:52 X: [debug] File: Finished code echo "var.N = " ^ var.N => var.N = 5
Mar 06 11:38:52 X: [debug] Evaluation result: (var.i > 2) = False
Mar 06 11:38:52 X: [debug] End of If block
Mar 06 11:38:52 X: [debug] Evaluating If block
Mar 06 11:38:52 X: [debug] Evaluating var.i > 5 on channel File
Mar 06 11:38:53 X: [debug] Evaluation result: (var.i > 5) = False
Mar 06 11:38:53 X: [debug] End of If block
Mar 06 11:38:53 X: [debug] File: Starting code set var.i = var.i + 1
Mar 06 11:38:53 X: [debug] Processing set var.i = var.i + 1
Mar 06 11:38:53 X: [debug] Setting variable var.i to var.i + 1 on channel File
Mar 06 11:38:53 X: [debug] Set variable var.i to 1
Mar 06 11:38:53 X: [debug] File: Finished code set var.i = var.i + 1 =>
Mar 06 11:38:53 X: [debug] Restarting While block, iterations = 1
Mar 06 11:38:53 X: [debug] Evaluating While block
Mar 06 11:38:53 X: [debug] Evaluating var.i < var.N on channel File
Mar 06 11:38:53 X: [debug] Evaluation result: (var.i < var.N) = True
Mar 06 11:38:53 X: [debug] File: Starting code echo "var.i = " ^ var.i
Mar 06 11:38:53 X: [debug] File: Starting code echo "var.N = " ^ var.N
Mar 06 11:38:53 X: [debug] Processing echo "var.i = " ^ var.i
Mar 06 11:38:53 X: [debug] Evaluating "var.i = " ^ var.i on channel File
Mar 06 11:38:53 X: [debug] Processing echo "var.N = " ^ var.N
Mar 06 11:38:53 X: [info] var.i = 1
Mar 06 11:38:53 X: [debug] Evaluating "var.N = " ^ var.N on channel File
Mar 06 11:38:53 X: [debug] File: Finished code echo "var.i = " ^ var.i => var.i = 1
Mar 06 11:38:53 X: [info] var.N = 5
Mar 06 11:38:53 X: [debug] Evaluating If block
Mar 06 11:38:53 X: [debug] File: Finished code echo "var.N = " ^ var.N => var.N = 5
Mar 06 11:38:53 X: [debug] Evaluating var.i > 2 on channel File
Mar 06 11:38:53 X: [debug] Evaluation result: (var.i > 2) = False
Mar 06 11:38:53 X: [debug] End of If block
Mar 06 11:38:53 X: [debug] Evaluating If block
Mar 06 11:38:53 X: [debug] Evaluating var.i > 5 on channel File
Mar 06 11:38:53 X: [debug] Evaluation result: (var.i > 5) = False
Mar 06 11:38:53 X: [debug] End of If block
Mar 06 11:38:53 X: [debug] File: Starting code set var.i = var.i + 1
Mar 06 11:38:53 X: [debug] Processing set var.i = var.i + 1
Mar 06 11:38:53 X: [debug] Setting variable var.i to var.i + 1 on channel File
Mar 06 11:38:53 X: [debug] Set variable var.i to 2
Mar 06 11:38:53 X: [debug] File: Finished code set var.i = var.i + 1 =>
Mar 06 11:38:53 X: [debug] Restarting While block, iterations = 2
Mar 06 11:38:53 X: [debug] Evaluating While block
Mar 06 11:38:53 X: [debug] Evaluating var.i < var.N on channel File
Mar 06 11:38:53 X: [debug] Evaluation result: (var.i < var.N) = True
Mar 06 11:38:53 X: [debug] File: Starting code echo "var.i = " ^ var.i
Mar 06 11:38:53 X: [debug] File: Starting code echo "var.N = " ^ var.N
Mar 06 11:38:53 X: [debug] Processing echo "var.i = " ^ var.i
Mar 06 11:38:53 X: [debug] Evaluating "var.i = " ^ var.i on channel File
Mar 06 11:38:53 X: [debug] Processing echo "var.N = " ^ var.N
Mar 06 11:38:53 X: [debug] Evaluating "var.N = " ^ var.N on channel File
Mar 06 11:38:53 X: [info] var.i = 2
Mar 06 11:38:53 X: [debug] File: Finished code echo "var.i = " ^ var.i => var.i = 2
Mar 06 11:38:53 X: [info] var.N = 5
Mar 06 11:38:53 X: [debug] File: Finished code echo "var.N = " ^ var.N => var.N = 5
Mar 06 11:38:53 X: [debug] Evaluating If block
Mar 06 11:38:53 X: [debug] Evaluating var.i > 2 on channel File
Mar 06 11:38:53 X: [debug] Evaluation result: (var.i > 2) = False
Mar 06 11:38:53 X: [debug] End of If block
Mar 06 11:38:53 X: [debug] Evaluating If block
Mar 06 11:38:53 X: [debug] Evaluating var.i > 5 on channel File
Mar 06 11:38:53 X: [debug] Evaluation result: (var.i > 5) = False
Mar 06 11:38:53 X: [debug] End of If block
Mar 06 11:38:53 X: [debug] File: Starting code set var.i = var.i + 1
Mar 06 11:38:53 X: [debug] Processing set var.i = var.i + 1
Mar 06 11:38:53 X: [debug] Setting variable var.i to var.i + 1 on channel File
Mar 06 11:38:53 X: [debug] Set variable var.i to 3
Mar 06 11:38:53 X: [debug] File: Finished code set var.i = var.i + 1 =>
Mar 06 11:38:53 X: [debug] Restarting While block, iterations = 3
Mar 06 11:38:53 X: [debug] Evaluating While block
Mar 06 11:38:53 X: [debug] Evaluating var.i < var.N on channel File
Mar 06 11:38:53 X: [debug] Evaluation result: (var.i < var.N) = True
Mar 06 11:38:53 X: [debug] File: Starting code echo "var.i = " ^ var.i
Mar 06 11:38:53 X: [debug] Processing echo "var.i = " ^ var.i
Mar 06 11:38:53 X: [debug] Evaluating "var.i = " ^ var.i on channel File
Mar 06 11:38:53 X: [debug] File: Starting code echo "var.N = " ^ var.N
Mar 06 11:38:54 X: [info] var.i = 3
Mar 06 11:38:54 X: [debug] File: Finished code echo "var.i = " ^ var.i => var.i = 3
Mar 06 11:38:54 X: [debug] Processing echo "var.N = " ^ var.N
Mar 06 11:38:54 X: [debug] Evaluating "var.N = " ^ var.N on channel File
Mar 06 11:38:54 X: [info] var.N = 5
Mar 06 11:38:54 X: [debug] Evaluating If block
Mar 06 11:38:54 X: [debug] File: Finished code echo "var.N = " ^ var.N => var.N = 5
Mar 06 11:38:54 X: [debug] Evaluating var.i > 2 on channel File
Mar 06 11:38:54 X: [debug] Evaluation result: (var.i > 2) = True
Mar 06 11:38:54 X: [debug] File: Starting code set var.N = var.i
Mar 06 11:38:54 X: [debug] Processing set var.N = var.i
Mar 06 11:38:54 X: [debug] Setting variable var.N to var.i on channel File
Mar 06 11:38:54 X: [debug] End of If block
Mar 06 11:38:54 X: [debug] Set variable var.N to 3
Mar 06 11:38:54 X: [debug] Evaluating If block
Mar 06 11:38:54 X: [debug] Evaluating var.i > 5 on channel File
Mar 06 11:38:54 X: [debug] File: Finished code set var.N = var.i =>
Mar 06 11:38:54 X: [debug] Evaluation result: (var.i > 5) = False
Mar 06 11:38:54 X: [debug] End of If block
Mar 06 11:38:54 X: [debug] File: Starting code set var.i = var.i + 1
Mar 06 11:38:54 X: [debug] Processing set var.i = var.i + 1
Mar 06 11:38:54 X: [debug] Setting variable var.i to var.i + 1 on channel File
Mar 06 11:38:54 X: [debug] Set variable var.i to 4
Mar 06 11:38:54 X: [debug] File: Finished code set var.i = var.i + 1 =>
Mar 06 11:38:54 X: [debug] Restarting While block, iterations = 4
Mar 06 11:38:54 X: [debug] Evaluating While block
Mar 06 11:38:54 X: [debug] Evaluating var.i < var.N on channel File
Mar 06 11:38:54 X: [debug] Evaluation result: (var.i < var.N) = False
Mar 06 11:38:54 X: [debug] End of While block
Mar 06 11:38:54 X: [debug] File: Starting code set var.x = var.x + 1
Mar 06 11:38:54 X: [debug] Processing set var.x = var.x + 1
Mar 06 11:38:54 X: [debug] Setting variable var.x to var.x + 1 on channel File
Mar 06 11:38:54 X: [debug] Set variable var.x to 1
Mar 06 11:38:54 X: [debug] End of generic block
Mar 06 11:38:54 X: [debug] File: Finished code set var.x = var.x + 1 =>
Mar 06 11:38:54 X: [debug] Deleting local variable i on channel File
Mar 06 11:38:54 X: [debug] Restarting While block, iterations = 1
Mar 06 11:38:54 X: [debug] Evaluating While block
Mar 06 11:38:54 X: [debug] Evaluating var.x < var.y on channel File
Mar 06 11:38:54 X: [debug] Evaluation result: (var.x < var.y) = False
Mar 06 11:38:54 X: [debug] End of While block
Mar 06 11:38:54 X: [debug] File: Starting code M0
Mar 06 11:38:54 X: [debug] Processing M0
Mar 06 11:38:54 X: [debug] Requesting update of key inputs, seq 44 -> 46
Mar 06 11:38:54 X: [debug] Updated key inputs
Mar 06 11:39:00 X: [debug] Requesting update of key boards, seq 166 -> 167
Mar 06 11:39:00 X: [debug] Updated key boards
Mar 06 11:39:04 X: [debug] Requesting update of key inputs, seq 46 -> 48
Mar 06 11:39:04 X: [debug] Updated key inputs
Mar 06 11:39:14 X: [debug] Requesting update of key inputs, seq 48 -> 50
Mar 06 11:39:14 X: [debug] Updated key inputs

timschneider

@timschneider
and when I pause and cancle the printjob, it appears that the printjob is not cancled - I'm not able to re-run a printjob without a restart of DCS.

Mar 06 11:44:45 X: [debug] HTTP: Starting code M25
Mar 06 11:44:45 X: [debug] Processing M25
Mar 06 11:44:45 X: [debug] HTTP: Sent M25, remaining space 1512, needed 24
Mar 06 11:44:45 X: [debug] Opening 0:/sys/resurrect.g for writing (not appending), prealloc 0
Mar 06 11:44:45 X: [debug] File 0:/sys/resurrect.g opened with handle #2
Mar 06 11:44:45 X: [debug] Closing file #2
Mar 06 11:44:45 X: [info] Resume state saved
Mar 06 11:44:45 X: [debug] HTTP: Finished code M25 => Printing paused at X0.0 Y0.0 Z0.0
Mar 06 11:44:45 X: [debug] IPC#16: Connection closed
Mar 06 11:44:45 X: [debug] Received print pause notification for file position 0, reason User
Mar 06 11:44:45 X: [debug] Requesting update of key inputs, seq 114 -> 115
Mar 06 11:44:46 X: [debug] Updated key inputs
Mar 06 11:44:46 X: [debug] Requesting update of key state, seq 5 -> 6
Mar 06 11:44:46 X: [debug] Updated key state
Mar 06 11:44:46 X: [debug] Requesting update of key volumes, seq 1 -> 2
Mar 06 11:44:46 X: [debug] Updated key volumes
Mar 06 11:44:46 X: [debug] Requesting update of key inputs, seq 115 -> 116
Mar 06 11:44:46 X: [debug] Updated key inputs
Mar 06 11:44:49 X: [debug] Got new UNIX connection via IPC#17, checking permissions...
Mar 06 11:44:49 X: [debug] IPC#17: Granting full DSF permissions to external plugin
Mar 06 11:44:49 X: [debug] Command processor added for IPC#17
Mar 06 11:44:49 X: [debug] IPC#17: Received command SimpleCode
Mar 06 11:44:49 X: [debug] HTTP: Starting code M0
Mar 06 11:44:49 X: [debug] Processing M0
Mar 06 11:44:49 X: [debug] HTTP: Sent M0, remaining space 1512, needed 24
Mar 06 11:44:49 X: [info] Cancelled printing file 0:/macros/test-sbc-3.gcode, print time was 0h 5m
Mar 06 11:44:49 X: [info] Starting macro file cancel.g on channel HTTP
Mar 06 11:44:49 X: [debug] HTTP: ==> Starting code M0
Mar 06 11:44:49 X: [debug] HTTP: Starting code ; cancel.g (macro code)
Mar 06 11:44:49 X: [debug] HTTP: Starting code ; called when a print is cancelled after a pause. (macro code)
Mar 06 11:44:49 X: [debug] Processing ; cancel.g
Mar 06 11:44:49 X: [debug] HTTP: Finished code ; cancel.g
Mar 06 11:44:49 X: [debug] Processing ; called when a print is cancelled after a pause.
Mar 06 11:44:49 X: [debug] HTTP: Finished code ; called when a print is cancelled after a pause.
Mar 06 11:44:49 X: [debug] HTTP: Starting code ;if move.axes[2].homed (macro code)
Mar 06 11:44:49 X: [debug] HTTP: Starting code G10 ; retract filament (macro code)
Mar 06 11:44:49 X: [debug] HTTP: Starting code G10 P0 R0 S0 ; disable heater (macro code)
Mar 06 11:44:49 X: [debug] HTTP: Starting code M140 P0 S0 ; disable bed heater (macro code)
Mar 06 11:44:49 X: [debug] HTTP: Starting code M107 ; disable fan (macro code)
Mar 06 11:44:49 X: [debug] HTTP: Starting code G90 ; absolute position (macro code)
Mar 06 11:44:49 X: [debug] Processing ;if move.axes[2].homed
Mar 06 11:44:49 X: [debug] HTTP: Finished code ;if move.axes[2].homed
Mar 06 11:44:49 X: [debug] Processing G10 ; retract filament
Mar 06 11:44:49 X: [debug] Processing G10 P0 R0 S0 ; disable heater
Mar 06 11:44:49 X: [debug] Processing M140 P0 S0 ; disable bed heater
Mar 06 11:44:49 X: [debug] Processing M107 ; disable fan
Mar 06 11:44:49 X: [debug] Processing G90 ; absolute position
Mar 06 11:44:49 X: [debug] HTTP: Sent G10 ; retract filament, remaining space 1512, needed 24
Mar 06 11:44:49 X: [debug] HTTP: Sent G10 P0 R0 S0 ; disable heater, remaining space 1464, needed 48
Mar 06 11:44:49 X: [debug] HTTP: Sent M140 P0 S0 ; disable bed heater, remaining space 1424, needed 40
Mar 06 11:44:49 X: [debug] HTTP: Sent M107 ; disable fan, remaining space 1400, needed 24
Mar 06 11:44:49 X: [debug] HTTP: Sent G90 ; absolute position, remaining space 1376, needed 24
Mar 06 11:44:49 X: [debug] HTTP: Finished code G10 ; retract filament
Mar 06 11:44:49 X: [debug] HTTP: Finished code G10 P0 R0 S0 ; disable heater
Mar 06 11:44:49 X: [debug] HTTP: Finished code M140 P0 S0 ; disable bed heater
Mar 06 11:44:49 X: [debug] HTTP: Finished code M107 ; disable fan
Mar 06 11:44:50 X: [debug] Evaluating If block
Mar 06 11:44:50 X: [debug] Evaluating (sensors.gpIn[2].value == 1 && sensors.gpIn[3].value == 1 ) on channel HTTP
Mar 06 11:44:50 X: [debug] HTTP: Finished code G90 ; absolute position
Mar 06 11:44:50 X: [debug] Evaluation result: ((sensors.gpIn[2].value == 1 && sensors.gpIn[3].value == 1 )) = True
Mar 06 11:44:50 X: [debug] HTTP: Starting code G91 ; relative (macro code)
Mar 06 11:44:50 X: [debug] Processing G91 ; relative
Mar 06 11:44:50 X: [debug] HTTP: Sent G91 ; relative, remaining space 1512, needed 24
Mar 06 11:44:50 X: [debug] HTTP: Finished code G91 ; relative
Mar 06 11:44:50 X: [debug] Evaluating If block
Mar 06 11:44:50 X: [debug] Evaluating move.axes[2].homed on channel HTTP
Mar 06 11:44:50 X: [debug] Evaluation result: (move.axes[2].homed) = False
Mar 06 11:44:50 X: [debug] End of If block
Mar 06 11:44:50 X: [debug] End of If block
Mar 06 11:44:50 X: [debug] Finished codes from macro file cancel.g
Mar 06 11:44:50 X: [info] Finished macro file cancel.g
Mar 06 11:44:50 X: [debug] Requesting update of key inputs, seq 116 -> 119
Mar 06 11:44:50 X: [debug] HTTP: ==> Unfinished starting code: M0
Mar 06 11:44:50 X: [debug] HTTP: Disposing macro file cancel.g
Mar 06 11:44:50 X: [debug] HTTP: Finished code M0 =>
Mar 06 11:44:50 X: [debug] IPC#17: Connection closed
Mar 06 11:44:50 X: [debug] Updated key inputs
Mar 06 11:44:50 X: [debug] Requesting update of key job, seq 4 -> 5

Mar 06 12:05:28 Meltingplot-MBL-480-vaswsq DuetControlServer[16205]: [debug] HTTP: Starting code M23 "0:/macros/test-sbc-3.gcode"
Mar 06 12:05:28 Meltingplot-MBL-480-vaswsq DuetControlServer[16205]: [debug] Processing M23 "0:/macros/test-sbc-3.gcode"
Mar 06 12:05:28 Meltingplot-MBL-480-vaswsq DuetControlServer[16205]: [debug] HTTP: Finished code M23 "0:/macros/test-sbc-3.gcode" => Error: M23: Cannot set file to print, because a file is already being printed

chrishamm

@timschneider I'm sorry but I cannot reproduce it here, print jobs complete/pause/cancel just as expected on my machine. Is it possible that you call M0 from channel File but not File2 e.g. from a macro file or other conditionals? That could indeed lead to problems. If not, please share the output of M122 when the machine appears to have finished but it doesn't let you start another print.

timschneider

@chrishamm
ok double checked it.

the following will not work / will just stuck

if !inputs[state.thisInput].active
  M0

var x = 0
var y = 1

var N = 5

while var.x < var.y
  var i = 0
  while var.i < var.N
    echo "var.i = " ^ var.i
    echo "var.N = " ^ var.N

    if var.i > 2
      set var.N = var.i
    if var.i > 5
      break
    set var.i = var.i + 1

  set var.x = var.x + 1

G90
G1 X100 F6000
G1 Y100
G1 X200 Y200

M0

and the following will work

if !inputs[state.thisInput].active
  M99

var x = 0
var y = 1

var N = 5

while var.x < var.y
  var i = 0
  while var.i < var.N
    echo "var.i = " ^ var.i
    echo "var.N = " ^ var.N

    if var.i > 2
      set var.N = var.i
    if var.i > 5
      break
    set var.i = var.i + 1

  set var.x = var.x + 1

G90
G1 X100 F6000
G1 Y100
G1 X200 Y200

M0

see the M0 at the beginning for the inactive channel.

ok another test revealed that is has something to do with the while code block, which is preventing it from cleaning the print job.

if !inputs[state.thisInput].active
  M99

M18 X
G90
G1 X10 ; not possible due to unhomed x axis

M0

and the following is not working / you will be unable to restart the print (it sometimes works / then just repeat)
caution: even the E-Stop via DWC will stuck - be delayed!

if !inputs[state.thisInput].active
  M99

var x = 0
var y = 1

var N = 5

while var.x < var.y
  var i = 0
  while var.i < var.N
    echo "var.i = " ^ var.i
    echo "var.N = " ^ var.N

    if var.i > 2
      set var.N = var.i
    if var.i > 5
      break
    set var.i = var.i + 1

  set var.x = var.x + 1

M18 X
G90
G1 X10 ; not possible due to unhomed x axis

M0

~~sorry but I'm unable to get an M122 of the above code, due to the fact, that DCS is stuck.~~

Error: Failed to connect to Duet, please check your connection (DCS is not started)

Mar 06 14:14:56 Meltingplot-MBL-480-vaswsq DuetControlServer[26336]: [warn] Received SIGTERM, shutting down...
Mar 06 14:15:00 Meltingplot-MBL-480-vaswsq DuetControlServer[26336]: [fatal] Regular shutdown failed, proceeding with unconditional program termination
Mar 06 14:15:01 Meltingplot-MBL-480-vaswsq systemd[1]: duetcontrolserver.service: Main process exited, code=exited, status=70/SOFTWARE

M122
=== Diagnostics ===
RepRapFirmware for Duet 3 MB6HC version 3.5.0-rc.3+6 (2024-03-01 12:32:32) running on Duet 3 MB6HC v1.02 or later (SBC mode)
Board ID: 08DJM-9P63L-DJ3T8-6JKD4-3SJ6K-9A77A
Used output buffers: 1 of 40 (17 max)
=== RTOS ===
Static ram: 155208
Dynamic ram: 88404 of which 4328 recycled
Never used RAM 95196, free system stack 204 words
Tasks: SBC(2,ready,0.4%,414) HEAT(3,nWait 6,0.0%,323) Move(4,nWait 6,0.0%,336) CanReceiv(6,nWait 1,0.0%,940) CanSender(5,nWait 7,0.0%,334) CanClock(7,delaying,0.0%,336) TMC(4,nWait 6,8.4%,56) MAIN(2,running,91.0%,103) IDLE(0,ready,0.2%,30), total 100.0%
Owned mutexes: HTTP(MAIN)
=== Platform ===
Last reset 00:08:06 ago, cause: software
Last software reset at 2024-03-06 14:00, reason: User, Gcodes spinning, available RAM 94716, slot 1
Software reset code 0x6003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00400000 BFAR 0x00000000 SP 0x00000000 Task SBC Freestk 0 n/a
Error status: 0x00
MCU temperature: min 32.6, current 32.9, max 34.8
Supply voltage: min 24.0, current 24.1, max 24.2, under voltage events: 0, over voltage events: 0, power good: yes
12V rail voltage: min 11.8, current 12.3, max 12.8, under voltage events: 0
Heap OK, handles allocated/used 99/0, heap memory allocated/used/recyclable 2048/440/440, gc cycles 0
Events: 0 queued, 0 completed
Driver 0: standstill, SG min n/a, mspos 296, reads 10168, writes 22 timeouts 0
Driver 1: standstill, SG min n/a, mspos 248, reads 10168, writes 22 timeouts 0
Driver 2: standstill, SG min n/a, mspos 168, reads 10169, writes 21 timeouts 0
Driver 3: standstill, SG min n/a, mspos 936, reads 10169, writes 21 timeouts 0
Driver 4: standstill, SG min n/a, mspos 680, reads 10169, writes 21 timeouts 0
Driver 5: standstill, SG min n/a, mspos 804, reads 10171, writes 19 timeouts 0
Date/time: 2024-03-06 14:08:31
Slowest loop: 66.36ms; fastest: 0.06ms
=== Storage ===
Free file entries: 20
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, segments created 0, maxWait 0ms, bed compensation in use: none, height map offset 0.000, max steps late 0, min interval 0, bad calcs 0, ebfmin 0.00, ebfmax 0.00
no step interrupt scheduled
Moves shaped first try 0, on retry 0, too short 0, wrong shape 0, maybepossible 0
=== DDARing 0 ===
Scheduled moves 0, completed 0, 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 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
File2* is idle in state(s) 0
Queue2 is idle in state(s) 0
Q0 segments left 0, axes/extruders owned 0x0000001
Code queue 0 is empty
Q1 segments left 0, axes/extruders owned 0x0000000
Code queue 1 is empty
=== Filament sensors ===
check 31279 clear 4266391
Extruder 0: pos 2160.00, errs: frame 0 parity 0 ovrun 0 pol 0 ovdue 0
=== CAN ===
Messages queued 4333, received 0, lost 0, errs 2298737, boc 0
Longest wait 0ms for reply type 0, peak Tx sync delay 0, free buffers 50 (min 50), ts 2435/0/0
Tx timeouts 0,0,2434,0,0,1897 last cancelled message type 4514 dest 127
=== SBC interface ===
Transfer state: 5, failed transfers: 0, checksum errors: 0
RX/TX seq numbers: 4628/4628
SPI underruns 0, overruns 0
State: 5, disconnects: 1, timeouts: 1 total, 1 by SBC, IAP RAM available 0x255b4
Buffer RX/TX: 0/0-0, open files: 0
=== Duet Control Server ===
Duet Control Server version 3.5.0-rc.3+7 (2024-03-06 11:22:55, 32-bit)
Failed to deserialize the following properties:
- MoveSegmentation -> Int32 from 2.0
Code buffer space: 4096
Configured SPI speed: 8000000Hz, TfrRdy pin glitches: 0
Full transfers per second: 40.79, max time between full transfers: 54.2ms, max pin wait times: 37.8ms/3.0ms
Codes per second: 0.02
Maximum length of RX/TX data transfers: 4349/48

https://streamable.com/u9d4i9

chrishamm

@timschneider said in [3.5.0-rc.3+5] [bug] nested while job Illegal para letter '.':

see the M0 at the beginning for the inactive channel.

Hence my question from the previous post. M0 attempts to synchronize both file streams but since File2 never reaches it due to your check, it leads to a deadlock. I'm going to investigate why it might delay E-STOP, though.

You should never call M0/M1/M2/M24/M25/M32 from a single file channel only.

Even without your condition at the top the file should behave like a macro.

timschneider

@chrishamm
ok, I missunderstood the concept of the two channels at all I guess - I thought if if tell channel File2 to leave/stop the file, it will just stop working as I do not utilize multiple motion systems, but in fact it turned out to do the opposit.

Anyhow the second example from above which will also fail is not using the conditional M0 as shown above.
Unfortunately, I cannot provide any further information from the journal this time, as there is no information / exceptions - it is just sitting in a dead lock

chrishamm

@timschneider If you do not use two motion systems you should not worry about File2 at all.

There was a recent bug which could lead to abort being executed even on an inactive file channel (aka File2) and the if-statement at the start of your files above (at least followed only by M99) was meant to work-around this particular case. But it won't be needed in the next versions either.

I could reproduce the deadlock that you managed to provoke and I am working on a fix. I'll keep you posted.

chrishamm

@timschneider This is now fixed as well.

timschneider

@chrishamm
Thanks for the great patch! Your work is outstanding! It's impressive to see the passion and dedication you and the duet3d team put into the software and hardware!

Now that all the show-stoppers are out of the way, we are going to switch completely to duet3 in the sbc setup. Starting with 4 closed loop steppers with 4 1HCL and 4 open loop steppers directly on the 6HC. Also two filament monitors and two IR probes per machine. This will be followed at a later stage by two tool boards and a distribution board per machine. I am excited to see the results.