[3.5.0-rc.3] M122 HTTP Failed to process code in stage Executed

[timschneider]

@chrishamm
today I got the following exception in the journal while simulating a file and requesting a M122.

Feb 19 10:52:39 Meltingplot-MBL-480-vaswsq DuetWebServer[1360]: DuetWebServer.Controllers.MachineController[0] [DoCode] Executing code 'M122'
Feb 19 10:52:39 Meltingplot-MBL-480-vaswsq DuetControlServer[2860]: [error] HTTP: Failed to process code in stage Executed
Feb 19 10:52:39 Meltingplot-MBL-480-vaswsq DuetControlServer[2860]:    System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
Feb 19 10:52:39 Meltingplot-MBL-480-vaswsq DuetControlServer[2860]:    at System.Collections.Generic.List`1.Enumerator.MoveNext()
Feb 19 10:52:39 Meltingplot-MBL-480-vaswsq DuetControlServer[2860]:    at DuetAPI.Commands.Code.ToString() in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetAPI/Commands/Code/Code.cs:line 1007
Feb 19 10:52:39 Meltingplot-MBL-480-vaswsq DuetControlServer[2860]:    at System.Text.StringBuilder.Append(Object value)
Feb 19 10:52:39 Meltingplot-MBL-480-vaswsq DuetControlServer[2860]:    at DuetControlServer.Codes.Pipelines.PipelineBase.Diagnostics(StringBuilder builder) in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetControlServer/Codes/Pipelines/PipelineBase.cs:line 92
Feb 19 10:52:39 Meltingplot-MBL-480-vaswsq DuetControlServer[2860]:    at DuetControlServer.Codes.ChannelProcessor.Diagnostics(StringBuilder builder) in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetControlServer/Codes/ChannelProcessor.cs:line 87
Feb 19 10:52:39 Meltingplot-MBL-480-vaswsq DuetControlServer[2860]:    at DuetControlServer.Codes.Processor.Diagnostics(StringBuilder builder) in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetControlServer/Codes/Processor.cs:line 48
Feb 19 10:52:39 Meltingplot-MBL-480-vaswsq DuetControlServer[2860]:    at DuetControlServer.Codes.Handlers.MCodes.Diagnostics(Message result) in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetControlServer/Codes/Handlers/MCodes.cs:line 1069
Feb 19 10:52:39 Meltingplot-MBL-480-vaswsq DuetControlServer[2860]:    at DuetControlServer.Codes.Handlers.MCodes.CodeExecuted(Code code) in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetControlServer/Codes/Handlers/MCodes.cs:line 1033
Feb 19 10:52:39 Meltingplot-MBL-480-vaswsq DuetControlServer[2860]:    at DuetControlServer.Codes.Pipelines.Executed.ProcessCodeAsync(Code code) in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetControlServer/Codes/Pipelines/Executed.cs:line 44
Feb 19 10:52:39 Meltingplot-MBL-480-vaswsq DuetControlServer[2860]:    at DuetControlServer.Codes.Pipelines.PipelineStackItem.<>c__DisplayClass0_0.<<-ctor>b__0>d.MoveNext() in /home/runner/work/DuetSoftwareFramework/DuetSoftwareFramework/src/DuetControlServer/Codes/Pipelines/PipelineStackItem.cs:line 64
 

M122

19.2.2024, 11:03:26 	M122
=== Diagnostics ===
RepRapFirmware for Duet 3 MB6HC version 3.5.0-rc.3+ (2024-02-04 11:40:04) 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 (30 max)
=== RTOS ===
Static ram: 155200
Dynamic ram: 88676 of which 4576 recycled
Never used RAM 93796, free system stack 204 words
Tasks: SBC(2,ready,10.0%,404) HEAT(3,nWait 1,0.0%,323) Move(4,nWait 6,8.9%,214) 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.7%,56) MAIN(2,running,72.4%,103) IDLE(0,ready,0.0%,30), total 100.0%
Owned mutexes: HTTP(MAIN)
=== Platform ===
Last reset 00:13:17 ago, cause: software
Last software reset at 2024-02-19 10:50, reason: User, Gcodes spinning, available RAM 93772, 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 33.1, current 33.1, max 33.2
Supply voltage: min 24.0, 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.3, max 12.5, under voltage events: 0
Heap OK, handles allocated/used 99/5, heap memory allocated/used/recyclable 2048/140/0, gc cycles 0
Events: 0 queued, 0 completed
Driver 0: standstill, SG min n/a, mspos 88, reads 1629, writes 0 timeouts 0
Driver 1: standstill, SG min n/a, mspos 408, reads 1629, writes 0 timeouts 0
Driver 2: standstill, SG min n/a, mspos 856, reads 1628, writes 0 timeouts 0
Driver 3: standstill, SG min n/a, mspos 280, reads 1628, writes 0 timeouts 0
Driver 4: standstill, SG min n/a, mspos 824, reads 1628, writes 0 timeouts 0
Driver 5: standstill, SG min n/a, mspos 60, reads 1629, writes 0 timeouts 0
Date/time: 2024-02-19 11:03:25
Slowest loop: 2.02ms; fastest: 0.07ms
=== 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 37, maxWait 3ms, bed compensation in use: none, height map offset 0.000, max steps late 0, ebfmin 0.00, ebfmax 0.00
no step interrupt scheduled
Moves shaped first try 68, on retry 14, too short 79, wrong shape 54, maybepossible 11
=== DDARing 0 ===
Scheduled moves 804403, completed 804361, 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 doing "G1 X437.990997 Y184.783005 E0.012350" 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 P100" 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 0x80000007
Code queue 0 is empty
Q1 segments left 0, axes/extruders owned 0x0000000
Code queue 1 is empty
=== Filament sensors ===
check 0 clear 4950014
Extruder 0: pos 2407.15, errs: frame 0 parity 0 ovrun 0 pol 0 ovdue 0
=== CAN ===
Messages queued 2, received 0, lost 0, errs 1490, boc 0
Longest wait 0ms for reply type 0, peak Tx sync delay 0, free buffers 50 (min 50), ts 1/0/0
Tx timeouts 0,0,1,0,0,1 last cancelled message type 4514 dest 127
=== SBC interface ===
Transfer state: 5, failed transfers: 0, checksum errors: 0
RX/TX seq numbers: 61570/61570
SPI underruns 0, overruns 0
State: 5, disconnects: 0, timeouts: 0 total, 0 by SBC, IAP RAM available 0x253b4
Buffer RX/TX: 2480/984-4064, open files: 0
=== Duet Control Server ===
Duet Control Server version 3.5.0-rc.3 (2024-01-26 12:37:35)
File+ProcessInternally:
> Busy
File /opt/dsf/sd/gcodes/Werkzeug_GridLine_V1_0.25mm_PA_MBL480_2d2h54m.gcode is selected, processing, simulating
Failed to deserialize the following properties:
- MoveSegmentation -> Int32 from 2.0
File:
Buffered code: G1 X437.847 Y185.192 E0.01949
Buffered code: G1 X437.77 Y185.456 E0.01234
Buffered code: G1 X437.667 Y185.877 E0.01949
Buffered code: G1 X437.619 Y186.135 E0.01177
Buffered code: G1 X437.565 Y186.505 E0.01678
Buffered code: G1 X437.54 Y186.759 E0.01146
Buffered code: G1 X437.522 Y187.107 E0.01568
Buffered code: G1 X437.518 Y187.248 E0.00632
Buffered code: G1 X437.518 Y191.815 E0.2052
Buffered code: G1 X437.515 Y191.921 E0.00474
Buffered code: G1 X437.512 Y191.966 E0.00201
Buffered code: G1 X437.504 Y192.025 E0.00268
Buffered code: G1 X437.493 Y192.081 E0.00257
Buffered code: G1 X437.48 Y192.135 E0.00248
Buffered code: G1 X437.463 Y192.187 E0.00248
Buffered code: G1 X437.444 Y192.239 E0.00247
Buffered code: G1 X437.421 Y192.289 E0.00246
Buffered code: G1 X437.396 Y192.338 E0.00246
Buffered code: G1 X437.368 Y192.386 E0.00251
Buffered code: G1 X437.338 Y192.431 E0.00242
Buffered code: G1 X437.305 Y192.474 E0.00243
Buffered code: G1 X437.269 Y192.516 E0.00248
Buffered code: G1 X437.233 Y192.554 E0.00236
Buffered code: G1 X437.192 Y192.592 E0.00253
Buffered code: G1 X437.15 Y192.627 E0.00245
Buffered code: G1 X437.106 Y192.659 E0.00246
Buffered code: G1 X437.059 Y192.689 E0.00251
Buffered code: G1 X437.012 Y192.716 E0.00243
Buffered code: G1 X436.963 Y192.741 E0.00246
Buffered code: G1 X436.914 Y192.761 E0.00236
Buffered code: G1 X436.861 Y192.78 E0.00256
Buffered codes: 1488 bytes total
Daemon:
Buffered code: G4 P100 ; wait 100ms
Buffered codes: 32 bytes total
>> Doing macro daemon.g, started by system
>> Number of flush requests: 1
File2:
Buffered code: G1 X234.282 Y193.167 E0.00543
Buffered code: G1 X234.21 Y193.07 E0.00541
Buffered code: G1 X234.146 Y192.971 E0.00533
Buffered code: G1 X234.085 Y192.864 E0.00552
Buffered code: G1 X234.031 Y192.755 E0.00543
Buffered code: G1 X233.983 Y192.644 E0.00544
Buffered code: G1 X233.942 Y192.53 E0.00543
Buffered code: G1 X233.907 Y192.409 E0.0057
Buffered code: G1 X233.882 Y192.307 E0.00471
Buffered code: G1 X233.863 Y192.2 E0.00489
Buffered code: G1 X233.849 Y192.091 E0.0049
Buffered code: G1 X233.84 Y191.983 E0.00486
Buffered code: G1 X233.836 Y191.828 E0.00699
Buffered code: G1 X233.836 Y187.244 E0.20593
Buffered code: G1 X233.816 Y186.799 E0.02003
Buffered code: G1 X233.743 Y186.26 E0.02442
Buffered code: G1 X233.618 Y185.722 E0.02481
Buffered code: G1 X233.551 Y185.516 E0.00973
Buffered code: G1 X233.435 Y185.179 E0.01604
Buffered code: G1 X233.35 Y184.981 E0.00967
Buffered code: G1 X233.201 Y184.656 E0.01605
Buffered code: G1 X233.099 Y184.466 E0.00968
Buffered code: G1 X232.914 Y184.15 E0.01647
Buffered code: G1 X232.793 Y183.969 E0.00977
Buffered code: G1 X232.571 Y183.665 E0.01692
Buffered code: G1 X232.433 Y183.497 E0.00977
Buffered codes: 1248 bytes total
Code buffer space: 1688
Configured SPI speed: 8000000Hz, TfrRdy pin glitches: 0
Full transfers per second: 542.35, max time between full transfers: 7.7ms, max pin wait times: 4.2ms/0.4ms
Codes per second: 2379.52
Maximum length of RX/TX data transfers: 7444/3372
 

[chrishamm]

@timschneider Thanks, I've just pushed a bug fix for this. The only way I can see how it occurred was that an expression in a code parameter was being evaluated while M122 attempted to output it.