Timeouts for first print, then never again until power cycle

What is the problem?

Printer freezes while printing and shows timeout messages in terminal for the first print of the day. Yes, I know, I am using a 5m usb cable which may be causing the problem. BUT if I cancel the print, disconnect from the printer and reconnect it works like a charm for the rest of the day (meaning until I switch off the printer for the night).

So it does not seem to be sporadic timeouts. Is OctoPrint increasing timeouts after first timeout events or something like that?

What did you already try to solve it?

Cancelling the print and reconnecting to printer (sometimes twice) solves it until next power cycle of printer.

Logs (syslog, dmesg, ... no logs, no support)

https://www.dropbox.com/s/4u1b8gl5kfwm217/octoprint.log?dl=1
https://www.dropbox.com/s/6uiugcv9lbzaz2q/serial.log?dl=1

Additional information about your network (Hardware you are trying to connect to, hardware you are trying to connect from, router, access point, used operating systems, ...)

OctoPrint 1.5.2 running in Docker Container on Synology NAS.

Hi, I have a similar, actually the same problem (Synology NAS, docker, octoprint), I tried everything possible (including a 30cm usb cable, usb driver installation, uninstallation, etc.), but it behaves the same. Have you figured anything out yet? Thanks for the info.

Hi @Lubos_Milko,

no unforunately I haven't. Given there are no responses from others so far it seems to be something very rare.

What printer are you using? I'm running an Prusa Mini. Maybe it is something hardware related?

Hi, I also thought there may be a problem in the HW, I have a Monoprice mini delta, but if it's angry even on Prusa, I don't know ,,, So far I've printed from raspberry, everything is OK and I bought a new NAS and I thought that I will print from it. : - / I'm looking for info on the net, but I haven't found a meaningful solution yet.

So from Raspberry it works without the freezing? That's interesting... so maybe its Docker related? I'll investigate further...

I just had an issue where I had to power cycle the printer and afterwards it tooks 4 attempts and another power cycle of the printer to get it running properly. :roll_eyes:

yes, from raspberry it works without problems. The problem will probably be somewhere in the Docker and USB access. I've found a few discussions on the net about Docker on Synology NAS and USB, but none of that solves my problem. I went back to raspberry before I found a solution.

Hey,

so I did not make any progress with the timeouts, but I just created a small gcode script to let the print head run around without actually extruding anything.

This way I can test if the head moves properly without freezing. Once the script completes correctly I am confident, that it works for the real print.

The script does work and that freezing also occurs. Let's see if there is any logic in resolving the problem.

Can you share a new octoprint.log with DEBUG disabled. This is only for programmers and not really helpful to find another issue - and just fills up the log with unnecessary stuff.

Your printer complains about an unknown command:

2021-01-07 08:06:23,087 - Recv: echo:Unknown command: "AT+CPIN?"

You may try in safe mode if a plugin is the culprit

Hey,

here are two fresh logs from this morning. It took a few attempts to get the printer running.

https://www.dropbox.com/s/0y8mj5uxawa0ex9/octoprint_20210120.log?dl=1

https://www.dropbox.com/s/8u2n57sfni2m7gi/serial_20210120.log?dl=1

I put octoprint in safe mode for the 3rd attempt and increased the communication timeout to 5 seconds. After that it worked, though I'm not sure if it is coincidence.

Also the "AT+CPIN?" command appears despite being in safe mode. What could be causing this?

So, I again had issues and took the time to watch the terminal output. Whenever I saw this mysterious "AT+CPIN?" command the printer stopped sooner or later. Several aborted test prints and restarts or printer and Octoprint later, he command did not appear anymore and the printer worked ok.

@Lubos_Milko Any chance you are seeing this command as well in your terminal output / serial log files? Again, even if Octoprint is running in safe mode it appears.

Is that command in your gcode file? save the file to your computer and check.

If it is clean out of the slicer, but they are put there after you upload it to OctoPrint, there may be a plugin that's pre-processing and replacing them. In which case, start in safe mode then upload a clean file and print it.

@Charlie_Powell
No, the command is not in the gcode. I created a gcode file for testing purposes myself. I didn't want to start and stop real prints including scraping filament from the bed all the time.

I attached the test gcode file (freshly downloaded from octoprint).

Connection_Test.gcode (13.2 KB)

I just looked again at your serial log, OctoPrint doesn't seem to think it is sending that command at all. It looks a lot like a firmware bug now that I look at it. Might be worth reaching out to Prusa on that one, it isn't a corrupted command by the looks of it, since it sounds like something internal to the firmware is choking and breaking the communication.

I did a bit googling myself: AT+CPIN? is a command used in communication with UMTS and LTE devices to query whether a PIN is needed for authentication. Example here: https://gist.github.com/m0rth1um/63bf812cf94dcbf8558e4907517bfd9a

I am wondering now who is thinking that my printer could be an UMTS modem and is making a PIN request? Doesn't make sense to me. It could be something else running in the Docker image?! Surely it is no plugin in Octoprint...

Maybe you should raise an issue for this firmware:

I don't think it's a firmware issue. I am now convinced, that some process on my NAS is interrupting the connection to Octoprint on ttyACM0. Maybe some discovery service? That's what I'm trying to find out now.

This "AT+CPIN?" appears in the serial.log.
How can your NAS can have access to the USB port of the printer?

I am running Octoprint in a Docker container that is running on my NAS (see my first post). The printer is connected via USB to my NAS and appears as /dev/ttyACM0. So any process could theoretically write to that device. And that might by the problem.

Whenever I switch off the printer /dev/ttyACM0 on the NAS disappears. When I switch it back on it reappears. My guess is that some routine on the NAS' linux starts kicking in and does some kind of discovery to see if it is a modem of sorts.

Ok, so udevadm monitor on the NAS shows me this when switching on the printer:

KERNEL[4830932.257411] add /devices/pci0000:00/0000:00:15.0/usb1/1-1 (usb)
KERNEL[4830932.257996] add /devices/pci0000:00/0000:00:15.0/usb1/1-1/1-1:1.0 (usb)
KERNEL[4830932.258120] add /devices/pci0000:00/0000:00:15.0/usb1/1-1/1-1:1.1 (usb)
UDEV [4830932.459206] add /devices/pci0000:00/0000:00:15.0/usb1/1-1 (usb)
UDEV [4830932.613340] add /devices/pci0000:00/0000:00:15.0/usb1/1-1/1-1:1.1 (usb)
KERNEL[4830932.644348] add /module/ppp_async (module)
UDEV [4830932.644758] add /module/ppp_async (module)
KERNEL[4830932.647904] add /module/cdc_acm (module)
UDEV [4830932.648374] add /module/cdc_acm (module)
KERNEL[4830932.654481] add /devices/pci0000:00/0000:00:15.0/usb1/1-1/1-1:1.0/tty/ttyACM0 (tty)
KERNEL[4830932.654497] add /bus/usb/drivers/cdc_acm (drivers)
UDEV [4830932.654738] add /bus/usb/drivers/cdc_acm (drivers)
UDEV [4830932.785619] add /devices/pci0000:00/0000:00:15.0/usb1/1-1/1-1:1.0 (usb)
UDEV [4830932.907125] add /devices/pci0000:00/0000:00:15.0/usb1/1-1/1-1:1.0/tty/ttyACM0 (tty)

And dmesg shows:

[Sat Jan 23 23:15:01 2021] usb 1-1: new full-speed USB device number 104 using xhci_hcd
[Sat Jan 23 23:15:02 2021] cdc_acm 1-1:1.0: ttyACM0: USB ACM device
[Sat Jan 23 23:15:02 2021] usbcore: registered new interface driver cdc_acm
[Sat Jan 23 23:15:02 2021] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters

Ok, so I now need a way to prevent that...

I found the culprit. Turns out Synology is running a process called synousbmodemd that seems to interfere with communication to ttyACM0.

I killed the process and renamed the file /usr/syno/sbin/synousbmodemd to prevent it from starting again, which it seems to do when reconnecting the printer.

Works like a charm. :partying_face: :partying_face:

@Lubos_Milko Might quite well be the same problem for you.

@Ewald_Ikemann, @Charlie_Powell Thx for your input!

2 Likes