New install webserver crash - Stuck on Anonymous Usage wizard

Mike_Mitchell · August 12, 2019, 7:15pm

On a new install of octopi-stretch-lite-0.16.0, which is OctoPrint 1.3.10 on an Rpi3B, I can't get past the Anonymous Usage wizard. Problem is similar to this issue, but this looked closed and unsolved: https://community.octoprint.org/t/anonymous-usage-setup/5151

Pressing either button results in a hang of the webserver. You can't open any new connections to it until the Rpi is rebooted, you get 504 errors.
I also noticed that even without pressing the button, the webserver is really hung, since it wont accept new connections from any browser after the first one, which leads me to think the issue is more basic, and not related to setting Anonymous specifically.

So it seems this console log maybe relevant:

Console Log:

nsLoginManager: searchLogins: `formSubmitURL` or `httpRealm` is recommended LoginManager.jsm:392:13
Invalid chrome URI: /
Password fields present on an insecure (http://) page. This is a security risk that allows user login credentials to be stolen. 192.168.1.12
[Exception... "Favicon at "http://192.168.1.12/favicon.ico" failed to load: NOT FOUND."  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource:///modules/FaviconLoader.jsm :: onStopRequest :: line 199"  data: no] FaviconLoader.jsm:199:42
nsLoginManager: searchLogins: `formSubmitURL` or `httpRealm` is recommended LoginManager.jsm:392:13
Invalid chrome URI: / 2
nsLoginManager: searchLogins: `formSubmitURL` or `httpRealm` is recommended 4 LoginManager.jsm:392:13
Invalid chrome URI: / 4
Password fields present on an insecure (http://) page. This is a security risk that allows user login credentials to be stolen. 4 192.168.1.12
Starting dependency resolution... packed_core.js:15919:13
... dependency resolution done packed_core.js:16029:13
Initial application setup done, connecting to server... packed_core.js:16333:13
Connected to the server packed_core.js:14069:13
Finalizing application startup packed_core.js:16311:17
Going to bind 38 view models... packed_core.js:16195:17
Did not bind view model CoreWizardAclViewModel to target #wizard_plugin_corewizard_acl since it does not exist packed_core.js:16248:37
Did not bind view model CoreWizardWebcamViewModel to target #wizard_plugin_corewizard_webcam since it does not exist packed_core.js:16248:37
Did not bind view model CoreWizardServerCommandsViewModel to target #wizard_plugin_corewizard_servercommands since it does not exist packed_core.js:16248:37
Did not bind view model SoftwareUpdateViewModel to target #softwareupdate_confirmation_dialog since it does not exist packed_core.js:16248:37
Did not bind view model SoftwareUpdateViewModel to target #wizard_plugin_softwareupdate since it does not exist packed_core.js:16248:37
User printer logged in packed_core.js:2443:29
... binding done packed_core.js:16287:17
Application startup complete packed_core.js:16307:17
1565636664440	addons.update-checker	WARN	onUpdateCheckComplete failed to parse update manifest: [Exception... "Update manifest is missing a required addons property."  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource://gre/modules/addons/AddonUpdateChecker.jsm :: getRequiredProperty :: line 119"  data: no] Stack trace: getRequiredProperty()@resource://gre/modules/addons/AddonUpdateChecker.jsm:119
parseJSONManifest()@resource://gre/modules/addons/AddonUpdateChecker.jsm:129
onLoad()@resource://gre/modules/addons/AddonUpdateChecker.jsm:289
UpdateParser/<()@resource://gre/modules/addons/AddonUpdateChecker.jsm:239

octoprint.log

2019-08-12 11:57:25,171 - octoprint.startup - INFO - ******************************************************************************
2019-08-12 11:57:25,173 - octoprint.startup - INFO - Starting OctoPrint 1.3.10
2019-08-12 11:57:25,178 - octoprint.startup - INFO - ******************************************************************************
2019-08-12 11:57:26,435 - 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...
2019-08-12 11:57:28,816 - octoprint.plugin.core - INFO - Found 15 plugin(s) providing 15 mixin implementations, 17 hook handlers
2019-08-12 11:57:28,939 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval
2019-08-12 11:57:28,990 - octoprint.server - INFO - Intermediary server started
2019-08-12 11:57:28,991 - 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...
2019-08-12 11:57:29,558 - octoprint.plugin.core - INFO - Found 15 plugin(s) providing 15 mixin implementations, 17 hook handlers
2019-08-12 11:57:29,602 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads...
2019-08-12 11:57:29,604 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully.
2019-08-12 11:57:29,650 - octoprint.plugins.softwareupdate - INFO - Loaded version cache from disk
2019-08-12 11:57:31,517 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python2 -m pip" as command to invoke pip
2019-08-12 11:57:32,972 - octoprint.util.pip - INFO - Version of pip is 19.0.1
2019-08-12 11:57:32,974 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python2.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2019-08-12 11:57:32,974 - octoprint.util.pip - INFO - ==> pip ok -> yes
2019-08-12 11:57:32,979 - octoprint.plugin.core - INFO - Initialized 15 plugin implementation(s)
2019-08-12 11:57:32,988 - octoprint.plugin.core - INFO - 15 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
|  CuraEngine (<= 15.04) (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/cura
|  Discovery (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/discovery
|  Force Login (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/forcelogin
|  Logging (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/logging
|  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
|  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
2019-08-12 11:57:33,010 - octoprint.environment - INFO - Detected environment is Python 2.7.13 under Linux (linux2). Details:
|  hardware:
|    cores: 4
|    freq: 1400.0
|    ram: 918188032
|  os:
|    id: linux
|    platform: linux2
|  plugins:
|    pi_support:
|      model: Raspberry Pi 3 Model B Plus Rev 1.3
|      octopi_version: 0.16.0
|  python:
|    pip: 19.0.1
|    version: 2.7.13
|    virtualenv: /home/pi/oprint
2019-08-12 11:57:33,022 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/webassets...
2019-08-12 11:57:33,038 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/.webassets-cache...
2019-08-12 11:57:33,444 - octoprint.server - INFO - Shutting down intermediary server...
2019-08-12 11:57:33,517 - octoprint.server - INFO - Intermediary server shut down
2019-08-12 11:57:33,520 - octoprint.events - INFO - Processing startup event, this is our first event
2019-08-12 11:57:33,520 - octoprint.events - INFO - Adding 0 events to queue that were held back before startup event
2019-08-12 11:57:33,522 - octoprint.filemanager - INFO - Adding backlog items from all storage types to analysis queue...
2019-08-12 11:57:33,528 - octoprint.filemanager - INFO - Added 0 items from storage type "local" to analysis queue
2019-08-12 11:57:33,543 - octoprint.plugins.discovery - INFO - Registered 'OctoPrint instance on octopi' for _http._tcp
2019-08-12 11:57:33,553 - octoprint.plugins.discovery - INFO - Registered 'OctoPrint instance on octopi' for _octoprint._tcp
2019-08-12 11:57:33,565 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance on octopi for SSDP
2019-08-12 11:57:33,576 - octoprint.server - INFO - Listening on http://127.0.0.1:5000
2019-08-12 11:57:33,615 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2019-08-12 11:57:34,016 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2019-08-12 11:57:35,065 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python2 -m pip" as command to invoke pip
2019-08-12 11:57:35,066 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python2.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2019-08-12 11:57:35,067 - octoprint.util.pip - INFO - ==> pip ok -> yes
2019-08-12 11:57:36,973 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python2 -m pip" as command to invoke pip
2019-08-12 11:58:09,953 - tornado.access - WARNING - 404 GET /favicon.ico (::ffff:192.168.1.4) 20.96ms
2019-08-12 11:58:09,963 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.1.4
2019-08-12 12:02:09,810 - octoprint.server.api - INFO - Actively logging in user printer from ::ffff:192.168.1.4
2019-08-12 12:02:09,842 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:192.168.1.4
2019-08-12 12:02:10,118 - octoprint.server.util.flask - INFO - Passively logging in user printer from ::ffff:192.168.1.4
2019-08-12 12:02:21,200 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.1.4
2019-08-12 12:02:21,283 - octoprint.server.util.flask - INFO - Passively logging in user printer from ::ffff:192.168.1.4
2019-08-12 12:02:22,243 - octoprint.server.util.sockjs - INFO - User printer logged in on the socket from client ::ffff:192.168.1.4

OutsourcedGuru · August 12, 2019, 10:14pm

Are you running an ad blocker on your browser?
Your browser name/version would help in all this.
What happens when you click Finish?

Mike_Mitchell · August 12, 2019, 10:40pm

No, I tried disabling it.
I've tried Firefox 68.0.1 and Chrome 75.0.3770.142
Finish also hangs. You can click next, but you can't click anything that makes another request. It's just hung until reboot - or sending HUP to the python2 process. SSH is fine though, RPi is fine.

Mike_Mitchell · August 13, 2019, 5:38am

The problem appears to have solved itself. I'm not exactly sure how I got around it, but the steps I used were:

Have the webpage open and restart the octoprint from the command line.
Restart sudo service octoprint restart then when the webpage reloaded, I got a popup to update to 1.3.11.
Install the update.
Restart using sudo service octoprint restart again

Ewald_Ikemann · August 13, 2019, 2:40pm

Great! Could you please: PSA: Please mark the solutions to your topics as such

OutsourcedGuru · August 13, 2019, 3:57pm

I do know that foosel was working on an issue that sounded like this. I'm guessing that she fixed it in 1.3.11, in theory.

What's interesting is that you pulled in the OctoPi image that still contains Stretch and OP 1.3.10. The Buster-still-isn't-mainstream-yet thing is possibly preventing them from creating a major-version image for OctoPi.