RRF 3.5.0-b3 sporadically stops extruding

Exerqtor

@Exerqtor
There it happened again on a new print job. No faults, errors, warnings, weird sounds, smoke, blinking or anything other that looks off. It just stops extruding.

I didn't manage to run a diagnose WHILE it had halted the extrusion, but this was right afterwards (if it's worth anyting):

15.4.2023, 18:44:05	M122
=== Diagnostics ===
RepRapFirmware for Duet 3 Mini 5+ version 3.5.0-beta.3 (2023-04-14 11:28:00) running on Duet 3 Mini5plus WiFi (standalone mode)
Board ID: FAP55-Q967A-G65J0-401GL-0S02Z-RF9TL
Used output buffers: 3 of 40 (29 max)
=== RTOS ===
Static ram: 102968
Dynamic ram: 126860 of which 232 recycled
Never used RAM 8516, free system stack 134 words
Tasks: NETWORK(nWait,20.9%,219) HEAT(nWait,0.0%,328) Move(nWait,0.8%,270) CanReceiv(nWait,0.0%,774) CanSender(nWait,0.0%,327) CanClock(delaying,0.0%,350) TMC(nWait,1.2%,74) MAIN(running,74.7%,351) IDLE(ready,1.4%,29) AIN(delaying,0.8%,266), total 100.0%
Owned mutexes: WiFi(NETWORK)
=== Platform ===
Last reset 00:04:30 ago, cause: power up
Last software reset at 2023-04-15 10:26, reason: HardFault imprec, Gcodes spinning, available RAM 10968, slot 0
Software reset code 0x4063 HFSR 0x40000000 CFSR 0x00000400 ICSR 0x00000803 BFAR 0xe000ed38 SP 0x20011b78 Task NETW Freestk 482 ok
Stack: 2002be48 00000000 200014ec 0000019f ffffffff 0002f609 00033e00 810f0000 0002f5f5 00000000 00000000 00000000 20030a34 00000800 20035758 2002be30 20018740 2002bcd5 20018740 2001e5d0 0002f78f 00000000 00000000 00000000 20011c28 00000014 62005448
Error status: 0x00
Aux0 errors 0,0,0
MCU revision 3, ADC conversions started 270209, completed 270208, timed out 0, errs 0
MCU temperature: min 41.5, current 44.5, max 44.5
Supply voltage: min 23.3, current 23.7, max 24.0, under voltage events: 0, over voltage events: 0, power good: yes
Heap OK, handles allocated/used 99/32, heap memory allocated/used/recyclable 2048/924/448, gc cycles 33
Events: 0 queued, 0 completed
Driver 0: ok, SG min 0, read errors 0, write errors 0, ifcnt 35, reads 24482, writes 35, timeouts 0, DMA errors 0, CC errors 0
Driver 1: ok, SG min 0, read errors 0, write errors 0, ifcnt 35, reads 24482, writes 35, timeouts 0, DMA errors 0, CC errors 0
Driver 2: standstill, SG min 0, read errors 0, write errors 0, ifcnt 24, reads 24492, writes 24, timeouts 0, DMA errors 0, CC errors 0
Driver 3: standstill, SG min 0, read errors 0, write errors 0, ifcnt 24, reads 24492, writes 24, timeouts 0, DMA errors 0, CC errors 0
Driver 4: standstill, SG min 0, read errors 0, write errors 0, ifcnt 24, reads 24493, writes 24, timeouts 0, DMA errors 0, CC errors 0
Driver 5: standstill, SG min 0, read errors 0, write errors 0, ifcnt 10, reads 24507, writes 10, timeouts 0, DMA errors 0, CC errors 0
Driver 6: standstill, SG min 0, read errors 0, write errors 0, ifcnt 10, reads 24506, writes 10, timeouts 0, DMA errors 0, CC errors 0
Date/time: 2023-04-15 18:44:03
Cache data hit count 428383395
Slowest loop: 231.95ms; fastest: 0.08ms
=== Storage ===
Free file entries: 16
SD card 0 detected, interface speed: 22.5MBytes/sec
SD card longest read time 6.1ms, write time 20.1ms, max retries 0
=== Move ===
DMs created 83, segments created 26, maxWait 58054ms, bed compensation in use: mesh, comp offset 0.000
next step interrupt due in 130 ticks, enabled
=== DDARing 0 ===
Scheduled moves 2041, completed 2001, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state 3
=== 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 doing "G1 X90.747 Y206.708 E.01123" 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 S1                                                                        " 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 1
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
=== CAN ===
Messages queued 4333, received 5521, lost 0, boc 0
Longest wait 4ms for reply type 6029, peak Tx sync delay 70, free buffers 18 (min 13), ts 1351/1350/0
Tx timeouts 0,0,0,0,0,0
=== Network ===
Slowest loop: 182.98ms; fastest: 0.00ms
Responder states: MQTT(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0)
HTTP sessions: 1 of 8
= WiFi =
Network state is active
Module is connected to access point 
Failed messages: pending 0, notready 0, noresp 0
Firmware version 2.1beta4
MAC address bc:ff:4d:e6:b1:62
Module reset reason: Power up, Vcc 3.38, flash size 2097152, free heap 42992
WiFi IP address 192.168.10.50
Signal strength -60dBm, channel 1, mode 802.11n, reconnections 0
Clock register 00002001
Socket states: 0 0 0 0 0 0 0 0

Have to keep the printer running, so I just rolled back too 3.5.0-b2.
This will also somewhat confirm if it's beta3 related and not my printer thats suddenly contracted herpagonasyphilaids out of nowhere.

jay_s_uk

@Exerqtor an m122 output from the toolboard would be more useful

gloomyandy

@Exerqtor Are you using input shaping and/or pressure advance? If so it might be worth providing your settings. I assume that you had updated the 1LC ro 3.5.0-B3 as well as the main board?

Exerqtor

Yeah i just updated it to 3.5.0-b3 again now before going to bed, I'm done with the prints that i had to get done so i can run some tests tomorrow.

I was using both IS & PA in all the prints i tried, and yes everything was updated to 3.5.0-b3 😅
The IS & PA settings for reference:

M593 P"zvdd" F39.75 S0.0           ; Use ZVDDD input shaping to cancel ringing at 41.8Hz with 0.0 damping factor
M572 D0 S0.040                     ; Set extruder 0 pressure advance to 0.040 seconds

Like I said, gonna run some more tests tomorrow. Hopefully with a M122 from the 1LC.

gloomyandy

@Exerqtor If you are running tests and able to reproduce it then repeating the test with PA and IS turned off would probably be a useful data point.

Exerqtor

@gloomyandy
The issue is that the bugger comes and goes sporadically, it's not at one single point each time.

My first thought was that it was related to RRF changing accelerations based on the feature type of the job (maybe in conjunction with the new PA/IS system, despite those vallues are the same throughout the whole print). I'm letting RRF handle this by emitting the feature type from the sliced gcode via a global and daemon.g changing based on that.

But since it seems to come and go all whilly nilly without a clear pattern i'm not so sure, I've got the accel control off on layer 1, and it's been happening on the first layer a couple times.

Exerqtor

Ok, so i finally managed to get a diagnosis when it wasn't extruding:

M122 B121
Diagnostics for board 121:
Duet TOOL1LC rev 1.1 or later firmware version 3.5.0-beta.3 (2023-04-13 18:44:05)
Bootloader ID: SAMC21 bootloader version 2.4 (2021-12-10)
All averaging filters OK
Never used RAM 4984, free system stack 38 words
Tasks: Move(nWait,0.1%,93) HEAT(nWait,0.5%,57) CanAsync(nWait,0.0%,49) CanRecv(nWait,0.0%,74) CanClock(nWait,0.0%,67) ACCEL(nWait,0.0%,53) TMC(delaying,3.0%,57) MAIN(running,91.3%,344) IDLE(ready,0.0%,27) AIN(delaying,5.0%,142), total 100.0%
Last reset 11:54:22 ago, cause: software
Last software reset data not available
Driver 0: pos 0, 568.8 steps/mm,standstill, SG min 0, read errors 0, write errors 0, ifcnt 40, reads 8529, writes 0, timeouts 0, DMA errors 0, CC errors 0, steps req 0 done 0
Moves scheduled 536, completed 536, in progress 0, hiccups 0, step errors 0, maxPrep 690, maxOverdue 0, maxInc 0, mcErrs 0, gcmErrs 0
Peak sync jitter -2/6, peak Rx sync delay 195, resyncs 0/0, no timer interrupt scheduled
VIN voltage: min 24.1, current 24.3, max 24.4
MCU temperature: min 40.5C, current 61.8C, max 61.8C
Last sensors broadcast 0x00000012 found 2 234 ticks ago, 0 ordering errs, loop time 1
CAN messages queued 367, send timeouts 0, received 208, lost 0, free buffers 37, min 37, error reg 0
dup 0, oos 0/0/0/15, bm 0, wbm 0, rxMotionDelay 310, adv 36379/74640
Accelerometer: LIS3DH, status: 00
I2C bus errors 0, naks 0, other errors 0

I find this a part a little bit interesting Driver 0: pos 0, 568.8 steps/mm,standstill,? If i run a diagnosis while it's working as intended it's saying ok instead of standstill 🤔

This was on the first layer of the print, where i'm not doing any funny stuff. It's locked too 500mms/3 acceleration through that whole layer.

Don't know if it's worth anything, but this is the job file.

Exerqtor

Normal operation:

M122 b121
Diagnostics for board 121:
Duet TOOL1LC rev 1.1 or later firmware version 3.5.0-beta.3 (2023-04-13 18:44:05)
Bootloader ID: SAMC21 bootloader version 2.4 (2021-12-10)
All averaging filters OK
Never used RAM 3952, free system stack 38 words
Tasks: Move(nWait,0.5%,93) HEAT(nWait,0.5%,57) CanAsync(nWait,0.0%,49) CanRecv(nWait,0.1%,74) CanClock(nWait,0.0%,67) ACCEL(nWait,0.0%,53) TMC(nWait,3.1%,57) MAIN(running,90.7%,344) IDLE(ready,0.0%,27) AIN(delaying,5.1%,142), total 100.0%
Last reset 12:21:31 ago, cause: software
Last software reset data not available
Driver 0: pos 0, 568.8 steps/mm,ok, SG min 0, read errors 0, write errors 0, ifcnt 40, reads 60968, writes 0, timeouts 1, DMA errors 0, CC errors 0, failedOp 0x01, steps req 0 done 1069416
Moves scheduled 18746, completed 18741, in progress 1, hiccups 1305, step errors 0, maxPrep 1907, maxOverdue 14034, maxInc 3271, mcErrs 0, gcmErrs 0
Peak sync jitter -4/10, peak Rx sync delay 278, resyncs 0/0, no timer interrupt scheduled
VIN voltage: min 24.1, current 24.3, max 24.5
MCU temperature: min 40.5C, current 81.8C, max 81.8C
Last sensors broadcast 0x00000012 found 2 104 ticks ago, 0 ordering errs, loop time 1
CAN messages queued 32031, send timeouts 0, received 33141, lost 0, free buffers 37, min 36, error reg 0
dup 0, oos 0/0/0/2340, bm 0, wbm 0, rxMotionDelay 614, adv 35814/74649
Accelerometer: LIS3DH, status: 00
I2C bus errors 0, naks 0, other errors 0

Exerqtor

I've ran that job file three times now with PA on, and it stops extruding each time it starts the first layer infill.

I'm printing another one of the same job now, with PA disabled, and it's just finished with the first layer WITHOUT the extruder halting. So it looks like it's something going on with the PA,

jay_s_uk

@Exerqtor i can also replicate an issue with PA and IS enabled using 3.5b3. Best to disable PA if you can for now as it seems to print ok without it enabled

Exerqtor

@jay_s_uk said in RRF 3.5.0-b3 sporadically stops extruding:

@Exerqtor i can also replicate an issue with PA and IS enabled using 3.5b3. Best to disable PA if you can for now as it seems to print ok without it enabled

Glad to hear it's not an isolated issue on my end at least. Yup, keeping PA of for the time being, while looking out for other bugs 😅

EDIT:

I retract my statement about disabling PA and keep trying it out. Since it's another bug that causes the whole printer to reboot at random (seemingly) intervals without any reason. So i'm reverting to 3.5.0-b2 again.

RIP 3.5.0-b3, you won't be missed🙈.

gloomyandy

@Exerqtor This may be too late, but if you get a reboot can you run M122 after it restarts and post the output. The info in there will help a lot with trying to solve the issue. It is probably worth checking the M122 output now (from whatever version you are now running) as the data from the previous crash may still be present.

Exerqtor

@gloomyandy
Yeah it's way to late at this point, after the third reboot i reverted to b2. Don't look like it's a prevalent issue either since it's not being reported by anyone else.

gloomyandy

@Exerqtor It may not be too late, the reset data is stored in flash that may not be erased when you reinstall. Worth checking to see what M122 reports.

gloomyandy

@gloomyandy Also even though others may not be reporting the problem, it may give clues towards other issues, so definitely worth reporting if you possibly can.

Exerqtor

@gloomyandy I can pull a M122 from both the mobo and toolboard as soon as this print finishes.
If it's anything worth looking at or not i have no idea 🤷‍♂️

gloomyandy

@Exerqtor This (and the stack trace that follows it) is the part of interest....

Last software reset at 2023-04-15 10:26, reason: HardFault imprec, Gcodes spinning, available RAM 10968, slot 0

Exerqtor

@gloomyandy
This is from the Mini:

Last reset 02:45:09 ago, cause: software
Last software reset at 2023-04-23 10:32, reason: User, Gcodes spinning, available RAM 5696, slot 1
Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00446000 BFAR 0xe000ed38 SP 0x00000000 Task MAIN Freestk 0 n/a

And the 1LC:

Last reset 02:46:46 ago, cause: software
Last software reset data not available

gloomyandy

@Exerqtor Unfortunately it looks like the reset data has been wiped by the older firmware. Oh well, thanks for taking the time to check. If you do decide to try 3.5.0-beta.3 again and you get a reset please grab the m122 output and post it.

Exerqtor

This issue has been solved as of RRF3.5b3+!