Clon1998 / mobileraker_companion

Companion for mobileraker, enabling push notification.
MIT License
203 stars 12 forks source link

Installed, now mainsail webgui stick on Initializing #72

Closed TheAussieTim closed 9 months ago

TheAussieTim commented 9 months ago

I've followed the installation steps to install the companion onto my RPi hosted Klipper/Mainsail (fully updated versions), however now I am not able to load the webgui - I'm stuck on the webpage saying "Initializing" and ERROR in the top of the browser.

I didn't see any errors during the installation. I have also added the companion update info to moonraker.conf

Fortunately I do still have SSH onto the Pi. When I inspect the moonraker.log I'm now seeing a repeat of this:

2023-12-30 00:06:19,440 [websockets.py:open()] - Websocket Opened: ID: 3887449976, Proxied: False, User Agent: , Host Name: 0.0.0.0 2023-12-30 00:06:19,446 [common.py:build_error()] - JSON-RPC Request Error - Requested Method: server.connection.identify, Code: 400, Message: Agent 'OctoEverywhere' already registere> 2023-12-30 00:06:19,449 [common.py:build_error()] - JSON-RPC Request Error - Requested Method: server.database.post_item, Code: -31000, Message: Attempt to operate on closed/deleted/d> 2023-12-30 00:06:19,456 [websockets.py:on_close()] - Websocket Closed: ID: 3887449976 Close Code: 1000, Close Reason: None, Pong Time Elapsed: 0.02

octoeverywhere.log is repeating this:

2023-12-30 00:09:53,628 - INFO - Moonraker client websocket shutdown called. 2023-12-30 00:09:53,630 - INFO - Moonraker client websocket shutdown complete. 2023-12-30 00:10:13,647 - INFO - Moonraker websocket connection closed. 2023-12-30 00:10:13,648 - INFO - Moonraker client websocket connection lost. We will try to restart it soon. 2023-12-30 00:10:15,653 - INFO - Connecting to moonraker: ws://0.0.0.0:7125/websocket 2023-12-30 00:10:15,660 - INFO - Websocket connected 2023-12-30 00:10:15,662 - INFO - Moonraker client websocket opened. 2023-12-30 00:10:15,662 - INFO - Moonraker client waiting for klippy ready... 2023-12-30 00:10:15,663 - INFO - Authenticating with moonraker... 2023-12-30 00:10:15,669 - ERROR - Ensure database entry item post failed. -31000 - Attempt to operate on closed/deleted/dropped object. 2023-12-30 00:10:15,670 - INFO - Moonraker client waiting for klippy ready... 2023-12-30 00:10:15,673 - ERROR - Moonraker client is in an unknown klippy waiting state. state 'disconnected' 2023-12-30 00:10:15,673 - ERROR - Moonraker client exception in klippy waiting logic.; Exception Exception: Unknown klippy waiting state. disconnected; Traceback (most recent call las> File "/home/tim/octoeverywhere/moonraker_octoeverywhere/moonrakerclient.py", line 588, in _AfterOpenReadyWaiter raise Exception(f"Unknown klippy waiting state. {state}") Exception: Unknown klippy waiting state. disconnected

And mobileraker.log is showing this after the last restart:

--------------------MobilerakerCompanion Log Start-------------------- Git Version: v0.4.0-37-gf65b679 2023-12-30 00:10:22,192 root INFO - MobilerakerCompanion version: v0.4.0-37-gf65b679 2023-12-30 00:10:22,193 root INFO - Passed config file is: /home/tim/Mobileraker.conf 2023-12-30 00:10:22,194 root INFO - Checking mobileraker_companion dir 2023-12-30 00:10:22,194 root INFO - Checking klipper_config dir 2023-12-30 00:10:22,195 root INFO - Checking printer_data/config dir 2023-12-30 00:10:22,195 root INFO - Checking user dir 2023-12-30 00:10:22,196 root WARNING - No config file was found, using default fallback values! 2023-12-30 00:10:22,196 root INFO - Read 1 printer config sections 2023-12-30 00:10:22,261 root INFO - Main section read, language:"en", timezone:"Australia/Brisbane", eta_format:"%d.%m.%Y, %H:%M:%S", include_snapshot:"True" 2023-12-30 00:10:22,263 mobileraker.jrpc INFO - Trying to connect to: ws://127.0.0.1:7125/websocket api key 2023-12-30 00:10:22,274 mobileraker.jrpc INFO - WebSocket connected 2023-12-30 00:10:22,275 mobileraker.jrpc INFO - Notifying listeners about connection state True 2023-12-30 00:10:22,276 mobileraker.sync INFO - Doing a (Re)Sync with moonraker 2023-12-30 00:10:22,277 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:10:22,295 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:10:22,297 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 2 seconds... 2023-12-30 00:10:22,298 mobileraker.jrpc WARNING - Error message received from WebSocket-Server Attempt to operate on closed/deleted/dropped object. 2023-12-30 00:10:22,300 mobileraker._Default WARNING - Could not write companion meta into moonraker database, moonraker returned error Attempt to operate on closed/deleted/dropped ob> 2023-12-30 00:10:24,298 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:10:24,302 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:10:24,304 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 4 seconds... 2023-12-30 00:10:28,305 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:10:28,314 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:10:28,315 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 8 seconds... 2023-12-30 00:10:36,316 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:10:36,320 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:10:36,320 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 16 seconds... 2023-12-30 00:10:52,322 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:10:52,327 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:10:52,328 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 32 seconds... 2023-12-30 00:11:24,331 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:11:24,334 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:11:24,335 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 64 seconds... 2023-12-30 00:12:28,338 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:12:28,345 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:12:28,346 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 128 seconds... 2023-12-30 00:14:36,349 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:14:36,353 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:14:36,361 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 256 seconds... 2023-12-30 00:17:09,403 mobileraker.sync INFO - Moonraker's connection to Klippy has terminated/disconnected 2023-12-30 00:17:09,405 mobileraker._Default INFO - No last snapshot available. Evaluating! 2023-12-30 00:17:09,405 mobileraker._Default INFO - Snapshot passed threshold. LastSnap: None, NewSnap: PrinterSnapshot(klippy_ready=False, print_state=error, m117=None, m117_hash=, v> 2023-12-30 00:17:09,410 mobileraker.jrpc WARNING - Error message received from WebSocket-Server Key 'fcm' in namespace 'mobileraker' not found 2023-12-30 00:17:09,411 mobileraker._Default WARNING - Could not fetch app cfgs from moonraker, moonraker returned error Key 'fcm' in namespace 'mobileraker' not found 2023-12-30 00:17:09,412 mobileraker._Default INFO - ---- Completed Evaluations Task! ---- 2023-12-30 00:17:13,010 mobileraker.sync INFO - Klippy has reported a ready state 2023-12-30 00:17:13,011 mobileraker.sync INFO - Doing a (Re)Sync with moonraker 2023-12-30 00:17:13,012 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:17:13,015 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:17:13,016 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 2 seconds... 2023-12-30 00:17:15,018 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:17:15,024 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:17:15,025 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 4 seconds... 2023-12-30 00:17:19,027 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:17:19,034 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:17:19,035 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 8 seconds... 2023-12-30 00:17:27,037 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:17:27,043 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:17:27,044 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 16 seconds... 2023-12-30 00:17:43,045 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:17:43,051 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:17:43,052 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 32 seconds... 2023-12-30 00:18:15,056 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:18:15,062 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:18:15,063 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 64 seconds... 2023-12-30 00:18:52,363 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:18:52,367 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:18:52,368 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 300 seconds... 2023-12-30 00:19:19,065 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:19:19,071 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:19:19,071 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 128 seconds... 2023-12-30 00:21:27,073 mobileraker.sync INFO - Syncing klippy Objects 2023-12-30 00:21:27,078 mobileraker.sync INFO - Received server info: {'jsonrpc': '2.0', 'result': {'klippy_connected': False, 'klippy_state': 'disconnected', 'components': ['klippy_c> 2023-12-30 00:21:27,080 mobileraker.sync WARNING - Klippy was not ready. Trying resync again in 256 seconds...

Restarting moonraker and octoeverywhere services hasn't changed the experience unfortunately.

What else can I try? Thank you.

Clon1998 commented 9 months ago

Hey, Sorry to hear about that experience. However, I do not think that this is related to the companion. To me, it seems like Klipper has a problem connecting since it is in the disconnected state and both, octoeverywhere and companion report connection problems to moonraker. Therefore, could you also upload the klipper.log file?

TheAussieTim commented 9 months ago

Oh really, that's interesting. I was successfully printing just before making the installation so that's what made me look into this first. Granted I'm not very technical on this side of printing, I can set things up but my troubleshooting game is weak.

Here's the klippy.log, figured it was easier to just put the whole thing on here. klippy.log

Clon1998 commented 9 months ago

Thanks. Sadly the logs do not indicate any issue with klipper and therefore my assumption is wrong. Thus, could you upload all log files (moonraker.log, mobileraker.log, ...). Can you also post the version of Moonraker you are using?

The companion it self is a passive listener except for the startup where it writes some meta data into the printer's database like its version. Besides that, all it does is listening to the same source as the GUIs do.

TheAussieTim commented 9 months ago

Sure thing - it's the latest version I believe, v0.8.0-239-gc4d15e4.

I have also just noticed that I still have Obico running on this thing too, I don't use it anymore - haven't for several months - but I think it seems to still be reaching out. Added the most recent log for that here too, though I don't believe it's conflicting with the operation. mobileraker.log moonraker.log moonraker-obico.log octoeverywhere.log

Clon1998 commented 9 months ago

Thanks, it seems like octoeverywhere is sending a database request close to every second which fails. Therefore, Id suggest to stop octoeverywhere and the mobileraker_companion services and restart moonraker just to see if we get the UIs back working.

Ensure you are connected via SSH to the printer and run:

sudo systemctl stop mobileraker.service
sudo systemctl stop octoeverywhere.service
sudo systemctl restart moonraker.service
TheAussieTim commented 9 months ago

Fantastic, that has restored the function again.

OK so I clearly need to focus more on general troubleshooting, thank you so much for your assistance, especially at this time of the year.

Clon1998 commented 9 months ago

Fantastic, that has restored the function again.

OK so I clearly need to focus more on general troubleshooting, thank you so much for your assistance, especially at this time of the year.

Awesome, can you do me a favor and start the companion once again (Either via mainsail/Fluidd or by replacing the stop with start in the bash command above)

TheAussieTim commented 9 months ago

Yes, I have restarted the companion again, and testing with a small print job I am now receiving updates on my phone.

image