Bug "Communication timeout while printing"

Get Help
1

What is the problem?

Hi,
Octoprint disconnects itself from the printer randomly. It is not a problem to restart the Raspberry because the uptime doesn't return to zero after the communication is cut.

When an Octoprint serial break does not pause.
In my case the printer is just waiting for further instructions, in the logs I can see that the connection comes back but octoprint doesn't do anything anymore.

What did you already try to solve it?

Full reinstallation of Octoprint
Try it with several USB cables
Removal of plugins
Testing of different communication speeds
Trying version 1.5RC, the bug is less present than with version 14, but it still occurs a few times.
Testing of linux update (apt update/upgrade)
Option "Request exclusive access to the serial port" unselected
Increase option "Max. consecutive timeouts during long running commands"

Have you tried running in safe mode and if so did it solve the issue?

Unresolved Issue

Complete Logs

Octoprint.log

2020-11-20 15:59:33,258 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: nichoir_oiseau/RIGHT_WALL.aw.gcode, owner: gaetan, user: gaetan
2020-11-20 15:59:33,281 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting"
2020-11-20 15:59:33,282 - octoprint.plugins.DisplayLayerProgress - INFO - File '/home/pi/.octoprint/uploads/nichoir_oiseau/RIGHT_WALL.aw.gcode' selected. Determining number of layers.
2020-11-20 15:59:33,289 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: nichoir_oiseau/RIGHT_WALL.aw.gcode, owner: gaetan, user: gaetan
2020-11-20 15:59:33,317 - octoprint.plugins.DisplayLayerProgress - INFO - Read total height from MetaFile
2020-11-20 15:59:33,384 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2020-11-20 15:59:33,417 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2020-11-20 15:59:33,955 - octoprint.plugins.DisplayLayerProgress - INFO - Store layer count in MetaFile
2020-11-20 15:59:33,971 - octoprint.plugins.DisplayLayerProgress - INFO - File select-event processing done!'
2020-11-20 15:59:34,021 - octoprint.plugins.DisplayLayerProgress - INFO - Printing started. Detailed progress started.{u'origin': u'local', u'name': u'RIGHT_WALL.aw.gcode', u'user': 'gaetan', u'owner': 'gaetan', u'path': u'nichoir_oiseau/RIGHT_WALL.aw.gcode', u'size': 2926977L}
2020-11-20 15:59:34,221 - octoprint.plugins.tracking - INFO - Sent tracking event print_started, payload: {u'origin': u'local', u'file': '760ec7c1b683aa4bf610d1f5cbe3679c3a77cb39'}
2020-11-20 15:59:35,546 - octoprint.util.comm - INFO - Printer seems to support the busy protocol, will adjust timeouts and set busy interval accordingly
2020-11-20 16:01:22,667 - octoprint.util.comm - INFO - Telling the printer to set the busy interval to our "communicationBusy" timeout - 1s = 4s
2020-11-20 16:11:44,670 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-11-20 16:11:52,030 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 907}
2020-11-20 16:26:44,671 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-11-20 16:26:52,028 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 1807}
2020-11-20 16:41:44,673 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-11-20 16:41:52,065 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 2707}
2020-11-20 16:56:44,675 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-11-20 16:56:52,040 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 3607}
2020-11-20 17:11:44,678 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-11-20 17:11:52,438 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 4507}
2020-11-20 17:16:12,730 - octoprint.util.comm - INFO - , trying to trigger response from printer.
2020-11-20 17:16:17,748 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:16:22,766 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:16:27,779 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:16:32,796 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:16:37,817 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:16:42,834 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:16:47,850 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:16:52,869 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:16:57,884 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:17:02,903 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:17:07,921 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:17:12,938 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:17:17,959 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:17:22,973 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:17:27,992 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:17:33,010 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:17:38,027 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:17:41,423 - octoprint.util.comm - INFO - Pausing/resuming job on behalf of user gaetan
2020-11-20 17:17:41,427 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Pausing"
2020-11-20 17:17:43,044 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2020-11-20 17:17:48,060 - octoprint.util.comm - INFO - No response from printer after 6 consecutive communication timeouts, considering it dead.
2020-11-20 17:17:48,120 - octoprint.util.comm - INFO - Changing monitoring state from "Pausing" to "Offline (Error: Too many consecutive timeouts, printer still connected and alive?)"
2020-11-20 17:17:48,158 - octoprint.plugins.action_command_notification - INFO - Notifications cleared
2020-11-20 17:17:48,356 - octoprint.plugins.tracking - INFO - Sent tracking event commerror_timeout, payload: {u'commerror_text': u'Too many consecutive timeouts, printer still connected and alive?'}
2020-11-20 17:18:00,257 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Opening serial connection"
2020-11-20 17:18:00,264 - octoprint.util.comm - INFO - Connecting to port /dev/ttyUSB0, baudrate 115200
2020-11-20 17:18:00,302 - octoprint.util.comm - INFO - Changing monitoring state from "Opening serial connection" to "Connecting"
2020-11-20 17:18:02,081 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2020-11-20 17:18:03,989 - octoprint.util.comm - INFO - Changing monitoring state from "Connecting" to "Operational"
2020-11-20 17:18:04,007 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2020-11-20 17:18:04,028 - octoprint.plugins.firmwareupdater - INFO - Got CONNECTED event
2020-11-20 17:18:04,034 - octoprint.plugins.firmwareupdater - INFO - Run postflash flag is not set
2020-11-20 17:18:04,111 - octoprint.util.comm - INFO - Printer reports firmware name "Marlin 2.0.7.1 (Nov  3 2020"
2020-11-20 17:18:04,133 - octoprint.util.comm - INFO - Firmware states that it supports temperature autoreporting
2020-11-20 17:18:04,291 - octoprint.plugins.tracking - INFO - Sent tracking event printer_connected, payload: {u'printer_baudrate': 115200, u'printer_port': u'/dev/ttyUSB0', u'firmware_name': u'Marlin 2.0.7.1 (Nov  3 2020'}

Serial.log (End of log only)

2020-11-20 17:16:04,687 - Send: N41406 G1 X117.123 Y144.879 E4.9576*92
2020-11-20 17:16:04,816 - Recv: ok
2020-11-20 17:16:04,821 - Send: N41407 G1 X121.079 Y140.924 E5.1502*81
2020-11-20 17:16:04,851 - Recv: ok
2020-11-20 17:16:04,856 - Send: N41408 G1 X120.459 Y140.907 E5.1715*92
2020-11-20 17:16:04,947 - Recv: ok
2020-11-20 17:16:04,952 - Send: N41409 G1 X116.481 Y144.885 E5.3652*82
2020-11-20 17:16:04,978 - Recv: ok
2020-11-20 17:16:04,982 - Send: N41410 G1 X115.838 Y144.891 E5.3873*95
2020-11-20 17:16:05,107 - Recv: ok
2020-11-20 17:16:05,112 - Send: N41411 M117 66% L=20/33*92
2020-11-20 17:16:05,119 - Recv: ok
2020-11-20 17:16:05,122 - Send: N41412 G1 X119.839 Y140.891 E5.5821*85
2020-11-20 17:16:05,141 - Recv: ok
2020-11-20 17:16:05,145 - Send: N41413 G1 X119.219 Y140.874 E5.6034*88
2020-11-20 17:16:05,245 - Recv: ok
2020-11-20 17:16:05,249 - Send: N41414 G1 X115.199 Y144.894 E5.7991*85
2020-11-20 17:16:05,275 - Recv: ok
2020-11-20 17:16:05,279 - Send: N41415 G1 X114.560 Y144.897 E5.8211*88
2020-11-20 17:16:05,406 - Recv: ok
2020-11-20 17:16:05,411 - Send: N41416 G1 X118.599 Y140.858 E6.0178*81
2020-11-20 17:16:05,416 - Recv:  T:189.79 /190.00 B:49.97 /50.00 @:60 B@:31
2020-11-20 17:16:05,440 - Recv: ok
2020-11-20 17:16:05,444 - Send: N41417 G1 X117.979 Y140.841 E6.0391*80
2020-11-20 17:16:05,544 - Recv: ok
2020-11-20 17:16:05,548 - Send: N41418 G1 X113.921 Y144.900 E6.2367*93
2020-11-20 17:16:05,575 - Recv: ok
2020-11-20 17:16:05,579 - Send: N41419 G1 X113.282 Y144.902 E6.2587*84
2020-11-20 17:16:05,705 - Recv: ok
2020-11-20 17:16:05,709 - Send: N41420 G1 X117.359 Y140.825 E6.4572*81
2020-11-20 17:16:05,739 - Recv: ok
2020-11-20 17:16:05,743 - Send: N41421 G2 X116.736 Y140.811 I-0.906 J26.433 E6.47869*121
2020-11-20 17:16:06,349 - Recv: ok
2020-11-20 17:16:06,354 - Send: N41422 G1 X112.642 Y144.905 E6.6780*83
2020-11-20 17:16:06,456 - Recv: ok
2020-11-20 17:16:06,460 - Send: N41423 G1 X112.003 Y144.908 E6.7000*82
2020-11-20 17:16:06,484 - Recv: ok
2020-11-20 17:16:06,488 - Send: N41424 G1 X116.113 Y140.798 E6.9001*93
2020-11-20 17:16:06,619 - Recv: ok
2020-11-20 17:16:06,622 - Send: N41425 G1 X115.490 Y140.785 E6.9215*90
2020-11-20 17:16:06,653 - Recv: ok
2020-11-20 17:16:06,657 - Send: N41426 G1 X111.364 Y144.910 E7.1224*92
2020-11-20 17:16:06,761 - Recv: ok
2020-11-20 17:16:06,764 - Send: N41427 G1 X110.725 Y144.913 E7.1444*94
2020-11-20 17:16:06,791 - Recv: ok
2020-11-20 17:16:06,795 - Send: N41428 G1 X114.866 Y140.772 E7.3460*84
2020-11-20 17:16:06,935 - Recv: ok
2020-11-20 17:16:06,940 - Send: N41429 G1 X114.243 Y140.759 E7.3674*86
2020-11-20 17:16:06,954 - Recv: ok
2020-11-20 17:16:06,958 - Send: N41430 G1 X110.086 Y144.916 E7.5698*84
2020-11-20 17:16:06,969 - Recv: ok
2020-11-20 17:16:06,974 - Send: N41431 G1 X109.447 Y144.918 E7.5918*93
2020-11-20 17:16:06,985 - Recv: ok
2020-11-20 17:16:06,990 - Send: N41432 G1 X113.619 Y140.746 E7.7949*91
2020-11-20 17:16:07,001 - Recv: ok
2020-11-20 17:16:07,008 - Send: N41433 G1 X112.996 Y140.733 E7.8164*89
2020-11-20 17:16:07,019 - Recv: ok
2020-11-20 17:16:07,024 - Send: N41434 G1 X108.808 Y144.921 E8.0202*94
2020-11-20 17:16:07,035 - Recv: ok
2020-11-20 17:16:07,038 - Send: N41435 G1 X108.169 Y144.924 E8.0422*80
2020-11-20 17:16:07,049 - Recv: ok
2020-11-20 17:16:07,053 - Send: N41436 G1 X112.372 Y140.720 E8.2469*83
2020-11-20 17:16:07,064 - Recv: ok
2020-11-20 17:16:07,067 - Send: N41437 G1 X111.749 Y140.707 E8.2684*89
2020-11-20 17:16:07,082 - Recv: ok
2020-11-20 17:16:07,088 - Send: N41438 G1 X107.530 Y144.926 E8.4737*91
2020-11-20 17:16:07,102 - Recv: ok
2020-11-20 17:16:07,105 - Send: N41439 G1 X106.891 Y144.929 E8.4957*90
2020-11-20 17:16:07,237 - Recv: ok
2020-11-20 17:16:07,242 - Send: N41440 G1 X111.125 Y140.694 E8.7019*89
2020-11-20 17:16:07,272 - Recv: ok
2020-11-20 17:16:07,276 - Send: N41441 G1 X110.502 Y140.681 E8.7234*81
2020-11-20 17:16:07,382 - Recv: ok
2020-11-20 17:16:07,386 - Send: N41442 G1 X106.252 Y144.932 E8.9303*95
2020-11-20 17:16:07,415 - Recv:  T:189.69 /190.00 B:50.03 /50.00 @:61 B@:22
2020-11-20 17:16:07,420 - Recv: ok
2020-11-20 17:16:07,425 - Send: N41443 G1 X105.613 Y144.934 E8.9523*94
2020-11-20 17:16:07,549 - Recv: ok
2020-11-20 17:16:07,553 - Send: N41444 G1 X109.878 Y140.669 E9.1600*94
2020-11-20 17:16:07,583 - Recv: ok
2020-11-20 17:16:07,598 - Send: N41445 G1 X109.255 Y140.656 E9.1814*93
2020-11-20 17:16:07,694 - Recv: ok
2020-11-20 17:16:07,698 - Send: N41446 G1 X104.974 Y144.937 E9.3899*80
2020-11-20 17:16:07,724 - Recv: ok
2020-11-20 17:16:07,728 - Send: N41447 G1 X104.334 Y144.940 E9.4119*89
2020-11-20 17:16:12,731 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:16:12,744 - Send: N41448 M105*42
2020-11-20 17:16:17,750 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:16:17,762 - Send: N41449 M105*43
2020-11-20 17:16:22,767 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:16:22,779 - Send: N41450 M105*35
2020-11-20 17:16:27,784 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:16:27,793 - Send: N41451 M105*34
2020-11-20 17:16:32,799 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:16:32,812 - Send: N41452 M105*33
2020-11-20 17:16:37,819 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:16:37,828 - Send: N41453 M105*32
2020-11-20 17:16:42,836 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:16:42,848 - Send: N41454 M105*39
2020-11-20 17:16:47,852 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:16:47,864 - Send: N41455 M105*38
2020-11-20 17:16:52,873 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:16:52,888 - Send: N41456 M105*37
2020-11-20 17:16:57,886 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:16:57,899 - Send: N41457 M105*36
2020-11-20 17:17:02,905 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:17:02,918 - Send: N41458 M105*43
2020-11-20 17:17:07,923 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:17:07,935 - Send: N41459 M105*42
2020-11-20 17:17:12,940 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:17:12,950 - Send: N41460 M105*32
2020-11-20 17:17:17,960 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:17:17,971 - Send: N41461 M105*33
2020-11-20 17:17:22,975 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:17:22,987 - Send: N41462 M105*34
2020-11-20 17:17:27,995 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:17:28,007 - Send: N41463 M105*35
2020-11-20 17:17:33,012 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:17:33,024 - Send: N41464 M105*36
2020-11-20 17:17:38,035 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:17:38,041 - Send: N41465 M105*37
2020-11-20 17:17:41,425 - Changing monitoring state from "Printing" to "Pausing"
2020-11-20 17:17:43,045 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:17:43,057 - Send: N41466 M400*38
2020-11-20 17:17:48,062 - No response from printer after 6 consecutive communication timeouts, considering it dead. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2020-11-20 17:17:48,116 - Changing monitoring state from "Pausing" to "Offline (Error: Too many consecutive timeouts, printer still connected and alive?)"
2020-11-20 17:17:48,133 - Connection closed, closing down monitor
2020-11-20 17:17:58,061 - Did not receive parseable position data from printer within 15.0s, continuing without it
2020-11-20 17:18:00,256 - Changing monitoring state from "Offline" to "Opening serial connection"
2020-11-20 17:18:00,268 - Connecting to port /dev/ttyUSB0, baudrate 115200
2020-11-20 17:18:00,299 - Changing monitoring state from "Opening serial connection" to "Connecting"
2020-11-20 17:18:00,316 - Connected to: Serial<id=0xab85aa30, open=True>(port='/dev/ttyUSB0', baudrate=115200, bytesize=8, parity='N', stopbits=1, timeout=10.0, xonxoff=False, rtscts=False, dsrdtr=False), starting monitor
2020-11-20 17:18:02,067 - Recv: echo:start
2020-11-20 17:18:02,082 - Recv: Marlin 2.0.7.1
2020-11-20 17:18:02,088 - Recv: 
2020-11-20 17:18:02,091 - Send: N0 M110 N0*125
2020-11-20 17:18:02,093 - Recv: echo: Last Updated: 2020-10-10 | Author: (thisiskeithb, Ender-5 Pro)
2020-11-20 17:18:02,098 - Recv: echo:Compiled: Nov  3 2020
2020-11-20 17:18:02,102 - Recv: echo: Free Memory: 12930  PlannerBufferBytes: 1200
2020-11-20 17:18:02,105 - Recv: echo:V81 stored settings retrieved (657 bytes; crc 55774)
2020-11-20 17:18:03,975 - Recv: ok
2020-11-20 17:18:03,988 - Changing monitoring state from "Connecting" to "Operational"
2020-11-20 17:18:04,024 - Send: N0 M110 N0*125
2020-11-20 17:18:04,074 - Recv: ok
2020-11-20 17:18:04,077 - Send: N1 M115*39
2020-11-20 17:18:04,109 - Recv: FIRMWARE_NAME:Marlin 2.0.7.1 (Nov  3 2020 23:41:23) SOURCE_CODE_URL:https://github.com/MarlinFirmware/Marlin PROTOCOL_VERSION:1.0 MACHINE_TYPE:Marlin 2.0.7.1 EXTRUDER_COUNT:1 UUID:cede2a2f-41a2-4748-9b12-c55c62f367ff
2020-11-20 17:18:04,117 - Recv: Cap:SERIAL_XON_XOFF:0
2020-11-20 17:18:04,122 - Recv: Cap:BINARY_FILE_TRANSFER:0
2020-11-20 17:18:04,126 - Recv: Cap:EEPROM:1
2020-11-20 17:18:04,128 - Recv: Cap:VOLUMETRIC:0
2020-11-20 17:18:04,132 - Recv: Cap:AUTOREPORT_TEMP:1
2020-11-20 17:18:04,139 - Recv: Cap:PROGRESS:0
2020-11-20 17:18:04,145 - Recv: Cap:PRINT_JOB:1
2020-11-20 17:18:04,146 - Recv: Cap:AUTOLEVEL:1
2020-11-20 17:18:04,148 - Recv: Cap:RUNOUT:0
2020-11-20 17:18:04,152 - Recv: Cap:Z_PROBE:1
2020-11-20 17:18:04,156 - Recv: Cap:LEVELING_DATA:1
2020-11-20 17:18:04,158 - Recv: Cap:BUILD_PERCENT:0
2020-11-20 17:18:04,160 - Recv: Cap:SOFTWARE_POWER:0
2020-11-20 17:18:04,164 - Recv: Cap:TOGGLE_LIGHTS:0
2020-11-20 17:18:04,165 - Recv: Cap:CASE_LIGHT_BRIGHTNESS:0
2020-11-20 17:18:04,168 - Recv: Cap:EMERGENCY_PARSER:0
2020-11-20 17:18:04,171 - Recv: Cap:PROMPT_SUPPORT:0
2020-11-20 17:18:04,174 - Recv: Cap:SDCARD:0
2020-11-20 17:18:04,175 - Recv: Cap:AUTOREPORT_SD_STATUS:0
2020-11-20 17:18:04,180 - Recv: Cap:LONG_FILENAME:0
2020-11-20 17:18:04,185 - Recv: Cap:THERMAL_PROTECTION:1
2020-11-20 17:18:04,188 - Recv: Cap:MOTION_MODES:0
2020-11-20 17:18:04,190 - Recv: Cap:ARCS:1
2020-11-20 17:18:04,192 - Recv: Cap:BABYSTEPPING:0
2020-11-20 17:18:04,194 - Recv: Cap:CHAMBER_TEMPERATURE:0
2020-11-20 17:18:04,197 - Recv: ok
2020-11-20 17:18:04,199 - Send: M155 S2
2020-11-20 17:18:04,202 - Recv: ok
2020-11-20 17:18:06,214 - Recv:  T:177.19 /0.00 B:48.96 /0.00 @:0 B@:0
2020-11-20 17:18:08,214 - Recv:  T:174.93 /0.00 B:48.85 /0.00 @:0 B@:0
2020-11-20 17:18:10,214 - Recv:  T:172.69 /0.00 B:48.70 /0.00 @:0 B@:0
2020-11-20 17:18:12,213 - Recv:  T:170.31 /0.00 B:48.67 /0.00 @:0 B@:0
2020-11-20 17:18:14,213 - Recv:  T:168.35 /0.00 B:48.47 /0.00 @:0 B@:0
2020-11-20 17:18:16,213 - Recv:  T:166.22 /0.00 B:48.42 /0.00 @:0 B@:0
2020-11-20 17:18:18,213 - Recv:  T:164.14 /0.00 B:48.17 /0.00 @:0 B@:0
2020-11-20 17:18:20,213 - Recv:  T:162.05 /0.00 B:48.16 /0.00 @:0 B@:0
2020-11-20 17:18:22,213 - Recv:  T:159.97 /0.00 B:47.99 /0.00 @:0 B@:0
2020-11-20 17:18:24,214 - Recv:  T:158.29 /0.00 B:47.89 /0.00 @:0 B@:0
2020-11-20 17:18:26,214 - Recv:  T:156.45 /0.00 B:47.75 /0.00 @:0 B@:0
2020-11-20 17:18:28,213 - Recv:  T:154.74 /0.00 B:47.63 /0.00 @:0 B@:0
2020-11-20 17:18:30,213 - Recv:  T:153.03 /0.00 B:47.60 /0.00 @:0 B@:0
2020-11-20 17:18:32,219 - Recv:  T:151.23 /0.00 B:47.43 /0.00 @:0 B@:0
2020-11-20 17:18:34,218 - Recv:  T:149.52 /0.00 B:47.37 /0.00 @:0 B@:0
2020-11-20 17:18:36,218 - Recv:  T:147.56 /0.00 B:47.27 /0.00 @:0 B@:0
2020-11-20 17:18:38,218 - Recv:  T:145.75 /0.00 B:47.11 /0.00 @:0 B@:0
2020-11-20 17:18:40,218 - Recv:  T:143.91 /0.00 B:47.11 /0.00 @:0 B@:0
2020-11-20 17:18:42,219 - Recv:  T:142.09 /0.00 B:47.07 /0.00 @:0 B@:0
2020-11-20 17:18:44,222 - Recv:  T:140.12 /0.00 B:46.89 /0.00 @:0 B@:0
2020-11-20 17:18:46,219 - Recv:  T:138.71 /0.00 B:46.84 /0.00 @:0 B@:0
2020-11-20 17:18:48,218 - Recv:  T:137.34 /0.00 B:46.76 /0.00 @:0 B@:0
2020-11-20 17:18:50,218 - Recv:  T:135.91 /0.00 B:46.61 /0.00 @:0 B@:0
2020-11-20 17:18:52,218 - Recv:  T:134.55 /0.00 B:46.58 /0.00 @:0 B@:0
2020-11-20 17:18:54,218 - Recv:  T:133.04 /0.00 B:46.51 /0.00 @:0 B@:0
2020-11-20 17:18:56,218 - Recv:  T:131.65 /0.00 B:46.38 /0.00 @:0 B@:0
2020-11-20 17:18:58,219 - Recv:  T:130.22 /0.00 B:46.32 /0.00 @:0 B@:0
2020-11-20 17:19:00,220 - Recv:  T:128.79 /0.00 B:46.23 /0.00 @:0 B@:0
2020-11-20 17:19:02,220 - Recv:  T:127.38 /0.00 B:46.20 /0.00 @:0 B@:0
2020-11-20 17:19:04,220 - Recv:  T:125.85 /0.00 B:46.05 /0.00 @:0 B@:0
2020-11-20 17:19:06,219 - Recv:  T:124.44 /0.00 B:46.04 /0.00 @:0 B@:0
2020-11-20 17:19:08,224 - Recv:  T:123.01 /0.00 B:45.95 /0.00 @:0 B@:0
2020-11-20 17:19:10,219 - Recv:  T:121.59 /0.00 B:45.86 /0.00 @:0 B@:0
2020-11-20 17:19:12,219 - Recv:  T:120.18 /0.00 B:45.79 /0.00 @:0 B@:0
2020-11-20 17:19:14,220 - Recv:  T:118.82 /0.00 B:45.76 /0.00 @:0 B@:0
2020-11-20 17:19:16,220 - Recv:  T:117.57 /0.00 B:45.69 /0.00 @:0 B@:0
2020-11-20 17:19:18,225 - Recv:  T:116.33 /0.00 B:45.67 /0.00 @:0 B@:0
2020-11-20 17:19:20,220 - Recv:  T:115.11 /0.00 B:45.53 /0.00 @:0 B@:0
2020-11-20 17:19:22,219 - Recv:  T:113.88 /0.00 B:45.53 /0.00 @:0 B@:0
2020-11-20 17:19:24,219 - Recv:  T:112.52 /0.00 B:45.49 /0.00 @:0 B@:0
2020-11-20 17:19:26,232 - Recv:  T:111.34 /0.00 B:45.26 /0.00 @:0 B@:0
2020-11-20 17:19:28,232 - Recv:  T:110.12 /0.00 B:45.26 /0.00 @:0 B@:0
2020-11-20 17:19:30,231 - Recv:  T:108.89 /0.00 B:45.25 /0.00 @:0 B@:0
2020-11-20 17:19:32,231 - Recv:  T:107.62 /0.00 B:45.16 /0.00 @:0 B@:0
2020-11-20 17:19:34,232 - Recv:  T:106.46 /0.00 B:45.03 /0.00 @:0 B@:0
2020-11-20 17:19:36,232 - Recv:  T:105.29 /0.00 B:45.00 /0.00 @:0 B@:0
2020-11-20 17:19:38,232 - Recv:  T:104.14 /0.00 B:44.98 /0.00 @:0 B@:0
2020-11-20 17:19:40,232 - Recv:  T:103.02 /0.00 B:44.94 /0.00 @:0 B@:0
2020-11-20 17:19:42,231 - Recv:  T:101.80 /0.00 B:44.80 /0.00 @:0 B@:0
2020-11-20 17:19:44,231 - Recv:  T:100.73 /0.00 B:44.71 /0.00 @:0 B@:0
2020-11-20 17:19:46,231 - Recv:  T:99.64 /0.00 B:44.71 /0.00 @:0 B@:0
2020-11-20 17:19:48,231 - Recv:  T:98.59 /0.00 B:44.71 /0.00 @:0 B@:0
2020-11-20 17:19:50,232 - Recv:  T:97.60 /0.00 B:44.58 /0.00 @:0 B@:0
2020-11-20 17:19:52,232 - Recv:  T:96.47 /0.00 B:44.47 /0.00 @:0 B@:0
2020-11-20 17:19:54,245 - Recv:  T:95.46 /0.00 B:44.41 /0.00 @:0 B@:0
2020-11-20 17:19:56,246 - Recv:  T:94.48 /0.00 B:44.41 /0.00 @:0 B@:0
2020-11-20 17:19:58,246 - Recv:  T:93.48 /0.00 B:44.41 /0.00 @:0 B@:0
2020-11-20 17:20:00,246 - Recv:  T:92.44 /0.00 B:44.34 /0.00 @:0 B@:0
2020-11-20 17:20:02,246 - Recv:  T:91.49 /0.00 B:44.30 /0.00 @:0 B@:0
2020-11-20 17:20:04,245 - Recv:  T:90.54 /0.00 B:44.12 /0.00 @:0 B@:0
2020-11-20 17:20:06,245 - Recv:  T:89.61 /0.00 B:44.12 /0.00 @:0 B@:0
2020-11-20 17:20:08,245 - Recv:  T:88.76 /0.00 B:44.10 /0.00 @:0 B@:0
2020-11-20 17:20:10,245 - Recv:  T:87.80 /0.00 B:44.04 /0.00 @:0 B@:0
2020-11-20 17:20:12,246 - Recv:  T:86.95 /0.00 B:44.06 /0.00 @:0 B@:0
2020-11-20 17:20:14,251 - Recv:  T:86.08 /0.00 B:43.95 /0.00 @:0 B@:0
2020-11-20 17:20:16,246 - Recv:  T:85.25 /0.00 B:43.84 /0.00 @:0 B@:0
2020-11-20 17:20:18,245 - Recv:  T:84.45 /0.00 B:43.82 /0.00 @:0 B@:0
2020-11-20 17:20:20,245 - Recv:  T:83.59 /0.00 B:43.81 /0.00 @:0 B@:0
2020-11-20 17:20:22,245 - Recv:  T:82.83 /0.00 B:43.62 /0.00 @:0 B@:0
2020-11-20 17:20:24,245 - Recv:  T:82.08 /0.00 B:43.55 /0.00 @:0 B@:0
2020-11-20 17:20:26,245 - Recv:  T:81.32 /0.00 B:43.53 /0.00 @:0 B@:0
2020-11-20 17:20:28,246 - Recv:  T:80.58 /0.00 B:43.51 /0.00 @:0 B@:0
2020-11-20 17:20:30,246 - Recv:  T:79.81 /0.00 B:43.47 /0.00 @:0 B@:0
2020-11-20 17:20:32,246 - Recv:  T:78.90 /0.00 B:43.27 /0.00 @:0 B@:0
2020-11-20 17:20:34,246 - Recv:  T:78.05 /0.00 B:43.24 /0.00 @:0 B@:0
2020-11-20 17:20:36,246 - Recv:  T:77.25 /0.00 B:43.24 /0.00 @:0 B@:0
2020-11-20 17:20:38,245 - Recv:  T:76.42 /0.00 B:43.24 /0.00 @:0 B@:0
2020-11-20 17:20:40,245 - Recv:  T:75.56 /0.00 B:43.24 /0.00 @:0 B@:0
2020-11-20 17:20:42,245 - Recv:  T:74.84 /0.00 B:43.16 /0.00 @:0 B@:0
2020-11-20 17:20:44,246 - Recv:  T:74.07 /0.00 B:43.03 /0.00 @:0 B@:0
2020-11-20 17:20:46,246 - Recv:  T:73.36 /0.00 B:42.94 /0.00 @:0 B@:0
2020-11-20 17:20:48,250 - Recv:  T:72.63 /0.00 B:42.94 /0.00 @:0 B@:0
2020-11-20 17:20:50,249 - Recv:  T:71.91 /0.00 B:42.94 /0.00 @:0 B@:0
2020-11-20 17:20:52,249 - Recv:  T:71.24 /0.00 B:42.90 /0.00 @:0 B@:0
2020-11-20 17:20:54,249 - Recv:  T:70.56 /0.00 B:42.81 /0.00 @:0 B@:0
2020-11-20 17:20:56,248 - Recv:  T:69.91 /0.00 B:42.74 /0.00 @:0 B@:0
2020-11-20 17:20:58,248 - Recv:  T:69.25 /0.00 B:42.65 /0.00 @:0 B@:0
2020-11-20 17:21:00,249 - Recv:  T:68.59 /0.00 B:42.65 /0.00 @:0 B@:0
2020-11-20 17:21:02,250 - Recv:  T:67.99 /0.00 B:42.63 /0.00 @:0 B@:0
2020-11-20 17:21:04,250 - Recv:  T:67.41 /0.00 B:42.48 /0.00 @:0 B@:0
2020-11-20 17:21:06,250 - Recv:  T:66.80 /0.00 B:42.39 /0.00 @:0 B@:0
2020-11-20 17:21:08,250 - Recv:  T:66.23 /0.00 B:42.35 /0.00 @:0 B@:0
2020-11-20 17:21:10,249 - Recv:  T:65.61 /0.00 B:42.35 /0.00 @:0 B@:0
2020-11-20 17:21:12,255 - Recv:  T:65.10 /0.00 B:42.32 /0.00 @:0 B@:0
2020-11-20 17:21:14,249 - Recv:  T:64.60 /0.00 B:42.24 /0.00 @:0 B@:0
2020-11-20 17:21:16,256 - Recv:  T:64.11 /0.00 B:42.21 /0.00 @:0 B@:0
2020-11-20 17:21:18,255 - Recv:  T:63.58 /0.00 B:42.15 /0.00 @:0 B@:0
2020-11-20 17:21:20,256 - Recv:  T:63.06 /0.00 B:42.06 /0.00 @:0 B@:0
2020-11-20 17:21:22,256 - Recv:  T:62.59 /0.00 B:42.06 /0.00 @:0 B@:0
2020-11-20 17:21:24,256 - Recv:  T:62.10 /0.00 B:42.04 /0.00 @:0 B@:0
2020-11-20 17:21:26,256 - Recv:  T:61.62 /0.00 B:42.00 /0.00 @:0 B@:0
2020-11-20 17:21:28,256 - Recv:  T:61.13 /0.00 B:41.86 /0.00 @:0 B@:0
2020-11-20 17:21:30,255 - Recv:  T:60.74 /0.00 B:41.80 /0.00 @:0 B@:0
2020-11-20 17:21:32,255 - Recv:  T:60.29 /0.00 B:41.76 /0.00 @:0 B@:0
2020-11-20 17:21:34,255 - Recv:  T:59.74 /0.00 B:41.76 /0.00 @:0 B@:0
2020-11-20 17:21:36,256 - Recv:  T:59.19 /0.00 B:41.73 /0.00 @:0 B@:0
2020-11-20 17:21:38,256 - Recv:  T:58.55 /0.00 B:41.60 /0.00 @:0 B@:0
2020-11-20 17:21:40,256 - Recv:  T:57.98 /0.00 B:41.53 /0.00 @:0 B@:0
2020-11-20 17:21:42,256 - Recv:  T:57.49 /0.00 B:41.47 /0.00 @:0 B@:0
2020-11-20 17:21:44,268 - Recv:  T:56.90 /0.00 B:41.47 /0.00 @:0 B@:0
2020-11-20 17:21:46,268 - Recv:  T:56.27 /0.00 B:41.43 /0.00 @:0 B@:0
2020-11-20 17:21:48,268 - Recv:  T:55.78 /0.00 B:41.32 /0.00 @:0 B@:0
2020-11-20 17:21:50,267 - Recv:  T:55.29 /0.00 B:41.19 /0.00 @:0 B@:0

Additional information about your setup

OctoPrint Version 1.5.0rc3, Marlin 2.0.7.1, Raspberry PI4 4Gb, Ender 5 Pro with motherboard V 1.1.5

2

Please, for the good of our eyes when posting logs use the </> button, to make sure they are not formatted. Even better would be that they were just the files uploaded, but at least they are there.

Its highly unlikely that this is a bug in OctoPrint, communication timeouts occur when no response is received from the printer. You can see from the log that this is the case, OctoPrint is doing exactly the right thing trying to trigger a response.

The common causes of this are bad cables - you mention you have tried a different USB cable, but not whether it was shielded, or had ferrite beads. At least use one of these, ideally both.

OctoPrint does not know where the printer was up to before it died. So it cannot resume printing properly. And it should not do this automatically, since it covers up the errors.

Maybe there is a fault in the hardware, more likely the firmware but either way there is not much OctoPrint can do to help with this, if it doesn't get a response. Look at updating the FW, or identifying if there may be a fault with the motherboard.

1 Like
3

Hi,

I don't think my cables are shielded because they are rather short (30cm).
I installed a ferrite ring on the one I have on the printer.
I have a Raspberry Pi 3, can I test Octoprint with?

4

Hi,

I was trying to fix something like this for several weeks. I read numerous post of people having timeout problems. I tried switching cables even isolationg the + connection on pin1 of the usb cable, replacing my printers firmware from the stock custom firmware (Anet ET4 Pro) to Marlin, but the problems always stayed the same: During the first couple of lines of the gcode the print stopped and Octoprint issued a timeout from which it couldn't recover.
So I took the advice and replaced my Raspi4 by a Raspi 3b that was still arround. In fact nothing was better with this. So I concluded ist was no hardware issue with my equipment.
Today, after another week trying to no avail I finally swapped my Raspi3 to my oldest Raspi 1 and guess what: I was able to start a print and got several minutes into them without any timeout issues.

Unfortunately after a few minutes the print stopped again. But then I could press "fake acknowledge" button on the terminal windows and the print continued. This repeated serveral times but I could finish the print.

So what am I seeing here:

  1. This doesn't seem to be a hardware issue. (The Raspi1 is simply much slower)
  2. There seems to be a handshake problem betweeen my printer and Octoprint.
  3. Since the slower Raspi works much much better, I suppose it's not the receiving part of octoprint, but the sending one.

Is there anyone who had the same experience? What Can I do about it?
Any input is welcome.
Cheers

5

... and thinking about it a bit longer:
Since a slower raspi works better I can only imagine, that the printer gets the next command faster after the ok than it can handle it?
Is there any way to test this? I need a delay after the ok before the next command is issued. Is there any way I could accomplish this?
TIA
Umtauscher

6

Easiest way for us to tell if there is something wrong, is for you to enable and upload serial.log.

This will help us to see what kind of communication there is with your printer, rather than look at the quite unreliable crystal ball to see what happened. Last time I tried it, it said it needed a log too.

The printer should be able to keep up with the commands, and if you need to add a delay then you will introduce severe problems on corners as the printer will pause. In short, awful prints.

2 Likes
7

Hi Charlie,

thanks for helping me out. I was thinking about a delay in msec, not
seconds but anyways, I have attached the requested logs.

I am using an Anet Et4 Pro printer, Firmware 1.02
Rasperry Pi 1 with Octopi 1.5

I printed this with the serial log enabled, which went even better. I
think this helps my theorie that a shot delay would help.
Anyways perhaps you can look over it and tell me your thoughts.
Thanks again

serial.log (2.76 MB)

octoprint.log (135 KB)

8

Sorry my mistake:
OctoPrint version : 1.4.2
OctoPi version : 0.18.0

9

Can't see a reason why those particular commands would fail. Looked at the timings between the log entries, and couldn't find a pattern with the ones that triggered a timeout. Found one that was ~15ms between the commands, that failed, but also found others that were that short that ran just fine. Sadly I have no idea in that case :slightly_smiling_face:

You could try flashing a newer firmware, something like Marlin 2.0.7 is pretty good in my experience.

10

Thanks, unfortunately I cannot flash another Marlin firmware, because the version is still in the works...
Do you think it would be helpful, if I tried log with one of the faster Raspberrys, because there would be much more errors Perhaps this would help to better to find the culprit?
Cheers

11

This fixed it for me (problem was disturbances in the electrical grid).

thingiverse

12

Hi there!
Happy to realize that it is not an issue I am the only one to face!

I have (I think) the exact same behavior on my CR-10 v2. It randomly pauses my print... But not as I am used to...
When I click "Pause" on Octoprint: the hotend gets up and secure. It remains hot, such as the bed, till I hit resume (or restart). The printer displays "Paused".
When the filament sensor "acts" a pause on octoprint, I have the exact same behavior...
But there, I have a complete filament retraction from the bowden, the hotends gets cold (while the bed is hot) and the printer is wainting for me to click, first to reheat the nozzle, and another time to get the filament in... And a last time to confirm taht I want to resume printing...
It is very strange, as this "pause" acts like an M600 command within the Gcode (that I doublecheked, and there is no M600).
I am running Marlin 2.0.x fw on this printer (2.0.7.2 exactly), baudrate 250000, Octoprint 1.4.2. But so far, I have never had this issue with Creality "stock" firmware.......
I guess a kinda miscommunication between those 2 versions of softs...

octoprint (3).log (124.8 KB)

13

A quick update: After switching to debug logs, I realized that the issue seems to be trigerred by a plugin:

2020-11-26 08:42:37,111 - octoprint.events.fire - DEBUG - Firing event: DisplayLayerProgress_feedrateChanged (Payload: {'changeFilamentTimeLeft': '-', 'feedrate': '9000', 'updateReason': 'feedrateChanged', 'totalHeight': '14.6', 'totalLayer': '73', 'estimatedEndTime': '21:37', 'changeFilamentCount': 0, 'estimatedChangedFilamentTime': '-', 'printTimeLeftInSeconds': 46478, 'totalHeightFormatted': '14.6', 'currentHeight': '1.80', 'printTimeLeft': u'12h54m38s', 'lastLayerDuration': '0h:17m:36s', 'averageLayerDurationInSeconds': 864, 'lastLayerDurationInSeconds': 1056, 'changeFilamentTimeLeftInSeconds': 0, 'averageLayerDuration': '0h:14m:24s', 'feedrateG1': '1500', 'feedrateG0': '9000', 'fanspeed': '100%', 'progress': '16', 'currentHeightFormatted': '1.8', 'currentLayer': '8'})

The serial Log file seems to be ok. I will open a dedicated topic on this

14

I finally have to report that I fixed tje problem by replacing the usb cable with a 20cm short cable.
All timeouts are finally gone.
Thanks for your help.
Cheers
Umtauscher

15

Resolved for me.
I added a ferrite ring around the USB cable.
After several weeks of testing the problem did not reappear.

2 Likes
16

I know this is an old topic. But for the completion I add my info and experience.

The same thing just happened to me. The printer slowed down and the logs at octoprint showed timeouts.
I was doing an update on the Home Assistant Core.
Octoprint is connected to my HA instance by octoprint and psu home assistant plugin and by mqtt

After the update was done the printer started printing normal and the timeout in the logs disappeared.
I suspect the PSU/PSU Home assistant plugin is causing this issue during reboot of HA.
Maybe not exactly the same issue, but because I googled this error in the logs and came here, I thought let's add this info.

1 Like
17

Yes, same here. When the PSU Home assistant plugin cannot reach Home Assistant it seems to block octoprint regularly

18

I can confirm this statement. The "PSU Home Assistant" is causing the issue, just by changing the switch entity name. Fully functional after correcting it on the Octprint integration.

PS: If you restart you HA instance, the bug starts again, braking you printing job!

19

@DavyRoswinkel, @hcrohland, @ReDaLeRt,

Please can someone report this issue to the plugin author so that they have a chance to fix it.

20

Do you have "Automatically turn PSU ON" enabled?