Communication timeout during homing probe + Extrude below Min Temp Errors

[dJOS_500]

Basic Information:

Printer Model: Mega Zero - Voron Edition
MCU / Printerboard: BTT SKR2 / U2C + EBB36 CanBus
klippy.log.zip (1.7 MB)

Describe your issue:

EDIT: this is actually a “Communication timeout during homing probe” error - I just hadn’t noticed the message disappearing down the list.

My Printer was printing fine, a job finished and now I cant print anything as the jobs all fail with “Extruder Temp out of Range”, and Im completely confused. I’ve upgraded Klipper et al, checked my gcode from SS slicer (below), power cycled all boards, and I;ve manually confirmed I can hit any extruder temp I want…

But for some reason, Klipper is skipping over the section that raises the extruder temp from 150c to (in this case) 235c and just tries to start printing.

;TYPE:Custom
;Klipper Config
STATUS_READY
SKEW_PROFILE LOAD=my_skew_profile
G21 ;metric values
G90 ;absolute positioning
M82 ;set extruder to absolute mode

M117 Homing X/Y ...
STATUS_HOMING
G28 ;home all axis
G28 X0 Y0 ;move X/Y to min endstops
G28 X Y ;move extruder back to front left corner
M107 ;start with the fan off

M117 Bed Heating ...
STATUS_HEATING
;Section to heat bed
M104 S150 ;Warm Up HE to 150c to speed up process
M190 S70;wait for bed temperature
M117 Bed Settling ...
G4 P60000 ;Wait 1 minute to let bed temps settle
M400 ;Wait for delay

M117 Auto Gantry Level ...
STATUS_LEVELING
G28 ;home all axis
Z_TILT_ADJUST ;Z Axis Level

M117 Adaptive Mesh ...
STATUS_MESHING
BED_MESH_CALIBRATE ;Auto Bed Level

G28 X0 Y0 ;move X/Y to min endstops
G28 X Y ;move extruder back to front left corner
G1 Z15.0 F300 ;move the platform down 15mm

;Section to heat hot end
M117 Ext Heating ...
STATUS_HEATING
M109 T0 S235 ;wait for hotend temperature

M117 Adaptive Purge ...
STATUS_PRINTING
ADAPTIVE_PURGE

[dJOS_500]

Just to add to my confusion, all of my Filament load / unload macros still work perfectly.

[EddyMI3D]

Where is this T0 coming from?

@dJOS_500

M109 T0 S235 ;wait for hotend temperature

Do you have multiple extruders?

[dJOS_500]

No, just the one extruder, it’s coming from SuperSlicer:

Start Gcode:

;Klipper Config
STATUS_READY
SKEW_PROFILE LOAD=my_skew_profile
G21 ;metric values
G90 ;absolute positioning
M82 ;set extruder to absolute mode

M117 Homing X/Y ...
STATUS_HOMING
G28 ;home all axis
G28 X0 Y0 ;move X/Y to min endstops
G28 X Y ;move extruder back to front left corner
M107 ;start with the fan off

M117 Bed Heating ...
STATUS_HEATING
;Section to heat bed
M104 S150 ;Warm Up HE to 150c to speed up process
M190 S[first_layer_bed_temperature];wait for bed temperature
M117 Bed Settling ...
G4 P60000 ;Wait 1 minute to let bed temps settle
M400 ;Wait for delay

M117 Auto Gantry Level ...
STATUS_LEVELING
G28 ;home all axis
Z_TILT_ADJUST ;Z Axis Level

M117 Adaptive Mesh ...
STATUS_MESHING
BED_MESH_CALIBRATE ;Auto Bed Level

G28 X0 Y0 ;move X/Y to min endstops
G28 X Y ;move extruder back to front left corner
G1 Z15.0 F[travel_speed] ;move the platform down 15mm

;Section to heat hot end
M117 Ext Heating ...
STATUS_HEATING
M109 T0 S{first_layer_temperature[0]} ;wait for hotend temperature

M117 Adaptive Purge ...
STATUS_PRINTING
ADAPTIVE_PURGE

M117 Printing...
STATUS_PRINTING

I’ve had my config like this for a really long time - so long in fact that I dont recall why the “T0” is specified.

[EddyMI3D]

@dJOS_500

;Section to heat hot end
M117 Ext Heating ...
STATUS_HEATING
M109 T0 S{first_layer_temperature[0]} ;wait for hotend temperature

That appears like a sequence in the slicer’s Start Gcode Scrips.
The only thing SuperSlicer does is to insert the temperature value {first_layer_temperature[0]}. The T0 is already there.

So, what happens when you enter

M109 T0 S235

into the terminal?

[dJOS_500]

@EddyMI3D

So, what happens when you enter

M109 T0 S235

into the terminal?

Exactly what I’d expect, It heats up the extruder - the behaviour is identical to “M109 S235”:

I am going to remove the “T0” from my Start Gcode just to see what happens.

[dJOS_500]

And that made no difference.

EDIT: actually this time I got a CanBus comms timeout as well … Hmmmm

[dJOS_500]

I think this issue has come back.

Communication timeout during homing probe

Changed TRSYNC_TIMEOUT value in “/home/pi/klipper/klippy/mcu.py” file from 0.025 to 0.050, i.e. was “TRSYNC_TIMEOUT = 0.025”, and became “TRSYNC_TIMEOUT = 0.050”, and the error “Communication timeout during homing probe” disappeared, and BL-Touch now works as it should. Only here there is one “BUT”, Mainsail in the update manager shows that the Klipper files are dirty, i.e. do not correspond to the original, and as I understand it, the next time Klipper is updated, the value of TRSYNC_TIMEOUT w…

EDIT: yep, my TRSYNC_TIMEOUT value in mcu.py had been reverted to 0.025 after the upgrade.

I’m trying again after changing it to the higher value.

@koconnor any chance you could please look into this issue?

I’ve even cranked the timeout settings all the way up to 0.5, and I’m getting nowhere.

TRSYNC_TIMEOUT = 0.500
TRSYNC_SINGLE_MCU_TIMEOUT = 0.500

[dJOS_500]

Any ideas guys? My printer is dead in the water ATM.

[Sineos]

There are quite a few

TMC 'stepper_x' reports DRV_STATUS: c01c0101 otpw=1(OvertempWarning!) t120=1 cs_actual=28 stealth=1 stst=1

messages in your log.

WRT your heating issue, please slice a small test file and attach the resulting gcode here.

[dJOS_500]

Cheers, I won’t get a chance to do the testing tonight, but I’ll do it tomorrow morning.

I’ll also reset the logs so there aren’t any red herrings. I’m not sure what date is against that stepper temp entry, but I suspect it isn’t recent. It’s likely from when I was playing with different electronics cooling strategies.

[dJOS_500]

Well now I’m even more confused, After clearing the Klipper Logs, I just printed a Voron cube with no issues at all.

I’ll run some additional tests, as it may be that Adaptive mesh probing over such a small print area is why it worked this time.

[dJOS_500]

Well I can’t explain it, despite setting the TRSYNC_TIMEOUT values to their defaults and starting 3 different prints, since clearing the Klipper logs, my printer is working perfectly again.

klippy.log (2.5 MB)

I’m confident this wasn’t a stepper driver overheating issue, as this was happening over a period of 2 days - my printer would fail from a cold start. Then on day 3 my printer mysteriously does a JC on me and comes back from the dead. I didn’t even restart it, I just cleared the logs and that was it.

[dJOS_500]

Ok, so after a couple of successful prints, the timeout has returned:

klippy.log.zip (2.6 MB)

Starting SD card print (position 0)
Stats 152150.2: gcodein=0  mcu: mcu_awake=0.000 mcu_task_avg=0.000005 mcu_task_stddev=0.000004 bytes_write=51477579 bytes_read=10401633 bytes_retransmit=177227 bytes_invalid=25176 send_seq=1002224 receive_seq=1002221 retransmit_seq=999146 srtt=0.001 rttvar=0.000 rto=0.025 ready_bytes=467 upcoming_bytes=216 freq=167993109 rpi: mcu_awake=0.000 mcu_task_avg=0.000008 mcu_task_stddev=0.000014 bytes_write=140217 bytes_read=433686 bytes_retransmit=0 bytes_invalid=0 send_seq=23335 receive_seq=23335 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999675 adj=50001708 EBBCan: mcu_awake=0.002 mcu_task_avg=0.000011 mcu_task_stddev=0.000011 bytes_write=26764718 bytes_read=5812876 bytes_retransmit=0 bytes_invalid=0 send_seq=493045 receive_seq=493045 retransmit_seq=0 srtt=0.001 rttvar=0.000 rto=0.025 ready_bytes=34 upcoming_bytes=0 freq=63999904 adj=64002572 sd_pos=250685 raspberry_pi: temp=60.1 mcu_temp: temp=30.9 EBBCan_temp: temp=31.4 heater_bed: target=0 temp=22.5 pwm=0.000 sysload=1.89 cputime=3623.462 memavail=715136 print_time=152109.875 buffer_time=0.000 print_stall=0 extruder: target=0 temp=23.9 pwm=0.000
Stats 152151.2: gcodein=0  mcu: mcu_awake=0.000 mcu_task_avg=0.000005 mcu_task_stddev=0.000004 bytes_write=51478928 bytes_read=10402503 bytes_retransmit=177227 bytes_invalid=25176 send_seq=1002272 receive_seq=1002272 retransmit_seq=999146 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=167993114 rpi: mcu_awake=0.001 mcu_task_avg=0.000010 mcu_task_stddev=0.000019 bytes_write=140223 bytes_read=433715 bytes_retransmit=0 bytes_invalid=0 send_seq=23336 receive_seq=23336 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999675 adj=50001689 EBBCan: mcu_awake=0.002 mcu_task_avg=0.000011 mcu_task_stddev=0.000011 bytes_write=26764783 bytes_read=5812997 bytes_retransmit=0 bytes_invalid=0 send_seq=493048 receive_seq=493048 retransmit_seq=0 srtt=0.001 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999907 adj=64002545 sd_pos=250685 raspberry_pi: temp=60.1 mcu_temp: temp=30.9 EBBCan_temp: temp=31.3 heater_bed: target=0 temp=22.4 pwm=0.000 sysload=1.89 cputime=3623.579 memavail=714612 print_time=152109.875 buffer_time=0.000 print_stall=0 extruder: target=0 temp=23.8 pwm=0.000
Stats 152152.2: gcodein=0  mcu: mcu_awake=0.000 mcu_task_avg=0.000005 mcu_task_stddev=0.000004 bytes_write=51479651 bytes_read=10403174 bytes_retransmit=177227 bytes_invalid=25176 send_seq=1002311 receive_seq=1002311 retransmit_seq=999146 srtt=0.001 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=167993113 rpi: mcu_awake=0.001 mcu_task_avg=0.000010 mcu_task_stddev=0.000019 bytes_write=140229 bytes_read=433731 bytes_retransmit=0 bytes_invalid=0 send_seq=23337 receive_seq=23337 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999674 adj=50001665 EBBCan: mcu_awake=0.002 mcu_task_avg=0.000011 mcu_task_stddev=0.000011 bytes_write=26764865 bytes_read=5813216 bytes_retransmit=0 bytes_invalid=0 send_seq=493054 receive_seq=493054 retransmit_seq=0 srtt=0.001 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999910 adj=64002566 sd_pos=250685 raspberry_pi: temp=59.6 mcu_temp: temp=31.1 EBBCan_temp: temp=31.4 heater_bed: target=0 temp=22.6 pwm=0.000 sysload=1.89 cputime=3623.709 memavail=714524 print_time=152110.357 buffer_time=0.000 print_stall=0 extruder: target=0 temp=23.9 pwm=0.000
Stats 152153.2: gcodein=0  mcu: mcu_awake=0.000 mcu_task_avg=0.000005 mcu_task_stddev=0.000004 bytes_write=51481276 bytes_read=10405141 bytes_retransmit=177227 bytes_invalid=25176 send_seq=1002429 receive_seq=1002429 retransmit_seq=999146 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=167993103 rpi: mcu_awake=0.001 mcu_task_avg=0.000010 mcu_task_stddev=0.000019 bytes_write=140241 bytes_read=433763 bytes_retransmit=0 bytes_invalid=0 send_seq=23339 receive_seq=23339 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999671 adj=50001656 EBBCan: mcu_awake=0.002 mcu_task_avg=0.000011 mcu_task_stddev=0.000011 bytes_write=26765178 bytes_read=5813835 bytes_retransmit=0 bytes_invalid=0 send_seq=493082 receive_seq=493082 retransmit_seq=0 srtt=0.001 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999905 adj=64002609 sd_pos=250685 raspberry_pi: temp=60.1 mcu_temp: temp=30.9 EBBCan_temp: temp=31.2 heater_bed: target=0 temp=22.5 pwm=0.000 sysload=1.89 cputime=3623.895 memavail=714620 print_time=152111.356 buffer_time=0.000 print_stall=0 extruder: target=0 temp=23.8 pwm=0.000
Communication timeout during homing y
Extrude below minimum temp
See the 'min_extrude_temp' config option for details
Extrude below minimum temp
See the 'min_extrude_temp' config option for details
virtual_sdcard on_error
Traceback (most recent call last):
  File "/home/pi/klipper/klippy/extras/virtual_sdcard.py", line 264, in work_handler
    self.gcode.run_script(line)
  File "/home/pi/klipper/klippy/gcode.py", line 216, in run_script
    self._process_commands(script.split('\n'), need_ack=False)
  File "/home/pi/klipper/klippy/gcode.py", line 198, in _process_commands
    handler(gcmd)
  File "/home/pi/klipper/klippy/extras/safe_z_home.py", line 64, in cmd_G28
    self.prev_G28(g28_gcmd)
  File "/home/pi/klipper/klippy/extras/homing.py", line 268, in cmd_G28
    kin.home(homing_state)
  File "/home/pi/klipper/klippy/kinematics/cartesian.py", line 91, in home
    self.home_axis(homing_state, axis, self.rails[axis])
  File "/home/pi/klipper/klippy/kinematics/cartesian.py", line 84, in home_axis
    homing_state.home_rails([rail], forcepos, homepos)
  File "/home/pi/klipper/klippy/extras/homing.py", line 185, in home_rails
    hmove.homing_move(homepos, hi.speed)
  File "/home/pi/klipper/klippy/extras/homing.py", line 138, in homing_move
    raise self.printer.command_error(error)
gcode.CommandError: Communication timeout during homing y

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/pi/klipper/klippy/extras/virtual_sdcard.py", line 268, in work_handler
    self.gcode.run_script(self.on_error_gcode.render())
  File "/home/pi/klipper/klippy/gcode.py", line 216, in run_script
    self._process_commands(script.split('\n'), need_ack=False)
  File "/home/pi/klipper/klippy/gcode.py", line 198, in _process_commands
    handler(gcmd)
  File "/home/pi/klipper/klippy/gcode.py", line 135, in <lambda>
    func = lambda params: origfunc(self._get_extended_params(params))
  File "/home/pi/klipper/klippy/extras/gcode_macro.py", line 189, in cmd
    self.template.run_gcode_from_command(kwparams)
  File "/home/pi/klipper/klippy/extras/gcode_macro.py", line 68, in run_gcode_from_command
    self.gcode.run_script_from_command(self.render(context))
  File "/home/pi/klipper/klippy/gcode.py", line 213, in run_script_from_command
    self._process_commands(script.split('\n'), need_ack=False)
  File "/home/pi/klipper/klippy/gcode.py", line 198, in _process_commands
    handler(gcmd)
  File "/home/pi/klipper/klippy/extras/gcode_move.py", line 143, in cmd_G1
    self.move_with_transform(self.last_position, self.speed)
  File "/home/pi/klipper/klippy/extras/skew_correction.py", line 71, in move
    self.next_transform.move(corrected_pos, speed)
  File "/home/pi/klipper/klippy/extras/bed_mesh.py", line 209, in move
    self.toolhead.move([x, y, z + self.fade_target, e], speed)
  File "/home/pi/klipper/klippy/toolhead.py", line 424, in move
    self.extruder.check_move(move)
  File "/home/pi/klipper/klippy/kinematics/extruder.py", line 234, in check_move
    "Extrude below minimum temp\n"
gcode.CommandError: Extrude below minimum temp
See the 'min_extrude_temp' config option for details
Exiting SD card print (position 0)

[Sineos]

Something is strange in your workflow according to the log:

1. The extruder was working at a target of 225°C
2. The extruder heating gets turned off since the print is about to end
3. The print apparently finished: Finished SD card print
4. Now without any startup procedure a new print seems to have started: Starting SD card print (position 0)

The result is that it does not work because the new print has not been correctly initialized.

Can you explain your workflow?

[dJOS_500]

@Sineos

Can you explain your workflow?

Im just as confused by that log as you - here Is the Print that failed with the timeout:

Fab365_SR-71_Port_Engine-Mega Zero 0.4mm-Sunlu PLA+.gcode.zip (6.4 MB)

And the previous print that worked just fine - both used the same SuperSlicer profile:

Fab365_SR-71_Top_Cover-Mega Zero 0.4mm-Sunlu PLA+.gcode.zip (2.7 MB)

[Sineos]

To be honest I have no clue.
I would recommend to switch your slicer start gcode to a macro. See https://github.com/Klipper3d/klipper/blob/5f990f93d533247d3a675e8c423280f4333ad8ce/config/sample-macros.cfg#L15-L34

This way you have more control and can use action_respond_info to output status messages

[dJOS_500]

Cheers, I’ll try that. I’m also going to see if there are any CanBus firmware updates available, as I haven’t touched them since I set them up over 10 months ago.

[EddyMI3D]

You may check if the part cooler and/or the heatbreak cooler affect the heater block.

[dJOS_500]

I only replaced the Revo 6 Voron Edition a month ago. I also replaced the heatsink fan at the same time.

I’m running a Stealthburner hot end:

https://www.printables.com/model/437977-voron-stealthburner-mount-with-bltouch-for-mega-ze