D1 Mini strange WiFi behaviour
Posted: 28 Mar 2020, 11:17
Hello everyone,
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:
I have the option to wait for result on SendToHTTP switched on.
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.
Now, when I turn on the "Deep sleep" option, everything appears to work nicely again. The WiFi#Connected appears and the update is apparently sent. However, note that the "Success" message is missing! Nothing is ever sent to Domoticz and the board goes back to sleep. This was why I was thinking it never woke up.
The final log is from rebooting the board after successful cold boot. You can see the board "connect" to the first AP like it did on wake-up. The send command is unsuccessful.
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.
I'm hoping that someone can explain what is going wrong here. Why is it not connecting reliably on wake-up and reboot, while it seems that all settings are correct?
Kind regards,
Johan
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