What is the problem?
Yesterday I started printing the owl model which comes bundled with Creality CR-10 MAX printer, on its SD Card. Printing started fine, was supposed to finish overnight, and when I woke up this morning, the printer was stuck at some point, hotend active, and OctoPrint was non-responsive. As a matter of fact, the whole Raspberry Pi was AWOL. It is the second time OctoPrint becomes unresponsive. The first time the print actually finished, so all I had to do was reboot the RPi. This time though...
What did you already try to solve it?
Nothing I really could do to resolve it, except read what is provided in the logs and try to make sense of it.
First off, I have installed and using Motion to connect to a USB Webcam and capture snapshots every minute. This way I was able to catch the moment it failed, and check the logs.
Logs (octoprint.log
, serial.log
or output on terminal tab at a minimum, browser error console if UI issue ... no logs, no support!)
I will post relevant excerpts but if you need me to, I can upload logs somewhere and link the here.
2020-05-22 03:22:04,503 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 03:22:14,438 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 66611}
2020-05-22 03:26:26,939 - octoprint.util.comm - INFO - Finished in 35004.658 s.
2020-05-22 03:26:26,940 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Finishing"
2020-05-22 03:26:26,950 - octoprint.filemanager.analysis - INFO - Starting analysis of local:Maria/CCR10MAX_ofw_face_front.gcode
2020-05-22 03:26:26,955 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python2 -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 /home/pi/.octoprint/uploads/Maria/CCR10MAX_ofw_face_front.gcode
2020-05-22 03:26:27,026 - octoprint.printer.standard.job - INFO - Print job done - origin: local, path: Maria/CCR10MAX_ofw_face_front.gcode, owner: war
2020-05-22 03:26:27,169 - octoprint.plugins.DisplayLayerProgress - INFO - Printing stopped. Detailed progress stopped.
2020-05-22 03:26:27,408 - octoprint.plugins.tracking - INFO - Sent tracking event print_done, payload: {'origin': u'local', u'throttled_mask': 131072, u'elapsed': 35004, 'file': '0c710814e2fce2509410a2f76650f02e9304aad8', u'throttled_now': False, u'throttled_past': True}
2020-05-22 03:26:30,122 - octoprint.util.comm - INFO - Changing monitoring state from "Finishing" to "Operational"
2020-05-22 03:27:21,277 - octoprint.filemanager.analysis - INFO - Analysis of entry local:Maria/CCR10MAX_ofw_face_front.gcode finished, needed 54.33s
2020-05-22 03:37:04,504 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 03:37:14,441 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 67511}
2020-05-22 03:52:04,506 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 03:52:14,540 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 68411}
2020-05-22 04:07:04,509 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 04:07:06,854 - octoprint.util.connectivity_checker - INFO - Connectivity changed from online to offline
2020-05-22 04:22:04,512 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 04:37:04,514 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 04:52:04,516 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 05:07:04,518 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 05:22:04,521 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 05:37:04,523 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 05:52:04,525 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 06:07:04,528 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 06:22:04,530 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 06:37:04,532 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 06:46:45,664 - octoprint.util.comm - ERROR - Unexpected error while reading from serial port
Traceback (most recent call last):
File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 2823, in _readline
ret = self._serial.readline()
File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 4968, in readline
c = self.read(1)
File "/home/pi/oprint/local/lib/python2.7/site-packages/serial/serialposix.py", line 501, in read
'device reports readiness to read but returned no data '
SerialException: device reports readiness to read but returned no data (device disconnected or multiple access on port?)
2020-05-22 06:46:45,801 - octoprint.util.comm - ERROR - Please see https://faq.octoprint.org/serialerror for possible reasons of this.
2020-05-22 06:46:45,811 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Offline (Error: SerialException: 'device reports readiness to read but returned no data (device disconnected or multiple access on port?)' @ comm.py:_readline:2823)"
2020-05-22 06:52:04,534 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-05-22 06:17:09,637 - octoprint.startup - INFO - ******************************************************************************
2020-05-22 06:17:09,640 - octoprint.startup - INFO - Starting OctoPrint 1.4.0
2020-05-22 06:17:09,641 - octoprint.startup - INFO - ******************************************************************************
As you can see, first off Octoprint (wrongly) believes the print has finished. The owl is still half way through, and my snapshot webcam images show the printer doing its job until the very last moment, when it stops abruptly, hotend at 200 degrees Celsius, and stays in that position until I wake up and shut down the printer.
Another issue is OctoPrint thinking it went offline at 04:07:06, something must have happened wither with the RPi or the OS.
Finally the log messes up timestamps for some reason, which makes no sense to me.
Syslog also points to loss of network connectivity:
May 22 04:05:03 octopi kernel: [232630.445064] CIFS VFS: Server 192.168.2.100 has not responded in 180 seconds. Reconnecting...
May 22 04:05:45 octopi kernel: [232672.924049] uvcvideo: Failed to query (GET_DEF) UVC control 2 on unit 2: -110 (exp. 2).
Motion outputs webcam snapshots directly to my NAS, and the last saved image was at exactly 4:00 AM.
Additional information about your setup (OctoPrint version, OctoPi version, printer, firmware, browser, operating system, ... as much data as possible)
OctoPrint Version 1.4.0, OctoPi Version 0.17.0, running on Raspberry Pi 4 Model B Rev 1.2, printer: Creality CR-10 MAX, firmware 1.7.0, browser is Google Chrome, Operating System (used to access OctoPrint) is both Windows 10 x64 1907 and Android (while using OctoRemote).
I really don't understand why OctoPrint suddenly decided the owl has finished printing (it was about half way through in terms of Z-Height). More troublesome is the fact that the hotend remained primed for hours.