Power off at startup

[ilgrank]

Hello! Now that I have the Tasmota plugin communicating correctly with my Tasmota Smart Plug, I have yet another small problem. When powering on the printer, the Tasmota Plugin begins within seconds the countdown to power it off. I've set the Idle timeout to 30 minutes, and I really don't understand why this happens. I've tried removing and reinstalling the plugin, fearing to have set some wrong config option while debugging the previous problem, but this didn't change anything. What could I be missing?

Thanks!

[jneilliii]

I'm going to take a wild guess that you have a Creality machine and that your printer is back powered by the USB connection to the Pi? This is known an issue and will actually cause the disconnect event monitoring to trigger right away when the connection is being established with the printer on startup. I think if you were to disable that disconnect monitoring option that would prevent this from happening, otherwise tape the 5V pin as described here.

[ilgrank]

Hi @jneilliii I do have a creality CR6, but I'm powering my Pi3 via a step-down converted from the printer's 24V PSU. I also have cut the +5V line from the USB cable connecting the Pi and my printer. I'll try disabling the disconnect monitoring and report back if it works or not.. many thanks!

[ilgrank]

~I can confirm that disabling event monitoring solved the problem~ It seemed to work, but I was wrong. On first power up, it behaved in the same way. Running in debug now to try to log the issue...

[ilgrank]

It seemed to work, but I was wrong. On first power up, it behaved in the same way. Running in debug now to try to log the issue...

[jneilliii]

Yeah, just share your logs once you've reproduced the issue.

[ilgrank]

Hello, it happened again today, luckily I had debug logging on. It seems the plugin detected an idle time of 30 minutes even just 30 seconds after power on:

pi@octopi:~ $ cat /home/pi/.octoprint/logs/plugin_tasmota_debug.log
[2021-03-01 11:11:55,170] DEBUG: Idle timeout reached after 30 minute(s). Turning heaters off prior to powering off plugs.
[2021-03-01 11:11:55,204] DEBUG: Heaters below temperature.
[2021-03-01 11:11:55,207] DEBUG: Checking timelapse status before shutting off power...
[2021-03-01 11:11:55,211] DEBUG: Starting abort power off timer.
[2021-03-01 11:13:07,849] DEBUG: {u'ip': u'192.168.0.61', u'command': u'checkStatus', u'idx': u'1'}
[2021-03-01 11:13:07,850] DEBUG: Checking status of 192.168.0.61 index 1.
[2021-03-01 11:13:07,851] DEBUG: {'username': 'admin', 'autoConnect': False, 'event_on_connecting': False, 'ip': '192.168.0.61', 'backlog_on_delay': 0, 'off_color': '#FF0000', 'autoDisconnectDelay': 0, 'sysCmdOff': True, 'gcodeEnabled': False, 'gcodeOnDelay': 0, 'backlog_off_delay': '60', 'label': 'TSP-01', 'warnPrinting': True, 'thermal_runaway': True, 'gcodeOffDelay': 0, 'sysCmdOnDelay': 0, 'event_on_error': True, 'label_extended': '', 'sysRunCmdOff': 'sudo shutdown now', 'use_backlog': True, 'autoDisconnect': False, 'automaticShutdownEnabled': True, 'event_on_upload': False, 'sysRunCmdOn': '', 'unknown_color': '#808080', 'password': '', 'icon': 'icon-bolt', 'idx': '1', 'displayWarning': True, 'sensor_identifier': '', 'autoConnectDelay': 10, 'event_on_disconnect': True, 'sysCmdOn': False, 'sysCmdOffDelay': '5', 'currentState': 'unknown', 'on_color': '#09ce09'}
[2021-03-01 11:13:08,095] DEBUG: check status code: 200
[2021-03-01 11:13:08,096] DEBUG: check status text: {"Status":{"Module":0,"DeviceName":"TSP-01","FriendlyName":["TSP-01"],"Topic":"TSP-01","ButtonTopic":"0","Power":1,"PowerOnState":3,"LedState":1,"LedMask":"FFFF","SaveData":1,"SaveState":1,"SwitchTopic":"0","SwitchMode":[0,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":1,"PowerRetain":1},"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"xxxx","OtaUrl":"http://ota.tasmota.com/tasmota/tasmota-lite.bin.gz","RestartReason":"Software/System restart","Uptime":"11T15:57:23","StartupUTC":"2021-02-17T18:15:45","Sleep":50,"CfgHolder":4617,"BootCount":40,"BCResetTime":"2020-04-27T10:11:56","SaveCount":249,"SaveAddress":"F9000"},"StatusFWR":{"Version":"9.2.0.7(lite)","BuildDateTime":"2021-02-17T13:26:08","Boot":31,"Core":"2_7_4_9","SDK":"2.2.2-dev(38a443e)","CpuFrequency":80,"Hardware":"ESP8285","CR":"412/699"},"StatusLOG":{"SerialLog":2,"WebLog":2,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["xxx2",""],"TelePeriod":300,"Resolution":"558180C0","SetOption":["04008229","2805C8000100060000005A00000000000000","00000080","00006000","00000000"]},"StatusMEM":{"ProgramSize":478,"Free":524,"Heap":26,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"144051","FlashFrequency":40,"FlashMode":3,"Features":["00000809","8F000783","04108001","00000006","010001C0","00000000","00004004","00000000","00000000"],"Drivers":"1,2,3,4,9,10,16,20,21,37","Sensors":"3"},"StatusNET":{"Hostname":"TSP-01","IPAddress":"192.168.0.61","Gateway":"192.168.0.1","Subnetmask":"255.255.255.0","DNSServer":"192.168.0.102","Mac":"24:62:xx:xx:xx:xx","Webserver":2,"WifiConfig":2,"WifiPower":17.0},"StatusMQT":{"MqttHost":"192.168.0.102","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_48F52E","MqttUser":"xxxx","MqttCount":11137,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30},"StatusTIM":{"UTC":"2021-03-01T10:13:08","Local":"2021-03-01T11:13:08","StartDST":"2021-03-28T02:00:00","EndDST":"2021-10-31T03:00:00","Timezone":"+01:00","Sunrise":"07:31","Sunset":"18:33"},"StatusPTH":{"PowerDelta":[0,0,0],"PowerLow":0,"PowerHigh":0,"VoltageLow":0,"VoltageHigh":0,"CurrentLow":0,"CurrentHigh":0},"StatusSNS":{"Time":"2021-03-01T11:13:08","ENERGY":{"TotalStartTime":"2020-04-27T10:08:30","Total":4.755,"Yesterday":0.000,"Today":0.001,"Power":19,"ApparentPower":30,"ReactivePower":24,"Factor":0.62,"Voltage":227,"Current":0.132}},"StatusSTS":{"Time":"2021-03-01T11:13:08","Uptime":"11T15:57:23","UptimeSec":1007843,"Vcc":3.424,"Heap":26,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":11137,"POWER1":"ON","Wifi":{"AP":1,"SSId":"xxx2","BSSId":"44:4E:6D:DD:0E:6F","Channel":11,"RSSI":78,"Signal":-61,"LinkCount":1,"Downtime":"0T00:00:03"}}}
[2021-03-01 11:13:08,098] DEBUG: 192.168.0.61 index 1 response: {u'Status': {u'DeviceName': u'TSP-01', u'ButtonTopic': u'0', u'SaveState': 1, u'Power': 1, u'SwitchRetain': 0, u'LedState': 1, u'Module': 0, u'ButtonRetain': 0, u'Topic': u'TSP-01', u'PowerRetain': 1, u'LedMask': u'FFFF', u'SensorRetain': 1, u'SaveData': 1, u'FriendlyName': [u'TSP-01'], u'SwitchMode': [0, 0, 0, 0, 0, 0, 0, 0], u'SwitchTopic': u'0', u'PowerOnState': 3}, u'StatusMEM': {u'Features': [u'00000809', u'8F000783', u'04108001', u'00000006', u'010001C0', u'00000000', u'00004004', u'00000000', u'00000000'], u'Drivers': u'1,2,3,4,9,10,16,20,21,37', u'ProgramSize': 478, u'Free': 524, u'FlashMode': 3, u'FlashChipId': u'144051', u'ProgramFlashSize': 1024, u'Heap': 26, u'FlashSize': 1024, u'FlashFrequency': 40, u'Sensors': u'3'}, u'StatusNET': {u'DNSServer': u'192.168.0.102', u'Hostname': u'TSP-01', u'Webserver': 2, u'Mac': u'24:62:xx:xx:xx:xx', u'WifiPower': 17.0, u'Subnetmask': u'255.255.255.0', u'IPAddress': u'192.168.0.61', u'Gateway': u'192.168.0.1', u'WifiConfig': 2}, u'StatusLOG': {u'LogHost': u'', u'SSId': [u'xxx2', u''], u'TelePeriod': 300, u'LogPort': 514, u'SetOption': [u'04008229', u'2805C8000100060000005A00000000000000', u'00000080', u'00006000', u'00000000'], u'MqttLog': 0, u'SysLog': 0, u'WebLog': 2, u'SerialLog': 2, u'Resolution': u'558180C0'}, u'StatusTIM': {u'UTC': u'2021-03-01T10:13:08', u'StartDST': u'2021-03-28T02:00:00', u'EndDST': u'2021-10-31T03:00:00', u'Sunset': u'18:33', u'Timezone': u'+01:00', u'Local': u'2021-03-01T11:13:08', u'Sunrise': u'07:31'}, u'StatusPTH': {u'CurrentLow': 0, u'CurrentHigh': 0, u'PowerHigh': 0, u'PowerDelta': [0, 0, 0], u'VoltageHigh': 0, u'VoltageLow': 0, u'PowerLow': 0}, u'StatusPRM': {u'GroupTopic': u'xxxx', u'Baudrate': 115200, u'CfgHolder': 4617, u'RestartReason': u'Software/System restart', u'SerialConfig': u'8N1', u'Uptime': u'11T15:57:23', u'SaveCount': 249, u'SaveAddress': u'F9000', u'StartupUTC': u'2021-02-17T18:15:45', u'OtaUrl': u'http://ota.tasmota.com/tasmota/tasmota-lite.bin.gz', u'Sleep': 50, u'BCResetTime': u'2020-04-27T10:11:56', u'BootCount': 40}, u'StatusMQT': {u'MqttClient': u'DVES_48F52E', u'MAX_PACKET_SIZE': 1200, u'MqttCount': 11137, u'MqttUser': u'xxxx', u'MqttClientMask': u'DVES_%06X', u'MqttPort': 1883, u'MqttHost': u'192.168.0.102', u'KEEPALIVE': 30}, u'StatusFWR': {u'Core': u'2_7_4_9', u'CpuFrequency': 80, u'Boot': 31, u'Hardware': u'ESP8285', u'Version': u'9.2.0.7(lite)', u'CR': u'412/699', u'BuildDateTime': u'2021-02-17T13:26:08', u'SDK': u'2.2.2-dev(38a443e)'}, u'StatusSNS': {u'ENERGY': {u'ApparentPower': 30, u'Power': 19, u'Yesterday': 0.0, u'TotalStartTime': u'2020-04-27T10:08:30', u'Current': 0.132, u'Voltage': 227, u'Factor': 0.62, u'ReactivePower': 24, u'Total': 4.755, u'Today': 0.001}, u'Time': u'2021-03-01T11:13:08'}, u'StatusSTS': {u'Uptime': u'11T15:57:23', u'Vcc': 3.424, u'MqttCount': 11137, u'Wifi': {u'SSId': u'xxx2', u'BSSId': u'44:4E:6D:DD:0E:6F', u'Signal': -61, u'AP': 1, u'Downtime': u'0T00:00:03', u'RSSI': 78, u'LinkCount': 1, u'Channel': 11}, u'UptimeSec': 1007843, u'LoadAvg': 19, u'Sleep': 50, u'Heap': 26, u'Time': u'2021-03-01T11:13:08', u'SleepMode': u'Dynamic', u'POWER1': u'ON'}}
[2021-03-01 11:13:08,099] DEBUG: Energy Data: {u'ApparentPower': 30, u'Power': 19, u'Yesterday': 0.0, u'TotalStartTime': u'2020-04-27T10:08:30', u'Current': 0.132, u'Voltage': 227, u'Factor': 0.62, u'ReactivePower': 24, u'Total': 4.755, u'Today': 0.001}
[2021-03-01 11:13:08,599] DEBUG: 192.168.0.61 index 1 is ON
[2021-03-01 11:13:43,066] DEBUG: {u'command': u'abortAutomaticShutdown'}
[2021-03-01 11:13:43,134] DEBUG: Cleared countdown rules for 192.168.0.61
[2021-03-01 11:13:43,134] DEBUG: <Response [200]>
[2021-03-01 11:13:43,135] DEBUG: Power off aborted.
[2021-03-01 11:13:43,135] DEBUG: Restarting idle timer.
pi@octopi:~ $ uptime
 11:14:56 up 3 min,  1 user,  load average: 0.30, 0.53, 0.25
pi@octopi:~ $

[jneilliii]

Is that the entire log? Juts seems odd that it's triggering the idle timeout reached message as the first line.

[ilgrank]

yes, it is the entire log. I put an rm -f /home/pi/.octoprint/logs/plugin_tasmota_debug.log at shutdown so to have just the log for the last session.

[jneilliii]

huh, that's odd. are you safely shutting down the pi prior to killing power to your printer?

[ilgrank]

I'm using the Tasmota plugin to shut down my Octopi. I have it consigured as per the docs:

Since I am near the printer, I can hear it turning off (correctly) 30 minutes after it finishes printing, and the interface goes offline just a minute or so before the power is cut, so it seems the shutdown command is invoked correctly.

[jneilliii]

Perfect, just wanted to make sure I wasn't chasing down SD card corruption related issues. After looking at your settings and the issue again I think this is exactly the issue I resolved in my TP-LinkSmartplug plugin with this commit using uptime. I can add those same changes to this one to see if it helps us get around this for you.

[jneilliii]

Added uptime with the above commit, available in 1.0.2rc1. This should help in your situation I think to give the pi's internal clock time to catch up on boot. If you want to test it out switch the Release Channel to Release Candidate in OctoPrint's Software Update settings and upgrade when prompted.

[ilgrank]

Thanks! I will try immediately and report

[ilgrank]

Ok, In a couple of days of testing so far, so good! Only issue is that now the power icon starts on red:

as soon as I click it tho, it turns green.

[jneilliii]

Ok, so it powers on as expected it's just the initial state doesn't appear to be getting populated properly. I'll go through the startup logic again and see if I'm missing some message send to front end somewhere in the process. That status should be checked on page load/initial connection, so I'm sure it's just some race condition somewhere.

[ilgrank]

Again it seems I spoke too early. The power off after 30 seconds is fixed, but now it won't turn off after 30 mins of inactivity

[jneilliii]

Every time you say it doesn't work please share the whole debug.log as an attachment for analysis. You can drag it directly into a comment here on github.

[Kozze]

Hi,

Thank you for this great plugin, currently I have installed version 1.0.2rc2. After the "Idle Timeout" of 2 minutes, the "Abort Off Power Timeout" starts to count down 240 sec. .

After the 240 seconds the Power Plug switches off, however the intention is that the Raspberry Pi first shutdown before the Power Plug switches off.

Can you tell me what adjustments I need to make for this to work? What is the sensor Identifier field for?

plugin_tasmota_debug (6).log

[jneilliii]

Can you tell me what adjustments I need to make for this to work?

@Kozze check the example here. You need to enable the countdown timers option to offload the power off command to the tasmota device, because once the server shuts down it won't be able to send the command.

What is the sensor Identifier field for?

Tasmota devices can have various types of sensors attached to them for reporting data. An example is a DHT11 for temp/humidity. You would put in the same sensor info into this field for it to be able to get status data and log that information and graph.

[Kozze]

Thank you very much, it now works as it should!

I probably haven't read it correctly, the Tooltip On Hover is very helpful but on the Tasmota editor screen it doesn't work for me. Maybe you can take a look at this, I think it can help to make the correct settings.

Thanks again for the great app.

[jneilliii]

Split that as a separate issue.