print job stutters / hangs when HA URL is inaccessible

[garyt72]

My Home Assistant instance became unavailable during a print, and it caused OctoPrint to 'hang' - sending only a single gcode command every few seconds until Home Assistant came back online - then returned to normal. I paused the print job when I realized what was happening, then resumed when HA was online again.

OctoPrint Log file from this incident provided below.

2021-05-20 16:08:17,534 - octoprint.plugins.action_command_notification - INFO - Got a notification: 24% L=64/233
2021-05-20 16:09:14,275 - octoprint.plugins.action_command_notification - INFO - Got a notification: 24% L=65/233
2021-05-20 16:10:11,573 - octoprint.plugins.action_command_notification - INFO - Got a notification: 24% L=66/233
2021-05-20 16:11:09,222 - octoprint.plugins.action_command_notification - INFO - Got a notification: 24% L=67/233
2021-05-20 16:11:09,239 - octoprint.plugins.action_command_notification - INFO - Got a notification: 25% L=67/233
2021-05-20 16:11:13,213 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:11:13,372 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G2)
2021-05-20 16:11:13,373 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:11:13,529 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:11:18,536 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:11:23,981 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G2)
2021-05-20 16:11:23,982 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:11:25,281 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:11:25,290 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:11:25,535 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:11:31,170 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:11:35,606 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:11:35,744 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G2)
2021-05-20 16:11:35,744 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:11:35,924 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:11:40,911 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:11:46,111 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G0)
2021-05-20 16:11:46,112 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:11:48,123 - octoprint.plugins.psucontrol_homeassistant - WARNING - Server returned 404 Not Found. Check Entity ID.
2021-05-20 16:11:49,246 - octoprint.plugins.psucontrol_homeassistant - WARNING - Server returned 404 Not Found. Check Entity ID.
2021-05-20 16:11:59,179 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G2)
2021-05-20 16:11:59,179 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:12:11,758 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G2)
2021-05-20 16:12:11,759 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:12:22,753 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G2)
2021-05-20 16:12:22,754 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:12:33,854 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G2)
2021-05-20 16:12:33,854 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:12:44,828 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G2)
2021-05-20 16:12:44,829 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:12:58,219 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G2)
2021-05-20 16:12:58,220 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:13:10,259 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G0)
2021-05-20 16:13:10,260 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:13:20,898 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G0)
2021-05-20 16:13:20,898 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:13:31,466 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G0)
2021-05-20 16:13:31,467 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:13:42,417 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G3)
2021-05-20 16:13:42,417 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:13:53,574 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G3)
2021-05-20 16:13:53,575 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:14:04,729 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G3)
2021-05-20 16:14:04,730 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:14:15,847 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G3)
2021-05-20 16:14:15,848 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:14:26,953 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G3)
2021-05-20 16:14:26,954 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:14:33,931 - octoprint.util.comm - INFO - Pausing/resuming job on behalf of user gjtaylor72
2021-05-20 16:14:38,718 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Pausing"
2021-05-20 16:14:38,815 - octoprint.server.views - WARNING - Client requested cache refresh via cache-control headers but we are printing. Not invalidating caches due to resource limitation. Append ?_refresh=true to the URL if you absolutely require a refresh now
2021-05-20 16:14:39,651 - octoprint.printer.standard.job - INFO - Print job paused - origin: local, path: Cup_Cover_v2---_Overture_Blue_PETG_02_50.aw.gcode, owner: gjtaylor72, user: gjtaylor72
2021-05-20 16:14:39,698 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G1)
2021-05-20 16:14:39,698 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:14:51,251 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G1)
2021-05-20 16:14:51,251 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:15:01,872 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G1)
2021-05-20 16:15:01,873 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:15:12,498 - octoprint.util.comm - INFO - Changing monitoring state from "Pausing" to "Paused"
2021-05-20 16:16:40,613 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:16:45,812 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:16:50,997 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:16:56,196 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:17:02,128 - octoprint.plugins.psucontrol_homeassistant - WARNING - Server returned 404 Not Found. Check Entity ID.
2021-05-20 16:17:07,564 - octoprint.plugins.psucontrol_homeassistant - WARNING - Server returned 404 Not Found. Check Entity ID.
2021-05-20 16:17:23,846 - octoprint.util.comm - INFO - Pausing/resuming job on behalf of user gjtaylor72
2021-05-20 16:17:23,847 - octoprint.util.comm - INFO - Changing monitoring state from "Paused" to "Resuming"
2021-05-20 16:17:23,884 - octoprint.printer.standard.job - INFO - Print job resumed - origin: local, path: Cup_Cover_v2---_Overture_Blue_PETG_02_50.aw.gcode, owner: gjtaylor72, user: gjtaylor72
2021-05-20 16:17:24,022 - octoprint.util.comm - INFO - Changing monitoring state from "Resuming" to "Printing"
2021-05-20 16:18:11,400 - octoprint.plugins.action_command_notification - INFO - Got a notification: 25% L=68/233
2021-05-20 16:19:11,436 - octoprint.plugins.action_command_notification - INFO - Got a notification: 25% L=69/233
2021-05-20 16:20:08,614 - octoprint.plugins.action_command_notification - INFO - Got a notification: 25% L=70/233
2021-05-20 16:20:36,581 - octoprint.plugins.action_command_notification - INFO - Got a notification: 27% L=70/233
2021-05-20 16:21:10,579 - octoprint.plugins.action_command_notification - INFO - Got a notification: 27% L=71/233
2021-05-20 16:22:11,429 - octoprint.plugins.action_command_notification - INFO - Got a notification: 27% L=72/233
2021-05-20 16:22:18,741 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2021-05-20 16:22:29,193 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 75595, 'printer_state': 'PRINTING'}
2021-05-20 16:23:09,804 - octoprint.plugins.action_command_notification - INFO - Got a notification: 27% L=73/233
2021-05-20 16:23:52,706 - octoprint.plugins.action_command_notification - INFO - Got a notification: 28% L=73/233
2021-05-20 16:24:14,291 - octoprint.plugins.action_command_notification - INFO - Got a notification: 28% L=74/233
2021-05-20 16:25:16,133 - octoprint.plugins.action_command_notification - INFO - Got a notification: 28% L=75/233
2021-05-20 16:26:18,148 - octoprint.plugins.action_command_notification - INFO - Got a notification: 28% L=76/233
2021-05-20 16:27:10,682 - octoprint.plugins.action_command_notification - INFO - Got a notification: 29% L=76/233
2021-05-20 16:27:19,507 - octoprint.plugins.action_command_notification - INFO - Got a notification: 29% L=77/233
2021-05-20 16:28:19,960 - octoprint.plugins.action_command_notification - INFO - Got a notification: 29% L=78/233
2021-05-20 16:29:20,785 - octoprint.plugins.action_command_notification - INFO - Got a notification: 29% L=79/233
2021-05-20 16:30:12,090 - octoprint.plugins.action_command_notification - INFO - Got a notification: 30% L=79/233
2021-05-20 16:30:21,646 - octoprint.plugins.action_command_notification - INFO - Got a notification: 30% L=80/233
2021-05-20 16:31:22,600 - octoprint.plugins.action_command_notification - INFO - Got a notification: 30% L=81/233
2021-05-20 16:32:22,764 - octoprint.plugins.action_command_notification - INFO - Got a notification: 30% L=82/233
2021-05-20 16:33:24,022 - octoprint.plugins.action_command_notification - INFO - Got a notification: 30% L=83/233
2021-05-20 16:33:24,036 - octoprint.plugins.action_command_notification - INFO - Got a notification: 31% L=83/233
2021-05-20 16:34:25,931 - octoprint.plugins.action_command_notification - INFO - Got a notification: 31% L=84/233
2021-05-20 16:35:29,260 - octoprint.plugins.action_command_notification - INFO - Got a notification: 31% L=85/233
2021-05-20 16:36:31,995 - octoprint.plugins.action_command_notification - INFO - Got a notification: 31% L=86/233
2021-05-20 16:36:37,228 - octoprint.plugins.action_command_notification - INFO - Got a notification: 32% L=86/233
2021-05-20 16:37:18,742 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2021-05-20 16:37:28,583 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 76495, 'printer_state': 'PRINTING'}
2021-05-20 16:37:39,543 - octoprint.plugins.action_command_notification - INFO - Got a notification: 32% L=87/233
2021-05-20 16:38:45,424 - octoprint.plugins.action_command_notification - INFO - Got a notification: 32% L=88/233
2021-05-20 16:39:44,116 - octoprint.plugins.action_command_notification - INFO - Got a notification: 33% L=88/233
2021-05-20 16:39:49,511 - octoprint.plugins.action_command_notification - INFO - Got a notification: 33% L=89/233
2021-05-20 16:40:58,458 - octoprint.plugins.action_command_notification - INFO - Got a notification: 33% L=90/233
2021-05-20 16:42:01,446 - octoprint.plugins.action_command_notification - INFO - Got a notification: 33% L=91/233
2021-05-20 16:43:00,654 - octoprint.plugins.action_command_notification - INFO - Got a notification: 34% L=91/233
2021-05-20 16:43:11,980 - octoprint.plugins.action_command_notification - INFO - Got a notification: 34% L=92/233
2021-05-20 16:44:18,582 - octoprint.plugins.action_command_notification - INFO - Got a notification: 34% L=93/233
2021-05-20 16:45:25,018 - octoprint.plugins.action_command_notification - INFO - Got a notification: 34% L=94/233
2021-05-20 16:46:03,237 - octoprint.plugins.action_command_notification - INFO - Got a notification: 35% L=94/233
2021-05-20 16:46:31,391 - octoprint.plugins.action_command_notification - INFO - Got a notification: 35% L=95/233
2021-05-20 16:47:38,642 - octoprint.plugins.action_command_notification - INFO - Got a notification: 35% L=96/233
2021-05-20 16:48:46,558 - octoprint.plugins.action_command_notification - INFO - Got a notification: 35% L=97/233
2021-05-20 16:48:48,556 - octoprint.plugins.psucontrol_homeassistant - ERROR - Unable to communicate with server. Check settings.
2021-05-20 16:48:48,828 - octoprint.plugins.psucontrol - INFO - Auto-On - Turning PSU On (Triggered by G2)
2021-05-20 16:48:48,829 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-05-20 16:49:52,334 - octoprint.server.views - WARNING - Client requested cache refresh via cache-control headers but we are printing. Not invalidating caches due to resource limitation. Append ?_refresh=true to the URL if you absolutely require a refresh now
2021-05-20 16:50:06,870 - octoprint.plugins.action_command_notification - INFO - Got a notification: 35% L=98/233
2021-05-20 16:51:14,386 - octoprint.plugins.action_command_notification - INFO - Got a notification: 35% L=99/233
2021-05-20 16:52:18,744 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2021-05-20 16:52:22,863 - octoprint.plugins.action_command_notification - INFO - Got a notification: 35% L=100/233
2021-05-20 16:52:25,899 - octoprint.plugins.action_command_notification - INFO - Got a notification: 36% L=100/233
2021-05-20 16:52:28,739 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 77395, 'printer_state': 'PRINTING'}
2021-05-20 16:53:30,622 - octoprint.plugins.action_command_notification - INFO - Got a notification: 36% L=101/233
2021-05-20 16:54:38,670 - octoprint.plugins.action_command_notification - INFO - Got a notification: 36% L=102/233
2021-05-20 16:55:01,200 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Cancelling"
2021-05-20 16:55:01,203 - octoprint.util.comm - INFO - Force-sending M108 to the printer
2021-05-20 16:55:01,867 - octoprint.printer.standard.job - INFO - Print job cancelled - origin: local, path: Cup_Cover_v2---_Overture_Blue_PETG_02_50.aw.gcode, owner: gjtaylor72, user: None
2021-05-20 16:55:01,941 - octoprint.plugins.DisplayLayerProgress - INFO - Printing stopped. Detailed progress stopped.

[edekeijzer]

@garyt72 what hardware are you running on? I have tried to reproduce this first on my virtual test environment in Docker and just now on my Ender 3 Pro connected to a Raspberry Pi 3B, but I do not see any printing issues or even increased system load when either stopping the HA webserver or even directing the plugin to an IP address that isn't used. @kantlivelong do you have any idea what could cause this? While the requests module itself is blocking, the PSU Control state check (which obviously is timing out here) is running threaded right?

[kantlivelong]

Taking a good guess I'm pretty sure it's because autoon is enabled which tries turning on based on the gcode command being sent. @garyt72 if your controller is powered by the device switching on and octoprint is normally disconnected from it when off then turn this option off as it wont do much for you anyway.

@edekeijzer You should be able to reproduce by using autoon/trigger command support and breaking connection to HA.

@edekeijzer For the future always ask for debug logs as the config for psucontrol will get dumped. You're free to just link https://github.com/kantlivelong/OctoPrint-PSUControl/wiki/Troubleshooting#how-to-provide-logs

I should rename the option to be more specific.

[garyt72]

I can confirm that the purposely disconnecting my Home Assistant instance while printing with the autoon option enabled replicated the suttering/hanging issue during a print. Disabling the autoon setting while Home Assistant was still disconnected almost immediately cause the issue to stop.

Thanks @kantlivelong and @edekeijzer!

[realumhelp]

This has happened to me a few times and I was able to narrow it down to losing communications with Home Assistant. Basically, my Home Assistant VM would crash because of a POS bug in ESXI (https://kb.vmware.com/s/article/86100) and if I were printing my printer would hang as well. So after just losing a 13hr print I decided to do a search, is the fix to disable "Power On Options -> Automatically turn PSU ON"? This is kind of a nice feature honestly but if it is killing my prints... Seems a bit rough to freeze a print because I lose comms with a power outlet, especially when my outlet is wireless.

[realumhelp]

I skimmed through the code here and in the main PSU Control it seems like we are stuck in a tough spot because On/Off status is binary (either ON or OFF). In our case it is Unknown... I think the ideal solution would be to add a 3rd state to Power Status of Unknown and then add settings around behavior. This isn't likely given the number of external plugins implementing this. So... a possibly more simple solution could be to add an option to this Plugin that says "Return Previous State When HA Is Lost". By default that previous state is False and if there is a transition store that value in a Current State Variable.

So basically inside of: def get_psu_state(self):

        if not response:
            return False
        data = response.json()

Here is some dummy code from a dummy :)

if not response:
  if NEW_OPTION_TO_RETURN_PREVIOUS_KNOWN_STATE:
    return PREVIOUS_KNOWN_STATE
  else
    return False

I didn't study the code super thoroughly but something like this might could solve our issue here. My theory is we are getting killed in the _check_psu_state thread thread which would return FALSE because of the above code not receiving a response. That would then kick the hook_gcode_queuing code into gear which would then try to turn the PSU back on. From there things will kinda spin until HA comes back. Now if you add a flag to basically return the previous state or ON then everything should continue as normal because there wouldn't be a change in state. I think this approach would be safe even if the plug was manually changed while HA was offline because then your printer would turn off and there would then be serial errors. There may be other edge cases but this is off the cuff idea. Let me know if it sounds reasonable.

[kantlivelong]

@realumhelp Is your controller ALWAYS connected even if the power supply in question is off?

[realumhelp]

@realumhelp Is your controller ALWAYS connected even if the power supply in question is off?

My printer is connected to a smart outlet and my Octoprint controller is running on an independent power supply. So Octoprint will run even if the printer is off, if that is what you're asking. My Home Assistant is a VM that runs 24/7 unless it crashes err.... The smart outlet is a WiFi Sonoff S31 flashed with ESPHome.

[kantlivelong]

if that is what you're asking.

Not quite. Is both the OctoPrint device and the printers controller(MCU) always on and connected to each other via serial?

[realumhelp]

Ah yes they are. I have a dedicated USB cable running between the two.

[kantlivelong]

Can you try sending M117 Test via the terminal tab while the HomeAssistant controlled device is off?

[realumhelp]

I am in the middle of a long print at the moment but I will experiment when it is done later tonight!

So would you like me to send the M117 Test while Home Assistant is offline or the Smart Plug? Do you want the Smart Plug's relay to be off or the actual device to be offline?

Thanks for the clarification!

[kantlivelong]

With the relay off.

[realumhelp]

With the relay off.

Hmmm with the relay off the printer is off so there is no connection to the printer. The Octoprint Terminal doesn't allow me to send gcode. Cura won't let me send anything over because the printer is disconnected, so I'm not really sure how to send raw gcode in this state.

So diving a bit deeper into the settings in Cura I have "Turn on printer with PSU Control" enabled. This would be what triggers the printer to turn on. This would mean that the setting discussed above (Power On Options -> Automatically turn PSU ON) is less important than I had originally thought.

I guess I can play around with it and see if disabling that resolves the issue as it is implied above by other users.

Thanks! I guess I had to step through this piece by piece before my mind caught up a bit slow today apparently!

[kantlivelong]

Right so "Automatically turn PSU ON" will not work for you anyway as it requires a continuous connection to the printer. Turn that off and it should help with your issue for now.

[medisoft]

I can confirm that disabling automatic turn PSU ON fixes the problem. The problem happens to me when:

• The smart switch is offline for any reason
• When the connection to the Home Assistant fails for an reason
• When I restart Home Assistant
• When the wifi connection is slow

So disabled the Automatic Turn PSU ON fixes the problem. And it seems that CURA can turn on the printer without that switch enabled.