"must home axis first" when print already active

General Discussion
1

Hi,
I’m getting a “must home axis first” error in the middle of a print. It seems like a hardware problem, but there is nothing in the log or console to indicate what triggered it. The error occurs randomly, usually fairly early on in the print - in the first few layers. I’ve inspected the gcode at the file offset that appears in the log and they are just normal print moves - no shutdown etc is occurring at that time. Usually, I can print the exact same file again from the job history successfully.

I’ve attached the log with an m112 shortly after the issue occurred again - suggest searching from the bottom up for the most recent must home axis error.
klippy.log (3.6 MB)

It’d be awesome to get a clue as to what might be the source of the problem - the log isn’t much help to me, and there’s nothing in the console to give a reason - if it’s hardware, like klipper sensed something wrong with a stepper - it’s not telling me. Thanks.

2

I quickly skimmed through the log and find it very confusing. I would not be surprised if in the vast number of macro lines something goes wrong (i.e. changes in velocities, force movements etc).
My only recommendation would be to reduce the config to a bare minimum:

  • Kick out all macros
  • Use only Klipper core functions
  • Do docking / undocking of the probe manually

If the error remains, it is more likely a hardware thing, if it is gone then some macros are to blame.

3

I will disable the moonraker_timelapse macro that is in use during a print. It is not moving the print head (or it is not supposed to be).
Other than that, macros are not in use during a print, and the error usually occurs in the middle of a print, so why do you think macros are the culprit? Can you be more specific about what you are seeing in the log and the many times this error occurs during a print? if helpful, I can download the gcode that was running at the time so that you can examine it at the offset noted in the log.
Whenever I have done this, it’s just normal print moves… no macros are involved.

4 
Z-CALIBRATION: ENDSTOP=0.144 NOZZLE=0.176 SWITCH=4.509 PROBE=5.920 --> OFFSET=1.039750
Probe locked
Stats 6393.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000009 mcu_task_stddev=0.000008 bytes_write=5169513 bytes_read=1761645 bytes_retransmit=9 bytes_invalid=0 send_seq=117521 receive_seq=117521 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=180000448 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000008 bytes_write=15443 bytes_read=49429 bytes_retransmit=0 bytes_invalid=0 send_seq=2549 receive_seq=2549 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998829 adj=49998754 sd_pos=74302 heater_bed: target=110 temp=110.1 pwm=0.297 chamber: temp=39.2 octo: temp=29.6 pi: temp=49.7 sysload=1.53 cputime=187.600 memavail=1512384 print_time=2417.654 buffer_time=0.660 print_stall=1 extruder: target=225 temp=224.7 pwm=0.261
toolhead: max_velocity: 500.000000
max_accel: 1000.000000
max_accel_to_decel: 7500.000000
square_corner_velocity: 7.000000
probe: open
toolhead: max_velocity: 500.000000
max_accel: 10000.000000
max_accel_to_decel: 7500.000000
square_corner_velocity: 7.000000
toolhead: max_velocity: 500.000000
max_accel: 10000.000000
max_accel_to_decel: 7500.000000
square_corner_velocity: 7.000000
Docking Probe
toolhead: max_velocity: 500.000000
max_accel: 1000.000000
max_accel_to_decel: 7500.000000
square_corner_velocity: 7.000000
Stats 6394.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000009 mcu_task_stddev=0.000008 bytes_write=5171917 bytes_read=1762405 bytes_retransmit=9 bytes_invalid=0 send_seq=117576 receive_seq=117574 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=42 stalled_bytes=10 freq=180000450 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000008 bytes_write=15449 bytes_read=49445 bytes_retransmit=0 bytes_invalid=0 send_seq=2550 receive_seq=2550 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998830 adj=49998774 sd_pos=74302 heater_bed: target=110 temp=110.1 pwm=0.297 chamber: temp=39.3 octo: temp=29.5 pi: temp=50.1 sysload=1.53 cputime=187.726 memavail=1512000 print_time=2420.750 buffer_time=2.757 print_stall=1 extruder: target=225 temp=224.8 pwm=0.213
Stats 6395.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000009 mcu_task_stddev=0.000008 bytes_write=5172727 bytes_read=1763009 bytes_retransmit=9 bytes_invalid=0 send_seq=117603 receive_seq=117603 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=11 stalled_bytes=0 freq=180000453 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000008 bytes_write=15461 bytes_read=49477 bytes_retransmit=0 bytes_invalid=0 send_seq=2552 receive_seq=2552 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998835 adj=49998721 sd_pos=74302 heater_bed: target=110 temp=110.1 pwm=0.331 chamber: temp=39.3 octo: temp=29.5 pi: temp=49.2 sysload=1.53 cputime=187.799 memavail=1512636 print_time=2420.750 buffer_time=1.757 print_stall=1 extruder: target=225 temp=225.0 pwm=0.151
Stats 6396.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000009 mcu_task_stddev=0.000008 bytes_write=5172978 bytes_read=1763546 bytes_retransmit=9 bytes_invalid=0 send_seq=117620 receive_seq=117620 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=180000453 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000008 bytes_write=15467 bytes_read=49493 bytes_retransmit=0 bytes_invalid=0 send_seq=2553 receive_seq=2553 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998835 adj=49998759 sd_pos=74302 heater_bed: target=110 temp=110.1 pwm=0.331 chamber: temp=39.3 octo: temp=29.5 pi: temp=50.1 sysload=1.53 cputime=187.862 memavail=1512260 print_time=2420.750 buffer_time=0.756 print_stall=1 extruder: target=225 temp=225.0 pwm=0.151
Stats 6397.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000009 mcu_task_stddev=0.000008 bytes_write=5174117 bytes_read=1764167 bytes_retransmit=9 bytes_invalid=0 send_seq=117651 receive_seq=117651 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=180000455 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000010 bytes_write=15473 bytes_read=49522 bytes_retransmit=0 bytes_invalid=0 send_seq=2554 receive_seq=2554 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998835 adj=49998757 sd_pos=74302 heater_bed: target=110 temp=110.1 pwm=0.331 chamber: temp=39.2 octo: temp=29.6 pi: temp=48.7 sysload=1.53 cputime=187.942 memavail=1512956 print_time=2422.335 buffer_time=1.341 print_stall=1 extruder: target=225 temp=225.1 pwm=0.151
Stats 6398.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000009 mcu_task_stddev=0.000008 bytes_write=5174373 bytes_read=1764708 bytes_retransmit=9 bytes_invalid=0 send_seq=117669 receive_seq=117669 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=180000455 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000010 bytes_write=15479 bytes_read=49538 bytes_retransmit=0 bytes_invalid=0 send_seq=2555 receive_seq=2555 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998840 adj=49998760 sd_pos=74302 heater_bed: target=110 temp=110.1 pwm=0.331 chamber: temp=39.3 octo: temp=29.7 pi: temp=49.2 sysload=1.48 cputime=188.000 memavail=1511980 print_time=2422.335 buffer_time=0.340 print_stall=1 extruder: target=225 temp=225.1 pwm=0.206
Stats 6399.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000011 mcu_task_stddev=0.000021 bytes_write=5175193 bytes_read=1765305 bytes_retransmit=9 bytes_invalid=0 send_seq=117695 receive_seq=117695 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=180000464 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000010 bytes_write=15485 bytes_read=49554 bytes_retransmit=0 bytes_invalid=0 send_seq=2556 receive_seq=2556 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998840 adj=49998814 sd_pos=74302 heater_bed: target=110 temp=110.1 pwm=0.379 chamber: temp=39.3 octo: temp=29.5 pi: temp=48.2 sysload=1.48 cputime=188.081 memavail=1512616 print_time=2423.107 buffer_time=0.111 print_stall=1 extruder: target=225 temp=225.2 pwm=0.206
toolhead: max_velocity: 500.000000
max_accel: 1000.000000
max_accel_to_decel: 7500.000000
square_corner_velocity: 7.000000
toolhead: max_velocity: 500.000000
max_accel: 10000.000000
max_accel_to_decel: 7500.000000
square_corner_velocity: 7.000000
toolhead: max_velocity: 500.000000
max_accel: 10000.000000
max_accel_to_decel: 7500.000000
square_corner_velocity: 7.000000
Stats 6400.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000011 mcu_task_stddev=0.000021 bytes_write=5175433 bytes_read=1765856 bytes_retransmit=9 bytes_invalid=0 send_seq=117712 receive_seq=117712 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=2 freq=180000489 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000010 bytes_write=15491 bytes_read=49570 bytes_retransmit=0 bytes_invalid=0 send_seq=2557 receive_seq=2557 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998843 adj=49998783 sd_pos=74302 heater_bed: target=110 temp=110.1 pwm=0.379 chamber: temp=39.3 octo: temp=29.6 pi: temp=49.7 sysload=1.48 cputime=188.167 memavail=1513008 print_time=2424.440 buffer_time=0.444 print_stall=1 extruder: target=225 temp=225.0 pwm=0.206
probe: TRIGGERED
toolhead: max_velocity: 500.000000
max_accel: 10000.000000
max_accel_to_decel: 7500.000000
square_corner_velocity: 7.000000
toolhead: max_velocity: 500.000000
max_accel: 10000.000000
max_accel_to_decel: 7500.000000
square_corner_velocity: 7.000000
extruder: pressure_advance: 0.045000
pressure_advance_smooth_time: 0.040000
Stats 6401.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000011 mcu_task_stddev=0.000021 bytes_write=5179620 bytes_read=1766749 bytes_retransmit=9 bytes_invalid=0 send_seq=117796 receive_seq=117796 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=180000493 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000010 bytes_write=15497 bytes_read=49586 bytes_retransmit=0 bytes_invalid=0 send_seq=2558 receive_seq=2558 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998847 adj=49998706 sd_pos=74302 heater_bed: target=110 temp=110.0 pwm=0.379 chamber: temp=39.3 octo: temp=29.6 pi: temp=50.1 sysload=1.48 cputime=188.328 memavail=1513428 print_time=2433.243 buffer_time=8.246 print_stall=1 extruder: target=225 temp=225.0 pwm=0.206
Stats 6402.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000011 mcu_task_stddev=0.000021 bytes_write=5179876 bytes_read=1767291 bytes_retransmit=9 bytes_invalid=0 send_seq=117814 receive_seq=117814 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=180000492 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000009 bytes_write=15503 bytes_read=49615 bytes_retransmit=0 bytes_invalid=0 send_seq=2559 receive_seq=2559 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998846 adj=49998717 sd_pos=74302 heater_bed: target=110 temp=110.0 pwm=0.379 chamber: temp=39.2 octo: temp=29.8 pi: temp=50.6 sysload=1.48 cputime=188.393 memavail=1513492 print_time=2433.243 buffer_time=7.245 print_stall=1 extruder: target=225 temp=225.0 pwm=0.210
Stats 6403.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000011 mcu_task_stddev=0.000021 bytes_write=5180131 bytes_read=1767847 bytes_retransmit=9 bytes_invalid=0 send_seq=117832 receive_seq=117832 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=180000489 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000009 bytes_write=15509 bytes_read=49631 bytes_retransmit=0 bytes_invalid=0 send_seq=2560 receive_seq=2560 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998846 adj=49998717 sd_pos=74302 heater_bed: target=110 temp=110.0 pwm=0.366 chamber: temp=39.1 octo: temp=29.8 pi: temp=49.7 sysload=1.44 cputime=188.459 memavail=1513412 print_time=2433.243 buffer_time=6.244 print_stall=1 extruder: target=225 temp=225.0 pwm=0.210
Stats 6404.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000011 mcu_task_stddev=0.000020 bytes_write=5180371 bytes_read=1768398 bytes_retransmit=9 bytes_invalid=0 send_seq=117849 receive_seq=117849 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=180000487 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000009 bytes_write=15515 bytes_read=49647 bytes_retransmit=0 bytes_invalid=0 send_seq=2561 receive_seq=2561 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998845 adj=49998718 sd_pos=74302 heater_bed: target=110 temp=110.0 pwm=0.366 chamber: temp=39.1 octo: temp=29.5 pi: temp=49.2 sysload=1.44 cputime=188.526 memavail=1513340 print_time=2433.243 buffer_time=5.243 print_stall=1 extruder: target=225 temp=225.1 pwm=0.210
Stats 6405.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000011 mcu_task_stddev=0.000020 bytes_write=5180619 bytes_read=1768951 bytes_retransmit=9 bytes_invalid=0 send_seq=117867 receive_seq=117867 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=180000489 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000009 bytes_write=15521 bytes_read=49663 bytes_retransmit=0 bytes_invalid=0 send_seq=2562 receive_seq=2562 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998846 adj=49998720 sd_pos=74302 heater_bed: target=110 temp=110.0 pwm=0.366 chamber: temp=39.2 octo: temp=29.5 pi: temp=49.2 sysload=1.44 cputime=188.590 memavail=1513340 print_time=2433.243 buffer_time=4.241 print_stall=1 extruder: target=225 temp=225.1 pwm=0.210
Stats 6406.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000011 mcu_task_stddev=0.000020 bytes_write=5180924 bytes_read=1769512 bytes_retransmit=9 bytes_invalid=0 send_seq=117886 receive_seq=117886 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=180000485 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000009 bytes_write=15527 bytes_read=49679 bytes_retransmit=0 bytes_invalid=0 send_seq=2563 receive_seq=2563 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998845 adj=49998720 sd_pos=74302 heater_bed: target=110 temp=110.0 pwm=0.366 chamber: temp=39.2 octo: temp=29.6 pi: temp=49.2 sysload=1.44 cputime=188.659 memavail=1512744 print_time=2433.243 buffer_time=3.240 print_stall=1 extruder: target=225 temp=225.1 pwm=0.193
Stats 6407.5: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000011 mcu_task_stddev=0.000020 bytes_write=5181172 bytes_read=1770064 bytes_retransmit=9 bytes_invalid=0 send_seq=117904 receive_seq=117904 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=180000484 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000008 bytes_write=15533 bytes_read=49708 bytes_retransmit=0 bytes_invalid=0 send_seq=2564 receive_seq=2564 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998847 adj=49998720 sd_pos=74302 heater_bed: target=110 temp=110.0 pwm=0.366 chamber: temp=39.2 octo: temp=29.5 pi: temp=49.7 sysload=1.44 cputime=188.718 memavail=1512668 print_time=2433.243 buffer_time=2.239 print_stall=1 extruder: target=225 temp=225.1 pwm=0.193
Must home axis first: 0.000 200.000 1.289 [2064.672]
Exiting SD card print (position 74612)

From the log it looks like the printer is working through these macros and then shortly after is erroring out.

5

that one died right after the print start macro, perhaps not the greatest example. take a look at some earlier must home axis first errors.

6

IMO all Must home axis first: instances in the posted log are following the same pattern.

7

ahh crap you’re right - the log rotated. I’ll try and find a better example and post it here.
thanks for looking.