Device going to sleep forever

thomas-lentz commented 4 years ago

BUG DESCRIPTION

It seems that under some conditions the sleep timer is set for a too short sleeping pause. As a result the device goes asleep and misses the wake up time. As a consequence it will probably never wake up again.

REQUESTED INFORMATION

[x ] Read the Contributing Guide and Policy and the Code of Conduct
[x] Searched the problem in the forum (https://groups.google.com/d/forum/sonoffusers)
[x] Device used (i.e. Sonoff Basic) : LOLIN D1 mini Pro V2.0.0
[x] Selfcompiled firmware version: Project sonoff Sonoff Version: 6.6.0.10 stb-1.11 (sonoff) build from source (8.9.2019: fix for #181)
[x] Development IDE - Compiler / Upload tools used : Arduino / Arduino

[x] Provide the output of command status 0 / Syslog Info :

ESP-MQT: tele/my-device/INFO1 = {"Module":"WEMOS","Version":"6.6.0.10 stb-1.11(sonoff)","FallbackTopic":"cmnd/my-device_fb/","GroupTopic":"my-iot-devs"}
ESP-MQT: tele/my-device/INFO2 = {"WebServerMode":"Admin","Hostname":"my-device-7689","IPAddress":"192.168.10.12"}
ESP-MQT: tele/my-device/INFO3 = {"RestartReason":"Deep-Sleep Wake"}

[x] Provide the output of syslog your issue if apply :

SYSLOG OUTPUT HERE:
2019-09-21T14:09:39.104644+02:00 my-device-7689 ESP-WIF - - - ESP-WIF: Connected
2019-09-21T14:09:39.104644+02:00 my-device-7689 ESP-HTP - - - ESP-HTP: Web server active on my-device-7689 with IP address 192.168.10.12
2019-09-21T14:09:40.303961+02:00 my-device-7689 ESP-MQT - - - ESP-MQT: Attempting connection...
2019-09-21T14:09:40.522665+02:00 my-device-7689 ESP-MQT - - - ESP-MQT: Connected
2019-09-21T14:09:40.539915+02:00 my-device-7689 ESP-MQT - - - ESP-MQT: tele/my-device/LWT = Online (retained)
2019-09-21T14:09:40.542255+02:00 my-device-7689 ESP-MQT - - - ESP-MQT: cmnd/my-device/POWER = 
2019-09-21T14:09:40.550599+02:00 my-device-7689 ESP-MQT - - - ESP-MQT: tele/my-device/INFO1 = {"Module":"WEMOS","Version":"6.6.0.10 stb-1.11(sonoff)","FallbackTopic":"cmnd/my-device_fb/","GroupTopic":"my-iot-devs"}
2019-09-21T14:09:40.552925+02:00 my-device-7689 ESP-MQT - - - ESP-MQT: tele/my-device/INFO2 = {"WebServerMode":"Admin","Hostname":"my-device-7689","IPAddress":"192.168.10.12"}
2019-09-21T14:09:40.559653+02:00 my-device-7689 ESP-MQT - - - ESP-MQT: tele/my-device/INFO3 = {"RestartReason":"Deep-Sleep Wake"}
2019-09-21T14:09:40.561776+02:00 my-device-7689 ESP-MQT - - - ESP-MQT: stat/my-device/RESULT = {"POWER":"OFF"}
2019-09-21T14:09:40.565009+02:00 my-device-7689 ESP-MQT - - - ESP-MQT: stat/my-device/POWER = OFF
2019-09-21T14:09:59.641578+02:00 my-device-7689 ESP-MQT - - - ESP-MQT: tele/my-device/STATE = {"Time":"2019-09-21T13:09:59","Epoch":1569067799,"Uptime":"0T00:00:30","UptimeSec":30,"Heap":26,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER":"OFF","Wifi":{"AP":1,"SSId":"MYWLAN","BSSId":"AA:BB:CC:DD:EE:FF","Channel":3,"RSSI":50,"LinkCount":1,"Downtime":"0T00:00:09","DeepSleep":300,"Heap":27568}}
2019-09-21T14:09:59.641578+02:00 my-device-7689 ESP-MQT - - - ESP-MQT: tele/my-device/SENSOR = {"Time":"2019-09-21T13:09:59","Epoch":1569067799,"ANALOG":{"A0":612},"DS18B20":{"Temperature":27.4},"BME280":{"Temperature":34.0,"Humidity":62.4,"Pressure":1022.3},"MAX17043":{"Voltage":3.731,"ChargeState":45.3,"Alert":0,"Treshold":32.00},"PressureUnit":"hPa","TempUnit":"C"}
2019-09-21T14:09:59.641642+02:00 my-device-7689 ESP-MQT - - - ESP-MQT: tele/my-device/LWT = Offline (retained)
2019-09-21T14:09:59.641642+02:00 my-device-7689 ESP-MQT - - - ESP-MQT: tele/my-device/UPDATE TIMER = 1569067800

TO REPRODUCE

I don't know, this happened the first time - device is not reachable anymore and more than 4000km away :-(

EXPECTED BEHAVIOUR

Should wake up after 5 minutes

ADDITIONAL CONTEXT

I think the problem is shown in these two lines:

ESP-MQT: tele/my-device/SENSOR = {"Time":"2019-09-21T13:09:59","Epoch":1569067799,"ANALOG":{"A0":612},"DS18B20":{"Temperature":27.4},"BME280":{"Temperature":34.0,"Humidity":62.4,"Pressure":1022.3},"MAX17043":{"Voltage":3.731,"ChargeState":45.3,"Alert":0,"Treshold":32.00},"PressureUnit":"hPa","TempUnit":"C"}
ESP-MQT: tele/my-device/UPDATE TIMER = 1569067800

Current time (Epoch) is: 1569067799 - GMT: Saturday, September 21, 2019 12:09:59 PM Update Timer (Epoch) is: 1569067800 - GMT: Saturday, September 21, 2019 12:10:00 PM

It shows that there is one second time for the device to fall asleep and wake up again. I think it went the second asleep, when it should wake up again and is now sleeping forever. In my opinion there should at least be a plausibility check for the size of the next sleeping window (Epoch-Time minus Update-Timer > 5 seconds).

thomas-lentz commented 4 years ago

Hi Stefan, frankly said it is very difficult to analyze your "sleeping code" given the current commenting. Is there some documentation I didn't find yet? Could you please elaborate a little more on the following routine? What is the need for _RtcSettings.deepsleepslip, why the window of 9000 to 11000?

if (Settings.deepsleep > 10 && Settings.deepsleep < 4294967295 && !disable_deepsleep_switch && tele_period < 2 && prep_called == 1 ) 
 {
  SettingsSaveAll();
  Response_P(S_OFFLINE);
  MqttPublishPrefixTopic_P(TELE, PSTR(D_LWT), true);  // Offline or remove previous retained topic
  yield();
  if (RtcSettings.nextwakeup == 0 || RtcSettings.deepsleep_slip < 9000 || RtcSettings.deepsleep_slip > 11000 || RtcSettings.nextwakeup > UtcTime()+Settings.deepsleep) {
    AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("Reset wrong settings wakeup: %ld, slip %ld"),  RtcSettings.nextwakeup, RtcSettings.deepsleep_slip );
    RtcSettings.nextwakeup = 0;
    RtcSettings.deepsleep_slip = 10000;
    //AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("new settings wakeup: %ld, slip %ld"),  RtcSettings.nextwakeup, RtcSettings.deepsleep_slip );
  }
  //timeslip in 0.1 seconds
  int16_t timeslip = (int16_t)(RtcSettings.nextwakeup+RtcSettings.uptime/1000-UtcTime())*10;
  AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("Timeslip 0.1 sec:? %d < %d < %ld"),  -Settings.deepsleep, timeslip, Settings.deepsleep );
  //allow 10% of deepsleep error to count as valid deepsleep
  timeslip = timeslip < -(int32_t)Settings.deepsleep ? 0 : (timeslip > (int32_t)Settings.deepsleep ? 0 : 1);
  AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("Normal deepsleep? %d"),  timeslip );
  if (timeslip) {
    RtcSettings.deepsleep_slip = (Settings.deepsleep+RtcSettings.nextwakeup-UtcTime()) *RtcSettings.deepsleep_slip / (Settings.deepsleep-(RtcSettings.uptime/1000));
    //Avoid crazy numbers.
    AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("%% calculate drift %ld"),  RtcSettings.deepsleep_slip );
    RtcSettings.deepsleep_slip = tmin(tmax(RtcSettings.deepsleep_slip, 9000),11000);

    AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("%% new drift %ld"),  RtcSettings.deepsleep_slip );
  }
  if (RtcSettings.nextwakeup <= UtcTime()) {
    RtcSettings.nextwakeup += (((UtcTime() - RtcSettings.nextwakeup) / Settings.deepsleep) + 1)*Settings.deepsleep;
  }
  Response_P(PSTR("%d"), RtcSettings.nextwakeup);
  MqttPublishPrefixTopic_P(TELE, PSTR(D_DOMOTICZ_UPDATE_TIMER), false);  // Offline or remove previous retained topic
  yield();
  MqttDisconnect();
  String dt = GetDT(RtcSettings.nextwakeup+LocalTime()- UtcTime());  // 2017-03-07T11:08:02
  AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("Next wakeup %s"), (char*)dt.c_str());
  //limit sleeptime to MAX_DEEPSLEEP_CYCLE
  uint32_t sleeptime = MAX_DEEPSLEEP_CYCLE < (RtcSettings.nextwakeup - UtcTime()) ? (uint32_t)MAX_DEEPSLEEP_CYCLE : RtcSettings.nextwakeup - UtcTime();
  RtcSettings.uptime = 0;
  RtcSettings.ultradeepsleep =  RtcSettings.nextwakeup - UtcTime();

  RtcSettingsSave();
  AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("Sleeptime %d sec, deepsleep_slip %ld"), sleeptime, RtcSettings.deepsleep_slip);
  ESP.deepSleep(100 * RtcSettings.deepsleep_slip * sleeptime);
  yield();
 }

Shouldn't the log entry level after the sanity check:

if (RtcSettings.nextwakeup == 0 || RtcSettings.deepsleep_slip < 9000 || ...

be of LOG_LEVEL_ERROR? Currently it is of LOG_LEVEL_DEBUG_MORE:

AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("Reset wrong settings wakeup: %ld, slip %ld"),  RtcSettings.nextwakeup, RtcSettings.deepsleep_slip );

As I understand this is the current plausability check, which unfortunately would allow the 1 second sleeping time:

 if (RtcSettings.nextwakeup <= UtcTime())
  {
   RtcSettings.nextwakeup += (((UtcTime() - RtcSettings.nextwakeup) / Settings.deepsleep) + 1)*Settings.deepsleep;
  }

Wouldn't it make sense to introduce a MinSleepIntervall of maybe 3 seconds which assures that the device can goto sleep and gets woken up again. If so, I would suggest:

MinSleepIntervall=3;

if (RtcSettings.nextwakeup <= UtcTime() + MinSleepIntervall)
 {
  RtcSettings.nextwakeup += (((UtcTime() - RtcSettings.nextwakeup) / Settings.deepsleep) + 1)*Settings.deepsleep;
  }

stefanbode commented 4 years ago

I added some comments to make it more understandable what we are doing here and why. I added your suggestion about the minimum sleep interval. I was able to send the device to death (infinite sleep) without. Thanks for bringing this up.

stefanbode commented 4 years ago

With the latest fix it now also does not wakeup more often than requested.

stefanbode / Sonoff-Tasmota