[TW#22514] Beacon timeouts after WiFi PM refactoring

[rojer]

attn: @TianHao-Espressif

after https://github.com/cesanta/esp-idf/commit/9b7454de0c171a7f94dd8f42a5453ef6c75370e0 i started seeing beacon timeouts. i've pinned down the regression to this exact commit, i.e. the commit before it (https://github.com/cesanta/esp-idf/commit/d6b1d0bb3d75e3402acfc8804d4dad0b97743846) works just fine, and after this change wifi connection becomes very unstable, with wifi: bcn_timout,ap_probe_send_start every approx 10 seconds. i've tried all 3 possible power saving settings and only setting PS to none makes wifi work again. fwiw my AP is TP-LINK N600, AP channel is 11 (but it doesn't really matter). let me know if there's any data you'd like me to collect or if you'd like me to try different libraries. for now, i will have to disable powersaving because wifi is just extremely unreliable.

P.S.: yes, i have tried updating IDF to current master (a2556229aa6f55b16b171e3325ee9ab1943e8552 at the time of writing) and the issue is still there.

[TianHao-Yoursmake]

@rojer , please provide me some information, like beacon interval, DTIM value. If possible, please provide a capture files by Wireshark or Omnipeek. Thanks.

@TimXia , please help check this.

[Arthedian]

I have the same issue. I updated ESP-IDF today, sadly even the power save set to none doesnt work in some situation. On my home router it works - TECHNICOLOR TC7200 (from UPC in Czech republic) Here are details: But sadly on different router, it doesnt work (tp-link archer mr200):

The code for connecting to a WIFI: `

if CONFIG_WIFI_ALL_CHANNEL_SCAN

#define DEFAULT_SCAN_METHOD WIFI_ALL_CHANNEL_SCAN
#elif CONFIG_WIFI_FAST_SCAN
#define DEFAULT_SCAN_METHOD WIFI_FAST_SCAN
#else
#define DEFAULT_SCAN_METHOD WIFI_FAST_SCAN
#endif /*CONFIG_SCAN_METHOD*/

#if CONFIG_WIFI_CONNECT_AP_BY_SIGNAL
#define DEFAULT_SORT_METHOD WIFI_CONNECT_AP_BY_SIGNAL
#elif CONFIG_WIFI_CONNECT_AP_BY_SECURITY
#define DEFAULT_SORT_METHOD WIFI_CONNECT_AP_BY_SECURITY
#else
#define DEFAULT_SORT_METHOD WIFI_CONNECT_AP_BY_SIGNAL
#endif /*CONFIG_SORT_METHOD*/

#if CONFIG_FAST_SCAN_THRESHOLD
#define DEFAULT_RSSI -127
#if CONFIG_EXAMPLE_OPEN
#define DEFAULT_AUTHMODE WIFI_AUTH_OPEN
#elif CONFIG_EXAMPLE_WEP
#define DEFAULT_AUTHMODE WIFI_AUTH_WEP
#elif CONFIG_EXAMPLE_WPA
#define DEFAULT_AUTHMODE WIFI_AUTH_WPA_PSK
#elif CONFIG_EXAMPLE_WPA2
#define DEFAULT_AUTHMODE WIFI_AUTH_WPA2_PSK
#else
#define DEFAULT_AUTHMODE WIFI_AUTH_OPEN
#endif
#else
#define DEFAULT_RSSI -127
#define DEFAULT_AUTHMODE WIFI_AUTH_OPEN
#endif /*CONFIG_FAST_SCAN_THRESHOLD*/

uint8_t wifi_connected=0;
uint8_t wifi_attempts=0;
uint8_t wifi_status=0;
MyConfig *configGlobal;

uint8_t wifi_isConnected(){
    return wifi_connected;
}

esp_err_t wifi_eventHandler(void *ctx, system_event_t *event){
    if(event->event_id == SYSTEM_EVENT_STA_START)
    {
        esp_wifi_disconnect();
        ESP_ERROR_CHECK(esp_wifi_connect());
    }
    else if(event->event_id == SYSTEM_EVENT_STA_GOT_IP)
    {
        wifi_status=2;
        wifi_connected=1;
        ESP_LOGI(WIFI_TAG, "Connected to WIFI!\n");
        tcpip_adapter_ip_info_t ip_info;

        ESP_ERROR_CHECK(tcpip_adapter_get_ip_info(TCPIP_ADAPTER_IF_STA, 
            &ip_info));
        ESP_LOGI(WIFI_TAG, "IP Address: %s", ip4addr_ntoa(&ip_info.ip));
        ESP_LOGI(WIFI_TAG, "/%s, ", ip4addr_ntoa(&ip_info.netmask));
        ESP_LOGI(WIFI_TAG, "Gateway:     %s\n", ip4addr_ntoa(&ip_info.gw));
    }
    else if(event->event_id == SYSTEM_EVENT_STA_DISCONNECTED)
    {
        if(wifi_connected){
            configGlobal->wifi_counter++;
            wifi_connected=0;
            wifi_status=1;
            ESP_LOGI(WIFI_TAG, "disconnected from WIFI!\n");
            esp_wifi_connect();
            wifi_attempts=0;
        }
        else if(wifi_attempts==5){
            ESP_LOGI(WIFI_TAG, "Wifi connection was not succesfull\n");
            wifi_status=0;
        }
        else{
            ESP_LOGI(WIFI_TAG, "try number  %d\n", wifi_attempts+1);
            wifi_status=1;
            wifi_attempts++;
            esp_wifi_connect();
        }
    }
    else if (event->event_id == SYSTEM_EVENT_SCAN_DONE) {
        uint16_t apCount = 0;
        esp_wifi_scan_get_ap_num(&apCount);
        printf("Nalezeno Wifin: %d\n",event->event_info.scan_done.number);
        if (apCount == 0) {
            return ESP_OK;
        }
        wifi_ap_record_t *list = (wifi_ap_record_t *)malloc(sizeof(wifi_ap_record_t) * apCount);
        ESP_ERROR_CHECK(esp_wifi_scan_get_ap_records(&apCount, list));
        int i;
        printf("======================================================================\n");
        printf("             SSID             |    RSSI    |           AUTH           \n");
        printf("======================================================================\n");
        for (i=0; i<apCount; i++) {
            char *authmode;
            switch(list[i].authmode) {
                case WIFI_AUTH_OPEN:
                    authmode = "WIFI_AUTH_OPEN";
                    break;
                case WIFI_AUTH_WEP:
                    authmode = "WIFI_AUTH_WEP";
                    break;           
                case WIFI_AUTH_WPA_PSK:
                    authmode = "WIFI_AUTH_WPA_PSK";
                    break;           
                case WIFI_AUTH_WPA2_PSK:
                    authmode = "WIFI_AUTH_WPA2_PSK";
                    break;           
                case WIFI_AUTH_WPA_WPA2_PSK:
                    authmode = "WIFI_AUTH_WPA_WPA2_PSK";
                    break;
                default:
                    authmode = "Unknown";
                    break;
            }
            printf("%26.26s    |    % 4d    |    %22.22s\n",list[i].ssid, list[i].rssi, authmode);
        }
        free(list);
        printf("\n\n");
    }
    return ESP_OK;
}

void wifi_reinit(MyConfig *config){
    wifi_attempts=0;
    wifi_config_t wifiConf = {
        .sta = {
            .ssid = "",
            .password = "",
            .scan_method = DEFAULT_SCAN_METHOD,
            .sort_method = DEFAULT_SORT_METHOD,
            .threshold.rssi = DEFAULT_RSSI,
            .threshold.authmode = DEFAULT_AUTHMODE,
        },
    };
    memcpy(wifiConf.sta.ssid, config->wifi_user, strlen(config->wifi_user)+1);
    memcpy(wifiConf.sta.password, config->wifi_password, strlen(config->wifi_password)+1);
    ESP_ERROR_CHECK(esp_wifi_stop());
    ESP_ERROR_CHECK(esp_wifi_deinit());

    wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();
    ESP_ERROR_CHECK(esp_wifi_init(&cfg));
    ESP_ERROR_CHECK(esp_wifi_set_storage(WIFI_STORAGE_FLASH));
    ESP_ERROR_CHECK(esp_wifi_set_mode(WIFI_MODE_STA));
    ESP_ERROR_CHECK(esp_wifi_set_config(WIFI_IF_STA, &wifiConf));
    ESP_ERROR_CHECK(esp_wifi_start());

    ESP_LOGD(WIFI_TAG, "Restart Wifi done");
}

void wifi_connect_led(void *param){
    while(1){
        if(wifi_status==0){
            led_set(12, 0);
        }
        else if(wifi_status==1){
            blink_led(12, 100);
        }
        else if(wifi_status==2){
            led_set(12, 1);
        }
        vTaskDelay(100 / portTICK_PERIOD_MS);
    }
}

void wifi_initMy(MyConfig *config){
    configGlobal=config;

    //Initialize the TCP Stack
    tcpip_adapter_init();

    //Initialize the system event handler
    ESP_ERROR_CHECK(esp_event_loop_init(wifi_eventHandler, NULL));

    //Config the wifi
    wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();
    ESP_ERROR_CHECK(esp_wifi_init(&cfg));

    //Config RAM as the wifi parameters storage
    ESP_ERROR_CHECK(esp_wifi_set_storage(WIFI_STORAGE_RAM));

    //Wifi as Station Mode (connect to another wifi)
    ESP_ERROR_CHECK(esp_wifi_set_mode(WIFI_MODE_STA));

    wifi_config_t wifiConf = {
        .sta = {
            .ssid = "",
            .password = "",
            .scan_method = DEFAULT_SCAN_METHOD,
            .sort_method = DEFAULT_SORT_METHOD,
            .threshold.rssi = DEFAULT_RSSI,
            .threshold.authmode = DEFAULT_AUTHMODE,
        },
    };
    memcpy(wifiConf.sta.ssid, config->wifi_user, strlen(config->wifi_user)+1);
    memcpy(wifiConf.sta.password, config->wifi_password, strlen(config->wifi_password)+1);

    ESP_ERROR_CHECK(esp_wifi_set_config(WIFI_IF_STA, &wifiConf));

    ESP_ERROR_CHECK(esp_wifi_start());

    ESP_ERROR_CHECK(esp_wifi_set_ps(WIFI_PS_NONE));

    ESP_LOGD(WIFI_TAG, "Wifi is initialized.");
}

`

Is the problem in my code?

[TimXia]

@Arthedian You did not set ssid before calling esp_wifi_connect().

wifi_config_t wifiConf = { .sta = { .ssid = "", .password = "", .scan_method = DEFAULT_SCAN_METHOD, .sort_method = DEFAULT_SORT_METHOD, .threshold.rssi = DEFAULT_RSSI, .threshold.authmode = DEFAULT_AUTHMODE, }, }; memcpy(wifiConf.sta.ssid, config->wifi_user, strlen(config->wifi_user)+1); memcpy(wifiConf.sta.password, config->wifi_password, strlen(config->wifi_password)+1);

ESP_ERROR_CHECK(esp_wifi_set_config(WIFI_IF_STA, &wifiConf));

[Arthedian]

I set it in memcpy from my variable in struct. I am successful with connection to my WiFi, but it disconnect a lot because of beacon timeout

[Arthedian]

@TianHao-Espressif Is there any fix for this problem? Sadly setting power saving mode for me doesnt work for me.

[TimXia]

@Arthedian Did you use BT or BLE?

[Arthedian]

@TimXia No I have BT turned off in config of the project. I found out on Moongoose forum here this:

Any function or task that takes longer than 15ms (milliseconds) may cause the WiFi subsystem to crash.

Is this true for ESP-IDF?

[TimXia]

@Arthedian No, it's not true. In fact, fucntion or task should take no longer than the task watchdog timeout which is set in menuconfig. Could you please provide us the IDF commit ID and sdkconfig file? Then we can try to reproduce the issue.

[Arthedian]

IDF commit 92c469b5993b001a21970f0e58b25acd3f375807 and sdkconfig is here

[TimXia]

@Arthedian Can you provide the log? And does this happen on other router?

[FayeY]

Closing due to lack of response, please feel free to reopen if this is still an issue and you can supply more details. Thanks.

[Arthedian]

Hello, I fixed this problem with two things: 1) I have a lot of threads - I give them smaller priority 2) I put esp32 far from charger. I had 20 cm usb cabel and when I used 2m, it is ok.

[bill1davis]

Here is a log. Ubiquiti Networks router 100ms beacon interval. DTIM was 1, I changed it to 3 and it still happened after about 5 minutes.

I (310) esp_image: segment 7: paddr=0x000957ec vaddr=0x400c0000 size=0x00064 ( 100) load I (310) esp_image: segment 8: paddr=0x00095858 vaddr=0x50000000 size=0x00000 ( 0) load I (328) boot: Loaded app from partition at offset 0x10000 I (328) boot: Disabling RNG early entropy source... I (330) cpu_start: Pro cpu up. I (333) cpu_start: Single core mode I (338) heap_init: Initializing. RAM available for dynamic allocation: I (345) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM I (351) heap_init: At 3FFB8A30 len 000275D0 (157 KiB): DRAM I (357) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM I (363) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (370) heap_init: At 40090A78 len 0000F588 (61 KiB): IRAM I (376) cpu_start: Pro cpu start user code I (394) cpu_start: Starting scheduler on PRO CPU. I (404) pm_esp32: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: XTAL, Light sleep: ENABLED I (414) wifi: wifi driver task: 3ffbf08c, prio:23, stack:3584, core=0 I (414) wifi: wifi firmware version: 4c398ce I (414) wifi: config NVS flash: enabled I (424) wifi: config nano formating: disabled I (424) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (434) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (454) wifi: Init dynamic tx buffer num: 32 I (454) wifi: Init data frame dynamic rx buffer num: 32 I (454) wifi: Init management frame dynamic rx buffer num: 32 I (464) wifi: Init static rx buffer size: 1600 I (464) wifi: Init static rx buffer num: 10 I (474) wifi: Init dynamic rx buffer num: 32 I (694) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 2 I (694) wifi: mode : sta (30:ae:a4:4b:4b:18) I (694) power_save: SYSTEM_EVENT_STA_START I (704) power_save: esp_wifi_set_ps(). I (704) wifi: Set ps type: 1

I (2034) wifi: n:11 0, o:1 0, ap:255 255, sta:11 0, prof:1 I (3994) wifi: state: init -> auth (b0) I (4004) wifi: state: auth -> assoc (0) I (4004) wifi: state: assoc -> run (10) I (4024) wifi: connected with CareTaker, channel 11 I (4104) wifi: pm start, type: 1

I (4114) power_save: Unknown system event 4 I (5024) event: sta ip: 10.1.10.216, mask: 255.255.255.0, gw: 10.1.10.1 I (5024) power_save: SYSTEM_EVENT_STA_GOT_IP I (5024) power_save: got ip:10.1.10.216

I (425394) wifi: bcn_timout,ap_probe_send_start I (427904) wifi: ap_probe_send over, resett wifi status to disassoc I (427904) wifi: state: run -> init (1) I (427904) wifi: pm stop, total sleep time: 397189362 us / 418623708 us

I (427904) wifi: n:11 0, o:11 0, ap:255 255, sta:11 0, prof:1 I (427914) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (430334) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (432754) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (435164) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (437584) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (440004) power_save: SYSTEM_EVENT_STA_DISCONNECTED

[bill1davis]

Here is another log against a comcast enterprise router made by Techicolor CH USA. Model: CGA4131COM. DTIM and beacon interval are not available to view/change on this model. You can see there are two bcn_timout events. The first one recovered and I was able to ping the ESP32 after the first timeout. rst:0x1 (POWERON_RESET),boot:0x3e (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0018,len:4 load:0x3fff001c,len:5740 load:0x40078000,len:7684 load:0x40080400,len:7392 entry 0x4008079c I (28) boot: ESP-IDF v3.2-dev-209-gbe81d2c1 2nd stage bootloader I (28) boot: compile time 12:14:40 I (30) boot: Enabling RNG early entropy source... I (34) boot: SPI Speed : 40MHz I (38) boot: SPI Mode : DIO I (42) boot: SPI Flash Size : 4MB I (46) boot: Partition Table: I (50) boot: ## Label Usage Type ST Offset Length I (57) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (65) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (72) boot: 2 factory factory app 00 00 00010000 00100000 I (80) boot: End of partition table I (84) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x10ca0 ( 68768) map I (117) esp_image: segment 1: paddr=0x00020cc8 vaddr=0x3ffb0000 size=0x02ac8 ( 10952) load I (121) esp_image: segment 2: paddr=0x00023798 vaddr=0x3ffb2ac8 size=0x00000 ( 0) load I (124) esp_image: segment 3: paddr=0x000237a0 vaddr=0x40080000 size=0x00400 ( 1024) load 0x40080000: _iram_start at C:/msys32/home/User/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

I (133) esp_image: segment 4: paddr=0x00023ba8 vaddr=0x40080400 size=0x0c468 ( 50280) load I (162) esp_image: segment 5: paddr=0x00030018 vaddr=0x400d0018 size=0x615c0 (398784) map 0x400d0018: _stext at ??:?

I (302) esp_image: segment 6: paddr=0x000915e0 vaddr=0x4008c868 size=0x04210 ( 16912) load 0x4008c868: xQueueGiveFromISR at C:/msys32/home/User/esp/esp-idf/components/freertos/queue.c:2037

I (310) esp_image: segment 7: paddr=0x000957f8 vaddr=0x400c0000 size=0x00064 ( 100) load I (310) esp_image: segment 8: paddr=0x00095864 vaddr=0x50000000 size=0x00000 ( 0) load I (328) boot: Loaded app from partition at offset 0x10000 I (328) boot: Disabling RNG early entropy source... I (330) cpu_start: Pro cpu up. I (333) cpu_start: Single core mode I (338) heap_init: Initializing. RAM available for dynamic allocation: I (345) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM I (351) heap_init: At 3FFB8A30 len 000275D0 (157 KiB): DRAM I (357) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM I (363) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (370) heap_init: At 40090A78 len 0000F588 (61 KiB): IRAM I (376) cpu_start: Pro cpu start user code I (394) cpu_start: Starting scheduler on PRO CPU. I (404) pm_esp32: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: XTAL, Light sleep: ENABLED I (414) wifi: wifi driver task: 3ffbf08c, prio:23, stack:3584, core=0 I (414) wifi: wifi firmware version: 4c398ce I (414) wifi: config NVS flash: enabled I (424) wifi: config nano formating: disabled I (424) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (434) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (454) wifi: Init dynamic tx buffer num: 32 I (454) wifi: Init data frame dynamic rx buffer num: 32 I (454) wifi: Init management frame dynamic rx buffer num: 32 I (464) wifi: Init static rx buffer size: 1600 I (464) wifi: Init static rx buffer num: 10 I (474) wifi: Init dynamic rx buffer num: 32 I (724) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 2 I (734) wifi: mode : sta (30:ae:a4:4b:4b:18) I (734) power_save: SYSTEM_EVENT_STA_START I (734) power_save: esp_wifi_set_ps(). I (734) wifi: Set ps type: 1

I (974) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1 I (2934) wifi: state: init -> auth (b0) I (2944) wifi: state: auth -> assoc (0) I (2954) wifi: state: assoc -> run (10) I (3084) wifi: connected with BILL_IS_TESTING, channel 1 I (3174) wifi: pm start, type: 1

I (3174) power_save: Unknown system event 4 I (4134) event: sta ip: 10.1.10.216, mask: 255.255.255.0, gw: 10.1.10.1 I (4134) power_save: SYSTEM_EVENT_STA_GOT_IP I (4134) power_save: got ip:10.1.10.216

I (482084) wifi: bcn_timout,ap_probe_send_start I (847914) wifi: bcn_timout,ap_probe_send_start I (850414) wifi: ap_probe_send over, resett wifi status to disassoc I (850414) wifi: state: run -> init (1) I (850414) wifi: pm stop, total sleep time: 742867035 us / 819743206 us

I (850424) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1 I (850424) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (852854) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (855264) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (857684) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (860094) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (862514) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (864934) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (867344) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (869764) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (872184) power_save: SYSTEM_EVENT_STA_DISCONNECTED I (874594) power_save: SYSTEM_EVENT_STA_DISCONNECTED