1LC - extruder randomly stopping/reversing - ≤3.5.0-rc1

[Exerqtor]

@dc42 Ok I'll give it a go later today.
I've got log level 3 running so i can post that whole "transcript" from when i run the test.

Want me to run M122 reports as well?

[dc42]

@Exerqtor I'd like M122 reports if it still stops extruding, or at the end if it no longer stops extruding,

If it no longer stops extruding, there may be small extrusion defects where it would previously have done so. In this build I detect when the infinity occurs, produce debug info to help me determine why, and attempt to recover from it (which is where the defects may occur).

[Exerqtor]

@dc42 I'm running the test print now, and it's passed the point where it used to fail earlier (it's throwing debug info, so it looks like you're on to something).

I'm going to let it complete and report back with the things you wanted.

As of writing this reply this is the following debug that's appeared in DWC:

12.3.2024, 16:52:22	Debug from 121: pex xpend=inf effsm=0.01 dsf=inf dbf=4.569
Debug from 121: 0 d=inf t=0.0 
Debug from 121: b=inf c=7.5001e+3 a=2.6666e-4
Debug from 121: 1 d=inf t=0.0 
Debug from 121: b=inf c=-7.5000e+3 a=-2.6667e-4
12.3.2024, 16:50:07	Debug from 121: pex xpend=inf effsm=0.01 dsf=inf dbf=133.702
Debug from 121: 0 d=inf t=0.0 
Debug from 121: b=inf c=3.7500e+3 a=5.3333e-4
Debug from 121: 1 d=inf t=0.0 
Debug from 121: b=inf c=-3.7501e+3 a=-5.3332e-4
12.3.2024, 16:49:46	Debug from 121: pex xpend=inf effsm=0.01 dsf=inf dbf=154.050
Debug from 121: 0 d=inf t=0.0 
Debug from 121: b=inf c=3.7500e+3 a=5.3333e-4
Debug from 121: 1 d=inf t=0.0 
Debug from 121: b=inf c=-3.7501e+3 a=-5.3332e-4
12.3.2024, 16:49:24	Debug from 121: pex xpend=inf effsm=0.01 dsf=inf dbf=77.951
Debug from 121: 0 d=inf t=0.0 
Debug from 121: b=inf c=3.7500e+3 a=5.3333e-4
Debug from 121: 1 d=inf t=0.0 
Debug from 121: b=inf c=-3.7496e+3 a=-5.3339e-4
12.3.2024, 16:49:03	Debug from 121: pex xpend=inf effsm=0.01 dsf=inf dbf=89.540
Debug from 121: 0 d=inf t=0.0 
Debug from 121: b=inf c=3.7500e+3 a=5.3333e-4
Debug from 121: 1 d=inf t=0.0 
Debug from 121: b=inf c=-3.7499e+3 a=-5.3334e-4

[dc42]

@Exerqtor thanks, the fact that it recovers now tells me that the infinity was responsible for the failing extrusion, and the debug tells me which of two places the infinity is generated in. You can stop the print if you wish.

[dc42]

@Exerqtor if I produce another tool board firmware in the next 30 mins or so, will you be able to test it?

[Exerqtor]

Well that fun didn't last long, all of a sudden i got a error in DWC that boar 121 had reconnected. Extrusion stopped at that point, and the tool heater reads offline & 2000.0C.

I grabbed M122 reports once i saw what had happened, then paused and canceled the print.
Here is the reports:

M122
=== Diagnostics ===
RepRapFirmware for Duet 3 Mini 5+ version 3.5.0-rc.3+ (2024-02-27 13:52:47) running on Duet 3 Mini5plus WiFi (standalone mode)
Board ID: XNHXF-HR6KL-K65J0-409N2-K9W1Z-RV2MZ
Used output buffers: 1 of 40 (40 max)
=== RTOS ===
Static ram: 103264
Dynamic ram: 128780 of which 24 recycled
Never used RAM 2724, free system stack 135 words
Tasks: NETWORK(1,ready,15.9%,196) HEAT(3,nWait 6,0.0%,336) Move(4,nWait 6,0.5%,238) CanReceiv(6,nWait 1,0.1%,543) CanSender(5,nWait 7,0.0%,328) CanClock(7,delaying,0.0%,340) TMC(4,nWait 6,0.8%,68) MAIN(1,running,80.8%,596) IDLE(0,ready,1.1%,30) AIN(4,delaying,0.8%,260), total 100.0%
Owned mutexes:
=== Platform ===
Last reset 01:06:39 ago, cause: software
Last software reset at 2024-03-12 15:49, reason: User, Gcodes spinning, available RAM 8824, slot 2
Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00000000 BFAR 0xe000ed38 SP 0x00000000 Task MAIN Freestk 0 n/a
Error status: 0x04
Aux0 errors 0,0,0
MCU revision 3, ADC conversions started 4000082, completed 4000081, timed out 0, errs 0
MCU temperature: min 35.7, current 46.0, max 46.8
Supply voltage: min 2.8, current 24.0, max 24.4, under voltage events: 0, over voltage events: 0, power good: yes
Heap OK, handles allocated/used 198/33, heap memory allocated/used/recyclable 4096/2560/2100, gc cycles 788
Events: 1 queued, 1 completed
Driver 0: standstill, SG min 0, read errors 0, write errors 0, ifcnt 33, reads 13838, writes 33, timeouts 0, DMA errors 0, CC errors 0
Driver 1: ok, SG min 0, read errors 0, write errors 0, ifcnt 33, reads 13838, writes 33, timeouts 0, DMA errors 0, CC errors 0
Driver 2: standstill, SG min 0, read errors 0, write errors 0, ifcnt 21, reads 13850, writes 21, timeouts 0, DMA errors 0, CC errors 0
Driver 3: standstill, SG min 0, read errors 0, write errors 0, ifcnt 20, reads 13851, writes 20, timeouts 0, DMA errors 0, CC errors 0
Driver 4: standstill, SG min 0, read errors 0, write errors 0, ifcnt 20, reads 13851, writes 20, timeouts 0, DMA errors 0, CC errors 0
Driver 5: not present
Driver 6: not present
Date/time: 2024-03-12 16:56:32
Cache data hit count 4294967295
Slowest loop: 217.34ms; fastest: 0.09ms
=== Storage ===
Free file entries: 16
SD card 0 detected, interface speed: 22.5MBytes/sec
SD card longest read time 10.0ms, write time 60.0ms, max retries 0
=== Move ===
DMs created 83, segments created 38, maxWait 3169000ms, bed compensation in use: mesh, height map offset 0.000, max steps late 1, min interval 0, bad calcs 0, ebfmin 0.00, ebfmax 0.00
next step interrupt due in 48 ticks, enabled
Moves shaped first try 1751, on retry 490, too short 531, wrong shape 8784, maybepossible 304
=== DDARing 0 ===
Scheduled moves 15147, completed 15107, hiccups 0, stepErrors 0, LaErrors 23, Underruns [0, 0, 1], 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
=== 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 X183.425 Y192.988 E.00782" 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 P250" 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 1, axes/extruders owned 0x0000807
Code queue 0 is empty
Q1 segments left 0, axes/extruders owned 0x0000000
Code queue 1 is empty
=== Filament sensors ===
check 0 clear 0
Extruder 0 sensor: no filament
=== CAN ===
Messages queued 49079, received 81477, lost 0, errs 1563, boc 0
Longest wait 3ms for reply type 6013, peak Tx sync delay 25557, free buffers 26 (min 25), ts 19999/19997/0
Tx timeouts 0,0,1,0,0,0 last cancelled message type 30 dest 127
=== Network ===
Slowest loop: 204.80ms; 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 ===
Interface state: active
Module is connected to access point 
Failed messages: pending 0, notrdy 0, noresp 0
Firmware version 2.1beta7
MAC address c4:5b:be:ce:91:93
Module reset reason: Power up, Vcc 3.38, flash size 2097152, free heap 42896
WiFi IP address 192.168.10.x
Signal strength -52dBm, channel 6, mode 802.11n, reconnections 0
Clock register 00002001
Socket states: 0 0 0 0 0 0 0 0
M122 B121
Diagnostics for board 121:
Duet TOOL1LC rev 1.1 or later firmware version 3.5.0-rc.3+db (2024-03-12 08:07:55)
Bootloader ID: SAMC21 bootloader version 2.8 (2023-07-25)
All averaging filters OK
Never used RAM 3948, free system stack 69 words
Tasks: Move(3,nWait 7,0.5%,5) HEAT(2,nWait 6,0.1%,131) CanAsync(5,nWait 4,0.0%,55) CanRecv(3,nWait 1,0.2%,71) CanClock(5,nWait 1,0.0%,59) ACCEL(3,nWait 6,0.0%,53) TMC(2,delaying,3.6%,53) MAIN(1,running,91.1%,419) IDLE(0,ready,0.0%,27) AIN(2,delaying,4.6%,112), total 100.0%
Owned mutexes:
Last reset 00:01:08 ago, cause: software
Last software reset at 2024-03-12 16:55, reason: StackOverflow, available RAM 2968, slot 0
Software reset code 0x0100 ICSR 0x0042600e SP 0x20007f34 Task Move Freestk 3342 ok
Stack: 20004a80 20004ab4 0001cf33 20004c98 20004938 00000000 0001c011 20003320 fffffffd a5a5a5a5 00000000 20007f8c 00000000 20007f8c 0001cc97 00000000 200017c4 20001748 0001c4d7 20001748 200017c4 00000032 454c4449 00022700 0001ac77 200018e0 200018e0
Driver 0: pos 0, 80.0 steps/mm, standstill, SG min 0, read errors 0, write errors 1, ifcnt 23, reads 33962, writes 9, timeouts 0, DMA errors 0, CC errors 0, steps req 0 done 98869
Moves scheduled 1525, completed 1525, in progress 0, hiccups 52, segs 20, step errors 0, maxLate 0 maxPrep 2886, maxOverdue 1344316502, maxInc 1344316502, mcErrs 0, gcmErrs 0, ebfmin 0.00 max 1.00
Peak sync jitter -1/8, peak Rx sync delay 219, resyncs 0/0, no timer interrupt scheduled
VIN voltage: min 24.5, current 24.6, max 24.8
MCU temperature: min 67.2C, current 67.2C, max 69.5C
Last sensors broadcast 0x00000000 found 0 103 ticks ago, 0 ordering errs, loop time 0
CAN messages queued 587, send timeouts 0, received 2159, lost 0, errs 0, boc 0, free buffers 18, min 18, error reg 0
dup 0, oos 0/0/0/0, bm 0, wbm 0, rxMotionDelay 347, adv -1344256972/74642
Accelerometer: LIS3DH, status: 00
I2C bus errors 0, naks 3, contentions 0, other errors 0

And i'll upload the entire debug log from the point where i started the print from DWC until i canceled it "here". It's INSANELY much getting printed all of a sudden for some reason, so i'll switch to log level 1 instead. It's not added this much to the log before!

[dc42]

@Exerqtor no need to upload the debug log, I have everything I need from the previous report. I'll provide another binary for you to run shortly. I'll also take a look at that M122 report.

[Exerqtor]

@dc42 Oh sorry I didn't see your replies since I was sifting through the debug log lol.

But I won't be able to test anything more today since i'm off to a meeting now, and will be away for the rest of the evening.

So do it whenever you have time and i'll test it tomorrow!

[dc42]

@Exerqtor I reproduced the issue on the bench and fixed it. Please try this tool board firmware.

Duet3Firmware_TOOL1LC.bin

[Exerqtor]

@dc42 said in 1LC - extruder randomly stopping/reversing - ≤3.5.0-rc1:

@Exerqtor I reproduced the issue on the bench and fixed it. Please try this tool board firmware.

Duet3Firmware_TOOL1LC.bin

Awesome! I'm warming up the bed now before i run a test with the new binaries 🤟

[dc42]

@Exerqtor FYI the latest binaries of everything are now at https://www.dropbox.com/scl/fo/ljnewqssbl9bdo9vex37f/h?rlkey=m11nef0mvuc9pc8wri7rabf1b&dl=0.

[Exerqtor]

@dc42 Ok, I just installed both the Mini (even though it's the MMS version) & 1LC from that drive now and am about to fire up the test, I'll update this post once that's done.

---

It finished without any issues! High five on that fix, it's been annoying me for quite some time now 😂

[dc42]

@Exerqtor thanks, I'm glad to get to the bottom of this. The problem was caused when the GCode called for a very short move that would take less than 2 microseconds to execute. When the move time was truncated to integer to send over CAN, the move ended up as taking zero time yet having nonzero extrusion. This resulted in a floating point divide-by-zero error. I changed the floating point library on the 1LC to a faster but less IEEE-conformant one between 3.4beta4 and 3.4rc1, and I think this caused a change in behaviour after the divide by zero occurred.

Now that we have solved this one, I'd like to revisit the issue with WiFi connection causing crashes. I note that you are doing a lot of things with an LED string connected to the Duet 3 Mini dedicated LED output. Please try changing enough of that LED macro code so that M150 commands to that output don't happen; then try running with DWC connected over WiFi. I am wondering whether the DMA to that port when you use M150 could be interfering with the WiFi DMA.

[droftarts]

@Exerqtor bug fixed, and I still haven't got my printer up and running to test! I've been rather busy on other things, sorry.

Ian

[jay_s_uk]

@droftarts I'll let you "draw" this one to a close

[jens55]

@dc42, could this bug that you just squashed also be causing my huge number of hiccups as well as the bogus Vin min/max numbers?
I noticed that a few of the M122 Bxxx reports posted in this thread also have large number of hiccups (although not as large as the ones I am seeing) as well as the bad voltage readings.
Please advise on what files I should upgrade to implement this fix so I can try out if it maybe fixes my issues.

[droftarts]

@jens55 see @dc42’s message above for link to latest binaries.

Ian

[jens55]

@droftarts
Do I just upgrade the .bin files? What are the .map files for? Do I just upgrade MB6HC.bin and Tool1LC.bin (I only have the 6HC and the 1LC boards) or do I need to upgrade other stuff?

With the .bin files uploaded, this is what I see for the version information:

Nothing seems to have changed on the 1LC firmware and only the MB6HC firmware changed. Is it ok to have three different versions of firmware (between the 6HC, 1LC and DWC)?

[dc42]

@jens55 yes just use the MB6HC and TOOL1LC .bin files. When you have installed them you can retrieve the build dates using M115. Ignore the .map files, they are for me in case there is a problem.

[jens55]

@dc42
Alas, that fix did nothing to my hiccup problem