bcn_timout,ap_probe_send_start

[davdav]

Hi everybody,

I have seen several thread about the in subject (bcn_timout,ap_probe_send_start) of disconnection of ESP32 from router, but most of them are unreplied. In my case it seems the problem arises after some files are written to filesystem (FATFS).

Code: Select all

I (779560) wifi: bcn_timout,ap_probe_send_start
I (782062) wifi: ap_probe_send over, resett wifi status to disassoc
I (782063) wifi: state: run -> init (1)
I (782064) wifi: pm stop, total sleep time: 71840063 us / 97139194 us
I (782068) wifi: n:4 0, o:4 1, ap:255 255, sta:4 1, prof:1

The disconnection reason in callback of WiFi handler

Code: Select all

(system_event_t*) event->event_info.disconnected.reason

is 201. Unfortunately I'm not able to get any trace from WiFi.

Can someone of Espressif's team reply into this?

As I workaround to restart WiFi I have to disconnect and stop Wifi

Code: Select all

esp_wifi_disconnect();
esp_wifi_stop();

and then restart

Code: Select all

esp_wifi_start();
esp_wifi_connect();

Thanks

[davdav]

Hi everybody,

I get back this thread because I have some problems related to "bcn_timout,ap_probe_send_start" of wifi.
From what I have understood is caused by unavailable RAM.

I have added a debug when wifi_event_handler reports a disconnection from router.
I print out the available heap (I used two function but the result is the same for both of them).

Code: Select all

ESP_LOGI("wifi", "free Heap:%d,%d", esp_get_free_heap_size(), heap_caps_get_free_size(MALLOC_CAP_8BIT));

Below is my log

Code: Select all

I (2591815) wifi: bcn_timout,ap_probe_send_start
I (2594319) wifi: ap_probe_send over, resett wifi status to disassoc
I (2594319) wifi: state: run -> init (100)
I (2594320) wifi: pm stop, total sleep time: 1226295175 us / 2548155021 us

I (2594325) wifi: n:7 0, o:7 2, ap:255 255, sta:7 2, prof:1
D (2594331) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, reason:200
I (2594343) wifi: free Heap:9396,9396
I (2594451) wifi: n:7 2, o:7 0, ap:255 255, sta:7 2, prof:1
I (2594452) wifi: state: init -> auth (b0)
I (2594455) wifi: state: auth -> assoc (0)
I (2594461) wifi: state: assoc -> run (10)
I (2594473) wifi: connected with Network-f8d111744bb5, channel 7
I (2594473) wifi: pm start, type: 1

D (2594474) event: SYSTEM_EVENT_STA_CONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, channel:7, authmode:3
20/09/18,10:39:11,WiFi disconnected: Network-f8d111744bb5
D (2598027) event: SYSTEM_EVENT_STA_GOT_IP, ip:10.0.0.13, mask:255.255.255.0, gw:10.0.0.1
I (2598028) event: sta ip: 10.0.0.13, mask: 255.255.255.0, gw: 10.0.0.1
20/09/18,10:39:15,WiFi connected: Network-f8d111744bb5
I (2724681) wifi: bcn_timout,ap_probe_send_start
I (2727184) wifi: ap_probe_send over, resett wifi status to disassoc
I (2727185) wifi: state: run -> init (100)
I (2727186) wifi: pm stop, total sleep time: 60230941 us / 132751135 us

I (2727190) wifi: n:7 0, o:7 2, ap:255 255, sta:7 2, prof:1
D (2727197) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, reason:200
I (2727208) wifi: free Heap:8880,8880
I (2727330) wifi: n:7 2, o:7 0, ap:255 255, sta:7 2, prof:1
I (2727332) wifi: state: init -> auth (b0)
I (2727335) wifi: state: auth -> assoc (0)
I (2727340) wifi: state: assoc -> run (10)
I (2727355) wifi: connected with Network-f8d111744bb5, channel 7
I (2727356) wifi: pm start, type: 1

D (2727356) event: SYSTEM_EVENT_STA_CONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, channel:7, authmode:3
20/09/18,10:41:24,WiFi disconnected: Network-f8d111744bb5
D (2731030) event: SYSTEM_EVENT_STA_GOT_IP, ip:10.0.0.13, mask:255.255.255.0, gw:10.0.0.1
I (2731031) event: sta ip: 10.0.0.13, mask: 255.255.255.0, gw: 10.0.0.1
20/09/18,10:41:28,WiFi connected: Network-f8d111744bb5
I (2738086) wifi: bcn_timout,ap_probe_send_start
I (2740589) wifi: ap_probe_send over, resett wifi status to disassoc
I (2740589) wifi: state: run -> init (100)
I (2740590) wifi: pm stop, total sleep time: 2120249 us / 13235152 us

I (2740594) wifi: n:7 0, o:7 2, ap:255 255, sta:7 2, prof:1
D (2740601) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, reason:200
I (2740612) wifi: free Heap:8880,8880
I (2740721) wifi: n:7 2, o:7 0, ap:255 255, sta:7 2, prof:1
I (2740723) wifi: state: init -> auth (b0)
I (2740726) wifi: state: auth -> assoc (0)
I (2740731) wifi: state: assoc -> run (10)
I (2740743) wifi: connected with Network-f8d111744bb5, channel 7
I (2740744) wifi: pm start, type: 1

D (2740745) event: SYSTEM_EVENT_STA_CONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, channel:7, authmode:3
20/09/18,10:41:37,WiFi disconnected: Network-f8d111744bb5
D (2744534) event: SYSTEM_EVENT_STA_GOT_IP, ip:10.0.0.13, mask:255.255.255.0, gw:10.0.0.1
I (2744535) event: sta ip: 10.0.0.13, mask: 255.255.255.0, gw: 10.0.0.1
20/09/18,10:41:41,WiFi connected: Network-f8d111744bb5
I (3374020) wifi: bcn_timout,ap_probe_send_start
I (3376523) wifi: ap_probe_send over, resett wifi status to disassoc
I (3376524) wifi: state: run -> init (100)
I (3376524) wifi: pm stop, total sleep time: 307966061 us / 636075279 us

I (3376529) wifi: n:7 0, o:7 2, ap:255 255, sta:7 2, prof:1
D (3376536) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, reason:200
I (3376547) wifi: free Heap:4904,4904
I (3376660) wifi: n:7 2, o:7 0, ap:255 255, sta:7 2, prof:1
I (3376662) wifi: state: init -> auth (b0)
I (3376665) wifi: state: auth -> assoc (0)
I (3376672) wifi: state: assoc -> run (10)
I (3376684) wifi: connected with Network-f8d111744bb5, channel 7
I (3376685) wifi: pm start, type: 1

D (3376686) event: SYSTEM_EVENT_STA_CONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, channel:7, authmode:3
20/09/18,10:52:13,WiFi disconnected: Network-f8d111744bb5
D (3380538) event: SYSTEM_EVENT_STA_GOT_IP, ip:10.0.0.13, mask:255.255.255.0, gw:10.0.0.1
I (3380539) event: sta ip: 10.0.0.13, mask: 255.255.255.0, gw: 10.0.0.1
20/09/18,10:52:18,WiFi connected: Network-f8d111744bb5
I (3387011) wifi: bcn_timout,ap_probe_send_start
I (3389514) wifi: ap_probe_send over, resett wifi status to disassoc
I (3389515) wifi: state: run -> init (100)
I (3389516) wifi: pm stop, total sleep time: 1949685 us / 12830407 us

I (3389520) wifi: n:7 0, o:7 2, ap:255 255, sta:7 2, prof:1
D (3389526) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, reason:200
I (3389537) wifi: free Heap:5168,5168
I (3389645) wifi: n:7 2, o:7 0, ap:255 255, sta:7 2, prof:1
I (3389647) wifi: state: init -> auth (b0)
I (3389650) wifi: state: auth -> assoc (0)
I (3389655) wifi: state: assoc -> run (10)
I (3389667) wifi: connected with Network-f8d111744bb5, channel 7
I (3389668) wifi: pm start, type: 1

D (3389669) event: SYSTEM_EVENT_STA_CONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, channel:7, authmode:3

20/09/18,10:52:27,WiFi disconnected: Network-f8d111744bb5
D (3393040) event: SYSTEM_EVENT_STA_GOT_IP, ip:10.0.0.13, mask:255.255.255.0, gw:10.0.0.1
I (3393041) event: sta ip: 10.0.0.13, mask: 255.255.255.0, gw: 10.0.0.1
20/09/18,10:52:30,WiFi connected: Network-f8d111744bb5
I (3399488) wifi: bcn_timout,ap_probe_send_start
I (3401991) wifi: ap_probe_send over, resett wifi status to disassoc
I (3401992) wifi: state: run -> init (100)
I (3401993) wifi: pm stop, total sleep time: 1568556 us / 12328699 us

I (3401997) wifi: n:7 0, o:7 2, ap:255 255, sta:7 2, prof:1
D (3402003) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, reason:200
I (3402015) wifi: free Heap:5100,5100
I (3402138) wifi: n:7 2, o:7 0, ap:255 255, sta:7 2, prof:1
I (3402140) wifi: state: init -> auth (b0)
I (3402143) wifi: state: auth -> assoc (0)
I (3402148) wifi: state: assoc -> run (10)
I (3402166) wifi: connected with Network-f8d111744bb5, channel 7
I (3402167) wifi: pm start, type: 1

D (3402168) event: SYSTEM_EVENT_STA_CONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, channel:7, authmode:3
20/09/18,10:52:39,WiFi disconnected: Network-f8d111744bb5
D (3406043) event: SYSTEM_EVENT_STA_GOT_IP, ip:10.0.0.13, mask:255.255.255.0, gw:10.0.0.1
I (3406043) event: sta ip: 10.0.0.13, mask: 255.255.255.0, gw: 10.0.0.1
20/09/18,10:52:43,WiFi connected: Network-f8d111744bb5
I (3412479) wifi: bcn_timout,ap_probe_send_start
I (3414982) wifi: ap_probe_send over, resett wifi status to disassoc
I (3414983) wifi: state: run -> init (100)
I (3414984) wifi: pm stop, total sleep time: 1824874 us / 12826577 us

I (3414988) wifi: n:7 0, o:7 2, ap:255 255, sta:7 2, prof:1
D (3414994) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, reason:200
I (3415005) wifi: free Heap:5036,5036

I (3415115) wifi: n:7 2, o:7 0, ap:255 255, sta:7 2, prof:1
I (3415117) wifi: state: init -> auth (b0)
20/09/18,10:52:52,WiFi disconnected: Network-f8d111744bb5
I (3415371) wifi: state: auth -> assoc (0)
I (3415377) wifi: state: assoc -> run (10)
I (3422400) wifi: bcn_timout,ap_probe_send_start
I (3424891) wifi: ap_probe_send over, resett wifi status to disassoc
I (3424891) wifi: state: run -> init (100)
I (3424892) wifi: n:7 0, o:7 2, ap:255 255, sta:7 2, prof:1
D (3424897) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, reason:200
I (3424907) wifi: free Heap:5016,5016
D (3427312) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:00:00:00:00:00:00, reason:201
I (3427313) wifi: free Heap:5064,5064
I (3427437) wifi: n:7 2, o:7 0, ap:255 255, sta:7 2, prof:1
I (3427439) wifi: state: init -> auth (b0)
I (3427442) wifi: state: auth -> assoc (0)
I (3427447) wifi: state: assoc -> run (10)
I (3427459) wifi: connected with Network-f8d111744bb5, channel 7
I (3427460) wifi: pm start, type: 1

D (3427460) event: SYSTEM_EVENT_STA_CONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, channel:7, authmode:3
D (3431044) event: SYSTEM_EVENT_STA_GOT_IP, ip:10.0.0.13, mask:255.255.255.0, gw:10.0.0.1
I (3431045) event: sta ip: 10.0.0.13, mask: 255.255.255.0, gw: 10.0.0.1
20/09/18,10:53:08,WiFi connected: Network-f8d111744bb5
I (3437627) wifi: bcn_timout,ap_probe_send_start
I (3440130) wifi: ap_probe_send over, resett wifi status to disassoc
I (3440130) wifi: state: run -> init (100)
I (3440131) wifi: pm stop, total sleep time: 1743335 us / 12678126 us

I (3440135) wifi: n:7 0, o:7 2, ap:255 255, sta:7 2, prof:1
D (3440142) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, reason:200
I (3440153) wifi: free Heap:4628,4628
I (3440276) wifi: n:7 2, o:7 0, ap:255 255, sta:7 2, prof:1
I (3440278) wifi: state: init -> auth (b0)
I (3440281) wifi: state: auth -> assoc (0)
I (3440286) wifi: state: assoc -> run (10)
I (3440298) wifi: connected with Network-f8d111744bb5, channel 7
I (3440299) wifi: pm start, type: 1

D (3440300) event: SYSTEM_EVENT_STA_CONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, channel:7, authmode:3
20/09/18,10:53:17,WiFi disconnected: Network-f8d111744bb5
I (3449274) wifi: bcn_timout,ap_probe_send_start
I (3451777) wifi: ap_probe_send over, resett wifi status to disassoc
I (3451778) wifi: state: run -> init (100)
I (3451778) wifi: pm stop, total sleep time: 1354519 us / 11479296 us

I (3451783) wifi: n:7 0, o:7 2, ap:255 255, sta:7 2, prof:1
D (3451789) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, reason:200
I (3451800) wifi: free Heap:4656,4656
I (3451924) wifi: n:7 2, o:7 0, ap:255 255, sta:7 2, prof:1
I (3451926) wifi: state: init -> auth (b0)
I (3451928) wifi: state: auth -> assoc (0)
I (3451934) wifi: state: assoc -> run (10)
I (3451946) wifi: connected with Network-f8d111744bb5, channel 7
I (3451946) wifi: pm start, type: 1

D (3451947) event: SYSTEM_EVENT_STA_CONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, channel:7, authmode:3
D (3455550) event: SYSTEM_EVENT_STA_GOT_IP, ip:10.0.0.13, mask:255.255.255.0, gw:10.0.0.1
I (3455551) event: sta ip: 10.0.0.13, mask: 255.255.255.0, gw: 10.0.0.1
20/09/18,10:53:33,WiFi connected: Network-f8d111744bb5
W (3513598) wifi: alloc eb len=24 type=3 fail, heap:576

W (3513598) wifi: m f null

I (3522978) wifi: bcn_timout,ap_probe_send_start
I (3525481) wifi: ap_probe_send over, resett wifi status to disassoc
I (3525481) wifi: state: run -> init (100)
I (3525482) wifi: pm stop, total sleep time: 28236878 us / 73560144 us

I (3525486) wifi: n:7 0, o:7 2, ap:255 255, sta:7 2, prof:1
D (3525493) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:f8:d1:11:74:4b:b5, reason:200
I (3525503) wifi: free Heap:2888,2888
20/09/18,10:54:43,WiFi disconnected: Network-f8d111744bb5
D (3527907) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:00:00:00:00:00:00, reason:201
I (3527909) wifi: free Heap:2888,2888
D (3530325) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:00:00:00:00:00:00, reason:201
I (3530326) wifi: free Heap:2888,2888
D (3532743) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:00:00:00:00:00:00, reason:201
I (3532744) wifi: free Heap:2888,2888
D (3535160) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:00:00:00:00:00:00, reason:201
I (3535161) wifi: free Heap:2888,2888
D (3537578) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Network-f8d111744bb5, ssid_len:20, bssid:00:00:00:00:00:00, reason:201
I (3537579) wifi: free Heap:2888,2888
D (3537623) event: SYSTEM_EVENT_STA_STOP
I (3537624) wifi: flush txq
I (3537624) wifi: stop sw txq
I (3537625) wifi: lmac stop hw txq
abort() was called at PC 0x4015253d on core 0

Backtrace: 0x40095fac:0x3ffe9330 0x4009614f:0x3ffe9350 0x4015253d:0x3ffe9370 0x4015d8de:0x3ffe93a0 0x4015d97a:0x3ffe93d0 0x4015dc6a:0x3ffe9400 0x4015dde2:0x3ffe9430 0x4008d178:0x3ffe9450

Entering gdb stub now.
$T0b#e6

And the GDB backtrace is:

Code: Select all

xtensa-esp32-elf-gdb ./build/Avior_ESP32_WiFi_v2.elf -b 115200 -ex 'target remote COM6'
GNU gdb (crosstool-NG crosstool-ng-1.22.0-80-g6c4433a5) 7.10
Copyright (C) 2015 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "--host=i686-host_pc-mingw32 --target=xtensa-esp32-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./build/Avior_ESP32_WiFi_v2.elf...done.
Remote debugging using COM6
0x40095fac in invoke_abort ()
    at C:/msys32/home/Davide/esp/esp-idf/components/esp32/panic.c:140
140             *((int *) 0) = 0;
(gdb) list
135     #endif
136         while (1) {
137             if (esp_cpu_in_ocd_debug_mode()) {
138                 __asm__ ("break 0,0");
139             }
140             *((int *) 0) = 0;
141         }
142     }
143
144     void abort()
(gdb) bt
#0  0x40095fac in invoke_abort ()
    at C:/msys32/home/Davide/esp/esp-idf/components/esp32/panic.c:140
#1  0x40096152 in abort ()
    at C:/msys32/home/Davide/esp/esp-idf/components/esp32/panic.c:149
#2  0x40152540 in esp_phy_load_cal_and_init (module=PHY_WIFI_MODULE)
    at C:/msys32/home/Davide/esp/esp-idf/components/esp32/phy_init.c:540
#3  0x4015d8e1 in wifi_rf_phy_enable ()
#4  0x4015d97d in wifi_hw_start ()
#5  0x4015dc6d in wifi_start_process ()
#6  0x4015dde5 in ieee80211_ioctl_process ()
#7  0x4008d17b in ppTask ()
(gdb)

Why the free heap is getting lower and lower and device got stuck? I'm using esp-idf v3.1

Code: Select all

git rev-parse HEAD
22da5f6de9ff3657fa7613fc06ad2eca1d1fe14a

Thanks

[felipeduque]

Hi, davda, any news on this? I'm facing the same bcn_timout issue here.

[felipeduque]

I just found out in this thread that it may be caused by too many consecutive flash writes. After following ESP_Sprite's suggestion in his reply to that thread, my issue was solved!

[davdav]

I just found out in this thread that it may be caused by too many consecutive flash writes. After following ESP_Sprite's suggestion in his reply to that thread, my issue was solved!

Thanks @felipeduque. Good to know.

[monkey]

I've been seeing this problem too. I have some comments to make. And a possible SOLUTION.
1) What does this error message tell us, as in what is the actual failure? I.e. missed n consecutive beacons or something. Can't find a definitive definition in docs and can't find the actual source code (Seriously where on earth is the source code - is it in a precompiled unit?)

2) It seems that the wifi recovery doesn't work after this error. When I catch the SYSTEM_EVENT_STA_DISCONNECTED event:

Code: Select all

case SYSTEM_EVENT_STA_DISCONNECTED:
        res = wifi_reconnect();                   
        ESP_LOGW(TAG, "wifi_reconnect() Returned status: %s.", wifiErrorCodes[(res & 0x00ff)]);
        break;

wifi_reconnect() calls esp_wifi_connect(). It returns no error, but the code bounces right back into SYSTEM_EVENT_STA_DISCONNECTED a second later...

3) I noticed that I was also seeing this exact same error during OTA update. I checked memory and watchdog - but neither seemed to be the cause. Then I noticed 2 things that did make a difference.
(i) increasing the buffer size during OTA made the problem worse - which ties up with other suggestions that the task is running too long and starving other tasks (but it's not he WDT that causes the failure - i.e. the task doesn't timeout - it just doesn't take care of it's business).
(ii) Changing the MODEM Power Setting seems to resolve the OTA issue for me. After changing to PS_MODEM_NONE - I saw a massive reduction in the failure rate of OTA.