Klipper: RESTART yields "MCU 'mcu' shutdown: Timer too close" with TMC UART timeout

[JRHeaton]

Problem description

Hi all, I installed and configured Klipper yesterday on an BTT SKR 1.4 Turbo. However, I'm having an issue where Klipper does not correctly respond to the RESTART command. The expected behavior would be for it to restart the host software and reconnect to the board, it never gets reconnected properly, and any subsequent commands issued yield a disconnect and a message telling me to run FIRMWARE_RESTART, which then fixes the problem. This is making iterating on new configs quite painful, and part of why I switched from Marlin was so that config updates would be less problematic. So hopefully I can provide the right data here to get this fixed and or a resolution/workaround found so that myself and others can continue using it.

I did start to report this on another issue thread but I feel it's probably best to make this its own thread as it may differ from the root cause of the timer error for the other person.

The (logged) issue

I've attached my Klippy log as well as my printer config, and here is a snippet of what I believe to be the relevant part of the log:

Receive: 80 58084.691850 58084.691542 12: seq: 10, shutdown clock=1633143497 static_string_id=Timer too close
Transition to shutdown state: MCU 'mcu' shutdown: Timer too close
This is generally indicative of an intermittent
communication failure between micro-controller and host.
Reactor garbage collection: (58084.181783786, 0.0, 0.0)
MCU 'mcu' shutdown: Timer too close
This is generally indicative of an intermittent
communication failure between micro-controller and host.
Once the underlying issue is corrected, use the
"FIRMWARE_RESTART" command to reset the firmware, reload the
config, and restart the host software.
Printer is shutdown

MCU 'mcu' shutdown: Timer too close
This is generally indicative of an intermittent
communication failure between micro-controller and host.
Once the underlying issue is corrected, use the
"FIRMWARE_RESTART" command to reset the firmware, reload the
config, and restart the host software.
Printer is shutdown

MCU error during connect
Traceback (most recent call last):
  File "/home/pi/klipper/klippy/klippy.py", line 151, in _connect
    cb()
  File "/home/pi/klipper/klippy/extras/tmc.py", line 119, in _handle_connect
    self._init_registers()
  File "/home/pi/klipper/klippy/extras/tmc.py", line 104, in _init_registers
    self.mcu_tmc.set_register(reg_name, val, print_time)
  File "/home/pi/klipper/klippy/extras/tmc_uart.py", line 224, in set_register
    self.ifcnt = self._do_get_register("IFCNT")
  File "/home/pi/klipper/klippy/extras/tmc_uart.py", line 205, in _do_get_register
    val = self.mcu_uart.reg_read(self.instance_id, self.addr, reg)
  File "/home/pi/klipper/klippy/extras/tmc_uart.py", line 153, in reg_read
    params = self.tmcuart_send_cmd.send([self.oid, msg, 10])
  File "/home/pi/klipper/klippy/mcu.py", line 367, in send
    return xh.get_response(cmd, self._cmd_queue, minclock=minclock)
  File "/home/pi/klipper/klippy/mcu.py", line 345, in get_response
    raise error("Timeout on wait for '%s' response" % (self.name,))
error: Timeout on wait for 'tmcuart_response' response
Build file /home/pi/klipper/klippy/../.config(1067): Thu Sep 24 01:28:32 2020

NOTE: To sanity check the TMC connection after a FIRMWARE_RESTART, i ran dump_tmc on each stepper and all of them report values for the queried registers, so they appear to be connected and configured properly.

Steps taken to try to fix

• Adding restart_method: command under [mcu] in the config (per suggestion in the other issue thread).
• Restarting the Pi and board physically
• Multiple different USB cables
• Multiple USB ports

NOTE: Getting the printer board stuck

Whilst running all of these firmware_restart commands, occasionally I will get into a state where the board never reconnects, and the host is indefinitely waiting for it. I have to power cycle the board and plug it into a different USB port to get it to work. It literally doesn't work if plugged into the same USB port (it doesn't show up in /dev/serial/by-id/). Not sure if this is a separate or related issue, but is a secondary problem to the primary restart issue.

printer.cfg.txt
klippy.log

[BlackStump]

I have no experience with that particular board, logic says to me if it was a klipper issue then the git would be flooded with the same issue, I have 4 BBT boards and a Duet running klipper and restart works as intended.
worth looking at - it may lead you to answers
I suspect you have a hardware issue but the Bigtreetech bootloaders are known to be flaky, do you have spare stepper drivers to try?
BTT boards model I use without issue.
SKR Pro 1.1 -TMC2208 UART
SKR Mini 1.1 -TMC2100
SKR Mini-e3-v1.2 -TMC2209 UART
SKR Mini-e3-v2.0 -TMC2209 UART
Duet2 Ethernet

[KevinOConnor]

It looks like there is a conflict in the bltouch initialization code and the low-level "pin" initialization code. It'll take me a couple of days to come up with a solution.

Until a fix can be deployed, the best alternative I can think of is to use FIRMWARE_RESTART instead of just RESTART.

-Kevin

[JRHeaton]

Thanks Kevin. Just to clarify, would that bug explain the references to TMC UART problems in the log as well? (I wanted to make sure there isn't more than one issue/a config problem/anything else on my end).

[KevinOConnor]

The "tmc uart" errors are likely just a cascading error report from the root "timer too close" issue.

-Kevin

[JRHeaton]

@KevinOConnor I got around to some further testing today, and observed that removing the BLTouch/safe homing config sections do allow restarts to work again (sanity check).

Is there anything I can do to assist in either testing or developing a fix for this issue? It's proving very cumbersome to work with Klipper when a lot of commands kick me into a state where I have to restart, and a full restart mid-calibration makes setup difficult. Judging by the other above response is it fair to assume this is only a problem w/ the 1.4 Turbo (LPC1769)? I'm hoping a resolution for this can stabilize the use case for others on this board as well if so. Thanks!

PS: I really like Klipper so far otherwise, keep up the great work.

[JRHeaton]

@KevinOConnor Is there any likelihood that based on the log and config, this could be an error on my end (including a hardware fault)? I've been at it for a couple of days trying out about every permutation of hardware and software config I can to overcome this. Intermittently I will be able to restart once or twice, but then back to tmc uart error and timer too close. What's quite odd and leading me to ask this is that I've not seen this issue reported by others, and in fact have been told that a friend with an SKR 1.4t and BLTouch is using Klipper without issue. I checked out the same commit as him (about 2 weeks ago) and tried that to no avail, as well as using his working config.

I appreciate any assistance on this :) thanks!

[KevinOConnor]

If you test with the code on the work-bltouch-20201006 branch, does the problem go away?

cd ~/klipper ; git fetch ; git checkout origin/work-bltouch-20201006 ; sudo service klipper restart

-Kevin

[JRHeaton]

@KevinOConnor That seems to have fixed the issue! I have not been able to reproduce the error on that branch yet, though I won't get around to fully testing the machine with a print until tomorrow. I'll report back to confirm and this issue can probably be closed once that branch is merged. I really appreciate you taking the time to look into this.

[JRHeaton]

@KevinOConnor it appears to indeed be stable with the fix. Looking forward to seeing this hit the main branch.

[KevinOConnor]

Great. I committed this to the master branch (commit d3177931).

-Kevin