jneilliii / OctoPrint-TPLinkSmartplug

106 stars 57 forks source link

[BUG]: PSU not switching off at OctoPi shutdown #269

Closed exotolon closed 3 years ago

exotolon commented 3 years ago

Hi jneilliii,

first off, I'm not fully sure this is a bug or a missing feature.

The TP Link PSU does not switch off, when I shutdown my OctoPi from the drop down menu in OctoPrint. I can turn the PSU on and off otherwise, it also switches off when I restart OctoPrint - just not when I shutdown the pi.

I'm running OctoPrint 1.6.0, Python 3.7.3, and OctoPi 0.18.0 on an RPi 4b with your plugin-ver 1.0.1.

Having the plugin power off the printer, when I shut down my OctoPi is the main reason why I downloaded your plugin ...

Am I missing something?

Looking forward to hearing from you :)

jneilliii commented 3 years ago

So for that specific option you need to have very specific options enabled and configured correctly, otherwise the system isn't running to send the command to the plug, etc. You will want to enable shutdown event monitoring in the general settings as well as in the specific plug's settings. You will also want to enable the option for using countdown timers. This will allow the plugin to offload the power off command to the plug to avoid the issue with the system not running to send the command.

Let me know if that helps or makes sense, or if it doesn't work as expected. If so, would be good to have debug logging enabled and share the plugin_tplinksmartplug_debug.log file and screenshots of your settings.

exotolon commented 3 years ago

Thanks for your quick reply! Exept of the countdown timers, I had everything set as you said. I've enabled the countdown timers and debug logging now. The priner is currently busy printing - I'll see if the new settings work after the job's done.

Regarding the countdown timers: The RPi is not plugged into the PSU, only the printer is...

exotolon commented 3 years ago

I'm afraid that didn't help :( Having everything set as you said, the PSU still does not switch off when I shut down the RPi. How do I extract the log files?

jneilliii commented 3 years ago

Go tp octoprint's logging section in settings and download the file from there.

exotolon commented 3 years ago

Here are screenshots of my settings along with the log file.

At timestamp [2021-05-08 15:22:47,453] the system shut down but didn't turn off the PSU.

plugin_tplinksmartplug_debug.log IMG_5514 IMG_5513

jneilliii commented 3 years ago

You don't have the option turned on for use timers...did you turn that back off?

jneilliii commented 3 years ago

Never mind, I see in the log where you did have it enabled. The parts of interest are highlighted below. I think the issue may be related to the date/time settings on your plug, based on this error message being returned by it, time not sync.

[2021-05-08 14:50:53,941] DEBUG: Sending command {'count_down': {'delete_all_rules': None}} to 192.168.178.11
[2021-05-08 14:50:53,954] DEBUG: «  Nž"count_down":{"delete_all_rules":{"err_code":-11,"err_msg":"time not sync"}}}
[2021-05-08 14:50:53,954] DEBUG: IP 192.168.178.11 is valid.
[2021-05-08 14:50:53,955] DEBUG: Sending command {'count_down': {'add_rule': {'enable': 1, 'delay': 1, 'act': 0, 'name': 'turn off'}}} to 192.168.178.11
[2021-05-08 14:50:53,962] DEBUG: «  F–"count_down":{"add_rule":{"err_code":-11,"err_msg":"time not sync"}}}
[2021-05-08 14:50:54,048] DEBUG: -11
[2021-05-08 14:51:06,445] DEBUG: Turning off 192.168.178.11.
[2021-05-08 14:51:06,445] INFO: Turning off 192.168.178.11 at 2021-05-08 14:51:06.445092
[2021-05-08 14:51:06,446] DEBUG: {'autoConnect': True, 'autoConnectDelay': 10, 'autoDisconnect': True, 'autoDisconnectDelay': 0, 'automaticShutdownEnabled': True, 'btnColor': '#808080', 'countdownOffDelay': 1, 'countdownOnDelay': 1, 'currentState': 'on', 'displayWarning': True, 'emeter': {'get_realtime': {}}, 'event_on_disconnect': False, 'event_on_error': False, 'event_on_shutdown': True, 'event_on_startup': False, 'event_on_upload': True, 'gcodeCmdOff': False, 'gcodeCmdOn': False, 'gcodeEnabled': False, 'gcodeOffDelay': 0, 'gcodeOnDelay': 0, 'gcodeRunCmdOff': '', 'gcodeRunCmdOn': '', 'icon': 'icon-bolt', 'ip': '192.168.178.11', 'label': 'Netzschalter', 'sysCmdOff': False, 'sysCmdOffDelay': 0, 'sysCmdOn': False, 'sysCmdOnDelay': 0, 'sysRunCmdOff': '', 'sysRunCmdOn': '', 'thermal_runaway': True, 'useCountdownRules': True, 'warnPrinting': True}
[2021-05-08 14:51:06,447] DEBUG: IP 192.168.178.11 is valid.
[2021-05-08 14:51:06,447] DEBUG: Sending command {'count_down': {'delete_all_rules': None}} to 192.168.178.11
[2021-05-08 14:51:06,456] DEBUG: «  Nž"count_down":{"delete_all_rules":{"err_code":-11,"err_msg":"time not sync"}}}
[2021-05-08 14:51:06,457] DEBUG: IP 192.168.178.11 is valid.
[2021-05-08 14:51:06,457] DEBUG: Sending command {'count_down': {'add_rule': {'enable': 1, 'delay': 1, 'act': 0, 'name': 'turn off'}}} to 192.168.178.11
[2021-05-08 14:51:06,465] DEBUG: «  F–"count_down":{"add_rule":{"err_code":-11,"err_msg":"time not sync"}}}
[2021-05-08 14:51:06,531] DEBUG: -11
[2021-05-08 14:51:34,034] DEBUG: powering off 192.168.178.11 due to shutdown event.
[2021-05-08 14:51:34,034] DEBUG: Turning off 192.168.178.11.
[2021-05-08 14:51:34,034] INFO: Turning off 192.168.178.11 at 2021-05-08 14:51:34.034564
[2021-05-08 14:51:34,036] DEBUG: {'autoConnect': True, 'autoConnectDelay': 10, 'autoDisconnect': True, 'autoDisconnectDelay': 0, 'automaticShutdownEnabled': True, 'btnColor': '#808080', 'countdownOffDelay': 1, 'countdownOnDelay': 1, 'currentState': 'on', 'displayWarning': True, 'emeter': {'get_realtime': {}}, 'event_on_disconnect': False, 'event_on_error': False, 'event_on_shutdown': True, 'event_on_startup': False, 'event_on_upload': True, 'gcodeCmdOff': False, 'gcodeCmdOn': False, 'gcodeEnabled': False, 'gcodeOffDelay': 0, 'gcodeOnDelay': 0, 'gcodeRunCmdOff': '', 'gcodeRunCmdOn': '', 'icon': 'icon-bolt', 'ip': '192.168.178.11', 'label': 'Netzschalter', 'sysCmdOff': False, 'sysCmdOffDelay': 0, 'sysCmdOn': False, 'sysCmdOnDelay': 0, 'sysRunCmdOff': '', 'sysRunCmdOn': '', 'thermal_runaway': True, 'useCountdownRules': True, 'warnPrinting': True}
[2021-05-08 14:51:34,036] DEBUG: IP 192.168.178.11 is valid.
[2021-05-08 14:51:34,037] DEBUG: Sending command {'count_down': {'delete_all_rules': None}} to 192.168.178.11
[2021-05-08 14:51:34,037] DEBUG: Could not connect to 192.168.178.11.
[2021-05-08 14:51:34,038] DEBUG: IP 192.168.178.11 is valid.
[2021-05-08 14:51:34,038] DEBUG: Sending command {'count_down': {'add_rule': {'enable': 1, 'delay': 1, 'act': 0, 'name': 'turn off'}}} to 192.168.178.11
[2021-05-08 14:51:34,039] DEBUG: Could not connect to 192.168.178.11.
[2021-05-08 14:51:34,040] DEBUG: None
github-actions[bot] commented 3 years ago

This issue has been automatically marked as stale because it has not had activity in 14 days. It will be closed if no further activity occurs in 7 days