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

dc42

@Exerqtor are you saying that when it is commanded to retract filament and is operating in reverse, it doesn't attempt to extrude filament instead?

Perhaps you should pause the print after it has started reversing, and see exactly how it does behave in response to extrusion commands?

Exerqtor

@dc42 What i meant is that when the issue happens, it don't behave like it simply reverses the extruder movement since it don't back the filament out at at the expected speed/feedrate.
I usually print at somewhere around 25mm³/s with a 0.4mm nozzle, so it's clearly visible when it works normally and one can see it pulling in filament. BUT when it starts acting up, it don't back out the filament at that rate at all.
It's more like it just stops doing the normal extrusions and only does retract moves (0.45mm FW retraction) but not the unretracts.
So if it was just reversing the stepper movement it would have unloaded the extruder within a minute as the job went on (have to do something like 35mm retraction to fully unload the extruder). But even after letting it go on with the problem active for 10-15minutes before pausing the print i only have to send one 20mm extrude command before it comes plastic out of the nozzle.

I've tried pausing the print(s) countless time when the issue happens, ans tried to run extrusion commands through PanelDue and those behave just as they should. But when i resue the print again it goes right back to the same mode of failure as before i paused.

Sorry for the messy atempt at an explenation 😮‍💨
I've changed the post title to better reflect whats going on.

dc42

@Exerqtor could it be that somehow the motor current has been reduced to a low value, so that the extruder motor is capable of retracting filament but not capable of overcoming nozzle back pressure?

It would be helpful if you could wait for the issue to happen, then pause the print and then run some tests on the extruder:

Verify that the nozzle temperature is correct stable, and was correct when the issue first occurred. Note, if you have a Revo hot end then on early ones the temperature sensing goes wrong after a while. The good ones have blue thermistor wires, the old ones were white.
Use M569 to check that the driver is in spread cycle mode, not stealthchop
Send M906 and M913 without parameters to check that RRF thinks it is using the correct motor current
Test extruding and retracting at slow and medium speeds, e.g. 1 to 5mm/sec.
Assuming it's not working properly try sending M906 Exxx (where xxx is the correct motor current) and M913 E100 to check whether this fixes it

Exerqtor

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

@Exerqtor could it be that somehow the motor current has been reduced to a low value, so that the extruder motor is capable of retracting filament but not capable of overcoming nozzle back pressure?

I have no idea where how that could happen, but it sounds like a possible cause. Weird that it wouldn't happen on 3.5.0-b4 though.

It would be helpful if you could wait for the issue to happen, then pause the print and then run some tests on the extruder:

Verify that the nozzle temperature is correct stable, and was correct when the issue first occurred. Note, if you have a Revo hot end then on early ones the temperature sensing goes wrong after a while. The good ones have blue thermistor wires, the old ones were white.

I've got the "new" 60W heater (blue thermistor wires), so that shouldn't be an issue. I haven't seen any dips / fluctuations in the temperatures either (after I got the warranty replacement for the "white wire" variant or 60w from E3D, way before these extrusion issues started). Looking at the temperature chart in DWC everything is rock solid when the issue occurres

Use M569 to check that the driver is in spread cycle mode, not stealthchop
Send M906 and M913 without parameters to check that RRF thinks it is using the correct motor current

Test extruding and retracting at slow and medium speeds, e.g. 1 to 5mm/sec.

Assuming it's not working properly try sending M906 Exxx (where xxx is the correct motor current) and M913 E100 to check whether this fixes it

I will try all thay out some time this weekend! Haven't had the time during the week.

Exerqtor

I just had time to do the testing, updated to 3.5.0-rc2 on everything, sliced one of the "doomed" models again to verify that it wasn't slicer generated (Orca Slicer 1.9.0 stable has launched since last testing), and surely it fails just like it did a month ago 🤣

Here is what you asked for @dc42, first off M122 B121 & M569 P121.0 while laying down the first layer (not paused) with everything working like it should as a "baseline":

M122 B121
Diagnostics for board 121:
Duet TOOL1LC rev 1.1 or later firmware version 3.5.0-rc.2 (2023-12-14 08:58:51)
Bootloader ID: SAMC21 bootloader version 2.4 (2021-12-10)
All averaging filters OK
Never used RAM 3252, free system stack 89 words
Tasks: Move(3,nWait,0.1%,75) HEAT(2,nWait,16.8%,97) CanAsync(5,nWait,0.0%,54) CanRecv(3,nWait,0.5%,77) CanClock(5,nWait,0.8%,67) ACCEL(3,nWait,0.0%,53) TMC(2,nWait,136.3%,57) MAIN(1,running,616.0%,316) IDLE(0,ready,0.0%,27) AIN(2,delaying,215.9%,114), total 986.4%
Last reset 08:07:59 ago, cause: power up
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 12, reads 24943, writes 12, timeouts 3, DMA errors 0, CC errors 0, failedOp 0x6f, steps req 0 done 106290
Moves scheduled 718, completed 716, in progress 1, hiccups 0, segs 14, step errors 0, maxLate 1 maxPrep 320, maxOverdue 1, maxInc 1, mcErrs 0, gcmErrs 0, ebfmin 0.00 max 1.00
Peak sync jitter -2/10, peak Rx sync delay 218, resyncs 0/0, no timer interrupt scheduled
VIN voltage: min 23.3, current 24.1, max 24.4
MCU temperature: min 37.8C, current 55.1C, max 55.1C
Last sensors broadcast 0x00000012 found 2 166 ticks ago, 0 ordering errs, loop time 0
CAN messages queued 600447, send timeouts 0, received 264383, 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 332, adv 35999/109737
Accelerometer: LIS3DH, status: 00
Inductive sensor: not found
I2C bus errors 0, naks 6, contentions 0, other errors 0
=== Filament sensors ===
Interrupt 5726621 to 0us, poll 4 to 1470us
Driver 0: ok

M569 P121.0
Driver 121.0 runs in reverse, active low enable, mode spreadCycle, ccr 0x00053, toff 3, tblank 0, hstart/hend/hdec 5/0/0, pos 448

And then we have M122 B121 & M569 P121.0 taken while the issue is occurring (not paused):

M122 B121
Diagnostics for board 121:
Duet TOOL1LC rev 1.1 or later firmware version 3.5.0-rc.2 (2023-12-14 08:58:51)
Bootloader ID: SAMC21 bootloader version 2.4 (2021-12-10)
All averaging filters OK
Never used RAM 2724, free system stack 89 words
Tasks: Move(3,nWait,0.3%,71) HEAT(2,nWait,0.4%,97) CanAsync(5,nWait,0.0%,54) CanRecv(3,nWait,0.1%,77) CanClock(5,nWait,0.0%,67) ACCEL(3,nWait,0.0%,53) TMC(2,nWait,3.1%,57) MAIN(1,running,91.2%,316) IDLE(0,ready,0.0%,27) AIN(2,delaying,4.9%,114), total 100.0%
Last reset 08:11:58 ago, cause: power up
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 12, reads 53546, writes 0, timeouts 0, DMA errors 0, CC errors 0, steps req 0 done 282853
Moves scheduled 2822, completed 2822, in progress 0, hiccups 3, segs 36, step errors 0, maxLate 1 maxPrep 833, maxOverdue 3250, maxInc 3250, mcErrs 0, gcmErrs 0, ebfmin -0.96 max inf
Peak sync jitter -2/10, peak Rx sync delay 226, resyncs 0/0, no timer interrupt scheduled
VIN voltage: min 23.9, current 24.0, max 24.3
MCU temperature: min 37.8C, current 56.7C, max 56.9C
Last sensors broadcast 0x00000012 found 2 25 ticks ago, 0 ordering errs, loop time 0
CAN messages queued 4935, send timeouts 0, received 5351, 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 350, adv 36140/74649
Accelerometer: LIS3DH, status: 00
Inductive sensor: not found
I2C bus errors 0, naks 0, contentions 0, other errors 0
=== Filament sensors ===
Interrupt 5726621 to 0us, poll 9 to 1550us
Driver 0: ok

M569 P121.0
Driver 121.0 runs in reverse, active low enable, mode spreadCycle, ccr 0x00053, toff 3, tblank 0, hstart/hend/hdec 5/0/0, pos 168

~~@Exerqtor could it be that somehow the motor current has been reduced to a low value, so that the extruder motor is capable of retracting filament but not capable of overcoming nozzle back pressure?~~

It would be helpful if you could wait for the issue to happen, then pause the print and then run some tests on the extruder:

Verify that the nozzle temperature is correct stable, and was correct when the issue first occurred. Note, if you have a Revo hot end then on early ones the temperature sensing goes wrong after a while. The good ones have blue thermistor wires, the old ones were white.

Screenshot of the temperature chart during warmup, working print & failing print:
alt text
So i would say that's sufficiently stable😄

~~Use M569 to check that the driver is in spread cycle mode, not stealthchop~~

~~Answered above.~~

Send M906 and M913 without parameters to check that RRF thinks it is using the correct motor current

Before pausing while issue is occuring:

M906
Motor current (mA) - X:1750, Y:1750, Z:850, E:650, idle factor 40%

M913
Motor current % of normal - X:100, Y:100, Z:100, E:100

After pausing while issue is occuring:

M906
Motor current (mA) - X:1750, Y:1750, Z:850, E:650, idle factor 40%

M913
Motor current % of normal - X:100, Y:100, Z:100, E:100

Test extruding and retracting at slow and medium speeds, e.g. 1 to 5mm/sec.

Tried extruding 100mm @ 1mm/sec through paneldue while paused : no issues
Tried extruding 100mm @ 5mm/sec through paneldue while paused : no issues

~~Assuming it's not working properly try sending M906 Exxx (where xxx is the correct motor current) and M913 E100 to check whether this fixes it~~

So yeah, that's that 😂

Exerqtor

@dc42 I suspect that didn't give you any more clues as to whats going on? 😓

Exerqtor

@dc42
I just ran the same job file/test after installing 3.5.0-rc3 and it still fails in the same exact manner.

I was touching/feeling the filament right as it enters the PTFE tube as the print progressed, and it stopped pulling it in right about at the 0.65mm (Z-axis height) mark.

Here is a link to the file (same as my previous post just for clarity).

M122 B121 & M569 P121.0 while laying down the first layer (not paused) with everything working like it should:

M122 B121
Diagnostics for board 121:
Duet TOOL1LC rev 1.1 or later firmware version 3.5.0-rc.3 (2024-01-24 17:55:14)
Bootloader ID: SAMC21 bootloader version 2.4 (2021-12-10)
All averaging filters OK
Never used RAM 3072, free system stack 83 words
Tasks: Move(3,nWait 7,0.0%,79) HEAT(2,nWait 6,7.3%,99) CanAsync(5,nWait 4,0.0%,49) CanRecv(3,nWait 1,0.3%,71) CanClock(5,nWait 1,0.4%,59) ACCEL(3,nWait 6,0.0%,53) TMC(2,nWait 6,67.2%,53) MAIN(1,running,97.2%,315) IDLE(0,ready,0.0%,27) AIN(2,delaying,96.9%,112), total 269.3%
Owned mutexes:
Last reset 18:26:14 ago, cause: power up
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 13, reads 26023, writes 13, timeouts 3, DMA errors 0, CC errors 0, failedOp 0x6c, steps req 0 done 83994
Moves scheduled 517, completed 516, in progress 1, hiccups 0, segs 13, step errors 0, maxLate 1 maxPrep 304, maxOverdue 1, maxInc 1, mcErrs 0, gcmErrs 0, ebfmin 0.00 max 1.00
Peak sync jitter -3/10, peak Rx sync delay 219, resyncs 0/0, no timer interrupt scheduled
VIN voltage: min 23.3, current 24.1, max 24.4
MCU temperature: min 34.9C, current 55.2C, max 55.2C
Last sensors broadcast 0x00000012 found 2 98 ticks ago, 0 ordering errs, loop time 0
CAN messages queued 1360939, send timeouts 0, received 598056, 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 330, adv 35701/74648
Accelerometer: LIS3DH, status: 00
I2C bus errors 0, naks 3, contentions 0, other errors 0
=== Filament sensors ===
Interrupt 5726621 to 0us, poll 4 to 1445us
Driver 0: ok

M569 P121.0
Driver 121.0 runs in reverse, active low enable, mode spreadCycle, ccr 0x00053, toff 3, tblank 0, hstart/hend/hdec 5/0/0, pos 267

And then we have M122 B121 & M569 P121.0 taken while the issue is occurring (not paused):

M122 B121
Diagnostics for board 121:
Duet TOOL1LC rev 1.1 or later firmware version 3.5.0-rc.3 (2024-01-24 17:55:14)
Bootloader ID: SAMC21 bootloader version 2.4 (2021-12-10)
All averaging filters OK
Never used RAM 2520, free system stack 83 words
Tasks: Move(3,nWait 7,0.3%,79) HEAT(2,nWait 6,0.4%,99) CanAsync(5,nWait 4,0.0%,49) CanRecv(3,nWait 1,0.1%,71) CanClock(5,nWait 1,0.0%,59) ACCEL(3,nWait 6,0.0%,53) TMC(2,nWait 6,3.5%,53) MAIN(1,running,90.6%,315) IDLE(0,ready,0.0%,27) AIN(2,delaying,5.1%,112), total 100.0%
Owned mutexes:
Last reset 18:30:29 ago, cause: power up
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 13, reads 61284, writes 0, timeouts 0, DMA errors 0, CC errors 0, steps req 0 done 304108
Moves scheduled 2820, completed 2820, in progress 0, hiccups 3, segs 36, step errors 0, maxLate 1 maxPrep 810, maxOverdue 41, maxInc 41, mcErrs 0, gcmErrs 0, ebfmin -0.98 max inf
Peak sync jitter -1/10, peak Rx sync delay 216, resyncs 0/0, no timer interrupt scheduled
VIN voltage: min 23.9, current 24.1, max 24.4
MCU temperature: min 34.9C, current 57.7C, max 57.7C
Last sensors broadcast 0x00000012 found 2 10 ticks ago, 0 ordering errs, loop time 0
CAN messages queued 5254, send timeouts 0, received 5624, 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 339, adv 35800/74648
Accelerometer: LIS3DH, status: 00
I2C bus errors 0, naks 0, contentions 0, other errors 0
=== Filament sensors ===
Interrupt 5726621 to 0us, poll 9 to 1438us
Driver 0: ok

M569 P121.0
Driver 121.0 runs in reverse, active low enable, mode spreadCycle, ccr 0x00053, toff 3, tblank 0, hstart/hend/hdec 5/0/0, pos 440

Screenshot of the temperature chart during warmup, working print & failing print (to show that the temps are stable, the drop off at the end is from when i cancelled the print) :
alt text

Before pausing while issue is occuring:

M906
Motor current (mA) - X:1750, Y:1750, Z:850, E:650, idle factor 40%

M913
Motor current % of normal - X:100, Y:100, Z:100, E:100

After pausing while issue is occuring:

M906
Motor current (mA) - X:1750, Y:1750, Z:850, E:650, idle factor 40%

M913
Motor current % of normal - X:100, Y:100, Z:100, E:100

While paused this time i tried extruding 1mm at the time until it actually started coming molten platic out of the nossle and i had to press "extrude" on PD 9-10 times before anything happened. So it's surely retracting the filament a little bit at a time.

Like i mentioned earlier i'm running 0.45mm FW retraction, and my pause.g don't contain any extruder movement at all. So all the 10mm (ish) of retracted filament has happened before i call for a pause.

dc42

@Exerqtor please test whether the new firmware binaries at https://www.dropbox.com/scl/fo/p0136wx04h8xf6ejwdnn9/h?rlkey=efrfwyb6o5tqid11gustz3uvy&dl=0 fix tihi issue.

Exerqtor

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

@Exerqtor please test whether the new firmware binaries at https://www.dropbox.com/scl/fo/p0136wx04h8xf6ejwdnn9/h?rlkey=efrfwyb6o5tqid11gustz3uvy&dl=0 fix tihi issue.

Just had time to try it, and it's still the exact same behaviour.

M122 B121 & M569 P121.0 while laying down the first layer (not paused) with everything working like it should:

M122 B121
Diagnostics for board 121:
Duet TOOL1LC rev 1.1 or later firmware version 3.5.0-rc.3+ (2024-02-01 12:48:48)
Bootloader ID: SAMC21 bootloader version 2.4 (2021-12-10)
All averaging filters OK
Never used RAM 3048, free system stack 83 words
Tasks: Move(3,nWait 7,0.0%,79) HEAT(2,nWait 6,0.4%,99) CanAsync(5,nWait 4,0.0%,55) CanRecv(3,nWait 1,0.0%,71) CanClock(5,nWait 1,0.0%,59) ACCEL(3,nWait 6,0.0%,53) TMC(2,delaying,3.4%,53) MAIN(1,running,91.2%,315) IDLE(0,ready,0.0%,27) AIN(2,delaying,5.0%,112), total 100.0%
Owned mutexes:
Last reset 00:12:59 ago, cause: VDD brownout
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 13, reads 61969, writes 13, timeouts 0, DMA errors 0, CC errors 0, steps req 0 done 42336
Moves scheduled 155, completed 154, in progress 1, hiccups 3, segs 12, step errors 0, maxLate 1 maxPrep 268, maxOverdue 17, maxInc 17, mcErrs 0, gcmErrs 0, ebfmin 0.00 max 0.99
Peak sync jitter -2/8, peak Rx sync delay 216, resyncs 0/0, no timer interrupt scheduled
VIN voltage: min 23.3, current 24.1, max 24.4
MCU temperature: min 43.5C, current 57.6C, max 57.6C
Last sensors broadcast 0x00000012 found 2 23 ticks ago, 0 ordering errs, loop time 0
CAN messages queued 16201, send timeouts 0, received 7328, 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 328, adv 35675/74645
Accelerometer: LIS3DH, status: 00
I2C bus errors 0, naks 3, contentions 0, other errors 0
=== Filament sensors ===
Interrupt 5726621 to 0us, poll 2 to 1474us
Driver 0: ok

M569 P121.0
Driver 121.0 runs in reverse, active low enable, mode spreadCycle, ccr 0x00053, toff 3, tblank 0, hstart/hend/hdec 5/0/0, pos 1017

And then we have M122 B121 & M569 P121.0 taken while the issue is occurring (not paused):

M122 B121
Diagnostics for board 121:
Duet TOOL1LC rev 1.1 or later firmware version 3.5.0-rc.3+ (2024-02-01 12:48:48)
Bootloader ID: SAMC21 bootloader version 2.4 (2021-12-10)
All averaging filters OK
Never used RAM 2472, free system stack 83 words
Tasks: Move(3,nWait 7,0.3%,79) HEAT(2,nWait 6,0.4%,99) CanAsync(5,nWait 4,0.0%,55) CanRecv(3,nWait 1,0.1%,71) CanClock(5,nWait 1,0.0%,59) ACCEL(3,nWait 6,0.0%,53) TMC(2,nWait 6,3.5%,53) MAIN(1,running,90.6%,315) IDLE(0,ready,0.0%,27) AIN(2,delaying,5.1%,112), total 100.0%
Owned mutexes:
Last reset 00:17:36 ago, cause: VDD brownout
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 13, reads 7102, writes 0, timeouts 0, DMA errors 0, CC errors 0, steps req 0 done 343188
Moves scheduled 2808, completed 2808, in progress 0, hiccups 29, segs 36, step errors 0, maxLate 1 maxPrep 842, maxOverdue 1, maxInc 1, mcErrs 0, gcmErrs 0, ebfmin -0.98 max inf
Peak sync jitter -1/10, peak Rx sync delay 217, resyncs 0/0, no timer interrupt scheduled
VIN voltage: min 23.9, current 24.0, max 24.3
MCU temperature: min 43.5C, current 59.9C, max 60.1C
Last sensors broadcast 0x00000012 found 2 148 ticks ago, 0 ordering errs, loop time 0
CAN messages queued 5716, send timeouts 0, received 5953, 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 357, adv 36225/109301
Accelerometer: LIS3DH, status: 00
I2C bus errors 0, naks 0, contentions 0, other errors 0
=== Filament sensors ===
Interrupt 5726621 to 0us, poll 9 to 1416us
Driver 0: ok

M569 P121.0
Driver 121.0 runs in reverse, active low enable, mode spreadCycle, ccr 0x00053, toff 3, tblank 0, hstart/hend/hdec 5/0/0, pos 776

Screenshot of the temperature chart during warmup, working print & failing print (to show that the temps are stable, the drop off at the end is from when i cancelled the print) :
alt text

dc42

@Exerqtor are you saying that when the issue occurs, the hot end stops heating and cools down?

Last reset 00:17:36 ago, cause: VDD brownout

Looks like the 1LC lost power.

Exerqtor

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

@Exerqtor are you saying that when the issue occurs, the hot end stops heating and cools down?

No nothing happens except it stops feeding filament. The cooling down part in the temp chart is from after I've cancelled the print.

I only included the temp charts to show that the temps are stable (I've updated the "caption" for the chart images on the original posts to reflect on that now).

Last reset 00:17:36 ago, cause: VDD brownout

Looks like the 1LC lost power.

That's from the reset point is from when i rebooted the mainboard after installing 3.5.0-rc3+, I've got relays on the 24v lines controlled with PS_ON.

Exerqtor

@dc42 Got any ideas for things i can do to try helping you narrowing down whats causing this?

Needless to say it renders the machine useless.

Exerqtor

@dc42 I've looked at the commits you did to 3.5-dev yesterday, are these potential solutions for this bug?

dc42

@Exerqtor yes, possibly.

Exerqtor

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

@Exerqtor yes, possibly.

Bad news then i guess, i just installed and tested the 3.5-dev build chrisham built a couple hours ago and tried a test print. And it's the exact same behaviour as before.

M122 & M122 B121 when it was extruding as it should:

2024-02-15 16:16:01 [debug] === Diagnostics ===
2024-02-15 16:16:01 [debug] RepRapFirmware for Duet 3 Mini 5+ version 3.5.0-rc.3+2 (2024-02-15 13:14:48) running on Duet 3 Mini5plus WiFi (standalone mode)
2024-02-15 16:16:01 [debug] Board ID: XNHXF-HR6KL-K65J0-409N2-K9W1Z-RV2MZ
2024-02-15 16:16:01 [debug] Used output buffers: 1 of 40 (40 max)
2024-02-15 16:16:01 [debug] === RTOS ===
2024-02-15 16:16:01 [debug] Static ram: 103264
2024-02-15 16:16:01 [debug] Dynamic ram: 128464 of which 0 recycled
2024-02-15 16:16:01 [debug] Never used RAM 5648, free system stack 139 words
2024-02-15 16:16:01 [debug] Tasks:
2024-02-15 16:16:01 [debug]  NETWORK(1,ready,15.0%,196)
2024-02-15 16:16:01 [debug]  HEAT(3,nWait 6,0.0%,330)
2024-02-15 16:16:01 [debug]  Move(4,nWait 6,0.4%,243)
2024-02-15 16:16:01 [debug]  CanReceiv(6,nWait 1,0.1%,798)
2024-02-15 16:16:01 [debug]  CanSender(5,nWait 7,0.0%,337)
2024-02-15 16:16:01 [debug]  CanClock(7,delaying,0.0%,340)
2024-02-15 16:16:01 [debug]  TMC(4,nWait 6,0.8%,68)
2024-02-15 16:16:01 [debug]  MAIN(1,running,81.8%,577)
2024-02-15 16:16:01 [debug]  IDLE(0,ready,1.0%,30)
2024-02-15 16:16:01 [debug]  AIN(4,delaying,0.9%,260)
2024-02-15 16:16:01 [debug] , total 100.0%
Owned mutexes:
2024-02-15 16:16:01 [debug]  WiFi(NETWORK)
2024-02-15 16:16:01 [debug] === Platform ===
2024-02-15 16:16:01 [debug] Last reset 00:17:18 ago, cause: software
2024-02-15 16:16:01 [debug] Last software reset at 2024-02-15 15:58, reason: User, Gcodes spinning, available RAM 12024, slot 2
2024-02-15 16:16:01 [debug] Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00000000 BFAR 0xe000ed38 SP 0x00000000 Task MAIN Freestk 0 n/a
2024-02-15 16:16:01 [debug] Error status: 0x04
2024-02-15 16:16:01 [debug] Aux0 errors 0,0,0
2024-02-15 16:16:01 [debug] MCU revision 3, ADC conversions started 1039400, completed 1039398, timed out 0, errs 0
2024-02-15 16:16:01 [debug] MCU temperature: min 35.1, current 46.4, max 46.7
2024-02-15 16:16:01 [debug] Supply voltage: min 2.9, current 23.9, max 24.5, under voltage events: 0, over voltage events: 0, power good: yes
2024-02-15 16:16:01 [debug] Heap OK, handles allocated/used 198/33, heap memory allocated/used/recyclable 2048/516/56, gc cycles 249
2024-02-15 16:16:01 [debug] Events: 0 queued, 0 completed
2024-02-15 16:16:01 [debug] Driver 0: standstill, SG min 0, read errors 0, write errors 0, ifcnt 46, reads 54608, writes 46, timeouts 0, DMA errors 0, CC errors 0
2024-02-15 16:16:01 [debug] Driver 1: ok, SG min 0, read errors 0, write errors 0, ifcnt 46, reads 54608, writes 46, timeouts 0, DMA errors 0, CC errors 0
2024-02-15 16:16:01 [debug] Driver 2: ok, SG min 0, read errors 0, write errors 0, ifcnt 25, reads 54628, writes 25, timeouts 0, DMA errors 0, CC errors 0
2024-02-15 16:16:01 [debug] Driver 3: ok, SG min 0, read errors 0, write errors 0, ifcnt 24, reads 54629, writes 24, timeouts 0, DMA errors 0, CC errors 0
2024-02-15 16:16:01 [debug] Driver 4: ok, SG min 0, read errors 0, write errors 0, ifcnt 25, reads 54629, writes 25, timeouts 0, DMA errors 0, CC errors 0
2024-02-15 16:16:01 [debug] Driver 5: not present
2024-02-15 16:16:01 [debug] Driver 6: not present
2024-02-15 16:16:01 [debug] Date/time: 
2024-02-15 16:16:01 [debug] 2024-02-15 16:16:01
2024-02-15 16:16:01 [debug] Cache data hit count 1679802919
2024-02-15 16:16:01 [debug] Slowest loop: 219.43ms; fastest: 0.09ms
2024-02-15 16:16:01 [debug] === Storage ===
Free file entries: 16
2024-02-15 16:16:01 [debug] SD card 0 detected, interface speed: 22.5MBytes/sec
2024-02-15 16:16:01 [debug] SD card longest read time 7.5ms, write time 4.6ms, max retries 0
2024-02-15 16:16:01 [debug] === Move ===
DMs created 83, segments created 16, maxWait 400258ms, 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
2024-02-15 16:16:01 [debug] next step interrupt due in 19 ticks, enabled
2024-02-15 16:16:01 [debug] Moves shaped first try 68, on retry 0, too short 25, wrong shape 1411, maybepossible 4
2024-02-15 16:16:01 [debug] === DDARing 0 ===
Scheduled moves 1676, completed 1654, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 1], CDDA state 3
2024-02-15 16:16:01 [debug] === DDARing 1 ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
2024-02-15 16:16:01 [debug] === Heat ===
2024-02-15 16:16:01 [debug] Bed heaters 0 -1 -1 -1, chamber heaters -1 -1 -1 -1, ordering errs 0
2024-02-15 16:16:01 [debug] Heater 0 is on, I-accum = 0.5
2024-02-15 16:16:01 [debug] Heater 1 is on, I-accum = 0.0
2024-02-15 16:16:01 [debug] === GCodes ===
2024-02-15 16:16:01 [debug] Movement locks held by null, null
2024-02-15 16:16:01 [debug] HTTP is idle in state(s) 0
2024-02-15 16:16:01 [debug] Telnet is idle in state(s) 0
2024-02-15 16:16:01 [debug] File is idle in state(s) 3
2024-02-15 16:16:01 [debug] USB is idle in state(s) 0
2024-02-15 16:16:01 [debug] Aux is idle in state(s) 0
2024-02-15 16:16:01 [debug] Trigger is idle in state(s) 0
2024-02-15 16:16:01 [debug] Queue is idle in state(s) 0
2024-02-15 16:16:01 [debug] LCD is idle in state(s) 0
2024-02-15 16:16:01 [debug] SBC is idle in state(s) 0
2024-02-15 16:16:01 [debug] Daemon is doing "G4 P250" in state(s) 0 0, running macro
2024-02-15 16:16:01 [debug] Aux2 is idle in state(s) 0
2024-02-15 16:16:01 [debug] Autopause is idle in state(s) 0
2024-02-15 16:16:01 [debug] File2 is idle in state(s) 0, sync state 1
2024-02-15 16:16:01 [debug] Queue2 is idle in state(s) 0
2024-02-15 16:16:01 [debug] Q0 segments left 4, axes/extruders owned 0x0000807
2024-02-15 16:16:01 [debug] Code queue 0 is empty
2024-02-15 16:16:01 [debug] Q1 segments left 0, axes/extruders owned 0x0000000
2024-02-15 16:16:01 [debug] Code queue 1 is empty
2024-02-15 16:16:01 [debug] === Filament sensors ===
check 0 clear 0
2024-02-15 16:16:01 [debug] Extruder 0 sensor: no filament
2024-02-15 16:16:01 [debug] === CAN ===
2024-02-15 16:16:01 [debug] Messages queued 10994, received 21506, lost 0, errs 1229, boc 0
2024-02-15 16:16:01 [debug] Longest wait 2ms for reply type 6031, peak Tx sync delay 45006, free buffers 26 (min 25), ts 5195/5193/0
2024-02-15 16:16:01 [debug] Tx timeouts 0,0,1,0,0,0 last cancelled message type 30 dest 127
2024-02-15 16:16:01 [debug] === Network ===
2024-02-15 16:16:01 [debug] Slowest loop: 13.08ms; fastest: 0.00ms
2024-02-15 16:16:01 [debug] Responder states:
2024-02-15 16:16:01 [debug]  MQTT(0)
2024-02-15 16:16:01 [debug]  HTTP(2)
2024-02-15 16:16:01 [debug]  HTTP(0)
2024-02-15 16:16:01 [debug]  HTTP(0)
2024-02-15 16:16:01 [debug]  HTTP(0)
2024-02-15 16:16:01 [debug]  FTP(0)
2024-02-15 16:16:01 [debug]  Telnet(0)
2024-02-15 16:16:01 [debug] HTTP sessions: 1 of 8
2024-02-15 16:16:01 [debug] === WiFi ===
Interface state: active
Module is connected to access point 
Failed messages: pending 0, notrdy 0, noresp 0
2024-02-15 16:16:01 [debug] Firmware version 2.1beta6
2024-02-15 16:16:01 [debug] MAC address c4:5b:be:ce:91:93
2024-02-15 16:16:01 [debug] Module reset reason: Power up, Vcc 3.38, flash size 2097152, free heap 36456
2024-02-15 16:16:01 [debug] WiFi IP address 192.168.10.x
2024-02-15 16:16:01 [debug] Signal strength -48dBm, channel 6, mode 802.11n, reconnections 0
2024-02-15 16:16:01 [debug] Clock register 00002001
2024-02-15 16:16:01 [debug] Socket states:
2024-02-15 16:16:01 [debug]  0
2024-02-15 16:16:01 [debug]  0
2024-02-15 16:16:01 [debug]  0
2024-02-15 16:16:01 [debug]  0
2024-02-15 16:16:01 [debug]  0
2024-02-15 16:16:01 [debug]  0
2024-02-15 16:16:01 [debug]  0
2024-02-15 16:16:01 [debug]  0
2024-02-15 16:16:04 [debug] Diagnostics for board 121:
2024-02-15 16:16:04 [debug] Duet TOOL1LC rev 1.1 or later firmware version 3.5.0-rc.3+ (2024-02-15 13:22:28)
Bootloader ID: SAMC21 bootloader version 2.4 (2021-12-10)
All averaging filters OK
2024-02-15 16:16:04 [debug] Never used RAM 3608, free system stack 87 words
Tasks: Move(3,nWait 7,0.0%,91) HEAT(2,nWait 6,0.4%,99) CanAsync(5,nWait 4,0.0%,51) CanRecv(3,nWait 1,0.0%,73) CanClock(5,nWait 1,0.0%,61) ACCEL(3,nWait 6,0.0%,53) TMC(2,nWait 6,3.4%,53) MAIN(1,running,91.2%,317) IDLE(0,ready,0.0%,27) AIN(2,delaying,4.9%,112), total 100.0%
Owned mutexes:
Last reset 00:17:21 ago, cause: power up
2024-02-15 16:16:04 [debug] Last software reset data not available
2024-02-15 16:16:04 [debug] Driver 0: pos 0, 568.8 steps/mm, ok, SG min 0, read errors 0, write errors 0, ifcnt 12, reads 61756, writes 12, timeouts 0, DMA errors 0, CC errors 0, steps req 0 done 221092
2024-02-15 16:16:04 [debug] Moves scheduled 1506, completed 1505, in progress 1, hiccups 8, segs 18, step errors 0, maxLate 0 maxPrep 296, maxOverdue 44, maxInc 44, mcErrs 0, gcmErrs 0, ebfmin 0.00 max 1.00
Peak sync jitter -2/9, peak Rx sync delay 214, resyncs 0/0, no timer interrupt scheduled
VIN voltage: min 23.3, current 24.1, max 24.4
MCU temperature: min 39.7C, current 55.6C, max 55.6C
2024-02-15 16:16:04 [debug] Last sensors broadcast 0x00000012 found 2 1 ticks ago, 0 ordering errs, loop time 1
CAN messages queued 21590, send timeouts 0, received 11048, 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 338, adv 35679/105203
2024-02-15 16:16:04 [debug] Accelerometer: LIS3DH, status: 00
I2C bus errors 0, naks 3, contentions 0, other errors 0
=== Filament sensors ===
Interrupt 5726621 to 0us, poll 4 to 1481us
Driver 0: ok

M122 & M122 B121 when it had stopped extruding:

2024-02-15 16:18:11 [debug] === Diagnostics ===
2024-02-15 16:18:11 [debug] RepRapFirmware for Duet 3 Mini 5+ version 3.5.0-rc.3+2 (2024-02-15 13:14:48) running on Duet 3 Mini5plus WiFi (standalone mode)
2024-02-15 16:18:11 [debug] Board ID: XNHXF-HR6KL-K65J0-409N2-K9W1Z-RV2MZ
2024-02-15 16:18:11 [debug] Used output buffers: 1 of 40 (40 max)
2024-02-15 16:18:11 [debug] === RTOS ===
2024-02-15 16:18:11 [debug] Static ram: 103264
2024-02-15 16:18:11 [debug] Dynamic ram: 128464 of which 0 recycled
2024-02-15 16:18:11 [debug] Never used RAM 5120, free system stack 139 words
2024-02-15 16:18:11 [debug] Tasks:
2024-02-15 16:18:11 [debug]  NETWORK(1,ready,17.5%,196)
2024-02-15 16:18:11 [debug]  HEAT(3,nWait 6,0.0%,330)
2024-02-15 16:18:11 [debug]  Move(4,nWait 6,2.4%,242)
2024-02-15 16:18:11 [debug]  CanReceiv(6,nWait 1,0.1%,798)
2024-02-15 16:18:11 [debug]  CanSender(5,nWait 7,0.0%,337)
2024-02-15 16:18:11 [debug]  CanClock(7,delaying,0.0%,340)
2024-02-15 16:18:11 [debug]  TMC(4,nWait 6,0.9%,68)
2024-02-15 16:18:11 [debug]  MAIN(1,running,77.2%,577)
2024-02-15 16:18:11 [debug]  IDLE(0,ready,0.9%,30)
2024-02-15 16:18:11 [debug]  AIN(4,delaying,0.9%,260)
2024-02-15 16:18:11 [debug] , total 100.0%
Owned mutexes:
2024-02-15 16:18:11 [debug] === Platform ===
2024-02-15 16:18:11 [debug] Last reset 00:19:29 ago, cause: software
2024-02-15 16:18:11 [debug] Last software reset at 2024-02-15 15:58, reason: User, Gcodes spinning, available RAM 12024, slot 2
2024-02-15 16:18:11 [debug] Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00000000 BFAR 0xe000ed38 SP 0x00000000 Task MAIN Freestk 0 n/a
2024-02-15 16:18:11 [debug] Error status: 0x04
2024-02-15 16:18:11 [debug] Aux0 errors 0,0,0
2024-02-15 16:18:11 [debug] MCU revision 3, ADC conversions started 1169660, completed 1169659, timed out 0, errs 0
2024-02-15 16:18:11 [debug] MCU temperature: min 46.0, current 46.4, max 46.6
2024-02-15 16:18:11 [debug] Supply voltage: min 23.7, current 23.7, max 24.3, under voltage events: 0, over voltage events: 0, power good: yes
2024-02-15 16:18:11 [debug] Heap OK, handles allocated/used 198/33, heap memory allocated/used/recyclable 2048/708/248, gc cycles 277
2024-02-15 16:18:11 [debug] Events: 0 queued, 0 completed
2024-02-15 16:18:11 [debug] Driver 0: ok, SG min 0, read errors 0, write errors 0, ifcnt 46, reads 6852, writes 0, timeouts 0, DMA errors 0, CC errors 0
2024-02-15 16:18:11 [debug] Driver 1: ok, SG min 0, read errors 0, write errors 0, ifcnt 46, reads 6852, writes 0, timeouts 0, DMA errors 0, CC errors 0
2024-02-15 16:18:11 [debug] Driver 2: ok, SG min 0, read errors 0, write errors 0, ifcnt 25, reads 6853, writes 0, timeouts 0, DMA errors 0, CC errors 0
2024-02-15 16:18:11 [debug] Driver 3: ok, SG min 0, read errors 0, write errors 0, ifcnt 24, reads 6852, writes 0, timeouts 0, DMA errors 0, CC errors 0
2024-02-15 16:18:11 [debug] Driver 4: ok, SG min 0, read errors 0, write errors 0, ifcnt 25, reads 6853, writes 0, timeouts 0, DMA errors 0, CC errors 0
2024-02-15 16:18:11 [debug] Driver 5: not present
2024-02-15 16:18:11 [debug] Driver 6: not present
2024-02-15 16:18:11 [debug] Date/time: 
2024-02-15 16:18:11 [debug] 2024-02-15 16:18:11
2024-02-15 16:18:11 [debug] Cache data hit count 1862287218
2024-02-15 16:18:11 [debug] Slowest loop: 40.78ms; fastest: 0.14ms
2024-02-15 16:18:11 [debug] === Storage ===
Free file entries: 16
2024-02-15 16:18:11 [debug] SD card 0 detected, interface speed: 22.5MBytes/sec
2024-02-15 16:18:11 [debug] SD card longest read time 9.1ms, write time 4.8ms, max retries 0
2024-02-15 16:18:11 [debug] === Move ===
DMs created 83, segments created 38, maxWait 852ms, 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
2024-02-15 16:18:11 [debug] next step interrupt due in 26 ticks, enabled
2024-02-15 16:18:11 [debug] Moves shaped first try 267, on retry 62, too short 102, wrong shape 1241, maybepossible 57
2024-02-15 16:18:11 [debug] === DDARing 0 ===
Scheduled moves 4017, completed 3977, hiccups 0, stepErrors 0, LaErrors 2, Underruns [0, 0, 0], CDDA state 3
2024-02-15 16:18:11 [debug] === DDARing 1 ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
2024-02-15 16:18:11 [debug] === Heat ===
2024-02-15 16:18:11 [debug] Bed heaters 0 -1 -1 -1, chamber heaters -1 -1 -1 -1, ordering errs 0
2024-02-15 16:18:11 [debug] Heater 0 is on, I-accum = 0.5
2024-02-15 16:18:11 [debug] Heater 1 is on, I-accum = 0.0
2024-02-15 16:18:11 [debug] === GCodes ===
2024-02-15 16:18:11 [debug] Movement locks held by null, null
2024-02-15 16:18:11 [debug] HTTP is idle in state(s) 0
2024-02-15 16:18:11 [debug] Telnet is idle in state(s) 0
2024-02-15 16:18:11 [debug] File is doing "G1 X213.608 Y214.933 E.00193" in state(s) 0
2024-02-15 16:18:11 [debug] USB is idle in state(s) 0
2024-02-15 16:18:11 [debug] Aux is idle in state(s) 0
2024-02-15 16:18:11 [debug] Trigger is idle in state(s) 0
2024-02-15 16:18:11 [debug] Queue is idle in state(s) 0
2024-02-15 16:18:11 [debug] LCD is idle in state(s) 0
2024-02-15 16:18:11 [debug] SBC is idle in state(s) 0
2024-02-15 16:18:11 [debug] Daemon is doing "G4 P250" in state(s) 0 0, running macro
2024-02-15 16:18:11 [debug] Aux2 is idle in state(s) 0
2024-02-15 16:18:11 [debug] Autopause is idle in state(s) 0
2024-02-15 16:18:11 [debug] File2 is idle in state(s) 0, sync state 1
2024-02-15 16:18:11 [debug] Queue2 is idle in state(s) 0
2024-02-15 16:18:11 [debug] Q0 segments left 1, axes/extruders owned 0x0000807
2024-02-15 16:18:11 [debug] Code queue 0 is empty
2024-02-15 16:18:11 [debug] Q1 segments left 0, axes/extruders owned 0x0000000
2024-02-15 16:18:11 [debug] Code queue 1 is empty
2024-02-15 16:18:11 [debug] === Filament sensors ===
check 0 clear 0
2024-02-15 16:18:11 [debug] Extruder 0 sensor: no filament
2024-02-15 16:18:11 [debug] === CAN ===
2024-02-15 16:18:11 [debug] Messages queued 3206, received 2701, lost 0, errs 0, boc 0
2024-02-15 16:18:11 [debug] Longest wait 6ms for reply type 6024, peak Tx sync delay 9, free buffers 26 (min 25), ts 651/651/0
2024-02-15 16:18:11 [debug] Tx timeouts 0,0,0,0,0,0
2024-02-15 16:18:11 [debug] === Network ===
2024-02-15 16:18:11 [debug] Slowest loop: 19.53ms; fastest: 0.06ms
2024-02-15 16:18:11 [debug] Responder states:
2024-02-15 16:18:11 [debug]  MQTT(0)
2024-02-15 16:18:11 [debug]  HTTP(0)
2024-02-15 16:18:11 [debug]  HTTP(0)
2024-02-15 16:18:11 [debug]  HTTP(0)
2024-02-15 16:18:11 [debug]  HTTP(0)
2024-02-15 16:18:11 [debug]  FTP(0)
2024-02-15 16:18:11 [debug]  Telnet(0)
2024-02-15 16:18:11 [debug] HTTP sessions: 1 of 8
2024-02-15 16:18:11 [debug] === WiFi ===
Interface state: active
Module is connected to access point 
Failed messages: pending 0, notrdy 0, noresp 0
2024-02-15 16:18:11 [debug] Firmware version 2.1beta6
2024-02-15 16:18:11 [debug] MAC address c4:5b:be:ce:91:93
2024-02-15 16:18:11 [debug] Module reset reason: Power up, Vcc 3.38, flash size 2097152, free heap 43160
2024-02-15 16:18:11 [debug] WiFi IP address 192.168.10.x
2024-02-15 16:18:11 [debug] Signal strength -49dBm, channel 6, mode 802.11n, reconnections 0
2024-02-15 16:18:11 [debug] Clock register 00002001
2024-02-15 16:18:11 [debug] Socket states:
2024-02-15 16:18:11 [debug]  0
2024-02-15 16:18:11 [debug]  0
2024-02-15 16:18:11 [debug]  0
2024-02-15 16:18:11 [debug]  0
2024-02-15 16:18:11 [debug]  0
2024-02-15 16:18:11 [debug]  0
2024-02-15 16:18:11 [debug]  0
2024-02-15 16:18:11 [debug]  0
2024-02-15 16:18:14 [debug] Diagnostics for board 121:
2024-02-15 16:18:14 [debug] Duet TOOL1LC rev 1.1 or later firmware version 3.5.0-rc.3+ (2024-02-15 13:22:28)
Bootloader ID: SAMC21 bootloader version 2.4 (2021-12-10)
All averaging filters OK

(Had to grab them from the debug file because DWC disconnected and i lost the console printout).

dc42

@Exerqtor thanks for testing this again. I'm puzzles that ebfmax is showing as zero in the Move section of both M122 reports. After doing some printing, it's normally close to 1.0.

Exerqtor

@dc42 No problem, yeah i have no idea what could be the cause 😓

Exerqtor

@dc42 i saw you added some more debug features for the expansionboard firmware on friday, do you have a build with that i could try to run? Or do you need to put some more things in it first?

dc42

@Exerqtor you are very welcome to try the new Duet 3 Mini TOOL1LC and files at https://www.dropbox.com/scl/fo/p0136wx04h8xf6ejwdnn9/h?rlkey=efrfwyb6o5tqid11gustz3uvy&dl=0. The changes clear up some issues I was having with debug output, caused by variables that were output even when they should not have been used in the current context. I don't think they should change the printing behaviour, but I could be wrong.

Exerqtor

@dc42 I'll try it this evening, maybe it will give some more insight into whats causing the stops (one might hope).