search

andriyadi / AzureIoTHubMQTTClient

Azure IoT Hub client for ESP8266 using MQTT
31 stars 17 forks source link

ESP8266 crashes after sending to Azure for a while #3

Open lunanigra opened 7 years ago

lunanigra commented 7 years ago

A while everything worked fine; then suddenly a crash.

Is there a chance for identifying the cause? Or trigger a reboot?

MAC address: A0:20:A6:0D:8F:D0
Connecting to WiFi...Got IP: 172.23.56.214

Beginning Azure IoT Hub Client... NTP server 0 set to: pool.ntp.org 
NTP time zone set to: 0, result: OK
--Set daylight OFF
Short sync interval set to 5
Long sync interval set to 1800
Time sync started
-- NTP Server hostname: pool.ntp.org
-- Transmit NTP Request
-- NTP error :-(
Time Sync error: NTP server not reachable
Long sync interval set to 5
Current timestamp: 92
OK, connected to MQTT
-- NTP Server hostname: pool.ntp.org
-- Transmit NTP Request
Sync frequency set low
No daylight
First sync! 21:45:18 12/08/2017
Succeccful NTP sync at 21:45:18 12/08/2017
Got NTP time: 21:45:18 12/08/2017
Long sync interval set to 61
Current timestamp: 97
Creating SAS Token!
SAS Token expire: 1503438318
Connected to Azure IoT Hub
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574319}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574322}
-- NTP Server hostname: pool.ntp.org
-- Transmit NTP Request
Sync frequency set low
No daylight
Succeccful NTP sync at 21:45:26 12/08/2017
Got NTP time: 21:45:26 12/08/2017
Current timestamp: 1502574325
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574326}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574329}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574332}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574335}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574338}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574341}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574344}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574347}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574350}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574353}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574356}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574359}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574362}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574365}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574368}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574371}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574374}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574377}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574380}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574383}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574386}
-- NTP Server hostname: pool.ntp.org
-- Transmit NTP Request
Sync frequency set low
No daylight
Succeccful NTP sync at 21:46:29 12/08/2017
Got NTP time: 21:46:29 12/08/2017
Current timestamp: 1502574389
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574389}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574392}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574395}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574398}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574401}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574404}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574407}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574410}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574413}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574416}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574419}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574422}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574425}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574428}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574431}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574434}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574437}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574440}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574443}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574446}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574449}
-- NTP Server hostname: pool.ntp.org
-- Transmit NTP Request
Sync frequency set low
No daylight
Succeccful NTP sync at 21:47:32 12/08/2017
Got NTP time: 21:47:32 12/08/2017
Current timestamp: 1502574452
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574452}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574455}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574458}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574461}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574464}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574467}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574470}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574473}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574476}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574479}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574482}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574485}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574488}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574491}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574494}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574497}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574500}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574503}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574506}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574509}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574512}
-- NTP Server hostname: pool.ntp.org
-- Transmit NTP Request
Sync frequency set low
No daylight
Succeccful NTP sync at 21:48:35 12/08/2017
Got NTP time: 21:48:35 12/08/2017
Current timestamp: 1502574515
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574515}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574518}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574521}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574524}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574527}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574530}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574533}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574536}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574539}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574542}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574545}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574548}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574551}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574554}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574557}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574560}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574563}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574566}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574569}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574572}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574575}
-- NTP Server hostname: pool.ntp.org
-- Transmit NTP Request
Sync frequency set low
No daylight
Succeccful NTP sync at 21:49:38 12/08/2017
Got NTP time: 21:49:38 12/08/2017
Current timestamp: 1502574578
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574578}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574581}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574584}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574587}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574590}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574593}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574596}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574599}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574602}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574605}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574608}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574611}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574614}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574617}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574620}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574623}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574626}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574629}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574632}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574635}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574638}
-- NTP Server hostname: pool.ntp.org
-- Transmit NTP Request
Sync frequency set low
No daylight
Succeccful NTP sync at 21:50:41 12/08/2017
Got NTP time: 21:50:41 12/08/2017
Current timestamp: 1502574641
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574641}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574644}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574647}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574650}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574653}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574656}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574659}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574662}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574665}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574668}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574671}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574674}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574677}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574680}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574683}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574686}
JSON: {"Switch":0,"DeviceId":"esp8266-02","EventTime":1502574694}

Exception (28):
epc1=0x402082c4 epc2=0x00000000 epc3=0x00000000 excvaddr=0x00000008 depc=0x00000000

ctx: cont 
sp: 3fff1700 end: 3fff1bc0 offset: 01a0

>>>stack>>>
3fff18a0:  00000064 00000004 3fff06a4 402082be  
3fff18b0:  00000064 3fff076c 3fff3374 40203e60  
3fff18c0:  00000040 3fff198c 00000000 00000001  
3fff18d0:  3fff06a4 3fff1950 00000003 402083cd  
3fff18e0:  00000002 00000004 00000000 4020406f  
3fff18f0:  00000040 3fff06a4 3fff06a4 3fff1b64  
3fff1900:  3fff1950 3fff06a4 00000001 40208579  
3fff1910:  3fff0ad8 00000008 3fff1950 4020b820  
3fff1920:  3fff06a4 3fff1b18 3fff198c 402073a1  
3fff1930:  00000040 3fff1b18 3fff06a4 3fff1b64  
3fff1940:  3fff06a4 3fff1b18 3fff06a4 402067cb  
3fff1950:  3ffe9648 00000003 007e3202 3fff1b01  
3fff1960:  00000000 3fff1b18 3fff1b18 00000000  
3fff1970:  3fff3a7c 3fff7854 0000002f 00000023  
3fff1980:  3fff788c 0000003b 3fff1b01 3fff2574  
3fff1990:  0000003f 0000003b 3fff3da4 0000002f  
3fff19a0:  00000023 3fff19f8 3fff1b24 4020b418  
3fff19b0:  3fff06a4 3fff19d0 3fff1b24 40206896  
3fff19c0:  3ffe94c8 3fff19d0 00000148 00000038  
3fff19d0:  3fff19c0 3fff19d8 3fff19e8 3ffe9107  
3fff19e0:  00000004 00000000 3fff19f8 3ffe910e  
3fff19f0:  00000002 3ffe9117 00000000 3ffe9122  
3fff1a00:  00000004 598f7866 3fff3f14 4022637e  
3fff1a10:  e03b3124 7744d2e8 97a780f4 00000014  
3fff1a20:  00000002 0000000f 3fff3efd 3fff1a60  
3fff1a30:  3fff3f21 00000017 0000002e 01000000  
3fff1a40:  00000014 00000014 3fff0ba0 00000000  
3fff1a50:  01820037 01000000 4020b8fc 3fff0ba0  
3fff1a60:  3fff3f11 3fff0b94 00000064 4020b974  
3fff1a70:  00bb9197 3fff30a4 00000064 4020b9b4  
3fff1a80:  01820037 3fff3f11 00000005 402041d0  
3fff1a90:  3fff1ac0 3fff3f11 3fff3e54 402279f2  
3fff1aa0:  3fff076c 00000001 00000000 401004d8  
3fff1ab0:  00000002 3fff076c 3fff076c 4020b80c  
3fff1ac0:  3fff1b10 0000031f 0000031f 3fff3e34  
3fff1ad0:  3fff3e24 3fff3e14 3fff3e34 401004d8  
3fff1ae0:  3fff1b10 3fff1b84 3fff1b88 4020b80c  
3fff1af0:  3fff1b8c 3fff3e14 3fff3d64 3fff3e34  
3fff1b00:  3fff3bcc 3fff3df4 3fff3e34 401004d8  
3fff1b10:  3fff1b88 3fff1b84 3fff252c 0000003f  
3fff1b20:  0000003b 3fff3a7c 0000003f 0000003b  
3fff1b30:  3fff1b24 3fff3bdc 00000000 40208e14  
3fff1b40:  3fff06a4 00000000 3fff0690 3fff0b94  
3fff1b50:  3fff06a4 00000000 3fff1b64 40202ba2  
3fff1b60:  3ffe9107 00000000 3fff3e34 3fff3d84  
3fff1b70:  3fff3d64 00000003 3ffe9122 00000004  
3fff1b80:  598f7866 00000000 00000000 3fff3df4  
3fff1b90:  3fff3bcc 3fff3e14 00000003 4020b91d  
3fff1ba0:  3fffdad0 00000000 3fff0b8c 4020b948  
3fff1bb0:  feefeffe feefeffe 3fff0ba0 40100718  
<<<stack<<<

 ets Jan  8 2013,rst cause:2, boot mode:(1,7)

 ets Jan  8 2013,rst cause:4, boot mode:(1,7)

wdt reset
andriyadi commented 7 years ago

Hi, sorry late response. How long do you think it survive before crash? I never test it out long enough

lunanigra commented 7 years ago

Hi, in this case the crash came just after a couple of minutes. In other cases it run for hours.

Currently we do some tests. As we want to put the ESP directly into a wall it should run stable. Otherwise we have to add a reset button somewhere.

andriyadi commented 7 years ago

@lunanigra thanks for reporting. Let's see if I can find time to investigate it further and fix it. I'm available to hire for professional work, though.

I suspect it has something to do with NTP request. Looking at your log, there are some NTP requests, that normally should be once. When more than once, it will trigger another actions again.

lunanigra commented 7 years ago

Ok, I guess it is difficult to identify the root cause. Will keep you updated if I can find any further details.

onionhammer commented 6 years ago

@andriyadi What is the NTP sync even for?

onionhammer commented 6 years ago

@andriyadi I've been testing with removing the NTP stuff, it works perfectly fine and is way less complicated & crashy.. why include it?

andriyadi commented 6 years ago

@onionhammer good question. During my exploration of Azure IoT Hub and subsequent services (Stream Analytics, etc), I need to publish timestamp field from the ESP8266. In my example, I wrote "EventTime". As we know, since there's no way to track time without using RTC, I get the current time first from NTP. I think, if you don't need the timestamp, you can remove NTP integration.

onionhammer commented 6 years ago

Unless you're queueing up events while the device is offline or something its probably going to be better to rely on the cloud's timestamp anyway

andriyadi commented 6 years ago

I just remember that the valid timestamp is used for calculating token expire (this line). Unless you have a better idea.

onionhammer commented 6 years ago

@andriyadi shrug I just went with the false branch there; 0 instead of now() and it seems to work fine