Server not running after 1.4.0 update

Get Help
1

What is the problem?
After initiating the 1.4.0 update via the webpage interface, I am unable to connect to the server. Entering the Raspberry Pi's IP address in a browser shows an error page stating that "The OctoPrint server is not currently running."

What did you already try to solve it?
Per the error page, I have verified that the process is not running (ps -ef | grep -i octoprint | grep -i python), and attempted to restart the service (sudo service octoprint restart), with no luck (no error, but service doesn't appear to start). Looking at the log suggests that something went wrong while it was updating. I have also rerun the pip install commands (per How can I update the OctoPrint installation on my OctoPi image?), which returns the following:

Looking in indexes: [link redacted due to posting restrictions]
Requirement already up-to-date: octoprint in ./oprint/lib/python2.7/site-packages (1.4.0)

And has no impact on the service restart command, seemingly.

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

2020-03-05 10:53:04,426 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-03-05 10:53:04,431 - octoprint.server - INFO - --- Log roll over detected ---------------------------------------------------
2020-03-05 10:53:04,432 - octoprint.server - INFO - OctoPrint 1.3.12
2020-03-05 10:53:04,439 - octoprint.plugin.core - INFO - 21 plugin(s) registered with the system:
| 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
| Backup & Restore (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/backup
| 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
| Error Tracking (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/errortracking
| Force Login (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/forcelogin
| GcodeEditor (0.2.6) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_GcodeEditor
| HeaterTimeout (0.0.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_HeaterTimeout
| LED Strip Control (0.3.6) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_LEDStripControl
| Logging (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/logging
| M73 Progress Plugin (0.2.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_m73progress
| Multi Colors (1.0.16) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_multi_colors
| 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
| Printer Safety Check (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/printer_safety_check
| Progress Title (0.1.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_progress_title
| Software Update (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/softwareupdate
| Virtual Printer (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/virtual_printer
2020-03-05 10:53:04,466 - octoprint.environment - INFO - Detected environment is Python 2.7.13 under Linux (linux2). Details:
| hardware:
| cores: 4
| freq: 1200.0
| ram: 918188032
| os:
| id: linux
| platform: linux2
| plugins:
| pi_support:
| model: Raspberry Pi 3 Model B Rev 1.2
| octopi_version: 0.16.0
| python:
| pip: 19.0.1
| version: 2.7.13
| virtualenv: /home/pi/oprint
2020-03-05 10:53:04,467 - octoprint.server - INFO - ------------------------------------------------------------------------------
2020-03-05 10:53:07,021 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 421224}
2020-03-05 11:08:04,428 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-03-05 11:08:07,716 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 422124}
2020-03-05 11:23:04,431 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-03-05 11:23:06,966 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 423024}
2020-03-05 11:23:10,470 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Pausing"
2020-03-05 11:23:10,472 - octoprint.filemanager.analysis - INFO - Starting analysis of local:LM2SE05MM_order_2041_12f7a1ad.gcode
2020-03-05 11:23:10,477 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python2 -m octoprint analysis gcode --speed-x=18000 --speed-y=18000 --max-t=10 --throttle=0.0 --throttle-lines=100 /home/pi/.octoprint/uploads/LM2SE05MM_order_2041_12f7a1ad.gcode
2020-03-05 11:23:14,937 - octoprint.printer.standard.job - INFO - Print job paused - origin: local, path: LM2SE05MM_order_2041_12f7a1ad.gcode, owner: _api, user: lulzbot
2020-03-05 11:23:14,947 - octoprint.util.comm - INFO - Changing monitoring state from "Pausing" to "Paused"
2020-03-05 11:23:22,763 - octoprint.filemanager.analysis - INFO - Analysis of entry local:LM2SE05MM_order_2041_12f7a1ad.gcode finished, needed 12.29s
2020-03-05 11:27:51,704 - octoprint.util.comm - INFO - Changing monitoring state from "Paused" to "Resuming"
2020-03-05 11:27:51,712 - octoprint.printer.standard.job - INFO - Print job resumed - origin: local, path: LM2SE05MM_order_2041_12f7a1ad.gcode, owner: _api, user: None
2020-03-05 11:27:51,718 - octoprint.util.comm - INFO - Changing monitoring state from "Resuming" to "Printing"
2020-03-05 11:27:51,732 - octoprint.util.comm - INFO - Pausing print job due to command M0
2020-03-05 11:27:51,735 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Pausing"
2020-03-05 11:27:51,738 - octoprint.util.comm - INFO - Not sending M0 to printer, it's configured as a blocked command
2020-03-05 11:27:51,818 - octoprint.printer.standard.job - INFO - Print job paused - origin: local, path: LM2SE05MM_order_2041_12f7a1ad.gcode, owner: _api, user: None
2020-03-05 11:27:51,829 - octoprint.util.comm - INFO - Changing monitoring state from "Pausing" to "Paused"
2020-03-05 11:28:42,681 - octoprint.util.comm - INFO - Changing monitoring state from "Paused" to "Resuming"
2020-03-05 11:28:42,709 - octoprint.printer.standard.job - INFO - Print job resumed - origin: local, path: LM2SE05MM_order_2041_12f7a1ad.gcode, owner: _api, user: lulzbot
2020-03-05 11:28:42,730 - octoprint.util.comm - INFO - Changing monitoring state from "Resuming" to "Printing"
2020-03-05 11:38:04,432 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-03-05 11:38:08,120 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 423924}
2020-03-05 11:48:47,758 - octoprint.util.comm - INFO - Finished in 4092.566 s.
2020-03-05 11:48:47,760 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Finishing"
2020-03-05 11:48:47,779 - octoprint.printer.standard.job - INFO - Print job done - origin: local, path: LM2SE05MM_order_2041_12f7a1ad.gcode, owner: _api
2020-03-05 11:48:47,840 - octoprint.util.comm - INFO - Changing monitoring state from "Finishing" to "Operational"
2020-03-05 11:48:48,992 - octoprint.plugins.tracking - INFO - Sent tracking event print_done, payload: {'origin': 'local', 'throttled_mask': 327680, 'elapsed': 3760, 'file': 'c38dcb116070cbc69cc932e293aa2692ee19cf14', 'throttled_now': False, 'throttled_past': True}
2020-03-05 11:53:04,434 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-03-05 11:53:07,443 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 424824}
2020-03-05 11:56:13,221 - octoprint.plugins.softwareupdate - INFO - Starting update of octoprint to 1.4.0...

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.16.0
Printer: Lulzbot Mini 2
Firmware: Marlin 2.0.0
Operating system: Windows 10
Browser: Chrome

2

If that's the last log then OctoPrint did not start up again as 1.4 or the upgrade failed in the middle of that. Clearly, it doesn't indicate that it's running as 1.4. The only indication is right at the end where it starts the update and says nothing else after that. It seems relatively clean other than this (noting a past throttling event, though).

ps -ax | grep octoprint
ps -ax | grep haproxy
ls -lt ~/.octoprint/logs
3

Hi OutsourcedGuru,

Thanks for your reply. I agree that it looks like it failed during the installation. I'm trying to figure out how to manually restart the process. Here's the output from your suggested queries:

pi@octopi:~ $ ps -ax | grep octoprint
1727 pts/0 S+ 0:00 grep --color=auto octoprint
pi@octopi:~ $ ps -ax | grep haproxy
572 ? Ss 0:00 /usr/sbin/haproxy-systemd-wrapper -f /etc/haproxy/hap roxy.cfg -p /run/haproxy.pid
574 ? S 0:00 /usr/sbin/haproxy-master
575 ? Ss 0:40 /usr/sbin/haproxy -f /etc/haproxy/haproxy.cfg -p /run /haproxy.pid -Ds
1729 pts/0 S+ 0:00 grep --color=auto haproxy
pi@octopi:~ $ ls -lt ~/.octoprint/logs
total 1324
-rw-r--r-- 1 pi pi 8192 Mar 5 11:58 octoprint.log
-rw-r--r-- 1 pi pi 54535 Mar 5 11:57 plugin_softwareupdate_console.log
-rw-r--r-- 1 pi pi 25718 Mar 5 10:41 octoprint.log.2020-03-04
-rw-r--r-- 1 pi pi 77862 Mar 4 10:41 octoprint.log.2020-03-03
-rw-r--r-- 1 pi pi 1036 Mar 3 16:40 serial.log
-rw-r--r-- 1 pi pi 23268 Mar 3 10:41 octoprint.log.2020-03-02
-rw-r--r-- 1 pi pi 23240 Mar 2 10:41 octoprint.log.2020-03-01
-rw-r--r-- 1 pi pi 984495 Mar 1 10:41 octoprint.log.2020-02-29
-rw-r--r-- 1 pi pi 444 Feb 29 10:35 serial.log.2020-02-29_10-35-12
-rw-r--r-- 1 pi pi 888 Feb 29 10:15 serial.log.2020-02-29_10-15-40
-rw-r--r-- 1 pi pi 24580 Feb 28 12:42 octoprint.log.2020-02-27
-rw-r--r-- 1 pi pi 148 Feb 18 15:25 serial.log.2020-02-18_15-25-38
-rw-r--r-- 1 pi pi 11358 Feb 13 10:44 plugin_pluginmanager_console.log
-rw-r--r-- 1 pi pi 57088 Oct 24 12:05 plugin_pluginmanager_console.log.2019-10- 24
-rw-r--r-- 1 pi pi 0 Nov 13 2018 plugin_pluginmanager_console.log.2018-11- 13
-rw-r--r-- 1 pi pi 0 Nov 13 2018 plugin_cura_engine.log

4

Are you sure you gave us the latest octoprint.log? You might double-check. And it would be good to see what's going on in your plugin_softwareupdate_console.log.

5

Quite sure. It's the latest log and the only one that isn't dated in the filename. Here's the last few lines of plugin_softwareupdate_console.log:

2020-03-05 11:57:51,366 > Successfully uninstalled futures-3.2.0
2020-03-05 11:57:51,367 > Found existing installation: OctoPrint 1.3.12
2020-03-05 11:57:52,633 > Uninstalling OctoPrint-1.3.12:
2020-03-05 11:57:52,634 > Successfully uninstalled OctoPrint-1.3.12
2020-03-05 11:57:52,634 > Running setup.py install for OctoPrint: started
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@

These escape characters show up in the octoprint.log as well but apparently didn't get copied when I grabbed the log to my local machine -- they only show up in less. So again, looks like something gnarly happened in the middle of the install, but running pip again isn't fixing it.

6

Okay, I managed to trick it into reinstalling 1.4.0 by using the method described here: Octopi not loading after the last upgrade by aolshove

to roll back to 1.3.10. That allowed the server to restart, and I was then prompted to upgrade to 1.4.0 again. A bit clunky, but it seems to have worked.

2 Likes
7

I'm pretty sure that those Ctl+@ symbols represent a 0x00 character. The log was trashed (corrupted?) would be a guess.

It sounds like you're back in business, though.