An MQTT message is published more than once, after deep sleep.

[demestav]

Steps to reproduce

How can we trigger this problem?

• Add a task with any delay. In my case this was a DHT11 sensor, and tested various delay values ranging from 60 to 120 seconds.
• Enable deep sleep mode. In my case this was set to 20 seconds awake and 60 seconds delay.
• Enable publishing to MQTT. In my case this was set to OpenHUB controller.
• Issue a subscriber to the MQTT broker to watch the messages.

Does the problem persists after powering off and on? (just resetting isn't enough sometimes) Yes.

Expected behavior

Tell us what should happen? The sensor values should be published to MQTT only once every time the module exits from deep sleep.

Actual behavior

Tell us what happens instead? The sensor values are published more than once to MQTT. Most of the time they are published twice, but sometimes more. A strange pattern that emerges is that not all values are published i.e.:

/testdht11/Temperature 23.00
/testdht11/Humidity 40.00
/testdht11/Temperature 23.00

Looking at the log, I can see that the sensor is indeed triggered twice (or sometimes more) every time the module exists from deep sleep.

System configuration

Hardware: NodeMCU development board

Software or git version: Precompiled test package from 28/03/2018 i.e. ESP_Easy_mega-20180328_test_ESP8266_4096.bin

[demestav]

I have pulled and tested the normal and dev version of https://github.com/letscontrolit/ESPEasy/commit/d083a58cd7738e0c3fe93d9a39d15db5f8e8beb8

In both versions MQTT publishing does not work after deep sleep. When deepsleep is disabled then all data is normally published to MQTT .

Please let me know if you require any more details to pinpoint this issue.

[TD-er]

Are you able to get some log output (serial log with at least info level) to show what happens when the ESP gets out of deep sleep?

I am not using deep-sleep myself and @v-a-d-e-r is reporting the same issues as you do, regarding MQTT and deep sleep.

[demestav]

[PLEASE IGNORE THIS COMMENT. SEE COMMENT BELOW]

Yes sure, The output is:

575882 : DHT  : Temperature: 24.00
575882 : DHT  : Humidity: 45.00
580881 : DHT  : Temperature: 24.00
580881 : DHT  : Humidity: 45.00
584070 : FILE : Saved config.dat
584160 : SLEEP: Entering deep sleep in 30 seconds.
614160 : EVENT: System#Sleep
614187 : SLEEP: Powering down to deepsleep...
��␀␀�␀␀␀��␀�␀���␀�␀␀␀�␀��␀�␀

Note that the last line is garbled text in my terminal too (i.e. not a problem with copy and paste).

At time 584070 is where I activated the deepsleep feature.

From the LED indicator, I understand that the module stays awake for about a second or less. It doesn't seem enough time to connect to WiFi then to MQTT broken and to publish.

[TD-er]

And what about when it wakes from deepsleep?

[demestav]

I just realized that the reset cable got disconnected so please disregard my previous comment. Sorry about that!

Here is the output of 2 cycles:

INIT : Booting version:
269 : INIT : Rebooted from deepsleep #10
271 : FS   : Mounting...
295 : FS   : Mount successful, used 75802 bytes of 957314
304 : CRC  : No program memory checksum found. Check output of crc2.py
308 : CRC  : Settings CRC           ...FAIL
336 : CRC  : SecuritySettings CRC   ...OK
441 : INIT : Free RAM:15784
442 : INIT : I2C
442 : INIT : SPI not enabled
458 : WIFI : Set WiFi to AP+STA
1345 : WIFI : AP Mode ssid will be test1_0 with address 192.168.4.1
1346 : WIFI : Connecting XXXXXX attempt #0
1358 : WD   : Uptime 0 ConnectFailures 0 FreeMem 11408
1397 : DHT  : Temperature: 25.00
1397 : DHT  : Humidity: 39.00
2391 : DHT  : Temperature: 25.00
2391 : DHT  : Humidity: 36.00
3391 : DHT  : Temperature: 25.00
3391 : DHT  : Humidity: 32.00
4480 : WIFI : Connected! AP: XXXXX Ch: 11 Duration: 3071 ms
4508 : DHT  : Temperature: 25.00
4508 : DHT  : Humidity: 31.00
5608 : DHT  : Temperature: 25.00
5608 : DHT  : Humidity: 30.00
6692 : EVENT: System#Sleep
6719 : SLEEP: Powering down to deepsleep...
{l␀l��|␀�d�|␃␄␄␌�␌d�␌b|��␃�

INIT : Booting version:
268 : INIT : Rebooted from deepsleep #11
269 : FS   : Mounting...
294 : FS   : Mount successful, used 75802 bytes of 957314
303 : CRC  : No program memory checksum found. Check output of crc2.py
306 : CRC  : Settings CRC           ...FAIL
335 : CRC  : SecuritySettings CRC   ...OK
439 : INIT : Free RAM:15912
439 : INIT : I2C
439 : INIT : SPI not enabled
455 : WIFI : Set WiFi to AP+STA
1342 : WIFI : AP Mode ssid will be test1_0 with address 192.168.4.1
1343 : WIFI : Connecting XXXXXX attempt #0
1354 : WD   : Uptime 0 ConnectFailures 0 FreeMem 11664
1392 : DHT  : Temperature: 25.00
1392 : DHT  : Humidity: 39.00
2388 : DHT  : Temperature: 25.00
2388 : DHT  : Humidity: 35.00
3387 : DHT  : Temperature: 25.00
3387 : DHT  : Humidity: 32.00
4486 : WIFI : Connected! AP: XXXXXX Ch: 11 Duration: 3079 ms
4516 : DHT  : Temperature: 25.00
4516 : DHT  : Temperature: 25.00
4517 : DHT  : Humidity: 31.00
5615 : DHT  : Temperature: 25.00
5615 : DHT  : Humidity: 30.00
6699 : EVENT: System#Sleep
6726 : SLEEP: Powering down to deepsleep...

[TD-er]

Hmm very strange, why is it trying to set the wifi to AP+STA?

What version are you running? This log output of the AP+STA is introduced in the last 2 days. Before that it was just in a pull request, not a pre compiled version of the nightly builds.

[demestav]

I used git clone on https://github.com/letscontrolit/ESPEasy/commit/d083a58cd7738e0c3fe93d9a39d15db5f8e8beb8 and then followed the instructions for building and uploading using PlatformIO.

From the info section of the module

Firmware
--
Build | 20101  - Mega (core 2_3_0)
GIT version |  
Plugins | 71 [Normal] [Testing] [Development]
Build Md5 | 4d44355f4d44355f4d44355f4d44355f
Md5 check | fail !
Build time | Apr 13 2018 10:52:26

[TD-er]

Ah, that's today's build. But you're using the 2.3.0 core library. Why the dev build and not the "normal"? Do you need something from the extra plugins not included in normal?

Could you try the normal build from today's build, or build one for yourself using the "normalesp8266" followed by the memory size you need? Those builds use Core 2.4.0 which solves a number of issues related to the wifi code. But it takes a bit more memory which is an issue with the Testing and Dev builds.

[demestav]

I have built and uploaded using PIO Build (normal_ESP8266_4096) and PIO Upload (normal_ESP8266_4096).

Here is the info section of the module:

Firmware
--
Build | 20101  - Mega (core 2_4_0)
GIT version |  
Plugins | 47 [Normal]
Build Md5 | 4d44355f4d44355f4d44355f4d44355f
Md5 check | fail !
Build time | Apr 13 2018 13:17:03

Here is the log from the serial:

INIT : Booting version:
204 : INIT : Rebooted from deepsleep #2
206 : FS   : Mounting...
231 : FS   : Mount successful, used 75802 bytes of 957314
241 : CRC  : No program memory checksum found. Check output of crc2.py
245 : CRC  : Settings CRC           ...FAIL
247 : CRC  : SecuritySettings CRC   ...OK
353 : INIT : Free RAM:18248
354 : INIT : I2C
354 : INIT : SPI not enabled
369 : WIFI : Set WiFi to AP+STA
1257 : WIFI : AP Mode ssid will be test1_0 with address 192.168.4.1
1258 : WIFI : Connecting XXXXXX attempt #0
1269 : WD   : Uptime 0 ConnectFailures 0 FreeMem 13888
1305 : DHT  : Temperature: 25.00
1306 : DHT  : Humidity: 39.00
2303 : DHT  : Temperature: 25.00
2303 : DHT  : Humidity: 35.00
3303 : DHT  : Temperature: 25.00
3303 : DHT  : Humidity: 32.00
4394 : WIFI : Connected! AP: XXXXXX Ch: 11 Duration: 3080 ms
4423 : DHT  : Temperature: 25.00
4424 : DHT  : Humidity: 31.00
5521 : DHT  : Temperature: 25.00
5522 : DHT  : Humidity: 31.00
6606 : EVENT: System#Sleep
6633 : SLEEP: Powering down to deepsleep...
;l␀d��|␀�$�|␃␄␌␄�␌$

and the same repeats.

Unfortunately still no MQTT messages are published.

[TD-er]

That's very strange it is trying to start AP + STA. That means the node does not accept the set password + SSID config as valid. (or some other reason, but given the timings in the log, that's my best estimate)

[demestav]

With deepsleep disabled the node is indeed in AP mode (I can see the ssid when searching WiFi) and at the same time, it is publishing to MQTT.

Isn't this the expected behavior?

[TD-er]

Nope, AP should not be active.

[demestav]

After some time the AP mode is disabled. From the log:

52164 : DHT  : Humidity: 16.00
57164 : DHT  : Temperature: 24.00
57164 : DHT  : Humidity: 16.00
61121 : WD   : Uptime 1 ConnectFailures 0 FreeMem 13488
62164 : DHT  : Temperature: 24.00
62164 : DHT  : Humidity: 16.00
65145 : WIFI : AP Mode Disabled for SSID: test1_0
65146 : WIFI : Set WiFi to STA
65161 : MQTT : Connection lost
65162 : WIFI : Disconnected! Reason: 'Assoc leave' Connected for 1 m 0 s
65162 : WIFI : Connecting XXXXXX attempt #0
66372 : WIFI : Connected! AP: XXXXXX Ch: 11 Duration: 1208 ms
67354 : DHT  : Temperature: 24.00
67355 : DHT  : Humidity: 16.00
70129 : WIFI : DHCP IP: 192.168.0.29 (test1-0) GW: 192.168.0.1 SN: 255.255.255.0   duration: 3757 ms
70484 : MQTT : Connected to broker with client ID: ESPClient_X
70486 : Subscribed to: /test1/#
72513 : DHT  : Temperature: 24.00
72513 : DHT  : Humidity: 16.00

[TD-er]

That's correct, there is a 60 seconds timeout to let users connect to the AP. As soon as someone connects, the timeout is stopped and when all are disconnected, the timeout is started again at 60 seconds.

[demestav]

So regarding your comment https://github.com/letscontrolit/ESPEasy/issues/1195#issuecomment-381096904 ,why isn't ok that the WiFi is AP+STA? According to the log, it seems to connect just fine to the WiFi.

[TD-er]

It should only be "STA" and not "AP+STA", since the AP should only be there when it cannot connect as STA (as a normal station to another accesspoint) As said, as long as this "AP+STA" is there, there is something preventing it from normal operations. And this is specific to the deep sleep mode, so there is something wrong in the logic here, which may explain the issues you're experiencing with MQTT publish after deep sleep.

[demestav]

I see. Should I open another issue for this?

[TD-er]

Starting AP+STA upon boot should be fixed with the last update I made. Which leaves the question of this topic why (and if...) MQTT and deep sleep is causing so many issues.

[demestav]

Indeed I think the AP+STA is gone now. Here is the new log:

INIT : Booting version:  (core 2_4_0)
204 : INIT : Rebooted from deepsleep #4
206 : FS   : Mounting...
231 : FS   : Mount successful, used 75802 bytes of 957314
241 : CRC  : No program memory checksum found. Check output of crc2.py
245 : CRC  : Settings CRC           ...FAIL
273 : CRC  : SecuritySettings CRC   ...OK
375 : INIT : Free RAM:19656
375 : INIT : I2C
376 : INIT : SPI not enabled
390 : INFO : Plugins: 47 [Normal] (core 2_4_0)
390 : WIFI : Connecting XXXXXX attempt #0
401 : WD   : Uptime 0 ConnectFailures 0 FreeMem 16528
437 : DHT  : Temperature: 24.00
437 : DHT  : Humidity: 17.00
1434 : DHT  : Temperature: 24.00
1434 : DHT  : Humidity: 17.00
2434 : DHT  : Temperature: 24.00
2434 : DHT  : Humidity: 17.00
3518 : WIFI : Connected! AP: XXXXXX Ch: 11 Duration: 3059 ms
3547 : DHT  : Temperature: 24.00
3547 : DHT  : Humidity: 17.00
4643 : DHT  : Temperature: 24.00
4643 : DHT  : Humidity: 17.00
5744 : DHT  : Temperature: 24.00
5744 : DHT  : Humidity: 17.00
6829 : EVENT: System#Sleep
6855 : SLEEP: Powering down to deepsleep...

Is it possible that there is not enough time to establish a connection with the MQTT broker? I noticed that even though in the settings the Sleep awake time is set to 20 sec, here the module goes to sleep after 7 seconds.

[DittelHome]

Today i have tested with ESP_Easy_mega-20180428_normal_ESP8266_4096.bin. The sensor values are published more than once to MQTT. I have set the awake time to 1 and the sensor delay to 60. I get two values. If i set the awake time to 5 seconds, i get 5 values. Problem still exits.

[TD-er]

As soon as the wifi issues are resolved, this one is high on my todo list (MQTT related issues)

[adcomrod]

Hi. Experiencing same issue. Tried first with ESP_Easy_mega-20180524_normal_ESP8266_4096 and ESP_Easy_mega-20180524_dev_ESP8266_4096. Went back to ESP_Easy_v2.0-20180322_normal_ESP8266_4096 and the issue was there also. As soon as the esp wakes up and connects to the broker, it start to publish the values over and over until the sleep message is displayed: .. 24320 : DHT : Humidity: 74.70 25320 : DHT : Temperature: 22.30 25320 : DHT : Humidity: 74.70 26319 : DHT : Temperature: 22.40 26319 : DHT : Humidity: 74.80 28917 : DHT : Temperature: 22.40 28917 : DHT : Humidity: 74.80 29916 : DHT : Temperature: 22.40 29917 : DHT : Humidity: 74.70 30396 : SLEEP: Entering deep sleep in 30 seconds. As soos as the sleep is disabled the publish stops

[uzi18]

@adcomrod any update ?

[TD-er]

Is this still an issue? (need to test with tomorrow's build of 20191028)

[TD-er]

This one is probably not an issue anymore, so I will close it. Please let me know if it still is an issue.

[RicardoCst]

Having the same issue with the AM2320 now. Its publishing the humidity and temperature messages 2 times.

INIT : Booting version: pygit2_not_installed (ESP82xx Core 929f0fb6, NONOS SDK 2.2.2-dev(a58da79), LWIP: 2.1.2 PUYA support) 193 : Info : INIT : Free RAM:29272 194 : Info : INIT : Deep Sleep #4 - Restart Reason: Deep-Sleep Wake 195 : Info : FS : Mounting... 220 : Info : FS : Mount successful, used 75802 bytes of 957314 238 : Info : CRC : SecuritySettings CRC ...OK 240 : Info : Time set to 91.000 Time adjusted by 90761.00 msec. Wander: 25.21 msec/second Source: RTC at boot 242 : Info : Current Time Zone: STD time start: 1970-10-25 03:00:00 offset: 0 min 244 : Info : Local time: 1970-01-01 00:01:31 246 : Info : WiFi : Start network scan all channels 358 : Info : INIT : Free RAM:26368 359 : Info : INIT : I2C 360 : Info : INIT : SPI not enabled 606 : Info : INFO : Plugins: 77 [Normal] [Testing] [TEST_A] (ESP82xx Core 929f0fb6, NONOS SDK 2.2.2-dev(a58da79), LWIP: 2.1.2 PUYA support) 613 : Info : Webserver: start 670 : Info : AM2320: Temperature: 26.5 671 : Info : AM2320: Humidity: 64 1981 : Info : WD : Uptime 0 ConnectFailures 0 FreeMem 19296 WiFiStatus 0 ESPeasy internal wifi status: DISCONNECTED 2661 : Info : WiFi : Scan finished, found: 11 2664 : Info : WiFi : Best AP candidate: Ziggo5717463 AC:F8:CC:1B:9E:3C Ch:1 (-62dBm) WPA2/PSK 2666 : Info : WIFI : Connecting Ziggo5717463 AC:F8:CC:1B:9E:3C Ch:1 (-62dBm) WPA2/PSK attempt #0 3657 : Info : WIFI : Connected! AP: Ziggo5717463 (AC:F8:CC:1B:9E:3C) Ch: 1 Duration: 989 ms 3822 : Info : WIFI : DHCP IP: 192.168.178.45 (MicroBox) GW: 192.168.178.1 SN: 255.255.255.0 duration: 164 ms 3826 : Info : firstLoopConnectionsEstablished 3832 : Error : MQTT : Intentional reconnect 3873 : Info : MQTT : Connected to broker with client ID: MicroBox_0 3877 : Info : Subscribed to: MicroBox/# 3880 : Info : WD : Uptime 1 ConnectFailures 0 FreeMem 14696 WiFiStatus 3 ESPeasy internal wifi status: Conn. IP Init 3897 : Info : AM2320: Temperature: 26.9 3898 : Info : AM2320: Humidity: 63