Deep Sleep longer than 6 hours causes Tasmota to reset to defaults.

cluelesscris commented 3 years ago

PROBLEM DESCRIPTION

A clear and concise description of what the problem is.

Using a DeepSleepTime more than 6 hours causes Tasmota to reset to defaults on 7th mini-sleep. Using any DeepSleepTime which causes less than 7 mini-sleeps appears to work flawlessly over many days. However, if there is a 7th mini-sleep - either because the DeepSleepTime was set to more than 6 hours or set to 6 hours and the vagaries of the rtc lead to a 7th mini-sleep, Tasmota resets to defaults. Any combination of SetOption36, 65 or 76 makes no difference. Issue occurs whether device is battery powered or USB powered.

REQUESTED INFORMATION

Make sure your have performed every step and checked the applicable boxes before submitting your issue. Thank you!

[y ] Read the Contributing Guide and Policy and the Code of Conduct
[y ] Searched the problem in issues
[y ] Searched the problem in the docs
[y ] Searched the problem in the forum
[y ] Searched the problem in the chat
[ ] Device used (e.g., Sonoff Basic): _____

Wemos D1 mini, Wemos battery shield v1.2, 18650 battery, US-100 sensor (SR04 mode), link battery +ve to A0 (ADC) to monitor battery.

[ ] Tasmota binary firmware version number used: _____

9.1.0 (also tested on 8.5.1 - similar results)

[ Y] Pre-compiled

[ ] Self-compiled

[ ] IDE / Compiler used: _____
[ ] Flashing tools used: _____ Tasmotizer 1.2

[ Y] Provide the output of command: Backlog Template; Module; GPIO 255:


20:44:19 CMD: Backlog Template; Module; GPIO 255
20:44:19 SRC: WebConsole from 192.168.1.67
20:44:19 CMD: Group 0, Index 1, Command "BACKLOG", Data "Template; Module; GPIO 255"
20:44:19 SRC: Backlog
20:44:19 CMD: Group 0, Index 1, Command "TEMPLATE", Data ""
20:44:19 MQT: stat/wemos1/tank/RESULT = {"NAME":"Generic","GPIO":[1,1,1,1,1,1,1,1,1,1,1,1,1,1],"FLAG":0,"BASE":18}
20:44:20 SRC: Backlog
20:44:20 CMD: Group 0, Index 1, Command "MODULE", Data ""
20:44:20 MQT: stat/wemos1/tank/RESULT = {"Module":{"18":"Generic"}}
20:44:20 SRC: Backlog
20:44:20 CMD: Group 0, Index 1, Command "GPIO", Data "255"
20:44:20 MQT: stat/wemos1/tank/RESULT = {"GPIO0":{"0":"None"},"GPIO1":{"0":"None"},"GPIO2":{"0":"None"},"GPIO3":{"0":"None"},"GPIO4":{"0":"None"},"GPIO5":{"0":"None"},"GPIO9":{"0":"None"},"GPIO10":{"0":"None"},"GPIO12":{"1856":"SR04 Tri/TX"},"GPIO13":{"1888":"SR04 Ech/RX"},"GPIO14":{"0":"None"},"GPIO15":{"0":"None"},"GPIO16":{"0":"None"},"GPIO17":{"4704":"ADC Input"}}

- [ ] If using rules, provide the output of this command: `Backlog Rule1; Rule2; Rule3`:

No rules used: 20:44:37 CMD: Backlog Rule1; Rule2; Rule3 20:44:37 SRC: WebConsole from 192.168.1.67 20:44:37 CMD: Group 0, Index 1, Command "BACKLOG", Data "Rule1; Rule2; Rule3" 20:44:37 SRC: Backlog 20:44:37 CMD: Group 0, Index 1, Command "RULE", Data "" 20:44:37 MQT: stat/wemos1/tank/RESULT = {"Rule1":"OFF","Once":"OFF","StopOnError":"OFF","Length":0,"Free":511,"Rules":""} 20:44:37 SRC: Backlog 20:44:37 CMD: Group 0, Index 2, Command "RULE", Data "" 20:44:37 MQT: stat/wemos1/tank/RESULT = {"Rule2":"OFF","Once":"OFF","StopOnError":"OFF","Length":0,"Free":511,"Rules":""} 20:44:38 SRC: Backlog 20:44:38 CMD: Group 0, Index 3, Command "RULE", Data "" 20:44:38 MQT: stat/wemos1/tank/RESULT = {"Rule3":"OFF","Once":"OFF","StopOnError":"OFF","Length":0,"Free":511,"Rules":""}

- [ ] Provide the output of this command: `Status 0`:

STATUS 0 output here:

14:37:15 CMD: status 0 14:37:15 MQT: stat/wemos1/tank/STATUS = {"Status":{"Module":18,"DeviceName":"Tasmota","FriendlyName":["Tasmota"],"Topic":"wemos1/tank","ButtonTopic":"0","Power":0,"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":0,"PowerRetain":0}} 14:37:15 MQT: stat/wemos1/tank/STATUS1 = {"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"tasmotas","OtaUrl":"http://ota.tasmota.com/tasmota/release/tasmota.bin","RestartReason":"Software/System restart","Uptime":"0T00:02:43","StartupUTC":"2020-11-25T13:34:32","Sleep":50,"CfgHolder":4617,"BootCount":34,"BCResetTime":"2020-11-13T11:35:31","SaveCount":41,"SaveAddress":"F8000"}} 14:37:15 MQT: stat/wemos1/tank/STATUS2 = {"StatusFWR":{"Version":"9.1.0(sensors)","BuildDateTime":"2020-11-07T11:59:31","Boot":31,"Core":"2_7_4_5","SDK":"2.2.2-dev(38a443e)","CpuFrequency":80,"Hardware":"ESP8266EX","CR":"388/699"}} 14:37:15 MQT: stat/wemos1/tank/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["BTHub5-6R6N","GeeGeeWiFig"],"TelePeriod":10,"Resolution":"558180C0","SetOption":["00008009","2805C8000000060000005A00000000000000","00000000","00006000","00000000"]}} 14:37:15 MQT: stat/wemos1/tank/STATUS4 = {"StatusMEM":{"ProgramSize":632,"Free":368,"Heap":17,"ProgramFlashSize":4096,"FlashSize":4096,"FlashChipId":"16405E","FlashFrequency":40,"FlashMode":3,"Features":["00000809","8FDA8787","0415A005","B7FFBFCF","01DA9BC4","64367CC7","00084052","00000000"],"Drivers":"1,2,3,4,5,6,7,8,9,10,12,14,16,17,20,21,24,29,34","Sensors":"1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,26,28,31,34,37,39,40,42,43,51,52,55,56,58,59,62,64,66,67,74"}} 14:37:15 MQT: stat/wemos1/tank/STATUS5 = {"StatusNET":{"Hostname":"wemos1","IPAddress":"192.168.1.94","Gateway":"192.168.1.254","Subnetmask":"255.255.255.0","DNSServer":"192.168.1.254","Mac":"F4:CF:A2:D1:5D:DF","Webserver":2,"WifiConfig":4,"WifiPower":17.0}} 14:37:15 MQT: stat/wemos1/tank/STATUS6 = {"StatusMQT":{"MqttHost":"192.168.1.200","MqttPort":1883,"MqttClientMask":"DVES%06X","MqttClient":"DVES_D15DDF","MqttUser":"DVES_USER","MqttCount":1,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30}} 14:37:15 MQT: stat/wemos1/tank/STATUS7 = {"StatusTIM":{"UTC":"2020-11-25T13:37:15","Local":"2020-11-25T14:37:15","StartDST":"2020-03-29T02:00:00","EndDST":"2020-10-25T03:00:00","Timezone":"+01:00","Sunrise":"08:14","Sunset":"16:59"}} 14:37:16 MQT: stat/wemos1/tank/STATUS10 = {"StatusSNS":{"Time":"2020-11-25T14:37:15","ANALOG":{"A0":863},"SR04":{"Distance":189.246}}} 14:37:16 MQT: stat/wemos1/tank/STATUS11 = {"StatusSTS":{"Time":"2020-11-25T14:37:16","Uptime":"0T00:02:44","UptimeSec":164,"Heap":19,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":48,"MqttCount":1,"Wifi":{"AP":1,"SSId":"BTHub5-6R6N","BSSId":"5C:B1:3E:45:C0:CE","Channel":1,"RSSI":16,"Signal":-92,"LinkCount":1,"Downtime":"0T00:00:07"}}}

- [ ] Provide the output of the Console log output when you experience your issue; if applicable:
  _(Please use_ `weblog 4` _for more debug information)_

Console output here:

This is a serial log as it is not possible to log everything from deep sleeps to the console.
This extract shows two deep sleep cycles the first works OK as although the deepsleeptime was 28800 it only did 14400 so less than 7 mini-sleeps. The second correctly starts deep sleep for 28800 but resets on 7th mini-sleep.

20:46:23 CMD: deepsleeptime 28800 20:46:23 SRC: WebConsole from 192.168.1.67 20:46:23 CMD: Group 0, Index 1, Command "DEEPSLEEPTIME", Data "28800" 20:46:23 MQT: stat/wemos1/tank/RESULT = {"DeepSleepTime":28800} 20:46:23 CFG: Saved to flash at F9, Count 14, Bytes 4096 20:46:23 DSL: Reset wrong settings wakeup: 0, slip 11000 20:46:23 MQT: stat/wemos1/tank/RESULT = {"DeepSleep":{"Time":"2020-11-27T01:00:00","Epoch":1606435200}} 20:46:26 APP: Sleeping

00:00:00 CFG: Loaded from flash at F9, Count 14 00:00:00 QPC: Count 1 00:00:00 CFG: CR 388/699, Busy 0 00:00:00 DSL: Remain DeepSleep 11613

00:00:00 CFG: Loaded from flash at F9, Count 14 00:00:00 QPC: Count 2 00:00:00 CFG: CR 388/699, Busy 0 00:00:00 DSL: Remain DeepSleep 8013

00:00:00 CFG: Loaded from flash at F9, Count 14 00:00:00 QPC: Count 3 00:00:00 CFG: CR 388/699, Busy 0 00:00:00 DSL: Remain DeepSleep 4413

00:00:00 CFG: Loaded from flash at F9, Count 14 00:00:00 QPC: Count 4 00:00:00 CFG: CR 388/699, Busy 0 00:00:00 DSL: Remain DeepSleep 813

00:00:00 CFG: Loaded from flash at F9, Count 14 00:00:00 QPC: Count 5 00:00:00 CFG: CR 388/699, Busy 0 00:00:00 SRC: Restart 00:00:00 Project tasmota Tasmota Version 9.1.0(sensors)-2_7_4_5 00:00:00 SR04: Mode 1 00:00:00 WIF: Checking connection... 00:00:00 WIF: Attempting connection... 00:00:00 WIF: Connecting to AP1 BTHub5-6R6N Channel 1 BSSId 5C:B1:3E:45:C0:CE in mode 11N as wemos1... 00:00:03 WIF: Checking connection... 00:00:03 WIF: Attempting connection... 00:00:04 WIF: Checking connection... 00:00:04 WIF: Connected 00:00:04 HTP: Web server active on wemos1 with IP address 192.168.1.94 01:16:14 NTP: UTC 2020-11-27T00:16:13, DST 2020-03-29T02:00:00, STD 2020-10-25T03:00:00 01:16:14 MQT: Attempting connection... 01:16:14 MQT: Connected 01:16:14 MQT: tele/wemos1/tank/LWT = Online (retained) 01:16:14 MQT: cmnd/wemos1/tank/POWER = 01:16:14 MQT: Subscribe to cmnd/wemos1/tank/# 01:16:14 MQT: Subscribe to cmnd/tasmotas/# 01:16:14 MQT: Subscribe to cmnd/DVES_D15DDF_fb/# 01:16:14 MQT: Unsubscribe from homeassistant/status 01:16:15 MQT: tasmota/discovery/F4CFA2D15DDF/config = {"ip":"192.168.1.94","dn":"Tasmota","fn":["Tasmota",null,null,null,null,null,null,null],"hn":"wemos1","mac":"F4CFA2D15DDF","md":"Generic","ty":0,"if":0,"ofln":"Offline","onln":"Online","state":["OFF","ON","TOGGLE","HOLD"],"sw":"9.1.0","t":"wemos1/tank","ft":"%prefix%/%topic%/","tp":["cmnd","stat","tele"],"rl":[0,0,0,0,0,0,0,0],"swc":[-1,-1,-1,-1,-1,-1,-1,-1],"swn":[null,null,null,null,null,null,null,null],"btn":[0,0,0,0],"so":{"4":0,"11":0,"13":0,"17":0,"20":0,"30":0,"68":0,"73":0,"82":0,"114":0},"lk":1,"lt_st":0,"ver":1} (retained) 01:16:16 MQT: tasmota/discovery/F4CFA2D15DDF/sensors = {"sn":{"Time":"2020-11-27T01:16:15","ANALOG":{"A0":921},"SR04":{"Distance":188.351}},"ver":1} (retained) 01:16:16 QPC: Reset 01:16:18 MQT: tele/wemos1/tank/STATE = {"Time":"2020-11-27T01:16:18","Uptime":"0T00:00:10","UptimeSec":10,"Heap":23,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":39,"MqttCount":1,"Wifi":{"AP":1,"SSId":"BTHub5-6R6N","BSSId":"5C:B1:3E:45:C0:CE","Channel":1,"RSSI":22,"Signal":-89,"LinkCount":1,"Downtime":"0T00:00:04"}} 01:16:18 MQT: tele/wemos1/tank/SENSOR = {"Time":"2020-11-27T01:16:18","ANALOG":{"A0":921},"SR04":{"Distance":187.965}} 01:16:18 MQT: stat/wemos1/tank/RESULT = {"DeepSleep":{"Time":"2020-11-27T09:00:00","Epoch":1606464000}} 01:16:21 APP: Sleeping 00:00:00 CFG: Loaded from flash at F9, Count 14 00:00:00 QPC: Count 1 00:00:00 CFG: CR 388/699, Busy 0 00:00:00 DSL: Remain DeepSleep 24218

00:00:00 CFG: Loaded from flash at F9, Count 14 00:00:00 QPC: Count 2 00:00:00 CFG: CR 388/699, Busy 0 00:00:00 DSL: Remain DeepSleep 20618

00:00:00 CFG: Loaded from flash at F9, Count 14 00:00:00 QPC: Count 3 00:00:00 CFG: CR 388/699, Busy 0 00:00:00 DSL: Remain DeepSleep 17018

00:00:00 CFG: Loaded from flash at F9, Count 14 00:00:00 QPC: Count 4 00:00:00 CFG: CR 388/699, Busy 0 00:00:00 DSL: Remain DeepSleep 13418

00:00:00 CFG: Loaded from flash at F9, Count 14 00:00:00 QPC: Count 5 00:00:00 CFG: CR 388/699, Busy 0 00:00:00 DSL: Remain DeepSleep 9818

00:00:00 CFG: Loaded from flash at F9, Count 14 00:00:00 QPC: Count 6 00:00:00 CFG: CR 388/699, Busy 0 00:00:00 DSL: Remain DeepSleep 6218

00:00:00 CFG: Loaded from flash at F9, Count 14 ets Jan 8 2013,rst cause:2, boot mode:(3,6)

load 0x4010f000, len 3584, room 16 tail 0 chksum 0xb0 csum 0xb0 v2843a5ac ~ld 00:00:00 CFG: Use defaults 00:00:00 FRC: Some settings have been reset (2) 00:00:00 Project tasmota Tasmota Version 9.1.0(sensors)-2_7_4_5 00:00:00 WIF: WifiManager active for 3 minutes 00:00:00 HTP: Web server active on tasmota_D15DDF-7647 with IP address 192.168.4.1 00:00:06 QPC: Reset 00:03:02 APP: Restarting


### TO REPRODUCE
_Steps to reproduce the behavior:_
Issue command through console or MQTT: deepSleepTime n (where n is > 21600).

Leave running and wait for 7 mini sleeps at which point tasmota will reset to defaults.
### EXPECTED BEHAVIOUR
_A clear and concise description of what you expected to happen._
Tasmota should perform a series of sleeps of about 1 hour until required DeepSleepTime duration has expired, then fully wake up, issuing normal telemetery and then repeat deepSleepTime. 
### SCREENSHOTS
_If applicable, add screenshots to help explain your problem._
### ADDITIONAL CONTEXT
_Add any other context about the problem here._
The documentation says that Tasmota should handle a DeepSleepTime up to 86400 (24 hours).
Note also that the documentation implies that SetOption36 (boot loop detection) defaults to 1 (enabled) but at least in sensors.bin appears to default to 0 (disabled).  Even so I issue an explicit ‘SetOption36 0’ command.  

An obvious workaround is to keep DeepSleepTime below about 21300.  Even at 21600 the inaccuracy of the RTC may result in a 7th mini-sleep and cause a reset.  However, ideally I would like sensor(s) to be monitored each 24 hours, which will also make the battery last as long as possible.
During testing some odd behaviour with the remaining deepsleep counter has been seen.  Twice the initial deep sleep target time has been set at twice the DeepSleepTime duration and once at half.   The latter is shown below:
20:46:23 CMD: deepsleeptime 28800
20:46:23 SRC: WebConsole from 192.168.1.67
20:46:23 CMD: Group 0, Index 1, Command "DEEPSLEEPTIME", Data "28800"
20:46:23 MQT: stat/wemos1/tank/RESULT = {"DeepSleepTime":28800}
20:46:23 CFG: Saved to flash at F9, Count 14, Bytes 4096
20:46:23 DSL: Reset wrong settings wakeup: 0, slip 11000
20:46:23 MQT: stat/wemos1/tank/RESULT = {"DeepSleep":{"Time":"2020-11-27T01:00:0                                                                                                                                         0","Epoch":1606435200}}
20:46:26 APP: Sleeping

00:00:00 CFG: Loaded from flash at F9, Count 14
00:00:00 QPC: Count 1
00:00:00 CFG: CR 388/699, Busy 0
00:00:00 DSL: Remain DeepSleep 11613 

**(Please, remember to close the issue when the problem has been addressed)**

arendst commented 3 years ago

Thx very much for the elaborate report. I will have a look.

arendst commented 3 years ago

The issue is definitly related to QPC which will reset settings after 7 quick restarts without being reset.

You might want to try a fix by changing this code in file tasmota.ino lines 230..233 from:

  if (1 == RtcReboot.fast_reboot_count) {  // Allow setting override only when all is well
    UpdateQuickPowerCycle(true);
    XdrvCall(FUNC_SETTINGS_OVERRIDE);
  }

into

  if ((1 == RtcReboot.fast_reboot_count) && (ResetReason() != REASON_DEEP_SLEEP_AWAKE)) {  // Allow setting override only when all is well
    UpdateQuickPowerCycle(true);
    XdrvCall(FUNC_SETTINGS_OVERRIDE);
  }

and report if it fixed your issue.

cluelesscris commented 3 years ago

Superb response. Many thanks. I've got it on test now - back to you in the morning.

cluelesscris commented 3 years ago

Fix confirmed. Very much appreciated.

arendst / Tasmota

Deep Sleep longer than 6 hours causes Tasmota to reset to defaults. #9993

PROBLEM DESCRIPTION

REQUESTED INFORMATION