D1 Mini strange WiFi behaviour

Moderators: grovkillen, Stuntteam, TD-er

Post Reply
Message
Author
JohanE
Normal user
Posts: 14
Joined: 28 Mar 2020, 10:17

D1 Mini strange WiFi behaviour

#1 Post by JohanE » 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:

Code: Select all

  on WiFi#Connected do
    SendToHTTP 192.168.1.11,8080,/json.htm?type=command&param=udevice&idx=147&svalue=
  endon
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.

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&param=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
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.

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&param=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¦
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.

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&param=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&param=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&param=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
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

TD-er
Core team member
Posts: 2768
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: D1 Mini strange WiFi behaviour

#2 Post by TD-er » 28 Mar 2020, 11:46

I have seen similar behavior and I am not sure yet what may be causing it.
It looks like sometimes it may take a very long time to get the first byte successful transmitted after connecting to some access points.
In my test setup, it may even take minutes sometimes.

Can you test by removing the SSID of the accesspoint that's sometimes giving issues? (remove it from the settings)
ESPEasy does perform a scan and try to match it with the strongest available access point, but sometimes not all access points are seen after a scan.

On a warm reboot, the first attempt to reconnect is by using the last used access point. This will fail if the BSSID (MAC address of the access point) is not visible or if the wifi channel has changed.
I don't think switching to DHCP will help here.

JohanE
Normal user
Posts: 14
Joined: 28 Mar 2020, 10:17

Re: D1 Mini strange WiFi behaviour

#3 Post by JohanE » 28 Mar 2020, 16:28

Thanks for your reply. I had tried before with reversing the two APs, but to no avail. I tried your suggestion, with only the closest AP in the settings and the behaviour is exactly the same, only now trying several times to access the one AP and eventually getting to a stable result. See log below. I also tried with only the other AP and this shows the same.

Code: Select all

13269 : Info  : Command: reboot
pm open,type:2 0

 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
   ▒cl`{▒gd▒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
96 : Info  : INIT : Warm boot #1 Last Task: Background Task Last systime: 1585406666 - Restart Reason: Software/System restart
96 : Info  : FS   : Mounting...
122 : Info  : FS   : Mount successful, used 76304 bytes of 957314
189 : Info  : FS   : Success garbage collection
256 : Info  : FS   : Success garbage collection
658 : Info  : CRC  : program checksum       ...OK
692 : Info  : CRC  : SecuritySettings CRC   ...OK
776 : Info  : INIT : Free RAM:30472
778 : Info  : INIT : I2C
779 : Info  : INIT : SPI not enabled
862 : Info  : INFO : Plugins: 46 [Normal] (ESP82xx Core 3d128e5c, NONOS SDK 2.2.2-dev(a58da79), LWIP: 2.1.2 PUYA support)
864 : Info  : EVENT: System#Wake
fpm close 3
            984 : Info  : WIFI : Set WiFi to STAmode : sta(50:02:91:47:fd:4f)
                                                                             add if0

1088 : Info  : WIFI : Connecting RommeNet2 attempt #0
1093 : Info  : Time set to 1585406666.000
1097 : 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
1102 : Info  : Local time: 2020-03-28 15:44:26
1104 : Info  : EVENT: System#Boot
scandone
        state: 0 -> 2 (b0)
                          2098 : Info  : WIFI : Connecting RommeNet2 attempt #1state: 2 -> 3 (0)
                                                                                                state: 3 -> 5 (10)
                                                                                                                  add 0
                                                                                                                       aid 3
                                                                                                                            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
                                                                                                                2321 : Info  : WIFI : Connected! AP: RommeNet2 (74:EA:3A:BD:19:74) Ch: 1 Duration: 27 ms
2323 : Info  : WIFI : DHCP IP: 192.168.1.23 (D1Mini-3) GW: 192.168.1.1 SN: 255.255.255.0   duration: 22 ms
2446 : Info  : EVENT: Time#Initialized
2581 : Info  : EVENT: Clock#Time=Sat,15:44
3028 : Info  : WD   : Uptime 0 ConnectFailures 0 FreeMem 26176 WiFiStatus 6
3135 : Info  : EVENT: WiFi#Connected
3143 : Info  : ACT  : SendToHTTP 192.168.1.11,8080,/json.htm?type=command&param=udevice&idx=147&svalue=
3147 : Info  : Command: SendToHTTP
pm open,type:2 0
                state: 5 -> 0 (0)
                                 rm 0
                                     pm close 7
                                               del if0
                                                      usl
                                                         mode : null
                                                                    20827 : 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

21822 : Info  : WIFI : AP Mode ssid will be D1Mini_3 with address 192.168.4.1
21828 : Info  : WIFI : Connecting RommeNet2 attempt #2
21932 : Info  : WIFI : Disconnected! Reason: '(8) Assoc leave' Connected for 18 s
21947 : Info  : EVENT: WiFi#APmodeEnabledscandone
                                                 state: 0 -> 2 (b0)

state: 2 -> 3 (0)
                 state: 3 -> 5 (10)
                                   add 0
                                        aid 3
                                             cnt

                                                 connected with RommeNet2, channel 1
                                                                                    dhcp client start...
                                                                                                        ip:192.168.1.23,mask:255.255.255.0,gw:192.168.1.1
                                                                                                                                                         23058 : Info  : WIFI : Connected! AP: RommeNet2 (74:EA:3A:BD:19:74) Ch: 1 Duration: 1037 ms
23060 : Info  : WIFI : DHCP IP: 192.168.1.23 (D1Mini-3) GW: 192.168.1.1 SN: 255.255.255.0   duration: 22 ms
23062 : Info  : Webserver: start
23098 : Info  : NTP  : NTP replied: delay 30 mSec Accuracy increased by 0.709 seconds
23100 : Info  : Time set to 1585406689.709 Time adjusted by 1736.56 msec. Wander: 0.48 msec/second
23104 : Info  : Local time: 2020-03-28 15:44:49
23107 : Info  : firstLoopConnectionsEstablished
23115 : Info  : EVENT: WiFi#Disconnected
23214 : Info  : EVENT: Time#Set
23314 : Info  : EVENT: WiFi#Connected
23321 : Info  : ACT  : SendToHTTP 192.168.1.11,8080,/json.htm?type=command&param=udevice&idx=147&svalue=
23325 : Info  : Command: SendToHTTP
23328 : Debug : SendToHTTP: Host: 192.168.1.11 port: 8080
24123 : Debug : HTTP : Command_HTTP_SendToHTTP Success! HTTP/1.1 200 OK
32456 : Info  : WD   : Uptime 1 ConnectFailures 0 FreeMem 20376 WiFiStatus 3
34113 : Info  : EVENT: Clock#Time=Sat,15:45
62455 : Info  : WD   : Uptime 1 ConnectFailures 0 FreeMem 20376 WiFiStatus 3
92456 : Info  : WD   : Uptime 2 ConnectFailures 0 FreeMem 20376 WiFiStatus 3
94113 : Info  : EVENT: Clock#Time=Sat,15:46
bcn 0
     del if1
            pm open,type:2 0
                            state: 5 -> 0 (0)
                                             rm 0
                                                 pm close 7
                                                           del if0
                                                                  usl
                                                                     mode : null
                                                                                101927 : Info  : WIFI : Set WiFi to STAmode : sta(50:02:91:47:fd:4f)
                                                                                                                                                    add if0

102031 : Info  : Webserver: stop
102134 : Info  : WIFI : Disconnected! Reason: '(8) Assoc leave' Connected for 1 m 18 s
102147 : Info  : EVENT: WiFi#APmodeDisabled
102168 : Info  : WIFI : Connecting RommeNet2 attempt #3
102299 : Info  : WIFI : Connecting RommeNet2 attempt #4scandone

102657 : Info  : EVENT: WiFi#Disconnected
scandone
        state: 0 -> 2 (b0)
                          state: 2 -> 3 (0)
                                           state: 3 -> 5 (10)
                                                             add 0
                                                                  aid 3
                                                                       cnt

                                                                           connected with RommeNet2, channel 1
                                                                                                              dhcp client start...
                                                                                                                                  ip:192.168.1.23,mask:255.255.255.0,gw:192.168.1.1
                                                                                                                                                                                   106254 : Info  : WIFI : Connected! AP: RommeNet2 (74:EA:3A:BD:19:74) Ch: 1 Duration: 3766 ms
106256 : Info  : WIFI : DHCP IP: 192.168.1.23 (D1Mini-3) GW: 192.168.1.1 SN: 255.255.255.0   duration: 21 ms
106257 : Info  : Webserver: start
106282 : Info  : NTP  : NTP replied: delay 20 mSec Accuracy increased by 0.890 seconds
106284 : Info  : Time set to 1585406772.890 Time adjusted by 22.10 msec. Wander: 0.01 msec/second
106288 : Info  : Local time: 2020-03-28 15:46:12
106292 : Info  : EVENT: Time#Set
106391 : Info  : EVENT: WiFi#Connected
106399 : Info  : ACT  : SendToHTTP 192.168.1.11,8080,/json.htm?type=command&param=udevice&idx=147&svalue=
106403 : Info  : Command: SendToHTTP
106405 : Debug : SendToHTTP: Host: 192.168.1.11 port: 8080
106457 : Debug : HTTP : Command_HTTP_SendToHTTP Success! HTTP/1.1 200 OK
pm open,type:2 0
                122455 : Info  : WD   : Uptime 2 ConnectFailures 0 FreeMem 22304 WiFiStatus 3
152455 : Info  : WD   : Uptime 3 ConnectFailures 0 FreeMem 22304 WiFiStatus 3
154113 : Info  : EVENT: Clock#Time=Sat,15:47


I noticed another possible issue while testing this. I tried to set the "Awake" time after deep sleep to 30 sec, so that it would have time to do this whole process and send at least once - the log shows success at about 24 sec. However, it doesn't seem to accept this value. Most of the times, it sleeps again after about 12 seconds. Note the "EVENT: System#NoSleep 30" at t=694.

Code: Select all

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 #2 Last Task: Background Task Last systime: 1585408887 - Restart Reason: Deep-Sleep Wake
88 : Info  : FS   : Mounting...
113 : Info  : FS   : Mount successful, used 76304 bytes of 957314
513 : Info  : CRC  : program checksum       ...OK
522 : Info  : CRC  : SecuritySettings CRC   ...OK
606 : Info  : INIT : Free RAM:30624
608 : Info  : INIT : I2C
610 : Info  : INIT : SPI not enabled
691 : Info  : INFO : Plugins: 46 [Normal] (ESP82xx Core 3d128e5c, NONOS SDK 2.2.2-dev(a58da79), LWIP: 2.1.2 PUYA support)
694 : Info  : EVENT: System#NoSleep=30
713 : Info  : EVENT: System#Wake
fpm close 3
            831 : Info  : WIFI : Set WiFi to STAmode : sta(50:02:91:47:fd:4f)
                                                                             add if0

935 : Info  : WIFI : Connecting RommeNet2 attempt #0
953 : Info  : EVENT: System#Boot
scandone
        state: 0 -> 2 (b0)
                          1944 : Info  : WIFI : Connecting RommeNet2 attempt #1state: 2 -> 3 (0)
                                                                                                state: 3 -> 5 (10)
                                                                                                                  add 0
                                                                                                                       aid 3
                                                                                                                            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
                                                                                                                2169 : Info  : WIFI : Connected! AP: RommeNet2 (74:EA:3A:BD:19:74) Ch: 1 Duration: 26 ms
2171 : Info  : WIFI : DHCP IP: 192.168.1.23 (D1Mini-3) GW: 192.168.1.1 SN: 255.255.255.0   duration: 16 ms
2297 : Info  : EVENT: WiFi#Connected
2305 : Info  : ACT  : SendToHTTP 192.168.1.11,8080,/json.htm?type=command&param=udevice&idx=147&svalue=
2309 : Info  : Command: SendToHTTP
2881 : Info  : WD   : Uptime 0 ConnectFailures 0 FreeMem 26232 WiFiStatus 6
pm open,type:2 0
                12720 : Info  : WD   : Uptime 1 ConnectFailures 0 FreeMem 25528 WiFiStatus 6
12738 : Info  : EVENT: System#Sleep
12757 : Info  : SLEEP: Powering down to deepsleep...
enter deep sleep
I have seen it work correctly just once. This coincided with a successful "send" after wake-up. Note there is a second "EVENT: System#NoSleep=30" at t=9230 this time.

Code: Select all

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: 1585408791 - Restart Reason: Deep-Sleep Wake
88 : Info  : FS   : Mounting...
114 : Info  : FS   : Mount successful, used 76304 bytes of 957314
179 : Info  : FS   : Success garbage collection
244 : Info  : FS   : Success garbage collection
644 : Info  : CRC  : program checksum       ...OK
653 : Info  : CRC  : SecuritySettings CRC   ...OK
737 : Info  : INIT : Free RAM:30472
739 : Info  : INIT : I2C
741 : Info  : INIT : SPI not enabled
824 : Info  : INFO : Plugins: 46 [Normal] (ESP82xx Core 3d128e5c, NONOS SDK 2.2.2-dev(a58da79), LWIP: 2.1.2 PUYA support)
826 : Info  : EVENT: System#NoSleep=30
845 : Info  : EVENT: System#Wake
fpm close 3
            962 : Info  : WIFI : Set WiFi to STAmode : sta(50:02:91:47:fd:4f)
                                                                             add if0

1067 : Info  : WIFI : Connecting RommeNet2 attempt #0
1084 : Info  : EVENT: System#Boot
1206 : Info  : WIFI : Connecting RommeNet2 attempt #1scandone

2766 : Info  : WD   : Uptime 0 ConnectFailures 0 FreeMem 27016 WiFiStatus 6
scandone
        4262 : Info  : WIFI : Disconnected! Reason: '(201) No AP found' Connected for 2851 ms
4382 : Info  : WIFI : Connecting RommeNet2 attempt #2
4517 : Info  : WIFI : Connecting RommeNet2 attempt #3scandone

4534 : Info  : EVENT: WiFi#Disconnected
scandone
        state: 0 -> 2 (b0)
                          state: 2 -> 3 (0)
                                           state: 3 -> 5 (10)
                                                             add 0
                                                                  aid 3
                                                                       cnt

                                                                           connected with RommeNet2, channel 1
                                                                                                              dhcp client start...
                                                                                                                                  ip:192.168.1.23,mask:255.255.255.0,gw:192.168.1.1
                                                                                                                                                                                   8477 : Info  : WIFI : Connected! AP: RommeNet2 (74:EA:3A:BD:19:74) Ch: 1 Duration: 3765 ms
8479 : Info  : WIFI : DHCP IP: 192.168.1.23 (D1Mini-3) GW: 192.168.1.1 SN: 255.255.255.0   duration: 16 ms
8481 : Info  : Webserver: start
8506 : Info  : NTP  : NTP replied: delay 20 mSec Accuracy increased by 0.891 seconds
8508 : Info  : Time set to 1585408855.891
8510 : 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
8514 : Info  : Local time: 2020-03-28 16:20:55
8517 : Info  : firstLoopConnectionsEstablished
8520 : Info  : EVENT: WiFi#ChangedAccesspoint
8532 : Info  : WD   : Uptime 1 ConnectFailures 0 FreeMem 22440 WiFiStatus 3
8535 : Info  : EVENT: Clock#Time=Sat,16:20
8549 : Info  : EVENT: WiFi#ChangedWiFichannel
8649 : Info  : EVENT: Time#Initialized
8749 : Info  : EVENT: WiFi#Connected
8757 : Info  : ACT  : SendToHTTP 192.168.1.11,8080,/json.htm?type=command&param=udevice&idx=147&svalue=
8761 : Info  : Command: SendToHTTP
8763 : Debug : SendToHTTP: Host: 192.168.1.11 port: 8080
9219 : Debug : HTTP : Command_HTTP_SendToHTTP Success! HTTP/1.1 200 OK
9230 : Info  : EVENT: System#NoSleep=30
12881 : Info  : EVENT: Clock#Time=Sat,16:21
pm open,type:2 0
                32436 : Info  : WD   : Uptime 1 ConnectFailures 0 FreeMem 23000 WiFiStatus 3
38520 : Info  : EVENT: System#Sleep
38532 : Info  : SLEEP: Powering down to deepsleep...
enter deep sleep
It appears to me that both issues are somehow connected ... ?

Regards,
Johan

JohanE
Normal user
Posts: 14
Joined: 28 Mar 2020, 10:17

Re: D1 Mini strange WiFi behaviour

#4 Post by JohanE » 28 Mar 2020, 16:47

Following up on my own conclusion from previous post, I decided to try by switching off the rules option and use the built-in reporting to Domoticz. Remarkably, that solves the problem! I do still see the occasional "Connection failed" error, but the WiFi appears to be connecting reliably. Hence, it appears that there is some negative interaction between the rules function and wifi on a warm boot...

Also note that the "SYSTEM#NoSleep" messages are missing in this log. Should they not be there?

Code: Select all

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 #12 Last Task: Background Task Last systime: 1585410303 - Restart Reason: Deep-Sleep Wake
88 : Info  : FS   : Mounting...
114 : Info  : FS   : Mount successful, used 76304 bytes of 957314
514 : Info  : CRC  : program checksum       ...OK
549 : Info  : CRC  : SecuritySettings CRC   ...OK
658 : Info  : INIT : Free RAM:30624
660 : Info  : INIT : I2C
661 : Info  : INIT : SPI not enabled
744 : Info  : INFO : Plugins: 46 [Normal] (ESP82xx Core 3d128e5c, NONOS SDK 2.2.2-dev(a58da79), LWIP: 2.1.2 PUYA support)fpm close 3

847 : Info  : WIFI : Set WiFi to STAmode : sta(50:02:91:47:fd:4f)
                                                                 add if0

951 : Info  : WIFI : Connecting RommeNet2 attempt #0
1072 : Info  : WIFI : Connecting RommeNet2 attempt #1scandone

scandone
        state: 0 -> 2 (b0)
                          state: 2 -> 3 (0)
                                           state: 3 -> 5 (10)
                                                             add 0
                                                                  aid 3
                                                                       cnt

                                                                           connected with RommeNet2, channel 1
                                                                                                              dhcp client start...
                                                                                                                                 ip:192.168.1.23,mask:255.255.255.0,gw:192.168.1.1
                                                2287 : Info  : WIFI : Connected! AP: RommeNet2 (74:EA:3A:BD:19:74) Ch: 1 Duration: 1032 ms
2289 : Info  : WIFI : DHCP IP: 192.168.1.23 (D1Mini-3) GW: 192.168.1.1 SN: 255.255.255.0   duration: 23 ms
2292 : Info  : Webserver: start
2317 : Info  : NTP  : NTP replied: delay 20 mSec Accuracy increased by 0.190 seconds
2319 : Info  : Time set to 1585410334.190
2322 : 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
2326 : Info  : Local time: 2020-03-28 16:45:34
2329 : Info  : firstLoopConnectionsEstablished
2333 : Info  : WD   : Uptime 0 ConnectFailures 0 FreeMem 22504 WiFiStatus 3
2353 : Debug : ADS1115 : Analog value: -32768
2358 : Info  :  Domoticz: Sensortype: 1 idx: 147 values: -2048.00
2366 : Info  : WD   : Uptime 1 ConnectFailures 0 FreeMem 22736 WiFiStatus 3
2606 : Error : HTTP : C001 connection failed (1/0)
2851 : Error : HTTP : C001 connection failed (2/0)
2866 : Debug : ADS1115 : Analog value: -32768
2870 : Info  :  Domoticz: Sensortype: 1 idx: 147 values: -2048.00
3097 : Debug : HTTP : C001 Success! HTTP/1.1 200 OK
3246 : Debug : HTTP : C001 Success! HTTP/1.1 200 OK
4688 : Debug : ADS1115 : Analog value: -32768
4693 : Info  :  Domoticz: Sensortype: 1 idx: 147 values: -2048.00
4750 : Debug : HTTP : C001 Success! HTTP/1.1 200 OK
6689 : Debug : ADS1115 : Analog value: -32768
6693 : Info  :  Domoticz: Sensortype: 1 idx: 147 values: -2048.00
6750 : Debug : HTTP : C001 Success! HTTP/1.1 200 OK
8332 : Info  : SLEEP: Powering down to deepsleep...
enter deep sleep
Johan

TD-er
Core team member
Posts: 2768
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: D1 Mini strange WiFi behaviour

#5 Post by TD-er » 28 Mar 2020, 18:06

Code: Select all

EVENT: System#NoSleep=30
This will only be logged the first time (since cold boot) the node will go to deep sleep.
This does allow to disable the deep sleep mode.
If you have accidentally set the awake time very short, it is impossible to disable the deep sleep. That's the reason this option is built in.

JohanE
Normal user
Posts: 14
Joined: 28 Mar 2020, 10:17

Re: D1 Mini strange WiFi behaviour

#6 Post by JohanE » 28 Mar 2020, 19:44

TD-er wrote:
28 Mar 2020, 18:06

Code: Select all

EVENT: System#NoSleep=30
This will only be logged the first time (since cold boot) the node will go to deep sleep.
Well, then how do you explain it's occurrence in the second and third logs in post #3? These are "wake from deep sleep", and the event appears there, at t=694 in the second log. In the third log it even appears twice: at t=826 and again at t=9230. I've seen it in the way you describe, but clearly it is used more often then that.

Also, what do you make of the fact that the problems with WiFi connect and with Awake time seem to go away when I disable Rules? Is that explainable?

Thanks,
Johan

TD-er
Core team member
Posts: 2768
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: D1 Mini strange WiFi behaviour

#7 Post by TD-er » 28 Mar 2020, 20:29

Ah well, I must stop replying all from memory and look into the code before talking....

Code: Select all

void prepare_deepSleep(int dsdelay)
{
  checkRAM(F("prepare_deepSleep"));

  if (!isDeepSleepEnabled())
  {
    // Deep sleep canceled by GPIO16(D0)=LOW
    return;
  }

  // first time deep sleep? offer a way to escape
  if (lastBootCause != BOOT_CAUSE_DEEP_SLEEP)
  {
    addLog(LOG_LEVEL_INFO, F("SLEEP: Entering deep sleep in 30 seconds."));

    if (Settings.UseRules && isDeepSleepEnabled())
    {
      eventQueue.add(F("System#NoSleep=30"));
      while (processNextEvent()) {
        delay(1);
      }
    }
    delayBackground(30000);

    // disabled?
    if (!isDeepSleepEnabled())
    {
      addLog(LOG_LEVEL_INFO, F("SLEEP: Deep sleep cancelled (GPIO16 connected to GND)"));
      return;
    }
  }
  deepSleepStart(dsdelay); // Call deepSleepStart function after these checks
}
As you can see, this should happen only if the last reboot was not waking up from deep sleep.
So it was not "only the first time", but more "if the last boot was not wake-from-deep-sleep"
Meaning you will see it in these conditions:

- If the last boot was something other than "wake from deep sleep" (e.g. a crash or pushing reset)
- if deep sleep is cancelled (GPIO 16 connected to GND)

JohanE
Normal user
Posts: 14
Joined: 28 Mar 2020, 10:17

Re: D1 Mini strange WiFi behaviour

#8 Post by JohanE » 30 Mar 2020, 17:54

OK, that solves that.

Still, it remains that I can't use rules, old or new engine. I had it running for two days without the rules and it sleeps, wakes up, connects, sends data and sleeps again flawlessly.
Now, I went back in and the ONLY thing I changed was to put the check in the box to switch "Rules" on. Didn't even add a rule yet. Now, after wake-up, it doesn't connect to the WiFi anymore, although it seems to work. Exactly like described in the posts above. I'd be grateful if anyone could help me out here, because I really would like to be able to use both rules and deep sleep...

Thanks,
Johan

TD-er
Core team member
Posts: 2768
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: D1 Mini strange WiFi behaviour

#9 Post by TD-er » 30 Mar 2020, 18:37

For that I don't have an answer as I have no idea what may be wrong here when enabling rules.

dampa
Normal user
Posts: 80
Joined: 19 Jul 2018, 01:48

Re: D1 Mini strange WiFi behaviour

#10 Post by dampa » 01 Apr 2020, 13:49

@JohanE - Do you have Config->Sleep mode->Sleep on connection failure checked off?
What are the other settings there?

I have rules sending the WeMos into deepsleep with no problems when waking up.

JohanE
Normal user
Posts: 14
Joined: 28 Mar 2020, 10:17

Re: D1 Mini strange WiFi behaviour

#11 Post by JohanE » 01 Apr 2020, 22:30

dampa wrote:
01 Apr 2020, 13:49
@JohanE - Do you have Config->Sleep mode->Sleep on connection failure checked off?
It was checked on, but checking it off makes no difference. I also tried various various settings of the times there, but always the same result.
I did do some more testing, after flashing the latest Mega firmware (ESP_Easy_mega-20200328_normal_ESP8266_4M1M). Now, using rules or not stopped making a difference, even when flashing the older firmware back. So it seems that the fact that it worked at some point was a freak incident. I wish I kept that version....

Anyway, the original problem that I started this thread with remains:
  • On cold boot everything works fine. WiFi connects first time and keeps working.
  • On wake from deep sleep, WiFi appears to connect, but all messages that are sent fail: reports to domoticz, and also syslog reports to my home server.
  • On reboot, the same happens, but after some time it re-connects to WiFi and then it starts to work
  • On wake from deep sleep, the board will always go back to sleep after 12.x seconds, unless you specify a shorter time
I got a second D1 mini and it behaves exactly the same, so I don't think there is a hardware problem. I tried with three different APs and it's always the same.
What I do notice is that, when WiFi is connected in the correct way, the log shows the message "Info : firstLoopConnectionsEstablished". You can see that in my first post, 1st and 3rd logs. This message doesn't show on wake from deep sleep nor on the first try on reboot. Does that provide some clue about what's going on?

Cheers,
Johan

TD-er
Core team member
Posts: 2768
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: D1 Mini strange WiFi behaviour

#12 Post by TD-er » 01 Apr 2020, 22:41

It looks like the unit does not receive any data for a while after it is connected.
So either the DHCP client does not receive the IP address, or the event to register this "got IP" is never sent or processed.

JohanE
Normal user
Posts: 14
Joined: 28 Mar 2020, 10:17

Re: D1 Mini strange WiFi behaviour

#13 Post by JohanE » 01 Apr 2020, 22:57

Well, the logs show that the IP address is received correctly every time. I also just noticed that the webserver appears to be up - at least, it threw me the login window before going back to sleep. Still ignores the awake time I set to 20 sec. It's just that outgoing messages are not going anywhere.

Johan

dampa
Normal user
Posts: 80
Joined: 19 Jul 2018, 01:48

Re: D1 Mini strange WiFi behaviour

#14 Post by dampa » 03 Apr 2020, 09:39

How about setting the IP address in the router based on the MAC address of the D1 and increasing the wake time?

JohanE
Normal user
Posts: 14
Joined: 28 Mar 2020, 10:17

Re: D1 Mini strange WiFi behaviour

#15 Post by JohanE » 03 Apr 2020, 17:35

dampa wrote:
03 Apr 2020, 09:39
How about setting the IP address in the router based on the MAC address of the D1 and increasing the wake time?
That is the way it's set. IP is received correctly.
Increasing the wake time is ignored by the D1. It ALWAYS sleeps at 12.some seconds...

TD-er
Core team member
Posts: 2768
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: D1 Mini strange WiFi behaviour

#16 Post by TD-er » 03 Apr 2020, 22:45

JohanE wrote:
03 Apr 2020, 17:35
dampa wrote:
03 Apr 2020, 09:39
How about setting the IP address in the router based on the MAC address of the D1 and increasing the wake time?
That is the way it's set. IP is received correctly.
Increasing the wake time is ignored by the D1. It ALWAYS sleeps at 12.some seconds...
That means the event is not processed to finalize the WiFi setup.
I think those events should also have a timeout

planedo79
Normal user
Posts: 21
Joined: 10 Apr 2020, 12:22

Re: D1 Mini strange WiFi behaviour

#17 Post by planedo79 » 18 Apr 2020, 11:12

Hi, I've had similar problems. Admittedly, I have wemos may have had wifi online connected for more than a week without any problems, sometimes during the day one connection problem that required a cold boot. Have you tried switching channels 1, 6 or 11 from the router and is the connection protocol b / n / g? I switched to channel 11 on my router and it is now being tested. The previous setting was automatic and there were connection problems. I need to see if this helps.

JohanE
Normal user
Posts: 14
Joined: 28 Mar 2020, 10:17

Re: D1 Mini strange WiFi behaviour

#18 Post by JohanE » 18 Apr 2020, 15:51

Hi. I tried fixed vs auto channels before and that didn't help.

I have one new development though. I had an old Linksys WRT54G lying around and decided to give that a try. And behold: with this router, everything works perfectly. No changes to the D1 mini, apart from the change in access point. So there is something with the newer routers (NetGear WNDR3700v2, TP-Link WR1043ND, and Ubiquity AirCube AC). Maybe it has to do with "N" wifi?

What still puzzles me is that I have no problems at all with any router when connecting on COLD boot, but only on WARM boot (reboot or wake). Apparently, there is something in ESP Easy as well that is different when connecting on warm boot.

Johan

TD-er
Core team member
Posts: 2768
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: D1 Mini strange WiFi behaviour

#19 Post by TD-er » 18 Apr 2020, 16:02

I happen to have made a test build of the current HEAD of the mega branch (well at least yesterday's state).
Can you test it? https://www.dropbox.com/s/osy03go9mbl4o ... 5.zip?dl=0

Hopefully it has a fix for the 'cold' vs 'warm' boot when connecting to WiFi.

JohanE
Normal user
Posts: 14
Joined: 28 Mar 2020, 10:17

Re: D1 Mini strange WiFi behaviour

#20 Post by JohanE » 18 Apr 2020, 19:46

No joy, I'm afraid. Again, there's no problem on a cold boot, but on warm boot the board goes in an endless loop. Here's a part of the serial log:

Code: Select all

    : Info  : FS   : Mount successful, used 76304 bytes of 957314
499 : Info  : CRC  : program checksum       ...OK
508 : Info  : CRC  : SecuritySettings CRC   ...OK 
621 : Info  : INIT : Free RAM:30592
623 : Info  : INIT : I2C
625 : Info  : INIT : SPI not enabled
701 : Info  : INFO : Plugins: 46 [Normal] (ESP82xx Core 3d128e5c, NONOS SDK 2.2.2-dev(38a443e), LWIP: 2.1.2 PUYA support)
703 : Info  : EVENT: System#NoSleep=5
716 : Info  : EVENT: System#Wake
fpm close 3 
831 : Info  : WIFI : Set WiFi to STAmode : sta(ec:fa:bc:21:5d:ea)
add if0

936 : Info  : WIFI : Connecting airCube-CD3 attempt #0
942 : Info  : Webserver: start
945 : Info  : Time set to 1.000 Time adjusted by 55.00 msec. Wander: 0.02 msec/second
948 : Info  : Current Time Zone: STD time start: 1970-10-25 03:00:00 offset: 60 min
952 : Info  : Local time: 1970-01-01 01:00:01
953 : Info  : EVENT: System#Boot
scandone
state: 0 -> 2 (b0)
1945 : Info  : WIFI : Connecting airCube-CD3 attempt #1state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 4
cnt 


connected with airCube-CD3, channel 9
dhcp client start...
ip:192.168.1.25,mask:255.255.255.0,gw:192.168.1.1
scandone
2172 : Info  : WIFI : Connected! AP: airCube-CD3 (1A:E8:29:3E:2C:D3) Ch: 9 Duration: 29 ms
2174 : Info  : WIFI : DHCP IP: 192.168.1.25 (D1Mini-2) GW: 192.168.1.1 SN: 255.255.255.0   duration: 22 ms
2190 : Info  : WIFI  : WiFiConnected() out of sync
2190 : Info  : WIFI  : WiFiConnected() out of sync
2190 : Info  : WIFI  : WiFiConnectestate: 5 -> 0 (0)
rm 0
Fatal exception 28(LoadProhibitedCause):
epc1=0x4021f17a, epc2=0x00000000, epc3=0x00000000, excvaddr=0x000a55dc, depc=0x00000000

Exception (28):
epc1=0x4021f17a epc2=0x00000000 epc3=0x00000000 excvaddr=0x000a55dc depc=0x00000000

>>>stack>>>

ctx: sys
sp: 3fff01c0 end: 3fffffb0 offset: 01a0
3fff0360:  3ffeec50 3fff2a64 3ffef394 00000001  
3fff0370:  00000000 000a55cc 4026b268 4026a1e5  
3fff0380:  4026b281 00000001 3fff282c 3fff282c  
3fff0390:  3fff00ec 002185d8 3ffef558 402413d0  
3fff03a0:  0000002a 00000000 00000000 00000000  
3fff03b0:  3fff6a44 00000002 3fff1118 402280ee  

[ This goes on for quite a while ... 1838 lines total]

3fff7610:  00000000 00000000 00000000 00000000  
3fff7620:  00000000 00000000 00000000 00000000  
3fff7630:  00000000 00000000 00000000 00000000  
3fff7640:  00000000 00000000
 ets Jan  8 2013,rst cause:4, boot mode:(3,6)

wdt reset
load 0x4010f000, len 1392, room 16 
tail 0
chksum 0xd0
csum 0xd0
v3d128e5c
~ld
U67 : Info  : 

INIT : Booting version:  (ESP82xx Core 3d128e5c, NONOS SDK 2.2.2-dev(38a443e), LWIP: 2.1.2 PUYA support)
68 : Info  : INIT : Free RAM:33296
69 : Info  : INIT : Warm boot #3 Last Task: Background Task Last systime: 1 - Restart Reason: Exception
70 : Info  : FS   : Mounting...
95 : Info  : FS   : Mount successful, used 76304 bytes of 957314
498 : Info  : CRC  : program checksum       ...OK
506 : Info  : CRC  : SecuritySettings CRC   ...OK 
620 : Info  : INIT : Free RAM:30592
622 : Info  : INIT : I2C
623 : Info  : INIT : SPI not enabled
699 : Info  : INFO : Plugins: 46 [Normal] (ESP82xx Core 3d128e5c, NONOS SDK 2.2.2-dev(38a443e), LWIP: 2.1.2 PUYA support)
702 : Info  : EVENT: System#NoSleep=5
715 : Info  : EVENT: System#Wake
fpm close 3 
829 : Info  : WIFI : Set WiFi to STAmode : sta(ec:fa:bc:21:5d:ea)
add if0

934 : Info  : WIFI : Connecting airCube-CD3 attempt #0
940 : Info  : Webserver: start
943 : Info  : Time set to 1.000 Time adjusted by 58.00 msec. Wander: 0.02 msec/second
946 : Info  : Current Time Zone: STD time start: 1970-10-25 03:00:00 offset: 60 min
950 : Info  : Local time: 1970-01-01 01:00:01
952 : Info  : EVENT: System#Boot
scandone
state: 0 -> 2 (b0)
1943 : Info  : WIFI : Connecting airCube-CD3 attempt #1state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 4
cnt 


connected with airCube-CD3, channel 9
dhcp client start...
ip:192.168.1.25,mask:255.255.255.0,gw:192.168.1.1
scandone
2169 : Info  : WIFI : Connected! AP: airCube-CD3 (1A:E8:29:3E:2C:D3) Ch: 9 Duration: 30 ms
2171 : Info  : WIFI : DHCP IP: 192.168.1.25 (D1Mini-2) GW: 192.168.1.1 SN: 255.255.255.0   duration: 22 ms
2187 : Info  : WIFI  : WiFiConnected() out of sync
2187 : Info  : WIFI  : WiFiConnected() out of sync
2187 : Info  : WIFI  : WiFiConnectestate: 5 -> 0 (0)
rm 0
Fatal exception 9(LoadStoreAlignmentCause):
epc1=0x4021f17a, epc2=0x00000000, epc3=0x00000000, excvaddr=0x000a522e, depc=0x00000000

Exception (9):
epc1=0x4021f17a epc2=0x00000000 epc3=0x00000000 excvaddr=0x000a522e depc=0x00000000

>>>stack>>>

ctx: sys
sp: 3fff01c0 end: 3fffffb0 offset: 01a0
3fff0360:  3ffeec50 3fff2a64 3ffef394 00000001  
3fff0370:  00000000 000a521e 4026b268 4026a1e5  
3fff0380:  4026b281 00000001 3fff282c 3fff282c  
3fff0390:  3fff00ec 002179ff 3ffef558 402413d0  
3fff03a0:  0000002a 00000000 00000000 00000000  

[ etc... ]

Here's part of a regular cold boot:

Code: Select all

2625 : Info  : WD   : Uptime 0 ConnectFailures 0 FreeMem 24648 WiFiStatus 6
scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 4
cnt 

connected with airCube-CD3, channel 9
dhcp client start...
ip:192.168.1.25,mask:255.255.255.0,gw:192.168.1.1
4233 : Info  : WIFI : Connected! AP: airCube-CD3 (1A:E8:29:3E:2C:D3) Ch: 9 Duration: 3101 ms
4235 : Info  : WIFI : DHCP IP: 192.168.1.25 (D1Mini-2) GW: 192.168.1.1 SN: 255.255.255.0   duration: 37 ms
4252 : Debug : WiFi : WiFi services initialized
4253 : Info  : firstLoopConnectionsEstablished
4256 : Info  : EVENT: WiFi#ChangedAccesspoint
4265 : Info  : WD   : Uptime 1 ConnectFailures 0 FreeMem 23240 WiFiStatus 3
4280 : Info  : NTP  : NTP replied: delay 10 mSec Accuracy increased by 0.714 seconds
4282 : Info  : Time set to 1587231194.714
4284 : Info  : Current Time Zone: STD time start: 2020-10-25 03:00:00 offset: 60 min
4288 : Info  : Local time: 2020-04-18 18:33:14
4290 : Info  : EVENT: Clock#Time=Sat,18:33
4302 : Info  : EVENT: WiFi#ChangedWiFichannel
4401 : Info  : EVENT: WiFi#Connected
4501 : Info  : EVENT: System#NoSleep=5
4601 : Info  : EVENT: Time#Initialized
9254 : Info  : SLEEP: Entering deep sleep in 30 seconds.
9256 : Info  : EVENT: System#NoSleep=30
Johan

JohanE
Normal user
Posts: 14
Joined: 28 Mar 2020, 10:17

Re: D1 Mini strange WiFi behaviour

#21 Post by JohanE » 18 Apr 2020, 19:55

ABove was using the "normal_4M1M" firmware. I also tried the "Test_beta" of the same, but with the same result.
Johan

JohanE
Normal user
Posts: 14
Joined: 28 Mar 2020, 10:17

Re: D1 Mini strange WiFi behaviour

#22 Post by JohanE » 20 Apr 2020, 08:28

FWIW: like before, there is no problem when using the old WRT54G router:

Code: Select all

15748 : Info  : EVENT: System#Sleep
15763 : Info  : SLEEP: Powering down to deepsleep...
enter deep sleepsll|l|lc|sccnnlggcpl{lrlpglcg|sbogld`gd`gsol{gdld`'bl`rolphU69 : Info  : 

INIT : Booting version:  (ESP82xx Core 9632e868, NONOS SDK 2.2.2-dev(bb83b9b), LWIP: 2.1.2 PUYA support)
70 : Info  : INIT : Free RAM:30200
71 : Info  : INIT : Rebooted from deepsleep #2 Last Task: Background Task Last systime: 1587363954 - Restart Reason: Deep-Sleep Wake
72 : Info  : FS   : Mounting...
98 : Info  : FS   : Mount successful, used 76304 bytes of 957314
580 : Info  : CRC  : program checksum       ...OK
589 : Info  : CRC  : SecuritySettings CRC   ...OK 
702 : Info  : INIT : Free RAM:27448
704 : Info  : INIT : I2C
705 : Info  : INIT : SPI not enabled
991 : Info  : INFO : Plugins: 83 [Normal] [Testing] (ESP82xx Core 9632e868, NONOS SDK 2.2.2-dev(bb83b9b), LWIP: 2.1.2 PUYA support)
993 : Info  : EVENT: System#NoSleep=5
1007 : Info  : EVENT: System#Wake
fpm close 3 
1119 : Info  : WIFI : Set WiFi to STAmode : sta(ec:fa:bc:21:5d:ea)
add if0

1224 : Info  : WIFI : Connecting Tomato24 attempt #0
1229 : Info  : Webserver: start
1243 : Info  : EVENT: System#Boot
1359 : Info  : WIFI : Connecting Tomato24 attempt #1scandone

2918 : Info  : WD   : Uptime 0 ConnectFailures 0 FreeMem 19448 WiFiStatus 6
scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 1
cnt 

connected with Tomato24, channel 7
dhcp client start...
5306 : Info  : WIFI : Connected! AP: Tomato24 (00:0F:66:57:27:C2) Ch: 7 Duration: 3768 ms
ip:192.168.1.25,mask:255.255.255.0,gw:192.168.1.1
7145 : Info  : WIFI : DHCP IP: 192.168.1.25 (D1Mini-2) GW: 192.168.1.1 SN: 255.255.255.0   duration: 1998 ms
7161 : Debug : WiFi : WiFi services initialized
7162 : Info  : firstLoopConnectionsEstablished
7165 : Info  : EVENT: WiFi#Connected
7175 : Info  : WD   : Uptime 1 ConnectFailures 0 FreeMem 18240 WiFiStatus 3
7190 : Info  : NTP  : NTP replied: delay 10 mSec Accuracy increased by 0.212 seconds
7192 : Info  : Time set to 1587363980.212
7195 : 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
7199 : Info  : Local time: 2020-04-20 08:26:20
7201 : Info  : EVENT: Clock#Time=Mon,08:26
7213 : Info  : EVENT: System#NoSleep=5
7240 : Info  : EVENT: Time#Initialized
12163 : Info  : WD   : Uptime 1 ConnectFailures 0 FreeMem 18424 WiFiStatus 3
12167 : Info  : EVENT: System#Sleep
12181 : Info  : SLEEP: Powering down to deepsleep...
enter deep sleep
Johan

JohanE
Normal user
Posts: 14
Joined: 28 Mar 2020, 10:17

Re: D1 Mini strange WiFi behaviour

#23 Post by JohanE » 20 Jun 2020, 10:12

Just found this issue on GitHub: https://github.com/letscontrolit/ESPEasy/issues/3072 that talks about a similar problem. Disabling syslogging appears to resolve my problem.
Johan

Post Reply

Who is online

Users browsing this forum: No registered users and 7 guests