Printer turns off too early

foosel · March 3, 2020, 2:45pm

Welcome to the wonderful world of 3d printer serial communication which can be confusing AF since it's not properly standardized and lots of firmware forks are buggy like hell too

h4nc · March 3, 2020, 2:52pm

So basically what I do shouldn’t work at all if it would work „correctly“.
I‘ll have to wait if it reappears. While I hope it doesn’t happen again, I would still be interested in what happened at all

h4nc · March 16, 2020, 9:23am

It happened again a few days ago. Here are the end parts of the logfiles.

I noticed two things.

the serial log of the print with the issue shows Send and Recv, the other one only Recv
the octoprint.log files without the issue shows more 409 warnings (so this probably shows you that it is online longer).

h4nc · March 16, 2020, 9:23am

Logfile endings without the issue:

from octoprint.log

2020-02-28 16:25:43,352 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-02-28 16:30:38,177 - octoprint.util.comm - INFO - Finished in 1750.955 s.
2020-02-28 16:30:38,178 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Finishing"
2020-02-28 16:30:38,189 - octoprint.printer.standard.job - INFO - Print job done - origin: local, path: test2.gcode, owner: myuser
2020-02-28 16:30:38,199 - octoprint.plugins.DisplayLayerProgress - INFO - Printing stopped. Detailed progress stopped.
2020-02-28 16:30:38,201 - octoprint.events - INFO - Executing a system command
2020-02-28 16:30:38,272 - octoprint.events - INFO - Executing a system command
2020-02-28 16:30:38,274 - octoprint.util.comm - INFO - Changing monitoring state from "Finishing" to "Operational"
2020-02-28 16:30:38,563 - 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 2793, in _readline
    ret = self._serial.readline()
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 4932, 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-02-28 16:30:38,581 - octoprint.util.comm - ERROR - Please see https://faq.octoprint.org/serialerror for possible reasons of this.
2020-02-28 16:30:38,587 - 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:2793)"
2020-02-28 16:30:40,935 - octoprint.plugins.stats - INFO - Printer Stats - on_event
2020-02-28 16:30:40,982 - octoprint.plugins.stats - INFO - Printer Stats - on_event
2020-02-28 16:31:09,136 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 14.64ms
2020-02-28 16:31:09,245 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 15.13ms
2020-02-28 16:31:09,298 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 14.42ms
2020-02-28 16:31:38,046 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 15.24ms
2020-02-28 16:31:38,093 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 14.75ms
2020-02-28 16:31:40,053 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 14.75ms
2020-02-28 16:31:40,113 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 15.39ms
2020-02-28 16:31:40,134 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 7.88ms
2020-02-28 16:32:09,048 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 14.52ms
2020-02-28 16:32:09,085 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 14.41ms
2020-02-28 16:32:11,091 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 14.19ms
2020-02-28 16:32:11,125 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 15.41ms
2020-02-28 16:32:11,169 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 23.05ms

from serial.log

2020-02-28 16:30:23,600 - Recv:  T:122 /120 B:49 /0 @:0 B@:0 W:?
2020-02-28 16:30:24,607 - Recv:  T:122 /120 B:49 /0 @:0 B@:0 W:?
2020-02-28 16:30:25,613 - Recv:  T:121 /120 B:49 /0 @:0 B@:0 W:?
2020-02-28 16:30:26,604 - Recv:  T:121 /120 B:49 /0 @:0 B@:0 W:?
2020-02-28 16:30:27,611 - Recv:  T:121 /120 B:49 /0 @:0 B@:0 W:?
2020-02-28 16:30:28,601 - Recv:  T:120 /120 B:49 /0 @:0 B@:0 W:9
2020-02-28 16:30:29,608 - Recv:  T:120 /120 B:49 /0 @:3 B@:0 W:8
2020-02-28 16:30:30,615 - Recv:  T:120 /120 B:49 /0 @:5 B@:0 W:7
2020-02-28 16:30:31,605 - Recv:  T:119 /120 B:49 /0 @:7 B@:0 W:6
2020-02-28 16:30:32,611 - Recv:  T:119 /120 B:49 /0 @:10 B@:0 W:5
2020-02-28 16:30:33,602 - Recv:  T:119 /120 B:48 /0 @:12 B@:0 W:4
2020-02-28 16:30:34,608 - Recv:  T:119 /120 B:48 /0 @:15 B@:0 W:3
2020-02-28 16:30:35,614 - Recv:  T:118 /120 B:48 /0 @:16 B@:0 W:2
2020-02-28 16:30:36,605 - Recv:  T:118 /120 B:48 /0 @:19 B@:0 W:1
2020-02-28 16:30:37,612 - Recv:  T:118 /120 B:48 /0 @:21 B@:0 W:0
2020-02-28 16:30:38,170 - Recv: ok
2020-02-28 16:30:38,177 - Changing monitoring state from "Printing" to "Finishing"
2020-02-28 16:30:38,207 - Send: N13045 M400*36
2020-02-28 16:30:38,255 - Recv: ok
2020-02-28 16:30:38,273 - Changing monitoring state from "Finishing" to "Operational"
2020-02-28 16:30:38,307 - Send: M117 0s 100% L=50/50
2020-02-28 16:30:38,316 - Recv: ok
2020-02-28 16:30:38,580 - Unexpected error while reading serial port, please consult octoprint.log for details: SerialException: 'device reports readiness to read but returned no data (device disconnected or multiple access on port?)' @ comm.py:_readline:2793
2020-02-28 16:30:38,583 - Please see https://faq.octoprint.org/serialerror for possible reasons of this.
2020-02-28 16:30:38,587 - 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:2793)"
2020-02-28 16:30:38,593 - Connection closed, closing down monitor
2020-02-28 16:30:47,598 - Disabling serial logging

Logfile endings with the issue:

from octoprint.log

2020-03-09 15:13:10,200 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-03-09 15:28:10,201 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-03-09 15:31:13,329 - octoprint.util.comm - INFO - Finished in 4437.691 s.
2020-03-09 15:31:13,336 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Finishing"
2020-03-09 15:31:13,357 - octoprint.printer.standard.job - INFO - Print job done - origin: local, path: test.gcode, owner: myuser
2020-03-09 15:31:13,373 - octoprint.plugins.DisplayLayerProgress - INFO - Printing stopped. Detailed progress stopped.
2020-03-09 15:31:13,369 - octoprint.events - INFO - Executing a system command
2020-03-09 15:31:13,456 - octoprint.plugin - ERROR - Error while calling plugin octobullet
Traceback (most recent call last):
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/plugin/__init__.py", line 224, in call_plugin
    result = getattr(plugin, method)(*args, **kwargs)
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint_octobullet/__init__.py", line 241, in on_event
    path = os.path.basename(payload["file"])
KeyError: 'file'
2020-03-09 15:31:13,472 - octoprint.plugins.stats - INFO - Printer Stats - on_event
2020-03-09 15:31:13,505 - octoprint.events - INFO - Executing a system command
2020-03-09 15:31:13,939 - 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-03-09 15:31:13,943 - octoprint.util.comm - ERROR - Please see https://faq.octoprint.org/serialerror for possible reasons of this.
2020-03-09 15:31:13,959 - octoprint.util.comm - INFO - Changing monitoring state from "Finishing" 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-03-09 15:31:13,967 - octoprint.plugins.stats - INFO - Printer Stats - on_event
2020-03-09 15:31:42,070 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 23.50ms
2020-03-09 15:31:42,130 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 18.37ms
2020-03-09 15:31:58,424 - octoprint.server.util.flask - INFO - Passively logging in user myuser from ::ffff:192.168.1.80
2020-03-09 15:31:58,429 - octoprint.access.users - INFO - Logged in user: myuser
2020-03-09 15:31:59,164 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.1.80
2020-03-09 15:31:59,352 - octoprint.server.util.flask - INFO - Passively logging in user myuser from ::ffff:192.168.1.80
2020-03-09 15:31:59,353 - octoprint.access.users - INFO - Logged in user: myuser
2020-03-09 15:32:00,755 - octoprint.plugins.announcements - INFO - Loaded channel _important from https://octoprint.org/feeds/important.xml in 0.24s
2020-03-09 15:32:01,182 - octoprint.plugins.announcements - INFO - Loaded channel _releases from https://octoprint.org/feeds/releases.xml in 0.2s
2020-03-09 15:32:02,541 - octoprint.plugins.announcements - INFO - Loaded channel _blog from https://octoprint.org/feeds/octoblog.xml in 0.24s
2020-03-09 15:32:02,844 - octoprint.plugins.announcements - INFO - Loaded channel _plugins from https://plugins.octoprint.org/feed.xml in 0.23s
2020-03-09 15:32:03,178 - octoprint.plugins.announcements - INFO - Loaded channel _octopi from https://octoprint.org/feeds/octopi.xml in 0.22s
2020-03-09 15:32:03,741 - octoprint.plugins.pluginmanager - INFO - Loaded plugin notices data from https://plugins.octoprint.org/notices.json
2020-03-09 15:32:04,611 - octoprint.server.util.sockjs - INFO - User myuser logged in on the socket from client ::ffff:192.168.1.80
2020-03-09 15:32:06,169 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 9.06ms
2020-03-09 15:32:06,213 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 9.04ms
2020-03-09 15:32:06,266 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 9.50ms
2020-03-09 15:32:13,066 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 25.16ms
2020-03-09 15:32:13,106 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.1.111) 17.26ms

from serial.log

2020-03-09 15:31:11,564 - Send: N44232 G1 X83.536 Y200.465 E9.83741*95
2020-03-09 15:31:11,575 - Recv: ok
2020-03-09 15:31:11,580 - Send: N44233 G1 X83.888 Y200.499 E9.84789*86
2020-03-09 15:31:11,592 - Recv: ok
2020-03-09 15:31:11,597 - Send: N44234 G1 X84.235 Y200.603 E9.85865*87
2020-03-09 15:31:11,609 - Recv: ok
2020-03-09 15:31:11,614 - Send: N44235 G1 X84.546 Y200.769 E9.86911*89
2020-03-09 15:31:11,625 - Recv: ok
2020-03-09 15:31:11,629 - Send: N44236 M105*32
2020-03-09 15:31:11,640 - Recv: ok T:193 /194 B:59 /60 @:73 B@:127
2020-03-09 15:31:11,649 - Send: N44237 G1 X84.818 Y200.993 E9.87958*90
2020-03-09 15:31:11,672 - Recv: ok
2020-03-09 15:31:11,677 - Send: N44238 G1 X85.042 Y201.265 E9.89005*95
2020-03-09 15:31:11,688 - Recv: ok
2020-03-09 15:31:11,692 - Send: N44239 G1 X85.208 Y201.576 E9.90052*93
2020-03-09 15:31:13,255 - Recv: ok
2020-03-09 15:31:13,264 - Send: N44240 G1 X85.311 Y201.914 E9.91099*84
2020-03-09 15:31:13,286 - Recv: ok
2020-03-09 15:31:13,294 - Send: N44241 G1 X85.346 Y202.275 E9.92176*91
2020-03-09 15:31:13,318 - Recv: ok
2020-03-09 15:31:13,334 - Changing monitoring state from "Printing" to "Finishing"
2020-03-09 15:31:13,334 - Send: N44242 G1 X85.346 Y251.255 E11.37605*105
2020-03-09 15:31:13,437 - Recv: ok
2020-03-09 15:31:13,474 - Send: N44243 G1 X85.311 Y251.616 E11.38681*106
2020-03-09 15:31:13,526 - Recv: ok
2020-03-09 15:31:13,545 - Send: N44244 G1 X85.208 Y251.953 E11.39728*105
2020-03-09 15:31:13,561 - Recv: ok
2020-03-09 15:31:13,566 - Send: N44245 G1 X85.042 Y252.264 E11.40776*109
2020-03-09 15:31:13,589 - Recv: ok
2020-03-09 15:31:13,593 - Send: N44246 G1 X84.824 Y252.530 E11.41795*109
2020-03-09 15:31:13,605 - Recv: ok
2020-03-09 15:31:13,609 - Send: N44247 G1 X84.527 Y252.771 E11.42931*102
2020-03-09 15:31:13,622 - Recv: ok
2020-03-09 15:31:13,641 - Send: N44248 G1 X84.236 Y252.669 F7200.000*109
2020-03-09 15:31:13,943 - Unexpected error while reading serial port, please consult octoprint.log for details: SerialException: 'device reports readiness to read but returned no data (device disconnected or multiple access on port?)' @ comm.py:_readline:2823
2020-03-09 15:31:13,944 - Please see https://faq.octoprint.org/serialerror for possible reasons of this.
2020-03-09 15:31:13,958 - Changing monitoring state from "Finishing" 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-03-09 15:31:13,970 - Connection closed, closing down monitor