Header extruder not headting at expected rate

[Xuid]

Hello All,

Yesterday, I updated Klipper to version “v.0.10.0-646” from “v.0.10.0-426” have have encounter the following two issues in the past 24 hours.

1. Transition to shutdown state: Timeout on wait for ‘tmcuart_response’ response
2. Heater extruder not heating at expected rate (see more below)

Both of these issue have occurred a few hours into the print. Some things to note:

1. The hardware has not changed prior to this issues occurring. Configuration: SkGo2, BitTreeTech Octopus and Raspberry Pi 4.
2. With Klipper v.0.10.0-426 prints of 53+ hours have occurred without any issue.
3. Mainsail and Moonraker have been updated to the latest version.
4. I DID NOT not create a new FW image for the BitTreeTech Octopus board.
5. Printing with PLA at 40-50 mm/s with a volcano nozzle.
6. Boards are well ventilated and running cool.

Looking at the log snippet below indicates a “potential” false failure for the temperature seems to be inline with expected values.

Stats 46982.7: gcodein=0  mcu: mcu_awake=0.010 mcu_task_avg=0.000014 mcu_task_stddev=0.000035 bytes_write=107933786 bytes_read=26383581 bytes_retransmit=9 bytes_invalid=0 send_seq=2291078 receive_seq=2291077 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=13 stalled_bytes=0 freq=180000684 sd_pos=1387188 heater_bed: target=60 temp=60.0 pwm=0.196 sysload=0.26 cputime=9429.333 memavail=7685296 print_time=46995.054 buffer_time=2.098 print_stall=0 extruder: target=205 temp=205.0 pwm=0.443
Stats 46985.6: gcodein=0  mcu: mcu_awake=0.007 mcu_task_avg=0.000013 mcu_task_stddev=0.000036 bytes_write=107940581 bytes_read=26384718 bytes_retransmit=9 bytes_invalid=0 send_seq=2291201 receive_seq=2291201 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=55 stalled_bytes=0 freq=180000684 sd_pos=1388012 heater_bed: target=60 temp=60.0 pwm=0.160 sysload=0.32 cputime=9432.078 memavail=7684736 print_time=46998.083 buffer_time=2.209 print_stall=0 extruder: target=205 temp=205.0 pwm=0.458
Stats 46988.6: gcodein=0  mcu: mcu_awake=0.007 mcu_task_avg=0.000013 mcu_task_stddev=0.000036 bytes_write=107948537 bytes_read=26385960 bytes_retransmit=9 bytes_invalid=0 send_seq=2291346 receive_seq=2291346 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=28 stalled_bytes=0 freq=180000684 sd_pos=1389071 heater_bed: target=60 temp=60.0 pwm=0.119 sysload=0.32 cputime=9434.775 memavail=7684736 print_time=47001.077 buffer_time=2.181 print_stall=0 extruder: target=205 temp=205.0 pwm=0.458
Stats 46992.4: gcodein=0  mcu: mcu_awake=0.010 mcu_task_avg=0.000014 mcu_task_stddev=0.000031 bytes_write=107958258 bytes_read=26387451 bytes_retransmit=9 bytes_invalid=0 send_seq=2291523 receive_seq=2291523 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=35 stalled_bytes=0 freq=180000681 sd_pos=1390278 heater_bed: target=60 temp=60.0 pwm=0.123 sysload=0.37 cputime=9438.159 memavail=7684736 print_time=47004.794 buffer_time=2.173 print_stall=0 extruder: target=205 temp=204.8 pwm=0.489
Stats 47001.5: gcodein=0  mcu: mcu_awake=0.006 mcu_task_avg=0.000012 mcu_task_stddev=0.000011 bytes_write=107980182 bytes_read=26390507 bytes_retransmit=9 bytes_invalid=0 send_seq=2291908 receive_seq=2291908 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=15 stalled_bytes=0 freq=180000682 sd_pos=1392629 heater_bed: target=60 temp=60.0 pwm=0.339 sysload=0.47 cputime=9447.301 memavail=7683224 print_time=47013.222 buffer_time=1.426 print_stall=0 extruder: target=205 temp=204.9 pwm=0.416
Stats 47004.6: gcodein=0  mcu: mcu_awake=0.006 mcu_task_avg=0.000012 mcu_task_stddev=0.000011 bytes_write=107992306 bytes_read=26391866 bytes_retransmit=9 bytes_invalid=0 send_seq=2292113 receive_seq=2292113 retransmit_seq=2 srtt=0.001 rttvar=0.000 rto=0.025 ready_bytes=33 stalled_bytes=0 freq=180000678 sd_pos=1393892 heater_bed: target=60 temp=60.0 pwm=0.251 sysload=0.47 cputime=9450.436 memavail=7680292 print_time=47016.978 buffer_time=2.137 print_stall=0 extruder: target=205 temp=205.0 pwm=0.465
Stats 47007.0: gcodein=0  mcu: mcu_awake=0.010 mcu_task_avg=0.000013 mcu_task_stddev=0.000020 bytes_write=107997108 bytes_read=26393034 bytes_retransmit=9 bytes_invalid=0 send_seq=2292212 receive_seq=2292212 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=31 stalled_bytes=0 freq=180000674 sd_pos=1394420 heater_bed: target=60 temp=60.0 pwm=0.198 sysload=0.51 cputime=9452.788 memavail=7678940 print_time=47019.355 buffer_time=2.073 print_stall=0 extruder: target=205 temp=205.0 pwm=0.465
Stats 47008.0: gcodein=0  mcu: mcu_awake=0.010 mcu_task_avg=0.000013 mcu_task_stddev=0.000020 bytes_write=108001413 bytes_read=26393782 bytes_retransmit=9 bytes_invalid=0 send_seq=2292296 receive_seq=2292296 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=180000662 sd_pos=1395048 heater_bed: target=60 temp=60.0 pwm=0.151 sysload=0.51 cputime=9452.956 memavail=7678940 print_time=47020.466 buffer_time=2.185 print_stall=0 extruder: target=205 temp=205.0 pwm=0.452
Stats 47010.7: gcodein=0  mcu: mcu_awake=0.008 mcu_task_avg=0.000013 mcu_task_stddev=0.000024 bytes_write=108009276 bytes_read=26394985 bytes_retransmit=9 bytes_invalid=0 send_seq=2292437 receive_seq=2292436 retransmit_seq=2 srtt=0.001 rttvar=0.000 rto=0.025 ready_bytes=13 stalled_bytes=0 freq=180000777 sd_pos=1396093 heater_bed: target=60 temp=60.0 pwm=0.225 sysload=0.55 cputime=9455.589 memavail=7676672 print_time=47023.344 buffer_time=2.399 print_stall=0 extruder: target=205 temp=204.9 pwm=0.461
Stats 47026.4: gcodein=0  mcu: mcu_awake=0.006 mcu_task_avg=0.000012 mcu_task_stddev=0.000011 bytes_write=108042786 bytes_read=26399630 bytes_retransmit=9 bytes_invalid=0 send_seq=2293011 receive_seq=2293011 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=17 stalled_bytes=0 freq=180000842 sd_pos=1400049 heater_bed: target=60 temp=60.0 pwm=0.314 sysload=0.65 cputime=9471.466 memavail=7674352 print_time=47038.777 buffer_time=2.160 print_stall=0 extruder: target=205 temp=204.9 pwm=0.473
Heater extruder not heating at expected rate
Transition to shutdown state: Heater extruder not heating at expected rate
See the 'verify_heater' section in docs/Config_Reference.md
for the parameters that control this check.

Lastly, my configuration file DOES NOT contain a [verify_header] section.

Prior to downgrading klipper to v.0.10.0-426, I thought I might check into the group to see if this is a user issue (e.g., I need to update my FW image) or something else.

Attached is a zipped up klippy log file that records the two issues observed, as well as, my configuration. In the log file, one will find information regarding:

1. The intial “tmcuart_response” timeout.
2. A successful print.
3. Heater extruder not heating at expected rate
   klippy.zip (3.6 MB)

Thanks ahead of time for any insights on what might be happening and how to address it.

Regards,
Stephen

[EddyMI3D]

Hello @Xuid !

Have you seen this?

Heater extruder not heating at expected rate - another one

I am having a problem with a print failing with “Heater extruder not heating at expected rate” at the same point in the print. I have done a PID calibration with no luck. Checked that the part cooling fan does not effect the temperature. Resliced the file with the print stopping at the same point. Because it happens at the same space, I don’t think it is an intermitted hardware problem. I have resliced the file with the same results. I also sliced it with Cura (used PrusaSlicer originally) and…

You also may check the hardware: The cabling, the connectors and the output voltage of the power supply.

[Xuid]

Hello EddyMI3D,

Thanks for replying. Yes, I did examine that discussion temporarily ruled that out as an issue for the following reasons:

1. The blower fan was on for away.
2. The hot end it a volcano nozzle with a silicon sock
3. The log temperatures indicate +/- 0.2 degrees from the desired temperature

I will re-examine the cables looking for “intermittent” connections (both with the cables and connectors), though I don’t expect to find anything.

With regards to the power supply, that got me thinking. Being that the prints I am doing consume the entire 310x310 build surface, I most likely have too high of a current for my stepper motors (6 months ago I increased it). Being that the control board and stepper motors are running off of the same power supply, there might be some “ground bounce” issues, which could impact these two observed issues.

That said, I was “hoping” that the log file would be of help, but I didn’t see anything that would be useful.

Are there any setting I could set to add addition verbosity to the log files.

Side Note
I was “hoping” that someone would say, you need to update your FW, but that didn’t happen. Being that these two issues seem to happen “randomly” after 1-2 hours, debugging this is going to be fun. That said, they both seem to fail when the print head was in the center of the build surface.

Over the next week or so, I will be debugging this issue and will be sure to let you know what I find for at this time, I don’t trust my 3D printer.

[EddyMI3D]

@Xuid

I was “hoping” that someone would say, you need to update your FW, but that didn’t happen

You can do it anyway without anyone suggesting it.

[Xuid]

@EddyMI3D Thanks for be a sounding board. Yes, it is clear to me that this an issue of one for no one else is observing what I have encountered. Going forward, I will update this thread regarding what I am doing to isolate the root issue (for future readers).

Update

1. I update the FW image and lowered the current to the stepper motors by 20%.
   • The thought here was to eliminate any FW / Klipper out-of-sync issues and to lower the power consumption.
2. Reran the print

After about 90 minutes the “Heater Extruder not heating” issue occurred. Looking over the logs all of the temperatures readings looks good.

Next Steps
I am assuming that there might be an intermittent open in the wires for the thermostat. Because of this I will be replacing these wire and re-running the print.

In addition, I will be modifying the klipper code to produce a more detail report regarding the temperature read and expected temperatures.

[Xuid]

After replacing the wiring and changing the sensor port, the issue still remained. So I modified the verify_heater.py script to produce debugging information when the error condition is tripped. In doing so, it was discovered that at times the temperature being returned back is zero (0). This zero temperature reading occurs about 90 minutes into the print.

Upon further investigation, it looks like get_temp (heater.py) returns back a zero temperature if the last_temp_time is less then the print_time. This is the cause of of all of my issues.

The question is: Why does this condition get tripped?

Next steps:

1. Create a new Raspberry Pi4 image and install a clean version of v.0.10.0-646.

• I have read that the could be CPU load issues. Since since this linux image had lots of random content installed over the years, it needed to be clean up.

2. If the issue still remains, then I will install version v.0.10.0-426 to validate that this condition exists with this older version of code.

[EddyMI3D]

On what host do you run Kipper?
Maybe there is a plugin that produces the issue?

[Xuid]

Update: Issue Resolved

After re-imaging the Raspberry Pi and installing Klipper, the print completed successfully.

Details
On a Raspberry Pi 4 (8G), I installed:

1. OS 64 Lite - (upgraded all the existing image packages)
2. Klipper on Python 3
3. Klipper FW on the BigTreeTech Octopus V1.1 control board
4. Moonraker and Mainsail

Note: The Raspberry PI is only used for klipper. At one point, it had OctoPi communicated to Marlin, but I have since moved away from this configuration.

Thank you @EddyMI3D for all of your prodding questions. It truly help in isolating the issue.