[3.5.0-rc.3] M122 HTTP Failed to process code in stage Executed
-
@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
-
@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.