search

xoseperez / espurna

Home automation firmware for ESP8266-based devices
http://tinkerman.cat
GNU General Public License v3.0
3k stars 638 forks source link

TimeLib / NtpClientLib syncs time in SYS context #1617

Closed darkoddio closed 5 years ago

darkoddio commented 5 years ago

hi all I have a sonoff POW r2 that was flashed with espurna 1.13.3: It is connected to my Audio/Video system in the living room (power strip connected to TV, Ampli, Xbox, Apple TV, Harmony Hub), so during the night, at 1AM, it is scheduled to remove power to everything. I discovered (when the switch is turned on) that sometimes it reboot, without any apparent reason. Yesterday I had the confirmation of this while I was watching the TV, everything went off and looking at the espurna web interface the uptime was just few minutes. I decided to upgrade it to 1.13.15 but today I had the same reboot issue. Is there any way to understand why it is rebooting?

darkoddio commented 5 years ago

Yesterday it happened again: it was around 23:50 and the sonoff rebooted, cutting the power to all the devices unexpectedly without proper turning off them before. I really need some idea here, I think I'll remove the sonoff from the power strip until this issue is fixed, otherwise the risk is to damage some device :(

mcspr commented 5 years ago

You see the last reboot reason via the terminal crash command, either use telnet or Debug panel in the WebUI

One known reason for surprise resets are malformed mDNS packets, specifically from KASA app: #1428

darkoddio commented 5 years ago

I was trying to login using the webUI, nothing were displayed, after a while it stopped pinging, it was restarting obviously, just after the restart I tried the crash command and this is the result

image

It crashed again immediately after this command Tried again, crashed again:

image

So at this point I don't really know the reason for the reboot when I was using the TV...

darkoddio commented 5 years ago

I have also a Teckin SP22, flashed with 1.13.5: I've just discovered after 2 days of uptime (more or less) today it restarted as well, this is the result of the crash command:

image

darkoddio commented 5 years ago

This night the sonoff rebooted again (around 3AM) and this time I was able to get the crash log without it restarts again. BTW I'm not able to understand the reason of these reboots, need some help here :)

image

mcspr commented 5 years ago

@darkoddio thank you for traces :) do you use pool.ntp.org as ntp server? if yes, can you try pointing it to your local ntp server instead?

darkoddio commented 5 years ago

yep, it's already using pool.ntp.org I don't have any local ntp server, I'll try to install some, maybe in a docker on rpi In th meantie I'll try to use time.google.com on both the devices

Today I had to unplug the sonoff from the power strip: there is an update available for the Xbox One X, try to imagine if the sonoff reboots in the middle of the upgrade...

mcspr commented 5 years ago

thanks. can you instead use an ip address to avoid using dns? google's server gives me rotating ones, maybe nslookup time.windows.com on some local machine. for me it's 52.178.161.41

darkoddio commented 5 years ago

Loaded Web UI to change to ip address (51.141.32.51 in my case) on the Teckin, espurna crashed :( Nevertheless ip saved Issued crash command -> crashed again :( image

darkoddio commented 5 years ago

any update here? new crash log, if needed:

[463457] [WEBSOCKET] #1 connected, ip: 192.168.1.126, url: /ws
[464201] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":231,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:37","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083418} (PID 1)
[465201] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":231,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:38","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083419} (PID 1)
[466203] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":231,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:39","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083420} (PID 1)
[467204] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":230,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:40","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083421} (PID 1)
[468205] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":230,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:41","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083422} (PID 1)
[469207] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":231,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:42","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083423} (PID 1)
[470209] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":231,"power":0,"apparent":0,"factor":2,"energy":0.001,"time":"2019-03-16 12:05:43","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083424} (PID 1)
[471143] [WEBSOCKET] Requested action: dbgcmd
[471146] [DEBUG] Latest crash was at 171201323 ms after boot
[471148] [DEBUG] Reason of restart: 3
[471149] [DEBUG] Exception cause: 4
[471150] [DEBUG] epc1=0x40201728 epc2=0x00000000 epc3=0x00000000
[471153] [DEBUG] excvaddr=0x00000000 depc=0x00000000
[471155] [DEBUG] sp=0x3ffffe90 end=0x3fffffb0
[471156] [DEBUG] >>>stack>>>
[DEBUG] 3ffffe90: 00000000 00000000 00000000 00000000 
[DEBUG] 3ffffea0: 3ffea6f0 33208d33 3fff6d8c 4022ced5 
[DEBUG] 3ffffeb0: 0000002f 0a343e61 3fff0f50 40228579 
[DEBUG] 3ffffec0: 3ffea6f0 33208d33 00000000 3fff6b64 
[DEBUG] 3ffffed0: 3fff7204 3fff6b54 3fff7150 402010e8 
[DEBUG] 3ffffee0: 3fff6b69 3fff6b54 3fff7208 00000000
[DEBUG] 3ffffef0: 3ffea6f0 33208d33 3fff7150 4020c23a 
[DEBUG] 3fffff00: 000003e7 3fff0f38 3fff0f40 402285c4 
[DEBUG] 3fffff10: 3fff7204 3fff0a00 3fffff50 40227e07 
[DEBUG] 3fffff20: dc13d709 3fff0a00 3fffff50 40204fa9 
[DEBUG] 3fffff30: dc13d709 3fff0a00 3fff7150 4020f288 
[DEBUG] 3fffff40: 3ffe9468 74c5f056 3fff7144 00000200 
[DEBUG] 3fffff50: 401048ee 3fff581c 74c5f056 00000000 
[DEBUG] 3fffff60: 40104832 74c5f737 3ffef310 60000600 
[DEBUG] 3fffff70: dc13d709 3ffef310 3fff581c 402355a1 
[DEBUG] 3fffff80: 402355e6 3fffdab0 00000000 3fffdcb0 
[DEBUG] 3fffff90: 3ffef328 3fffdad0 3fff1154 4022ce07 
[DEBUG] 3fffffa0: 40000f49 40000f49 3fffdab0 40000f49 
[DEBUG] <<<stack<<<
[471389] +OK
[472212] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":231,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:45","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083426} (PID 1)
[473213] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":231,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:46","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083427} (PID 1)
[474214] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":232,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:47","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083428} (PID 1)
[475215] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":232,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:48","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083429} (PID 1)
[476216] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":232,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:49","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083430} (PID 1)
[477218] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":232,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:50","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083431} (PID 1)
[478219] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":232,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:51","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083432} (PID 1)
[479220] [MQTT] Sending ESPURNA-3230D6/data => {"current":0,"voltage":231,"power":0,"apparent":0,"factor":100,"energy":0.001,"time":"2019-03-16 12:05:52","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2083433} (PID 1)
mcspr commented 5 years ago

Looks like the same issue with NTP and threading. By the looks of it, NTP sync sometimes fails in the main thread and tries to do it anyways in the wrong one. I'll push the update asap for that, got sidetracked with timezone support for the same module. Will be included in the next release bin / nightly builds

darkoddio commented 5 years ago

this is the crash log of the Teckin plug, if you need it to confirm that is the same issue, it seems it reboot less often than the sonoff btw, it reached 3days of uptime

[470201] [MQTT] Sending ESPURNA-D62938/data => {"current":0,"voltage":224,"power":0,"reactive":0,"apparent":0,"factor":0,"energy":0,"time":"2019-03-17 12:04:36","mac":"DC:4F:22:D6:29:38","host":"ESPURNA-D62938","ip":"192.168.1.122","id":1010574} (PID 1) [471202] [MQTT] Sending ESPURNA-D62938/data => {"current":0,"voltage":224,"power":0,"reactive":0,"apparent":0,"factor":0,"energy":0,"time":"2019-03-17 12:04:37","mac":"DC:4F:22:D6:29:38","host":"ESPURNA-D62938","ip":"192.168.1.122","id":1010575} (PID 1) [471925] [WEBSOCKET] Requested action: dbgcmd [471929] [DEBUG] Latest crash was at 272362059 ms after boot [471931] [DEBUG] Reason of restart: 3 [471932] [DEBUG] Exception cause: 4 [471933] [DEBUG] epc1=0x40201728 epc2=0x00000000 epc3=0x00000000 [471939] [DEBUG] excvaddr=0x00000000 depc=0x00000000 [471942] [DEBUG] sp=0x3ffffe90 end=0x3fffffb0 [471947] [DEBUG] >>>stack>>> [DEBUG] 3ffffe90: 00000000 00000000 00000000 00000000 [DEBUG] 3ffffea0: 3ffea690 33208d33 3fff7a5c 4022cf71 [DEBUG] 3ffffeb0: 0000002f 103be0d3 3fff0ec8 40228619 [DEBUG] 3ffffec0: 3ffea690 33208d33 00000000 3fff6e4c [DEBUG] 3ffffed0: 3fff7a30 3fff5fb4 3fff7958 402010e8 [DEBUG] 3ffffee0: 3fff6e51 3fff5fb4 3fff7a34 00000002 [DEBUG] 3ffffef0: 3ffea690 33208d33 3fff7958 4020bf76 [DEBUG] 3fffff00: 000003e7 3fff0eb0 3fff0eb8 40228664 [DEBUG] 3fffff10: 3fff7a30 3fff0998 3fffff50 40227ea7 [DEBUG] 3fffff20: 69e67f92 3fff0998 3fffff50 40204e69 [DEBUG] 3fffff30: 69e67f92 3fff0998 3fff7958 4020efc4 [DEBUG] 3fffff40: 3ffe9450 d117d783 3fff794c 00000200 [DEBUG] 3fffff50: 401048ee 3fff680c d117d783 00000000 [DEBUG] 3fffff60: 40104832 d117e113 3ffef2b0 60000600 [DEBUG] 3fffff70: 69e67f92 3ffef2b0 3fff680c 40235aed [DEBUG] 3fffff80: 40235b32 3fffdab0 00000000 3fffdcb0 [DEBUG] 3fffff90: 3ffef2c0 3fffdad0 3fff10cc 4022cea3 [DEBUG] 3fffffa0: 40000f49 40000f49 3fffdab0 40000f49 [DEBUG] <<<stack<<< [472204] +OK [472315] [MQTT] Sending ESPURNA-D62938/data => {"current":0,"voltage":224,"power":0,"reactive":0,"apparent":0,"factor":0,"energy":0,"time":"2019-03-17 12:04:38","mac":"DC:4F:22:D6:29:38","host":"ESPURNA-D62938","ip":"192.168.1.122","id":1010576} (PID 1) [473316] [MQTT] Sending ESPURNA-D62938/data => {"current":0,"voltage":224,"power":0,"reactive":0,"apparent":0,"factor":0,"energy":0,"time":"2019-03-17 12:04:39","mac":"DC:4F:22:D6:29:38","host":"ESPURNA-D62938","ip":"192.168.1.122","id":1010577} (PID 1)

darkoddio commented 5 years ago

Super strange behavior I have downgraded the firmware of the Sonoff Pow2 to 1.13.3 that was the first firmware loaded on this device and that was not rebooting (I noticed the issue only starting from 1.13.4) and now it reboots as well Here is the crash log:

[120461] [WEBSOCKET] #1 connected, ip: 192.168.1.142, url: /ws
[121036] [MQTT] Sending ESPURNA-3230D6/data => {"current":0.271,"voltage":235,"power":32,"apparent":64,"factor":50,"energy":0.001,"time":"2019-03-23 23:04:40","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2689052} (PID 1)
[122046] [MQTT] Sending ESPURNA-3230D6/data => {"current":0.271,"voltage":235,"power":32,"apparent":64,"factor":50,"energy":0.001,"time":"2019-03-23 23:04:41","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2689053} (PID 1)
[123048] [MQTT] Sending ESPURNA-3230D6/data => {"current":0.271,"voltage":235,"power":32,"apparent":64,"factor":50,"energy":0.001,"time":"2019-03-23 23:04:42","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2689054} (PID 1)
[124058] [MQTT] Sending ESPURNA-3230D6/data => {"current":0.271,"voltage":235,"power":32,"apparent":64,"factor":50,"energy":0.001,"time":"2019-03-23 23:04:43","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2689055} (PID 1)
[125066] [MQTT] Sending ESPURNA-3230D6/data => {"current":0.271,"voltage":235,"power":32,"apparent":64,"factor":50,"energy":0.001,"time":"2019-03-23 23:04:44","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2689056} (PID 1)
[126067] [MQTT] Sending ESPURNA-3230D6/data => {"current":0.271,"voltage":235,"power":32,"apparent":64,"factor":50,"energy":0.001,"time":"2019-03-23 23:04:45","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2689057} (PID 1)
[127076] [MQTT] Sending ESPURNA-3230D6/data => {"current":0.271,"voltage":235,"power":32,"apparent":64,"factor":50,"energy":0.001,"time":"2019-03-23 23:04:46","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2689058} (PID 1)
[128086] [MQTT] Sending ESPURNA-3230D6/data => {"current":0.271,"voltage":235,"power":32,"apparent":64,"factor":50,"energy":0.001,"time":"2019-03-23 23:04:47","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2689059} (PID 1)
[128983] [WEBSOCKET] Requested action: dbgcmd
[128988] [DEBUG] Latest crash was at 39737549 ms after boot
[128990] [DEBUG] Reason of restart: 3
[128992] [DEBUG] Exception cause: 4
[128993] [DEBUG] epc1=0x40201728 epc2=0x00000000 epc3=0x00000000
[128994] [DEBUG] excvaddr=0x00000000 depc=0x00000000
[128995] [DEBUG] >>>stack>>>
[DEBUG] 3ffffe80: 00000000 00000000 00000000 00000000 
[DEBUG] 3ffffe90: 3ffea620 33208d33 3fff6a7c 4022aaf5 
[DEBUG] 3ffffea0: 0000002f 025e47e0 3fff0e28 40226199 
[DEBUG] 3ffffeb0: 3ffea620 33208d33 00000000 3f847ae1 
[DEBUG] 3ffffec0: 00000006 00000000 00000020 3fff6c3c 
[DEBUG] 3ffffed0: 3fff6c44 3fff8b0c 3fff6b90 402010e8 
[DEBUG] 3ffffee0: 3ffea620 33208d33 3fff6c48 3fff6c3c 
[DEBUG] 3ffffef0: 000003e7 3fff0e10 3fff0e18 402261e4 
[DEBUG] 3fffff00: 00000006 00000006 3fff0e18 40225a27 
[DEBUG] 3fffff10: 4048c86a 3fff0924 3fff6b90 40225aed 
[DEBUG] 3fffff20: 3fff2624 3fff2620 e3fce6ed [139300] [MQTT] Sending ESPURNA-3230D6/data => {"current":0.27,"voltage":235,"power":32,"apparent":63,"factor":50,"energy":0.002,"time":"2019-03-23 23:04:58","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2689070} (PID 1)
[140301] [MQTT] Sending ESPURNA-3230D6/data => {"current":0.27,"voltage":235,"power":32,"apparent":63,"factor":50,"energy":0.002,"time":"2019-03-23 23:04:59","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2689071} (PID 1)
[141306] [MQTT] Sending ESPURNA-3230D6/data => {"current":0.271,"voltage":235,"power":32,"apparent":64,"factor":50,"energy":0.002,"time":"2019-03-23 23:05:00","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2689072} (PID 1)
[142314] [MQTT] Sending ESPURNA-3230D6/data => {"current":0.271,"voltage":235,"power":32,"apparent":64,"factor":50,"energy":0.002,"time":"2019-03-23 23:05:01","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2689073} (PID 1)
[143323] [MQTT] Sending ESPURNA-3230D6/data => {"current":0.271,"voltage":235,"power":32,"apparent":64,"factor":50,"energy":0.002,"time":"2019-03-23 23:05:02","mac":"80:7D:3A:32:30:D6","host":"ESPURNA-3230D6","ip":"192.168.1.124","id":2689074} (PID 1)
darkoddio commented 5 years ago

any progress here?

mcspr commented 5 years ago

https://github.com/xoseperez/espurna/pull/1642 is in dev, will be in the next release. or https://github.com/mcspr/espurna-nightly-builder/releases will build them some time this week

btw, you can see that the exception number is the same. address too.

darkoddio commented 5 years ago

ok but the issue is now that even rolling back to 1.13.3 it is again rebooting randomly, while at the beginning, when I bought it and flashed with 1.13.3, it was not having this behavior. What can be the cause? any configuration remained from 1.13.5? is there a way to completely wipe it? I'm going to try the factory reset button, I'll let you know

mcspr commented 5 years ago

Like I said, same place is crashing. Old version has the same code for MQTT JSON handling, no configuration can change that. External conditions did change however, hence the crashing.

Interpyme commented 5 years ago

I've tried all version with different sonoff (pow, bridge, basic, dual, pro 4ch...) from 1.13.1 to 1.13.5 and the result is always the same, after a random time, it reboots. I've tried with ntp local, only ip with and without dns, the same result. The last version, and the one I've got installed and it is stable, 1.12.6, from then on, reboots.

mcspr commented 5 years ago

@Interpyme Do you use mqtt json? Can you try build from https://github.com/mcspr/espurna-nightly-builder/releases on one of the devices?

Interpyme commented 5 years ago

I use mqtt with Jeedom, and yes, I can build it and try it. I will tell you the result asap.

Interpyme commented 5 years ago

I´ve updated one rfbridge to 1.13.6-dev build 20190412

I´will inform if there are more reboots.

This is the log from the crash command (I ran it after the firmware was upgraded):

127101] [WEBSOCKET] Requested action: dbgcmd [127106] [DEBUG] Latest crash was at 28811243 ms after boot [127110] [DEBUG] Reason of restart: 3 [127113] [DEBUG] Exception cause: 4 [127117] [DEBUG] epc1=0x40201728 epc2=0x00000000 epc3=0x00000000 [127119] [DEBUG] excvaddr=0x00000000 depc=0x00000000 [127122] [DEBUG] sp=0x3ffffc60 end=0x3fffffb0 [127124] [DEBUG] >>>stack>>> [DEBUG] 3ffffc60: 00000000 00000000 00000000 00000000 [DEBUG] 3ffffc70: 3ffea410 1a079c93 3fff71dc 4022ae89 [DEBUG] 3ffffc80: 0000002f 01b7933c 3fff0bf8 40226505 [DEBUG] 3ffffc90: 3ffea410 1a079c93 00000000 00000001 [DEBUG] 3ffffca0: 3fff80a4 00000000 0ccccccc 00000009 [DEBUG] 3ffffcb0: 00000019 00000001 00000000 3fff80a6 [DEBUG] 3ffffcc0: 3ffea410 1a079c93 3ffffd1c 3fff659c [DEBUG] 3ffffcd0: 000003e7 3fff0be0 3fff0be8 40226550 [DEBUG] 3ffffce0: 3ffe8a8f 3ffe8ab8 3fff6f58 40225d8f [DEBUG] 3ffffcf0: 00000009 00000001 3fff6f58 40225e6c [DEBUG] 3ffffd00: 00000009 00000001 3fff6f58 40209e46 [DEBUG] 3ffffd10: 00000001 00000000 00000000 00000000 [DEBUG] 3ffffd20: 00000000 00000000 3fff6f00 40209204 [DEBUG] 3ffffd30: 00000001 00000000 3fff6f58 3fff659c [DEBUG] 3ffffd40: 00000009 3fff652c 3fff6f58 4022b220 [DEBUG] 3ffffd50: 00000000 00000000 00000000 4020818e [DEBUG] 3ffffd60: 0a732520 40104100 3fff04bc 402129b2 [DEBUG] 3ffffd70: 3ffe9278 00000000 3fff875c 00000800 [DEBUG] 3ffffd80: 00007fff 00000009 0000000a 0000000f [DEBUG] 3ffffd90: 00000059 000000a0 3ffffdd0 00000000 [DEBUG] 3ffffda0: 3fff70cc 00000001 3fff04bc 40215e03 [DEBUG] 3ffffdb0: 3fff35e4 00000a44 00000a44 4010020c [DEBUG] 3ffffdc0: 00000001 3fff70cc 3ffffe10 4010068c [DEBUG] 3ffffdd0: 3ffea410 a0590f0a 3ffffe10 4022ab48 [DEBUG] 3ffffde0: 3fff1f28 000008f0 000008f0 4010020c [DEBUG] 3ffffdf0: 00000001 00000000 3ffffe40 3fff7be4 [DEBUG] 3ffffe00: 00000001 3fff70cc 00000000 4022b39e [DEBUG] 3ffffe10: 3fff793c 3ffe85a1 4021f5cc 4022be29 [DEBUG] 3ffffe20: 00000000 00000000 3fff70cc 4021dca9 [DEBUG] 3ffffe30: 3fff1f28 00000000 3fff70cc 4021e592 [DEBUG] 3ffffe40: 3fff70cc 3ffe85a1 4021d9fc 4021f120 [DEBUG] 3ffffe50: 3fff763c 0000002a 3fff7ac4 401004d8 [DEBUG] 3ffffe60: 3fff1f28 00000a21 00000a21 3fff2514 [DEBUG] 3ffffe70: 00000104 0000002a 3fff7ac4 4021e5c9 [DEBUG] 3ffffe80: 3fff7be4 b516b5c7 00002200 4010740c [DEBUG] 3ffffe90: 3fff7824 3fff2520 3fff7be4 4022be88 [DEBUG] 3ffffea0: 3fff7be4 00000104 3fff763c 4021f729 [DEBUG] 3ffffeb0: 00000001 3fff270c 3fff763c 402184b8 [DEBUG] 3ffffec0: 3fff6dd4 3fff251c 3fff2518 402184d8 [DEBUG] 3ffffed0: 3fff6dd4 3fff251c 3fff2518 402413e5 [DEBUG] 3ffffee0: 00000000 4a590f0a 00000010 00000000 [DEBUG] 3ffffef0: 00000010 00000000 3fff0dfc 401073fc [DEBUG] 3fffff00: 40230000 00000000 0000007d 3fff2704 [DEBUG] 3fffff10: 3ffed48a 3fff270c 3fff5f3c 4023f935 [DEBUG] 3fffff20: 3fff2428 3fff6204 3fff6204 3ffefc80 [DEBUG] 3fffff30: 00000000 3fff5f3c 0000001c 3fff6204 [DEBUG] 3fffff40: 3ffed47c 00000000 3fff5f3c 4023ed2d [DEBUG] 3fffff50: a0590f0a 0000005e 00000000 00000040 [DEBUG] 3fffff60: 00000002 0000001a 4022e51f 3ffee648 [DEBUG] 3fffff70: 3ffed454 3fffdcc0 3ffeace0 3ffeace0 [DEBUG] 3fffff80: 4022e492 3ffee648 00000000 3fff6254 [DEBUG] 3fffff90: 3fffdc80 00000000 3fff5f3c 402369a3 [DEBUG] 3fffffa0: 40000f49 3fffdab0 3fffdab0 40000f49 [DEBUG] <<<stack<<< [128158] +OK

Interpyme commented 5 years ago

No luck, it keeps rebooting randomly. No more than 24 hours yet.

mcspr commented 5 years ago

Does turning off MQTT JSON feature make any difference? Does "heap" value in heartbeat message decrease overtime? What about "crash" output?

Interpyme commented 5 years ago

I didn´t understand you before, I have MQTT activated, but NOT the JSON feature (I´ve never had it before).

crash command says there is no crash info... So no help here.

heap value keeps changing up and down, I will review it in more detail, but it goes up to 19k and down to 15k. So no continued decreasing here either.

Thanks for your help ;)

mcspr commented 5 years ago

If you don't see crash dump, does info show Hardware Watchdog for reset reason? If so, then we have another issue here :/ I remember https://github.com/xoseperez/espurna/issues/1236 dealing with hardware resets because of something caused by the wireless hardware. 1.12.6 noted as last working is interesting, because since 1.13.0 ESPurna switched to JustWifi v2 (maybe something different in handling?)

Can you try running erase.config on the rfbridge with nightly build and see if it continues behaving erratically? Note that it will reset immediately after that command, since we need to reinitialize some things.

The bug described here is triggered when using MQTT JSON and sometimes when accessing WebUI or trying to backup the config json. It might've been there all this time, since we do not store real-time timestamp and do not invalidate it until it is read.

Interpyme commented 5 years ago

The info command gives the result I pasted at the end of the post.

I´ve read the wieless hardware.... Maybe it´s that, but I´ve updated my wifi aps, I´ve tried connecting to a mikrotik device and a unifi (ubiquiti) with the same results in either one of them.

I will erase the config later today and will try it again and post the results here.

[621355] [MAIN] ESPURNA 1.13.6-dev (f86a3c6) [621358] [MAIN] xose.perez@gmail.com [621361] [MAIN] http://tinkerman.cat

[621365] [MAIN] CPU chip ID: 0x82644A [621367] [MAIN] CPU frequency: 80 MHz [621369] [MAIN] SDK version: 1.5.3(aec24ac9) [621373] [MAIN] Core version: 2.3.0 [621376] [MAIN] Core revision: 159542381 [621380] [621382] [MAIN] Flash chip ID: 0x144051 [621387] [MAIN] Flash speed: 40000000 Hz [621389] [MAIN] Flash mode: DOUT [621392] [621395] [MAIN] Flash size (CHIP) : 1048576 bytes / 256 sectors ( 0 to 255) [621401] [MAIN] Flash size (SDK) : 1048576 bytes / 256 sectors ( 0 to 255) [621405] [MAIN] Reserved : 4096 bytes / 1 sectors ( 0 to 0) [621409] [MAIN] Firmware size : 480960 bytes / 118 sectors ( 1 to 118) [621412] [MAIN] Max OTA size : 540672 bytes / 132 sectors ( 119 to 250) [621418] [MAIN] EEPROM size : 4096 bytes / 1 sectors ( 251 to 251) [621421] [MAIN] Reserved : 16384 bytes / 4 sectors ( 252 to 255) [621425] [621427] [MAIN] EEPROM sectors: 251, 250 [621430] [MAIN] EEPROM current: 251 [621433] [621437] [MAIN] EEPROM: 4096 bytes initially | 1342 bytes used (32%) | 2754 bytes free (67%) [621439] [MAIN] Heap : 35312 bytes initially | 18352 bytes used (51%) | 16960 bytes free (48%) [621442] [MAIN] Stack : 4096 bytes initially | 1360 bytes used (33%) | 2736 bytes free (66%) [621446] [621448] [MAIN] Boot version: 6 [621451] [MAIN] Boot mode: 1 [621454] [MAIN] Last reset reason: Power on [621458] [MAIN] Last reset info: flag: 0 [621460] [621463] [MAIN] Board: ITEAD_SONOFF_RFBRIDGE [621466] [MAIN] Support: ALEXA API BROKER BUTTON DEBUG_TELNET DEBUG_WEB DOMOTICZ HOMEASSISTANT LED MDNS_SERVER MQTT NTP RF SCHEDULER TELNET TERMINAL THINGSPEAK WEB [621470] [MAIN] WebUI image: RFBRIDGE [621474] [621477] [MAIN] Firmware MD5: ed39c1fbea14d2a8319f78ee3ffdbe3f [621481] [MAIN] Power: 3108 mV [621483] [MAIN] Power saving delay value: 1 ms [621486]

---8<-------

[621488] +OK

Interpyme commented 5 years ago

I´ve erased the values, but the random reboots after some hours continue.

No data from crash command and info the same as the last post.

mcspr commented 5 years ago

But does it actually say about hardware watchdog in boot reason? "info" output from above shows that the board was just powered on. Does it lock-up completely so you need to power it off to make it work?

Can you try erasing rfbridge flash completely and flash it again? i.e. follow these steps from Wiki, erase_flash + write_flash

Two runtime settings can also be worth checking. Loop delay. set loopDelay 20 (more than default 1 ms) WiFi scanning. See WIFI panel / set wifiScan 0. Not sure about this, however. Both require reboot after setting

Interpyme commented 5 years ago

I´ve tried 1.13.5 with a Son Off pow r2. It was working for more than a day, and I made log in from another browser (I had a browser in one computer opened and monitoring it every few hours) and then I opened the second one in another computer and made login again, the Sonoff was rebooted.

I paste the information from the crash command.

[038911] [DEBUG] Latest crash was at 179498184 ms after boot [038915] [DEBUG] Reason of restart: 2 [038918] [DEBUG] Exception cause: 29 [038921] [DEBUG] epc1=0x4020e0de epc2=0x00000000 epc3=0x00000000 [038925] [DEBUG] excvaddr=0x00000000 depc=0x00000000 [038928] [DEBUG] sp=0x3ffffd20 end=0x3fffffb0 [038931] [DEBUG] >>>stack>>> [DEBUG] 3ffffd20: 3fff872c 3fffa808 3fff07b4 4020ccd9 [DEBUG] 3ffffd30: 00000aac 00000aac 00000aac 00000000 [DEBUG] 3ffffd40: 00000014 3fff710c 3fff07b4 40215d8d [DEBUG] 3ffffd50: 00000000 00000000 00000000 3fff624c [DEBUG] 3ffffd60: 00000014 3fff624c 3fff6f98 40215e1b [DEBUG] 3ffffd70: 3ffe9468 00000000 3fffaa34 00002000 [DEBUG] 3ffffd80: 3fff7146 00000014 0000000a 0000000f [DEBUG] 3ffffd90: 00000059 00000050 3ffffdd0 00000000 [DEBUG] 3ffffda0: 3fff710c 00000001 3fff07b4 40217b83 [DEBUG] 3ffffdb0: 3fff3714 00000910 00000910 4010020c [DEBUG] 3ffffdc0: 00000001 3fff710c 3ffffe10 4010068c [DEBUG] 3ffffdd0: 3ffea6f0 50590f0a 3ffffe10 4022cb94 [DEBUG] 3ffffde0: 3fff2274 00000a2f 00000a2f 4010020c [DEBUG] 3ffffdf0: 00000001 00000000 3ffffe40 3fff7bf4 [DEBUG] 3ffffe00: 00000001 3fff710c 00000000 4022d47a [DEBUG] 3ffffe10: 3fff72e4 3ffe85e4 40221648 4022df4d [DEBUG] 3ffffe20: 00000000 31343033 3fff710c 4021fd4d [DEBUG] 3ffffe30: 3fff2274 00000000 3fff710c 40220636 [DEBUG] 3ffffe40: 3fff710c 3ffe85e4 4021faa0 4022119c [DEBUG] 3ffffe50: 3fff755c 000000d8 3fff731c 401004d8 [DEBUG] 3ffffe60: 3fff2274 00000906 00000906 3fff2860 [DEBUG] 3ffffe70: 00000104 000000d8 3fff731c 4022066d [DEBUG] 3ffffe80: 3fff7bf4 caa5a253 00002200 401075b0 [DEBUG] 3ffffe90: 3fff7294 3fff286c 3fff7bf4 4022dfac [DEBUG] 3ffffea0: 3fff7bf4 00000104 3fff755c 402217a5 [DEBUG] 3ffffeb0: 00000001 3fff2a58 3fff755c 4021a228 [DEBUG] 3ffffec0: 3fff7744 3fff2868 3fff2864 4021a248 [DEBUG] 3ffffed0: 3fff7744 3fff2868 3fff2864 40243505 [DEBUG] 3ffffee0: 00000000 9e590f0a 00000010 00000000 [DEBUG] 3ffffef0: 00000010 00000000 3fff1154 401075a0 [DEBUG] 3fffff00: 40230000 00000000 00000064 3fff2a50 [DEBUG] 3fffff10: 3ffebe5a 3fff2a58 3fff6cc4 40241a55 [DEBUG] 3fffff20: 3fff27bc 3fff650c 3fff650c 3ffeff60 [DEBUG] 3fffff30: 00000000 3fff6cc4 0000001c 3fff650c [DEBUG] 3fffff40: 3ffebe4c 00000000 3fff6cc4 40240e4d [DEBUG] 3fffff50: 50590f0a 0000005e 00000000 00000044 [DEBUG] 3fffff60: 00000002 0000001a 4023063b 3ffee978 [DEBUG] 3fffff70: 3ffebe24 3fffdcc0 3ffeaff8 3ffeaff8 [DEBUG] 3fffff80: 402305ae 3ffee978 00000000 3fff657c [DEBUG] 3fffff90: 3fffdc80 00000000 3fff6cc4 40238acb [DEBUG] 3fffffa0: 40000f49 3fffdab0 3fffdab0 40000f49 [DEBUG] <<<stack<<< [039652] +OK

sofakng commented 5 years ago

I don't have any information to contribute, but I'm having the exact same problem. I'm trying to monitor the power usage on a server but I had to remove the device because it kept rebooting and turning off the relay.

It seemed to happen when I accessed the web interface. Sometimes it would happen immediately and other times I could leave it running for hours, and then access the web interface and then it would crash again.

serestre commented 5 years ago

I have a similar problem ... sometimes the SonOff pow R2 restarts and at other times it goes "off"; The red LED and the blue LED turn off

I paste the information from the crash command:

[155674] [WEBSOCKET] Requested action: dbgcmd [155678] [DEBUG] Latest crash was at 49445 ms after boot [155679] [DEBUG] Reason of restart: 2 [155680] [DEBUG] Exception cause: 28 [155681] [DEBUG] epc1=0x4021a5ab epc2=0x00000000 epc3=0x00000000 [155682] [DEBUG] excvaddr=0x00000000 depc=0x00000000 [155683] [DEBUG] sp=0x3ffffe70 end=0x3fffffb0 [155684] [DEBUG] >>>stack>>> [DEBUG] 3ffffe70: 00000184 00000000 3fff717c 402010d4 [DEBUG] 3ffffe80: 00000000 3fff7104 00000000 402122da [DEBUG] 3ffffe90: 3fff2866 3fff287c 00000000 4021a63c [DEBUG] 3ffffea0: 3fff6cbc 3ffeb7ec 3fff6cbc 40242895 [DEBUG] 3ffffeb0: 00000000 00000002 00000100 3fff2860 [DEBUG] 3ffffec0: 3fff6cbc 3fff2868 3fff2864 4021a687 [DEBUG] 3ffffed0: 3fff6cbc 3fff2868 3fff2864 4024354c [DEBUG] 3ffffee0: 000002a8 4001a8c0 00000018 000002a8 [DEBUG] 3ffffef0: 00000018 00000000 3fff1154 401075a0 [DEBUG] 3fffff00: 00000000 3ffed1a2 3ffed143 3fff2a50 [DEBUG] 3fffff10: 3ffeb816 3fff2a58 3fff7104 40241a55 [DEBUG] 3fffff20: 002c4a88 3fff618c 3fff618c 3ffeff60 [DEBUG] 3fffff30: 00000000 3fff7104 0000001c 3fff618c [DEBUG] 3fffff40: 3ffeb808 00000000 3fff7104 40240e4d [DEBUG] 3fffff50: 17561634 00000306 00000000 00000016 [DEBUG] 3fffff60: 4010482a 00dfc759 3ffef310 60000600 [DEBUG] 3fffff70: 402355c0 3fff21d0 3ffef310 02ccd9f0 [DEBUG] 3fffff80: 402355e6 3fffdab0 00000000 3fff6204 [DEBUG] 3fffff90: 3fffdc80 00000000 3fff7104 40238acb [DEBUG] 3fffffa0: 40000f49 3fffdab0 3fffdab0 40000f49 [DEBUG] <<<stack<<< [155895] +OK [157051] [THINGSPEAK] Enqueuing field #1 with value 3.061 [157057] [THINGSPEAK] Enqueuing field #2 with value 114 [157062] [THINGSPEAK] Enqueuing field #3 with value 324 [157069] [THINGSPEAK] Enqueuing field #4 with value 0.015 [159053] [THINGSPEAK] Enqueuing field #1 with value 3.130 [159057] [THINGSPEAK] Enqueuing field #2 with value 114 [159061] [THINGSPEAK] Enqueuing field #3 with value 344 [159065] [THINGSPEAK] Enqueuing field #4 with value 0.015

chrisdaloa commented 5 years ago

Hi guys, any news? My espurna 1.13.5 installed on a Sonoff Inching rebot every 8-10 hours.

[276105] [DEBUG] Reason of restart: 3 [276106] [DEBUG] Exception cause: 4 [276107] [DEBUG] epc1=0x40226851 epc2=0x00000000 epc3=0x00000000 [276114] [DEBUG] excvaddr=0x400369c0 depc=0x00000000

mcspr commented 5 years ago

@chrisdaloa you can try upgrading to the -dev version. fix for json data is applied there: https://github.com/xoseperez/espurna/issues/1617#issuecomment-477485296

regarding web interface crashes - those are different problems. for example, i can force device to crash with webui opened on one device and telnet attached whenever some other device tries to open web interface. hardware watchdog kicks in. same is likely to happen with more than 2 web clients attached. another one is with device logging. that one is a more obvious fix, avoiding logging when DEBUG panel isn't in focus.

chrisdaloa commented 5 years ago

@mcspr I will try to upgrading to the -dev version, thanks.

Now ( I haven't upgraded yet) when I digit "crash" in the debug web terminal it crashes with this cause:

199126] [MAIN] Last reset reason: Exception [199130] [MAIN] Last reset info: Fatal exception:29 flag:2 (EXCEPTION) epc1:0x4021d93a epc2:0x00000000 epc3:0x00000000 excvaddr:0x00000000 depc:0x00000000

mcspr commented 5 years ago

It crashes after you type "crash"? Do you connect to esp directly, via soft AP, or is it connected to the router?

chrisdaloa commented 5 years ago

@mcspr Yes it crashes if I type "crash" in the debug console via web. It's connected to the router, I access to the web panel.

chrisdaloa commented 5 years ago

@mcspr after 2 days the sonoff inching reboot with this code

[689222] [MAIN] Last reset reason: Software Watchdog [689227] [MAIN] Last reset info: Fatal exception:4 flag:3 (SOFT_WDT) epc1:0x4022b2d0 epc2:0x00000000 epc3:0x00000000 excvaddr:0x00000008 depc:0x00000000

I had a similar issue (software watchdog) on another sonoff with another firmware and I solved this disabling the serial log. Is it possible to do the same in espurna?

Interpyme commented 5 years ago

This error, after 12 days working sonoff pow r2 1.13.5 Crash command didn´t show any info.

[228245] [MAIN] Boot version: 31 [228249] [MAIN] Boot mode: 1 [228250] [MAIN] Last reset reason: Hardware Watchdog [228252] [MAIN] Last reset info: Fatal exception:4 flag:1 (WDT) epc1:0x40102271 epc2:0x00000000 epc3:0x00000000 excvaddr:0x00000000 depc:0x00000000 [228255]

mcspr commented 5 years ago

@chrisdaloa Current build starts up serial logging + listens to terminal input and quick google search shows that Inching uses serial to communicate with secondary MCU. You might be onto something... Can't disable serial debug without rebuilding, but we can do that to test things with nightlies. @Interpyme From your previous message, are you opening webui across multiple devices? Or is this related to the NTP issue here? If the former, let's use another issue for that since it may not be related. And have you tried development builds at all?

Quoting ESP8266 debug guide @ https://github.com/esp8266/Arduino/blob/master/doc/faq/a02-my-esp-crashes.rst#watchdog

Restart by the software watchdog is generally easier to troubleshoot since log includes the stack trace. The trace can be then used to find particular line in code where wdt has been triggered.

Hardware wdt is the last resort of ESP to tell you that application is locked up (if s/w wdt timer is disabled or not working).

Please note that for restarts initialized by h/w wdt, there is no stack trace to help you identify the place in code where the lockup has happened. In such case, to identify the place of lock up, you need to rely on debug messages like Serial.print distributed across the application. Then by observing what was the last debug message printed out before restart, you should be able to narrow down part of code firing the h/w wdt reset. If diagnosed application or library has debug option then switch it on to aid this troubleshooting.

If this is related to CSE7766 code, one place to look is sensor read code. It looks somewhat suspect because of condition that is sometimes resetting index to zero and never timing out while(true) loop.

Another problem is async lib handling too much requests (since we may lock something up inside SYS context => no SW watchdog => HW watchdog triggers) if it is something related to flood of messages because of logging. Buffering debug messages should help with that, but I wanted to check a couple of things before merging that change.

Interpyme commented 5 years ago

@mcspr I just wanted to share the error with (POW R2 1.13.5) just in case is helping you in any way and because this is the first time I´ve seen it work for 12 days. I have tested the developer release in my sonoff rfbridge and now it´s working for 4 days straight and counting... I´ve changed the developer release for the POW R2 too and I will post if there is a crash on it.

Thanks for all your support and efforts!

mcspr commented 5 years ago

@Interpyme It does help! But let's separate things a bit here. NtpClient uses a special wrapper now that avoids original issue. I think we found out another 2 problems:

kiralikbeyin commented 5 years ago 
[269022] [DEBUG] Latest crash was at 7166 ms after boot
[269023] [DEBUG] Reason of restart: 3
[269026] [DEBUG] Exception cause: 4
[269028] [DEBUG] epc1=0x40201684 epc2=0x00000000 epc3=0x00000000
[269029] [DEBUG] excvaddr=0x00000000 depc=0x00000000
[269032] [DEBUG] sp=0x3ffffb40 end=0x3fffffb0
[269034] [DEBUG] >>>stack>>>
[DEBUG] 3ffffb40: 3ffe83c0 3fff7cf0 ffff8000 00000020 00000000 3fff10c5 
[DEBUG] 00000000 3ffffb80: 4010068c 0000002c 
[DEBUG] 00000000 00000000 3ffffbc0: 40211094 00000000 00000030 0000ff00 704f0065 3fff70c0 3ffffc00: 00000030 3ffffc60 
[DEBUG] 00000d53 00000010 4010053d 3fff0030 00000001 0000000f 
[DEBUG] 00000000 3ffffc70: 3ffffcc0 3fff1ab4 
[DEBUG] 40211699 3fff7c5c 3fff7944 
[DEBUG] 
[DEBUG] 656c0100 3ffffcf0: 56450800 10004652 6d614e64 20646f6b 3832352c 
[DEBUG] 3132332c 3ffffd60: 3732332c 3132352c 3133332c 3233332c 
[DEBUG] 3733332c 3ffffda0: 3733332c 3436322c 
[DEBUG] 3633332c 3730352c 
[DEBUG] 3234332c 3ffffdf0: 4f776172 4e4f2064 4f626672

rfbridge begins ap mode and cant reconnect to router until i unplug the usb.

Reason of restart: 3 Exception cause: 4 do you understand what is trouble?

https://github.com/xoseperez/espurna/issues/1748