"Heatbed Failed" only when using Octoprint

GregH · March 21, 2021, 1:19am

What is the problem?

New Creality Ender 5 Plus fails with Heatbed Failed displayed on its LCD. Here's the catch. This only happens when sending a print via Octoprint. A gcode file loaded via SD card directly to the E5+ and the bed/hotend heated via the LCD works and prints normally.

What did you already try to solve it?

Reset EEPROM, shutdown restarted PC, RPi, and E5+ numerous times.

Have you tried running in safe mode?

Yes, no change.

Did running in safe mode solve the problem?

No change.

Complete Logs

octoprint.log, serial.log or output on terminal tab at a minimum, browser error console if UI issue ... no logs, no support! Not log excerpts, complete logs.)

2021-03-21 01:11:03,533 - octoprint.startup - INFO - ******************************************************************************
2021-03-21 01:11:03,534 - octoprint.startup - INFO - Starting OctoPrint 1.5.3
2021-03-21 01:11:03,535 - octoprint.startup - INFO - Starting in SAFE MODE. Third party plugins will be disabled!
2021-03-21 01:11:03,536 - octoprint.startup - INFO - Reason for safe mode: setting in config.yaml
2021-03-21 01:11:03,537 - octoprint.startup - INFO - ******************************************************************************
2021-03-21 01:11:03,906 - octoprint.util.connectivity.connectivity_checker - INFO - Connectivity changed from offline to online
2021-03-21 01:11:03,966 - octoprint.util.connectivity.connectivity_checker - INFO - Connectivity state is currently: online
2021-03-21 01:11:03,967 - octoprint.util.connectivity.connectivity_checker - INFO - Connecting to 8.8.8.8:53 is working
2021-03-21 01:11:03,967 - octoprint.util.connectivity.connectivity_checker - INFO - Resolving octoprint.org is working
2021-03-21 01:11:04,620 - octoprint.startup - INFO - Blacklist processing done, adding 12 blacklisted plugin versions: roomtemp (any), GcodeEditor (0.1.1), GcodeEditor (0.2.0), GcodeEditor (0.2.1), GcodeEditor (0.2.2), GcodeEditor (0.2.3), GcodeEditor (0.2.4), GcodeEditor (0.2.5), GcodeEditor (0.2.6), GcodeEditor (0.2.8), gcodeleveling (0.1.0), gcodeleveling (0.1.1)
2021-03-21 01:11:04,642 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2021-03-21 01:11:05,409 - octoprint.plugin.core - INFO - Plugin Tasmota (0.8.13) is disabled.
2021-03-21 01:11:05,604 - octoprint.startup - INFO - Added settings overlay from plugin firmware_check
2021-03-21 01:11:05,605 - octoprint.plugin.core - INFO - Found 36 plugin(s) providing 17 mixin implementations, 34 hook handlers
2021-03-21 01:11:05,830 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval
2021-03-21 01:11:05,844 - octoprint.server - INFO - Intermediary server started
2021-03-21 01:11:05,863 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads...
2021-03-21 01:11:06,092 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully.
2021-03-21 01:11:06,095 - octoprint.server - INFO - Added new permission from plugin action_command_notification: PLUGIN_ACTION_COMMAND_NOTIFICATION_SHOW (needs: u"Need(method='role', value=u'plugin_action_command_notification_show')")
2021-03-21 01:11:06,096 - octoprint.server - INFO - Added new permission from plugin action_command_notification: PLUGIN_ACTION_COMMAND_NOTIFICATION_CLEAR (needs: u"Need(method='role', value=u'plugin_action_command_notification_clear')")
2021-03-21 01:11:06,097 - octoprint.server - INFO - Added new permission from plugin action_command_prompt: PLUGIN_ACTION_COMMAND_PROMPT_INTERACT (needs: u"Need(method='role', value=u'plugin_action_command_prompt_interact')")
2021-03-21 01:11:06,098 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_READ (needs: u"Need(method='role', value=u'plugin_announcements_read')")
2021-03-21 01:11:06,098 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_MANAGE (needs: u"Need(method='role', value=u'plugin_announcements_manage'), Need(method='role', value=u'plugin_announcements_read')")
2021-03-21 01:11:06,099 - octoprint.server - INFO - Added new permission from plugin appkeys: PLUGIN_APPKEYS_ADMIN (needs: u"Need(method='role', value=u'plugin_appkeys_admin')")
2021-03-21 01:11:06,100 - octoprint.server - INFO - Added new permission from plugin backup: PLUGIN_BACKUP_ACCESS (needs: u"Need(method='role', value=u'plugin_backup_access')")
2021-03-21 01:11:06,101 - octoprint.server - INFO - Added new permission from plugin firmware_check: PLUGIN_FIRMWARE_CHECK_DISPLAY (needs: u"Need(method='role', value=u'plugin_firmware_check_display')")
2021-03-21 01:11:06,102 - octoprint.server - INFO - Added new permission from plugin logging: PLUGIN_LOGGING_MANAGE (needs: u"Need(method='role', value=u'plugin_logging_manage')")
2021-03-21 01:11:06,103 - octoprint.server - INFO - Added new permission from plugin pi_support: PLUGIN_PI_SUPPORT_STATUS (needs: u"Need(method='role', value=u'plugin_pi_support_check')")
2021-03-21 01:11:06,104 - octoprint.server - INFO - Added new permission from plugin pluginmanager: PLUGIN_PLUGINMANAGER_MANAGE (needs: u"Need(method='role', value=u'plugin_pluginmanager_manage')")
2021-03-21 01:11:06,105 - octoprint.server - INFO - Added new permission from plugin pluginmanager: PLUGIN_PLUGINMANAGER_INSTALL (needs: u"Need(method='role', value=u'plugin_pluginmanager_install'), Need(method='role', value=u'plugin_pluginmanager_manage')")
2021-03-21 01:11:06,107 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_CHECK (needs: u"Need(method='role', value=u'plugin_softwareupdate_check')")
2021-03-21 01:11:06,107 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_UPDATE (needs: u"Need(method='role', value=u'plugin_softwareupdate_update')")
2021-03-21 01:11:06,108 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_CONFIGURE (needs: u"Need(method='role', value=u'plugin_softwareupdate_configure')")
2021-03-21 01:11:06,340 - octoprint.plugins.softwareupdate - INFO - Loaded version cache from disk
2021-03-21 01:11:06,879 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python2 -m pip" as command to invoke pip
2021-03-21 01:11:07,392 - octoprint.util.pip - INFO - Version of pip is 20.1.1
2021-03-21 01:11:07,393 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python2.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2021-03-21 01:11:07,394 - octoprint.util.pip - INFO - ==> pip ok -> yes
2021-03-21 01:11:07,408 - octoprint.plugin.core - INFO - Initialized 17 plugin implementation(s)
2021-03-21 01:11:07,422 - octoprint.plugin.core - INFO - 36 plugin(s) registered with the system:
| !ABL Expert Plugin (0.6) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_ABL_Expert
|  Action Command Notification Support (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/action_command_notification
|  Action Command Prompt Support (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/action_command_prompt
|  Announcement Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/announcements
|  Anonymous Usage Tracking (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/tracking
|  Application Keys Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/appkeys
| !Autoselect Plugin (0.3.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_autoselect
|  Backup & Restore (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/backup
| !Bed Visualizer (1.0.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_bedlevelvisualizer
| !BetterHeaterTimeout (1.3.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_BetterHeaterTimeout
|  Core Wizard (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/corewizard
|  Discovery (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/discovery
| !DisplayZ (0.1.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_displayz
|  Error Tracking (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/errortracking
| !Extra Distance Buttons (0.1.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_extradistance
| !Fan Speed Control (0.2.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_fanspeedslider
|  File Check (2021.2.23) (bundled) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_file_check
|  Firmware Check (2021.2.4) (bundled) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_firmware_check
| !Firmware Updater (1.10.9) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_firmwareupdater
| !Fullscreen Plugin (0.0.6) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_fullscreen
|  GCode Viewer (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/gcodeviewer
| !ipOnConnect (0.2.4) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_ipOnConnect
|  Logging (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/logging
| !M73 Progress Plugin (0.2.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_m73progress
| !Marlin EEPROM Editor (3.0.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_eeprom_marlin
| !Navbar Temperature Plugin (0.14) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_navbartemp
|  Pi Support Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pi_support
|  Plugin Manager (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pluginmanager
| !Preheat Button (0.7.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_preheat
| !Simple Emergency Stop (1.0.4) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_simpleemergencystop
|  Software Update (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/softwareupdate
| !Tab Order (0.5.12) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_taborder
| !Tasmota (0.8.13) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_tasmota
| !Terminal Commands Extended (0.1.6) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_terminalcommandsextended
| !Themeify (1.2.2) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_themeify
|  Virtual Printer (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/virtual_printer
Prefix legend: ! = disabled, # = blacklisted, * = incompatible
2021-03-21 01:11:07,451 - octoprint.environment - INFO - Detected environment is Python 2.7.16 under Linux (linux2). Details:
|  hardware:
|      cores: 4
|      freq: 1500.0
|      ram: 3928305664
|  os:
|      bits: 64
|      id: linux
|      platform: linux2
|  plugins:
|      pi_support:
|          model: Raspberry Pi 4 Model B Rev 1.2
|          octopi_version: 0.18.0
|          throttle_state: '0x0'
|  python:
|      pip: 20.1.1
|      version: 2.7.16
|      virtualenv: /home/pi/oprint
2021-03-21 01:11:07,468 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/webassets...
2021-03-21 01:11:07,495 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/.webassets-cache...
2021-03-21 01:11:08,027 - octoprint.server - INFO - Shutting down intermediary server...
2021-03-21 01:11:08,464 - octoprint.server - INFO - Intermediary server shut down
2021-03-21 01:11:08,465 - octoprint.events - INFO - Processing startup event, this is our first event
2021-03-21 01:11:08,466 - octoprint.events - INFO - Adding 2 events to queue that were held back before startup event
2021-03-21 01:11:08,473 - octoprint.filemanager - INFO - Adding backlog items from all storage types to analysis queue...
2021-03-21 01:11:08,474 - octoprint.server - INFO - Autoconnect on startup is configured, trying to connect to the printer...
2021-03-21 01:11:08,475 - octoprint.filemanager - INFO - Added 0 items from storage type "local" to analysis queue
2021-03-21 01:11:08,479 - octoprint.plugins.softwareupdate - INFO - Fetching check overlays from https://plugins.octoprint.org/update_check_overlay.json
2021-03-21 01:11:08,526 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2021-03-21 01:11:09,652 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2021-03-21 01:11:09,669 - octoprint.server - INFO - Trying to connect to configured serial port None
2021-03-21 01:11:09,702 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Detecting serial connection"
2021-03-21 01:11:09,707 - octoprint.server.util.watchdog - INFO - Running initial scan on watched folder...
2021-03-21 01:11:09,710 - octoprint.server.util.watchdog - INFO - ... initial scan done.
2021-03-21 01:11:09,721 - octoprint.util.comm - INFO - Serial detection: Performing autodetection with 1 port/baudrate candidates: /dev/ttyUSB0@115200
2021-03-21 01:11:09,727 - octoprint.util.comm - INFO - Serial detection: Trying port /dev/ttyUSB0, baudrate 115200
2021-03-21 01:11:09,729 - octoprint.util.comm - INFO - Connecting to port /dev/ttyUSB0, baudrate 115200
2021-03-21 01:11:09,746 - octoprint.util.comm - INFO - Serial detection: Handshake attempt #1 with timeout 2.0s
2021-03-21 01:11:09,749 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-03-21 01:11:09,948 - 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 3831, in _readline
    ret = self._serial.readline()
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 6455, in readline
    c = self.read(1)
  File "/home/pi/oprint/local/lib/python2.7/site-packages/serial/serialposix.py", line 596, 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?)
2021-03-21 01:11:09,973 - octoprint.util.comm - ERROR - Please see https://faq.octoprint.org/serialerror for possible reasons of this.
2021-03-21 01:11:09,975 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial connection" to "Offline (Error: SerialException: 'device reports readiness to read but returned no data (device disconnected or multiple access on port?)' @ comm.py:_readline:3831)"
2021-03-21 01:11:09,978 - octoprint.plugins.action_command_notification - INFO - Notifications cleared
2021-03-21 01:11:10,529 - octoprint.plugins.discovery - INFO - Registered 'OctoPrint instance "EZPi Pro"._http._tcp.local.' for _http._tcp.local.
2021-03-21 01:11:11,338 - octoprint.plugins.discovery - INFO - Registered 'OctoPrint instance "EZPi Pro"._octoprint._tcp.local.' for _octoprint._tcp.local.
2021-03-21 01:11:11,347 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance "EZPi Pro" for SSDP
2021-03-21 01:11:11,361 - octoprint.server - INFO - Listening on http://127.0.0.1:5000
2021-03-21 01:11:11,364 - octoprint.server - INFO - Server started successfully in safe mode as requested from config, removing flag
2021-03-21 01:11:11,686 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2021-03-21 01:11:12,355 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python2 -m pip" as command to invoke pip
2021-03-21 01:11:12,443 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python2.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2021-03-21 01:11:12,505 - octoprint.util.pip - INFO - ==> pip ok -> yes
2021-03-21 01:11:12,591 - octoprint.plugins.softwareupdate - INFO - Minimum free storage across all update relevant locations is 24.0GB. That is considered sufficient for updating.
2021-03-21 01:11:12,641 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.1.23
2021-03-21 01:11:12,893 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2021-03-21 01:11:13,089 - octoprint.server.util.flask - INFO - Passively logging in user Greg from ::ffff:192.168.1.23
2021-03-21 01:11:13,100 - octoprint.access.users - INFO - Logged in user: Greg
2021-03-21 01:11:13,176 - octoprint.server.util.sockjs - INFO - User Greg logged in on the socket from client ::ffff:192.168.1.23
2021-03-21 01:11:13,223 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'query_string': 'l10n=en', 'path': '/', 'base_url': 'http://192.168.1.15/'}
2021-03-21 01:11:19,421 - octoprint.server.preemptive_cache - INFO - ... done in 6.20s
2021-03-21 01:11:40,577 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:192.168.1.23
2021-03-21 01:11:40,841 - octoprint.server.util.flask - INFO - Passively logging in user Greg from ::ffff:192.168.1.23
2021-03-21 01:11:40,842 - octoprint.access.users - INFO - Logged in user: Greg
2021-03-21 01:11:41,063 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.1.23
2021-03-21 01:11:41,138 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:192.168.1.23
2021-03-21 01:11:41,794 - octoprint.server.util.flask - INFO - Passively logging in user Greg from ::ffff:192.168.1.23
2021-03-21 01:11:41,795 - octoprint.access.users - INFO - Logged in user: Greg
2021-03-21 01:11:42,473 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.1.23
2021-03-21 01:11:42,517 - octoprint.server.util.flask - INFO - Passively logging in user Greg from ::ffff:192.168.1.23
2021-03-21 01:11:42,518 - octoprint.access.users - INFO - Logged in user: Greg
2021-03-21 01:11:44,447 - octoprint.server.util.sockjs - INFO - User Greg logged in on the socket from client ::ffff:192.168.1.23
2021-03-21 01:12:10,975 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Detecting serial connection"
2021-03-21 01:12:11,007 - octoprint.util.comm - INFO - Serial detection: Performing autodetection with 1 port/baudrate candidates: /dev/ttyUSB0@115200
2021-03-21 01:12:11,008 - octoprint.util.comm - INFO - Serial detection: Trying port /dev/ttyUSB0, baudrate 115200
2021-03-21 01:12:11,011 - octoprint.util.comm - INFO - Connecting to port /dev/ttyUSB0, baudrate 115200
2021-03-21 01:12:11,077 - octoprint.util.comm - INFO - Serial detection: Handshake attempt #1 with timeout 2.0s
2021-03-21 01:12:11,099 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-03-21 01:12:13,106 - octoprint.util.comm - INFO - Serial detection: Handshake attempt #2 with timeout 2.0s
2021-03-21 01:12:13,108 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-03-21 01:12:15,112 - octoprint.util.comm - INFO - Serial detection: Handshake attempt #3 with timeout 2.0s
2021-03-21 01:12:15,116 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-03-21 01:12:17,121 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial connection" to "Error: No more candidates to test, and no working port/baudrate combination detected."
2021-03-21 01:12:17,146 - octoprint.util.comm - INFO - Changing monitoring state from "Error: No more candidates to test, and no working port/baudrate combination detected." to "Offline (Error: No more candidates to test, and no working port/baudrate combination detected.)"
2021-03-21 01:12:17,160 - octoprint.plugins.action_command_notification - INFO - Notifications cleared
2021-03-21 01:12:25,512 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Detecting serial connection"
2021-03-21 01:12:25,545 - octoprint.util.comm - INFO - Serial detection: Performing autodetection with 1 port/baudrate candidates: /dev/ttyUSB0@115200
2021-03-21 01:12:25,546 - octoprint.util.comm - INFO - Serial detection: Trying port /dev/ttyUSB0, baudrate 115200
2021-03-21 01:12:25,547 - octoprint.util.comm - INFO - Connecting to port /dev/ttyUSB0, baudrate 115200
2021-03-21 01:12:25,594 - octoprint.util.comm - INFO - Serial detection: Handshake attempt #1 with timeout 2.0s
2021-03-21 01:12:25,611 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-03-21 01:12:26,531 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial connection" to "Operational"
2021-03-21 01:12:26,557 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-03-21 01:12:28,696 - octoprint.util.comm - INFO - Printer reports firmware name "Marlin Ver 1.70.2 BL (Creality3D)"
2021-03-21 01:12:28,702 - octoprint.util.comm - INFO - Firmware states that it supports temperature autoreporting
2021-03-21 01:12:35,590 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: temperature.gcode, owner: Greg, user: Greg
2021-03-21 01:12:35,609 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting"
2021-03-21 01:12:35,615 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: temperature.gcode, owner: Greg, user: Greg
2021-03-21 01:12:35,625 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-03-21 01:12:37,654 - octoprint.util.comm - INFO - Printer seems to support the busy protocol, will adjust timeouts and set busy interval accordingly
2021-03-21 01:13:02,322 - octoprint.util.comm - INFO - Telling the printer to set the busy interval to our "communicationBusy" timeout - 1s = 2s
2021-03-21 01:13:02,339 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2021-03-21 01:15:39,476 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:192.168.1.23

Additional information about your setup

OctoPrint version, OctoPi version, printer, firmware, browser, operating system, ... as much data as possible

OctoPrint 1.5.3
OctoPi is TH3D EZPi which uses a RPi-4B ver 1.2 preloaded with Octoprint

PrintedWeezl · March 21, 2021, 1:22am

Just to be sure - was the printer powered on?

GregH · March 21, 2021, 2:17am

LOL, yes and not via the RPi. To be more explicit and clear, the RPi is using the supply that shipped with the unit from TH3D. The E5+ is using its internal power supply. The RPi is connected via USB to the E5+ mainboard.

b-morgan · March 21, 2021, 1:42pm

I think we are going to need a serial.log (click link for instructions) to help troubleshoot this issue. You will need to enable it and capture the failure.

Have you isolated the 5V pin in the USB cable? What firmware is installed in the printer?

GregH · March 21, 2021, 3:24pm

Serial log from today's very repeatable experience. It doesn't have any red flags of which we're not already aware. That's actually a good thing. Read on...

==========================
2021-03-21 14:47:47,877 - Recv:  == T:21.17 /0.00 == B:20.04 /0.00 @:0 B@:0
2021-03-21 14:47:48,338 - Send: M117 Preheating...
2021-03-21 14:47:48,360 - Recv: ok
2021-03-21 14:47:48,362 - Send: M140 S60.0
2021-03-21 14:47:48,373 - Recv: ok
2021-03-21 14:47:48,374 - Send: M104 S200.0
2021-03-21 14:47:48,389 - Recv: ok
2021-03-21 14:47:49,877 - Recv:  == T:21.21 /200.00 == B:20.00 /60.00 @:127 B@:0
2021-03-21 14:47:51,876 - Recv:  == T:22.11 /200.00 == B:20.04 /60.00 @:127 B@:0
2021-03-21 14:47:53,876 - Recv:  == T:24.73 /200.00 == B:20.00 /60.00 @:127 B@:0
2021-03-21 14:47:55,876 - Recv:  == T:28.12 /200.00 == B:20.04 /60.00 @:127 B@:0
2021-03-21 14:47:57,876 - Recv:  == T:32.68 /200.00 == B:20.04 /60.00 @:127 B@:0
2021-03-21 14:47:59,875 - Recv:  == T:38.17 /200.00 == B:20.00 /60.00 @:127 B@:0
2021-03-21 14:48:01,875 - Recv:  == T:43.51 /200.00 == B:20.04 /60.00 @:127 B@:0
2021-03-21 14:48:03,875 - Recv:  == T:49.14 /200.00 == B:20.00 /60.00 @:127 B@:0
2021-03-21 14:48:05,875 - Recv:  == T:54.69 /200.00 == B:20.08 /60.00 @:127 B@:0
2021-03-21 14:48:07,874 - Recv:  == T:60.27 /200.00 == B:20.08 /60.00 @:127 B@:0
2021-03-21 14:48:09,874 - Recv:  == T:66.16 /200.00 == B:20.04 /60.00 @:127 B@:0
2021-03-21 14:48:11,874 - Recv:  == T:71.62 /200.00 == B:20.00 /60.00 @:127 B@:0
2021-03-21 14:48:13,873 - Recv:  == T:77.01 /200.00 == B:20.08 /60.00 @:127 B@:0
2021-03-21 14:48:15,873 - Recv:  == T:82.29 /200.00 == B:20.08 /60.00 @:127 B@:0
2021-03-21 14:48:17,873 - Recv:  == T:87.36 /200.00 == B:20.08 /60.00 @:127 B@:0
2021-03-21 14:48:19,873 - Recv:  == T:92.80 /200.00 == B:20.08 /60.00 @:127 B@:0
2021-03-21 14:48:21,872 - Recv:  == T:97.81 /200.00 == B:20.04 /60.00 @:127 B@:0
2021-03-21 14:48:23,872 - Recv:  == T:102.62 /200.00 == B:20.12 /60.00 @:127 B@:0
2021-03-21 14:48:25,872 - Recv:  == T:107.31 /200.00 == B:20.08 /60.00 @:127 B@:0
2021-03-21 14:48:27,871 - Recv:  == T:112.38 /200.00 == B:20.16 /60.00 @:127 B@:0
2021-03-21 14:48:29,871 - Recv:  == T:116.99 /200.00 == B:20.16 /60.00 @:127 B@:0
2021-03-21 14:48:31,871 - Recv:  == T:121.43 /200.00 == B:20.04 /60.00 @:127 B@:0
2021-03-21 14:48:33,871 - Recv:  == T:125.82 /200.00 == B:20.08 /60.00 @:127 B@:0
2021-03-21 14:48:35,870 - Recv:  == T:130.13 /200.00 == B:20.12 /60.00 @:127 B@:0
2021-03-21 14:48:37,870 - Recv:  == T:134.65 /200.00 == B:20.12 /60.00 @:127 B@:0
2021-03-21 14:48:39,870 - Recv:  == T:138.87 /200.00 == B:20.12 /60.00 @:127 B@:0
2021-03-21 14:48:41,869 - Recv:  == T:142.97 /200.00 == B:20.12 /60.00 @:127 B@:0
2021-03-21 14:48:43,869 - Recv:  == T:146.96 /200.00 == B:20.16 /60.00 @:127 B@:0
2021-03-21 14:48:45,869 - Recv:  == T:150.87 /200.00 == B:20.12 /60.00 @:127 B@:0
2021-03-21 14:48:47,868 - Recv:  == T:154.99 /200.00 == B:20.16 /60.00 @:127 B@:0
2021-03-21 14:48:49,868 - Recv:  == T:158.87 /200.00 == B:20.20 /60.00 @:127 B@:0
2021-03-21 14:48:51,868 - Recv:  == T:162.66 /200.00 == B:20.04 /60.00 @:127 B@:0
2021-03-21 14:48:53,868 - Recv:  == T:166.37 /200.00 == B:20.12 /60.00 @:127 B@:0
2021-03-21 14:48:55,867 - Recv:  == T:169.90 /200.00 == B:20.04 /60.00 @:127 B@:0
2021-03-21 14:48:57,867 - Recv:  == T:173.83 /200.00 == B:20.16 /60.00 @:127 B@:0
2021-03-21 14:48:59,867 - Recv:  == T:177.42 /200.00 == B:20.16 /60.00 @:127 B@:0
2021-03-21 14:49:01,866 - Recv:  == T:180.84 /200.00 == B:20.12 /60.00 @:127 B@:0
2021-03-21 14:49:03,866 - Recv:  == T:184.38 /200.00 == B:20.16 /60.00 @:127 B@:0
2021-03-21 14:49:05,866 - Recv:  == T:187.81 /200.00 == B:20.16 /60.00 @:127 B@:0
2021-03-21 14:49:07,866 - Recv:  == T:191.51 /200.00 == B:20.16 /60.00 @:56 B@:0
2021-03-21 14:49:09,865 - Recv:  == T:194.55 /200.00 == B:20.20 /60.00 @:36 B@:0
2021-03-21 14:49:11,865 - Recv:  == T:196.62 /200.00 == B:20.20 /60.00 @:29 B@:0
2021-03-21 14:49:13,865 - Recv:  == T:197.67 /200.00 == B:20.16 /60.00 @:36 B@:0
2021-03-21 14:49:15,864 - Recv:  == T:198.07 /200.00 == B:20.16 /60.00 @:49 B@:0
2021-03-21 14:49:17,864 - Recv:  == T:197.90 /200.00 == B:20.04 /60.00 @:68 B@:0
2021-03-21 14:49:19,864 - Recv:  == T:197.59 /200.00 == B:20.12 /60.00 @:84 B@:0
2021-03-21 14:49:21,864 - Recv:  == T:197.53 /200.00 == B:20.16 /60.00 @:92 B@:0
2021-03-21 14:49:23,863 - Recv:  == T:197.76 /200.00 == B:20.20 /60.00 @:93 B@:0
2021-03-21 14:49:25,863 - Recv:  == T:198.47 /200.00 == B:20.12 /60.00 @:84 B@:0
2021-03-21 14:49:27,863 - Recv:  == T:199.29 /200.00 == B:20.27 /60.00 @:72 B@:0
2021-03-21 14:49:29,862 - Recv:  == T:200.17 /200.00 == B:20.31 /60.00 @:58 B@:0
2021-03-21 14:49:31,862 - Recv:  == T:201.15 /200.00 == B:20.23 /60.00 @:42 B@:0
2021-03-21 14:49:33,878 - Recv:  == T:201.67 /200.00 == B:20.20 /60.00 @:35 B@:0
2021-03-21 14:49:35,877 - Recv:  == T:201.74 /200.00 == B:20.23 /60.00 @:36 B@:0
2021-03-21 14:49:37,877 - Recv:  == T:201.56 /200.00 == B:20.20 /60.00 @:39 B@:0
2021-03-21 14:49:39,876 - Recv:  == T:201.04 /200.00 == B:20.12 /60.00 @:48 B@:0
2021-03-21 14:49:41,875 - Recv:  == T:200.21 /200.00 == B:20.20 /60.00 @:63 B@:0
2021-03-21 14:49:43,874 - Recv:  == T:199.57 /200.00 == B:20.20 /60.00 @:73 B@:0
2021-03-21 14:49:45,873 - Recv:  == T:199.29 /200.00 == B:20.23 /60.00 @:76 B@:0
2021-03-21 14:49:47,872 - Recv:  == T:199.26 /200.00 == B:20.23 /60.00 @:74 B@:0
2021-03-21 14:49:49,871 - Recv:  == T:199.40 /200.00 == B:20.16 /60.00 @:71 B@:0
2021-03-21 14:49:51,871 - Recv:  == T:199.77 /200.00 == B:20.16 /60.00 @:63 B@:0
2021-03-21 14:49:53,870 - Recv:  == T:200.35 /200.00 == B:20.23 /60.00 @:52 B@:0
2021-03-21 14:49:55,869 - Recv:  == T:200.49 /200.00 == B:20.27 /60.00 @:51 B@:0
2021-03-21 14:49:57,868 - Recv:  == T:200.76 /200.00 == B:20.20 /60.00 @:46 B@:0
2021-03-21 14:49:59,867 - Recv:  == T:200.94 /200.00 == B:20.16 /60.00 @:42 B@:0
2021-03-21 14:50:01,867 - Recv:  == T:200.56 /200.00 == B:20.12 /60.00 @:50 B@:0
2021-03-21 14:50:03,866 - Recv:  == T:200.28 /200.00 == B:20.12 /60.00 @:55 B@:0
2021-03-21 14:50:05,865 - Recv:  == T:199.91 /200.00 == B:20.20 /60.00 @:61 B@:0
2021-03-21 14:50:07,865 - Recv:  == T:199.55 /200.00 == B:20.20 /60.00 @:68 B@:0
2021-03-21 14:50:09,864 - Recv:  == T:199.49 /200.00 == B:20.27 /60.00 @:68 B@:0
2021-03-21 14:50:11,863 - Recv:  == T:199.52 /200.00 == B:20.27 /60.00 @:67 B@:0
2021-03-21 14:50:13,863 - Recv:  == T:199.66 /200.00 == B:20.20 /60.00 @:64 B@:0
2021-03-21 14:50:15,862 - Recv:  == T:200.00 /200.00 == B:20.27 /60.00 @:57 B@:0
2021-03-21 14:50:17,861 - Recv:  == T:200.17 /200.00 == B:20.23 /60.00 @:54 B@:0
2021-03-21 14:50:19,861 - Recv:  == T:200.31 /200.00 == B:20.20 /60.00 @:52 B@:0
2021-03-21 14:50:21,860 - Recv:  == T:200.38 /200.00 == B:20.23 /60.00 @:52 B@:0
2021-03-21 14:50:23,860 - Recv:  == T:200.35 /200.00 == B:20.20 /60.00 @:52 B@:0
2021-03-21 14:50:25,859 - Recv:  == T:200.24 /200.00 == B:20.31 /60.00 @:54 B@:0
2021-03-21 14:50:27,859 - Recv:  == T:200.00 /200.00 == B:20.31 /60.00 @:59 B@:0
2021-03-21 14:50:29,858 - Recv:  == T:199.91 /200.00 == B:20.23 /60.00 @:60 B@:0
2021-03-21 14:50:31,858 - Recv:  == T:199.77 /200.00 == B:20.27 /60.00 @:62 B@:0
2021-03-21 14:50:33,857 - Recv:  == T:199.63 /200.00 == B:20.27 /60.00 @:65 B@:0
2021-03-21 14:50:35,857 - Recv:  == T:199.69 /200.00 == B:20.27 /60.00 @:64 B@:0
2021-03-21 14:50:37,856 - Recv:  == T:199.97 /200.00 == B:20.31 /60.00 @:58 B@:0
2021-03-21 14:50:39,856 - Recv:  == T:200.07 /200.00 == B:20.31 /60.00 @:56 B@:0
2021-03-21 14:50:41,855 - Recv:  == T:200.17 /200.00 == B:20.27 /60.00 @:55 B@:0
2021-03-21 14:50:43,855 - Recv:  == T:200.31 /200.00 == B:20.23 /60.00 @:52 B@:0
2021-03-21 14:50:45,854 - Recv:  == T:200.24 /200.00 == B:20.35 /60.00 @:54 B@:0
2021-03-21 14:50:47,854 - Recv:  == T:200.10 /200.00 == B:20.31 /60.00 @:57 B@:0
2021-03-21 14:50:48,599 - Recv: Error:Heating failed, system stopped! Heater_ID: bed
2021-03-21 14:50:48,601 - Recv: Error:Printer halted. kill() called!
2021-03-21 14:50:48,606 - Changing monitoring state from "Operational" to "Error: Heating failed, system stopped! Heater_ID: bed - Printer halted. kill() called!"
2021-03-21 14:50:48,624 - Send: M112
2021-03-21 14:50:48,629 - Send: N2 M112*35
2021-03-21 14:50:48,631 - Send: N3 M104 T0 S0*34
2021-03-21 14:50:48,632 - Send: N4 M140 S0*97
2021-03-21 14:50:48,645 - Changing monitoring state from "Error: Heating failed, system stopped! Heater_ID: bed - Printer halted. kill() called!" to "Offline (Error: Heating failed, system stopped! Heater_ID: bed - Printer halted. kill() called!)"
2021-03-21 14:50:48,662 - Connection closed, closing down monitor
====================================

Following the above failure, and to be certain of the issue, I again manually set the bed element heat using the unit's LCD panel. Something unusual happened in that this time the bed did not heat at all. Previously when I'd done this, albeit this is a brand new setup so the number of attempts is small but, manually setting the heat would work. Today, nada.
Bed resistance measurement is ~1.4Ω. With DC VMM at bed power connector I ran another manual bed heat cycle and measured 24.1Vdc. Hmm, all seems good now. Set unit to cool and VMM went to zero. Reconnected bed power cable. Set unit to heat and bed began to heat. WHAT!?!?!

So, all my previous attempts to troubleshoot and isolate were matched by improbable coincidence leading me to believe that the problem was with Octoprint and/or the RPi. With today's experience this no longer appears to be the case.

Conclusion: The E5+ mobo's bed power driver appears to be failing intermittently.

b-morgan · March 22, 2021, 1:31pm

Yet another Creality anomaly to add to the list.