I've been experimenting with ESP Easy for a while on D1 mini boards. Mostly successful, but I thought I was having problems with recovery from deep sleep. However, after some experimenting and logging, it turns out the board does wake up reliably, but it does not reconnect to wifi. I made some logs to show the problem. This is using standard mega-20200310. I have two access points, named RommeNet_1 and RommeNet2. The second is set as primary, since it is closest to the D1 mini. The board has a static DHCP IP, so it will always get the same IP address.
First one is cold boot. For the test, I disabled the sensors and only had a single rule:
Code: Select all
on WiFi#Connected do
SendToHTTP 192.168.1.11,8080,/json.htm?type=command¶m=udevice&idx=147&svalue=
endon
On cold boot, everything works "as advertised": it connects to the AP and sends the message successfully (t=4650). Also, everything keeps on working reliably after this.
Code: Select all
515 : Info : CRC : program checksum ...OK
548 : Info : CRC : SecuritySettings CRC ...OK
634 : Info : INIT : Free RAM:30688
636 : Info : INIT : I2C
638 : Info : INIT : SPI not enabled
719 : Info : INFO : Plugins: 46 [Normal] (ESP82xx Core 3d128e5c, NONOS SDK 2.2.2-dev(a58da79), LWIP: 2.1.2 PUYA support)
721 : Info : EVENT: System#Wake
fpm close 3
841 : Info : WIFI : Set WiFi to STAmode : sta(50:02:91:47:fd:4f)
add if0
945 : Info : WIFI : Start network scan
948 : Info : WIFI : Connecting RommeNet2 attempt #0scandone
965 : Info : EVENT: System#Boot
2610 : Info : WD : Uptime 0 ConnectFailures 0 FreeMem 27168 WiFiStatus 6
scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 4
cnt
connected with RommeNet2, channel 1
dhcp client start...
ip:192.168.1.23,mask:255.255.255.0,gw:192.168.1.1
4243 : Info : WIFI : Connected! AP: RommeNet2 (74:EA:3A:BD:19:74) Ch: 1 Duration: 3103 ms
4245 : Info : WIFI : DHCP IP: 192.168.1.23 (D1Mini-3) GW: 192.168.1.1 SN: 255.255.255.0 duration: 21 ms
4247 : Info : Webserver: start
4272 : Info : NTP : NTP replied: delay 20 mSec Accuracy increased by 1.006 seconds
4275 : Info : Time set to 1585384664.006
4277 : Info : Current Time Zone: DST time start: 2020-03-29 02:00:00 offset: 120 min STD time start: 2020-10-25 03:00:00 offset: 60 min
4281 : Info : Local time: 2020-03-28 09:37:44
4284 : Info : firstLoopConnectionsEstablished
4288 : Info : EVENT: Clock#Time=Sat,09:37
4301 : Info : EVENT: WiFi#ChangedAccesspoint
4400 : Info : EVENT: WiFi#ChangedWiFichannel
4500 : Info : EVENT: Time#Initialized
4600 : Info : EVENT: WiFi#Connected
4607 : Info : ACT : SendToHTTP 192.168.1.11,8080,/json.htm?type=command¶m=udevice&idx=147&svalue=
4612 : Info : Command: SendToHTTP
4614 : Debug : SendToHTTP: Host: 192.168.1.11 port: 8080
4650 : Debug : HTTP : Command_HTTP_SendToHTTP Success! HTTP/1.1 200 OK
pm open,type:2 0
20761 : Info : EVENT: Clock#Time=Sat,09:38
32316 : Info : WD : Uptime 1 ConnectFailures 0 FreeMem 22904 WiFiStatus 3
Code: Select all
59801 : Info : SLEEP: Entering deep sleep in 30 seconds.
59803 : Info : EVENT: System#NoSleep=30
89847 : Info : EVENT: System#Sleep
89859 : Info : SLEEP: Powering down to deepsleep...
enter deep sleep¦
INIT : Booting version: mega-20200310 (ESP82xx Core 3d128e5c, NONOS SDK 2.2.2-dev(a58da79), LWIP: 2.1.2 PUYA support)
86 : Info : INIT : Free RAM:33360
87 : Info : INIT : Rebooted from deepsleep #1 Last Task: Background Task Last systime: 1585385263 - Restart Reason: Deep-Sleep Wake
88 : Info : FS : Mounting...
114 : Info : FS : Mount successful, used 76304 bytes of 957314
512 : Info : CRC : program checksum ...OK
547 : Info : CRC : SecuritySettings CRC ...OK
633 : Info : INIT : Free RAM:30624
635 : Info : INIT : I2C
636 : Info : INIT : SPI not enabled
718 : Info : INFO : Plugins: 46 [Normal] (ESP82xx Core 3d128e5c, NONOS SDK 2.2.2-dev(a58da79), LWIP: 2.1.2 PUYA support)
721 : Info : EVENT: System#NoSleep=10
740 : Info : EVENT: System#Wake
fpm close 3
858 : Info : WIFI : Set WiFi to STAmode : sta(50:02:91:47:fd:4f)
add if0
962 : Info : WIFI : Connecting RommeNet2 attempt #0
980 : Info : EVENT: System#Boot
scandone
state: 0 -> 2 (b0)
1972 : Info : WIFI : Connecting RommeNet2 attempt #1
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 4
cnt
connected with RommeNet2, channel 1
dhcp client start...
ip:192.168.1.23,mask:255.255.255.0,gw:192.168.1.1
scandone
2195 : Info : WIFI : Connected! AP: RommeNet2 (74:EA:3A:BD:19:74) Ch: 1 Duration: 78 ms
2197 : Info : WIFI : DHCP IP: 192.168.1.23 (D1Mini-3) GW: 192.168.1.1 SN: 255.255.255.0 duration: 32 ms
2325 : Info : EVENT: WiFi#Connected
2332 : Info : ACT : SendToHTTP 192.168.1.11,8080,/json.htm?type=command¶m=udevice&idx=147&svalue=
2336 : Info : Command: SendToHTTP
2909 : Info : WD : Uptime 0 ConnectFailures 0 FreeMem 26232 WiFiStatus 6
pm open,type:2 0
12744 : Info : WD : Uptime 1 ConnectFailures 0 FreeMem 25696 WiFiStatus 6
12761 : Info : EVENT: System#Sleep
12781 : Info : SLEEP: Powering down to deepsleep...
enter deep sleep¦
After some time, it breaks the connection and connects to the alternate AP. This works and the update is successfully sent (t=26049).
Finally, the connection breaks again, and the board reconnects to the primary AP. Again, this is successful and the connection will remain reliable after that.
Code: Select all
70796 : Info : Command: reboot
ets Jan 8 2013,rst cause:2, boot mode:(3,7)
load 0x4010f000, len 1392, room 16
tail 0
chksum 0xd0
csum 0xd0
v3d128e5c
~ld
¦bl`s¦ol¦U93 : Info :
INIT : Booting version: mega-20200310 (ESP82xx Core 3d128e5c, NONOS SDK 2.2.2-dev(a58da79), LWIP: 2.1.2 PUYA support)
94 : Info : INIT : Free RAM:33360
95 : Info : INIT : Warm boot #1 Last Task: Background Task Last systime: 1585389721 - Restart Reason: Software/System restart
96 : Info : FS : Mounting...
122 : Info : FS : Mount successful, used 76304 bytes of 957314
522 : Info : CRC : program checksum ...OK
555 : Info : CRC : SecuritySettings CRC ...OK
639 : Info : INIT : Free RAM:30624
641 : Info : INIT : I2C
642 : Info : INIT : SPI not enabled
724 : Info : INFO : Plugins: 46 [Normal] (ESP82xx Core 3d128e5c, NONOS SDK 2.2.2-dev(a58da79), LWIP: 2.1.2 PUYA support)
726 : Info : EVENT: System#Wake
fpm close 3
846 : Info : WIFI : Set WiFi to STAmode : sta(50:02:91:47:fd:4f)
add if0
950 : Info : WIFI : Connecting RommeNet2 attempt #0
955 : Info : Time set to 1585389721.000
959 : Info : Current Time Zone: DST time start: 2020-03-29 02:00:00 offset: 120 min STD time start: 2020-10-25 03:00:00 offset: 60 min
964 : Info : Local time: 2020-03-28 11:02:01
966 : Info : EVENT: System#Boot
scandone
state: 0 -> 2 (b0)
1960 : Info : WIFI : Connecting RommeNet2 attempt #1state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 4
cnt
connected with RommeNet2, channel 1
dhcp client start...
ip:192.168.1.23,mask:255.255.255.0,gw:192.168.1.1
scandone
2182 : Info : WIFI : Connected! AP: RommeNet2 (74:EA:3A:BD:19:74) Ch: 1 Duration: 24 ms
2184 : Info : WIFI : DHCP IP: 192.168.1.23 (D1Mini-3) GW: 192.168.1.1 SN: 255.255.255.0 duration: 16 ms
2307 : Info : EVENT: Time#Initialized
2443 : Info : EVENT: Clock#Time=Sat,11:02
2890 : Info : WD : Uptime 0 ConnectFailures 0 FreeMem 26232 WiFiStatus 6
2997 : Info : EVENT: WiFi#Connected
3004 : Info : ACT : SendToHTTP 192.168.1.11,8080,/json.htm?type=command¶m=udevice&idx=147&svalue=
3008 : Info : Command: SendToHTTP
pm open,type:2 0
state: 5 -> 0 (0)
rm 0
pm close 7
del if0
usl
mode : null
20698 : Info : WIFI : Set WiFi to AP+STAmode : sta(50:02:91:47:fd:4f) + softAP(52:02:91:47:fd:4f)
add if0
add if1
dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
bcn 100
bcn 0
del if1
add if1
dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
bcn 100
21693 : Info : WIFI : AP Mode ssid will be D1Mini_3 with address 192.168.4.1
21697 : Info : WIFI : Connecting RommeNet_1 attempt #2ap_loss
21800 : Info : WIFI : Disconnected! Reason: '(8) Assoc leave' Connected for 18 s
21814 : Info : EVENT: WiFi#APmodeEnabled
22189 : Info : EVENT: WiFi#Disconnected
scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 2
cnt
connected with RommeNet_1, channel 4
dhcp client start...
ip:192.168.1.23,mask:255.255.255.0,gw:192.168.1.1
25655 : Info : WIFI : Connected! AP: RommeNet_1 (E0:91:F5:CC:EF:D2) Ch: 4 Duration: 3762 ms
25657 : Info : WIFI : DHCP IP: 192.168.1.23 (D1Mini-3) GW: 192.168.1.1 SN: 255.255.255.0 duration: 25 ms
25660 : Info : Webserver: start
25685 : Info : NTP : NTP replied: delay 20 mSec Accuracy increased by 0.447 seconds
25687 : Info : Time set to 1585389747.447 Time adjusted by 1740.23 msec. Wander: 0.48 msec/second
25691 : Info : Local time: 2020-03-28 11:02:27
25694 : Info : firstLoopConnectionsEstablished
25698 : Info : EVENT: WiFi#ChangedAccesspoint
25797 : Info : EVENT: WiFi#ChangedWiFichannel
25897 : Info : EVENT: Time#Set
25997 : Info : EVENT: WiFi#Connected
26004 : Info : ACT : SendToHTTP 192.168.1.11,8080,/json.htm?type=command¶m=udevice&idx=147&svalue=
26008 : Info : Command: SendToHTTP
26011 : Debug : SendToHTTP: Host: 192.168.1.11 port: 8080
26049 : Debug : HTTP : Command_HTTP_SendToHTTP Success! HTTP/1.1 200 OK
32317 : Info : WD : Uptime 1 ConnectFailures 0 FreeMem 20480 WiFiStatus 3
58762 : Info : EVENT: Clock#Time=Sat,11:03
62317 : Info : WD : Uptime 1 ConnectFailures 0 FreeMem 20480 WiFiStatus 3
92317 : Info : WD : Uptime 2 ConnectFailures 0 FreeMem 20480 WiFiStatus 3
bcn 0
del if1
pm open,type:2 0
state: 5 -> 0 (0)
rm 0
pm close 7
del if0
usl
mode : null
101796 : Info : WIFI : Set WiFi to STAmode : sta(50:02:91:47:fd:4f)
add if0
101910 : Info : Webserver: stop
102012 : Info : WIFI : Disconnected! Reason: '(8) Assoc leave' Connected for 1 m 16 s
102025 : Info : EVENT: WiFi#APmodeDisabled
102072 : Info : WIFI : Connecting RommeNet_1 attempt #3
102192 : Info : WIFI : Connecting RommeNet2 attempt #4scandone
102553 : Info : EVENT: WiFi#Disconnected
scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 4
cnt
connected with RommeNet2, channel 1
dhcp client start...
ip:192.168.1.23,mask:255.255.255.0,gw:192.168.1.1
106150 : Info : WIFI : Connected! AP: RommeNet2 (74:EA:3A:BD:19:74) Ch: 1 Duration: 3786 ms
106152 : Info : WIFI : DHCP IP: 192.168.1.23 (D1Mini-3) GW: 192.168.1.1 SN: 255.255.255.0 duration: 29 ms
106152 : Info : Webserver: start
106187 : Info : NTP : NTP replied: delay 30 mSec Accuracy increased by 0.955 seconds
106189 : Info : Time set to 1585389827.955 Time adjusted by 38.51 msec. Wander: 0.01 msec/second
106193 : Info : Local time: 2020-03-28 11:03:47
106198 : Info : EVENT: WiFi#ChangedAccesspoint
106297 : Info : EVENT: WiFi#ChangedWiFichannel
106397 : Info : EVENT: Time#Set
106497 : Info : EVENT: WiFi#Connected
106505 : Info : ACT : SendToHTTP 192.168.1.11,8080,/json.htm?type=command¶m=udevice&idx=147&svalue=
106509 : Info : Command: SendToHTTP
106512 : Debug : SendToHTTP: Host: 192.168.1.11 port: 8080
106578 : Debug : HTTP : Command_HTTP_SendToHTTP Success! HTTP/1.1 200 OK
pm open,type:2 0
118762 : Info : EVENT: Clock#Time=Sat,11:04
122318 : Info : WD : Uptime 2 ConnectFailures 0 FreeMem 22360 WiFiStatus 3
Kind regards,
Johan