espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.33k stars 7.2k forks source link

[TW#13146] Wifi disconnects when using Bluetooth (IDFGH-829) #675

Closed Resultfactory closed 5 years ago

Resultfactory commented 7 years ago

We have noticed frequent Wifi disconnects when using Bluetooth. The scan_interval and scan_window severely impacts the Wifi stability.

We are able to reproduce this problem on several devices (DOIT from aliexpress, Pycom LoPy and SiPy). If we reduce the values of scan_interval and scan_window to 0x10 the problem will occur within the first few minutes. This is part of the log when running with these settings:

I (56414) Wifi+BLE Crash: Scan result event: 3 
D (56414) tcpip_adapter: check: local, if=0 fn=0x4010e024 
D (56424) tcpip_adapter: call api in lwip: ret=0x0, give sem 
D (56424) tcpip_adapter: check: remote, if=0 fn=0x4010e024 
E (56434) Wifi+BLE Crash: Wifi Disconnected! 
I (56744) Wifi+BLE Crash: Scan result event: 3 
I (56954) Wifi+BLE Crash: Scan result event: 3 
I (56954) Wifi+BLE Crash: Scan result event: 3 
I (56954) Wifi+BLE Crash: Scan result event: 3 
E (56964) BT: btc_search_callback  BLE observe complete. Num Resp 5 
I (56964) Wifi+BLE Crash: Scan result event: 3 
I (56964) Wifi+BLE Crash: Scan started event: 7 
I (57274) Wifi+BLE Crash: Scan result event: 3 
I (57274) Wifi+BLE Crash: Scan result event: 3 
I (57274) Wifi+BLE Crash: Scan result event: 3 
I (57274) Wifi+BLE Crash: Scan result event: 3 
I (57484) Wifi+BLE Crash: Scan result event: 3 
I (57484) Wifi+BLE Crash: Scan result event: 3 
I (57484) Wifi+BLE Crash: Scan result event: 3 
I (57854) Wifi+BLE Crash: Scan result event: 3 
I (57904) Wifi+BLE Crash: Scan result event: 3 
I (57904) Wifi+BLE Crash: Scan result event: 3 
D (58124) tcpip_adapter: check: local, if=0 fn=0x4010e024 
D (58124) tcpip_adapter: call api in lwip: ret=0x0, give sem 
D (58124) tcpip_adapter: check: remote, if=0 fn=0x4010e024 
E (58124) Wifi+BLE Crash: Wifi Disconnected! 

When setting the values to 0x50, 0x30 respectively, this issue will occur less frequent (within hours).

We improved stability by setting the values to 0x100 and 0x30. But this is not what we want, we would like to reduce the scan_interval back to 0x50.

We need the BLE scanner to listen infinitely and Wifi should be connected 24/7.  

This sample illustrates the behavior described here. We would like to know what causes the disconnects and please advise us how to prevent disconnects while scanning.

#include <stdio.h> 
#include <string.h> 

#include "freertos/FreeRTOS.h" 
#include "freertos/task.h" 
#include "freertos/event_groups.h" 

#include "esp_wifi.h" 
#include "esp_event_loop.h" 
#include "esp_log.h" 

#include "esp_gap_ble_api.h" 
#include "esp_bt_main.h" 
#include "bt.h" 

#define TAG "Wifi+BLE Crash" 

#define WIFI_SSID "????" 
#define WIFI_PASS "???" 

#define CRASHINTERVAL 0x10 //Disconnects occur in the first few minutes 
#define CRASHWINDOW 0x10   //Disconnects occur in the first few minutes 

// #define LESSCRASHINTERVAL 0x50 //Disconnects still occur 
// #define LESSCRASHWINDOW 0x30 //Disconnects still occur 
// #define ALMOSTNOCRASHINTERVAL 0x100 //Almost no disconnects occur 
// #define ALMOSTNOCRASHWINDOW 0x30 //Almost no disconnects occur 

static EventGroupHandle_t wifi_event_group;

const int CONNECTED_BIT = BIT0;

void esp_gap_cb(esp_gap_ble_cb_event_t event, esp_ble_gap_cb_param_t *param)
{
    switch (event)
    {
        case ESP_GAP_BLE_SCAN_PARAM_SET_COMPLETE_EVT:  ESP_LOGI(TAG, "Scan param set completed event: %d", event);
            break;

        case ESP_GAP_BLE_SCAN_START_COMPLETE_EVT:  ESP_LOGI(TAG, "Scan started event: %d", event);
            break;

        case ESP_GAP_BLE_SCAN_STOP_COMPLETE_EVT: /*!< When stop scan complete, the event comes */  ESP_LOGI(TAG, "Scan stopped event: %d", event);
            break;

        case ESP_GAP_BLE_SCAN_RESULT_EVT: // Called when one scan result is ready 
            ESP_LOGI(TAG, "Scan result event: %d", event);
            break;

        default:  ESP_LOGE(TAG, "Unhandled bt event: %d", event);
            break;
    }
}

static esp_err_t event_handler(void *ctx, system_event_t *event)
{
    switch (event->event_id)
    {
        case SYSTEM_EVENT_STA_START:  esp_wifi_connect();
            break;

        case SYSTEM_EVENT_STA_GOT_IP:  xEventGroupSetBits(wifi_event_group, CONNECTED_BIT);
            break;

        case SYSTEM_EVENT_STA_DISCONNECTED:
            /* This is a workaround as ESP32 WiFi libs don't currently 
                       auto-reassociate. */  esp_wifi_connect();
            xEventGroupClearBits(wifi_event_group, CONNECTED_BIT);
            ESP_LOGE(TAG, "Wifi Disconnected!");
            break;

        default:  
            break;
    }
    return ESP_OK;
}

static void initialise_wifi(void)
{
    tcpip_adapter_init();
    wifi_event_group = xEventGroupCreate();
    ESP_ERROR_CHECK(esp_event_loop_init(event_handler, NULL));
    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_RAM));

    wifi_config_t wifi_config;

    // wifi_config_t wifi_config; 
    memset(&wifi_config, 0, sizeof(wifi_config));
    strcpy((char *)wifi_config.sta.ssid, WIFI_SSID);
    strcpy((char *)wifi_config.sta.password, WIFI_PASS);

    ESP_LOGI(TAG, "Setting WiFi configuration SSID %s...", wifi_config.sta.ssid);
    ESP_ERROR_CHECK(esp_wifi_set_mode(WIFI_MODE_STA));
    ESP_ERROR_CHECK(esp_wifi_set_config(ESP_IF_WIFI_STA, &wifi_config));
    ESP_ERROR_CHECK(esp_wifi_start());
}

esp_ble_scan_params_t scanparams = {
    .scan_type = BLE_SCAN_TYPE_ACTIVE,
    .own_addr_type = BLE_ADDR_TYPE_PUBLIC,
    .scan_filter_policy = BLE_SCAN_FILTER_ALLOW_ALL,
    .scan_interval = CRASHINTERVAL,
    .scan_window = CRASHWINDOW 
};

static void initialise_bt(void)
{
    esp_err_t status;

    ESP_LOGI(TAG, "initBluetooth");

    esp_bt_controller_config_t bt_cfg = BT_CONTROLLER_INIT_CONFIG_DEFAULT();
    ESP_LOGD(TAG, "esp_bt_controller_enable: %d", esp_bt_controller_init(&bt_cfg));
    ESP_LOGD(TAG, "esp_bt_controller_enable: %d", esp_bt_controller_enable(ESP_BT_MODE_BTDM));
    ESP_LOGD(TAG, "esp_bluedroid_init: %d", esp_bluedroid_init());
    ESP_LOGD(TAG, "esp_bluedroid_enable: %d", esp_bluedroid_enable());

    // Register callback 
    if ((status = esp_ble_gap_register_callback(esp_gap_cb)) != ESP_OK)
    {
        ESP_LOGE(TAG, "Failed to register callback (status: %x)", status);
        return;
    }
    ESP_ERROR_CHECK(esp_ble_gap_set_scan_params(&scanparams));
}

extern "C" void app_main()
{
    initialise_wifi();
    initialise_bt();
    while (1)
    {
        esp_ble_gap_start_scanning(2);
        vTaskDelay(2000 / portTICK_PERIOD_MS);
    }
}
Resultfactory commented 7 years ago

We ran the test again, now the same problem occurs after 10~ minutes, instead of the first two minutes. Also the amount of found advertisements drops from a average 6~ to 0 Any help would be appreciated.

I (548336) Wifi+BLE Crash: Last scan found 1 advertisements, Scan started event: 7
E (550336) BT: BTM_BleObserve Observe Already Active
E (550336) BT:  bta_dm_ble_observe start observe failed. status=0x6
I (550336) Wifi+BLE Crash: Last scan found 11 advertisements, Scan started event: 7
E (550346) BT: btc_search_callback  BLE observe complete. Num Resp 111
I (552346) Wifi+BLE Crash: Last scan found 1 advertisements, Scan started event: 7
E (554346) BT: BTM_BleObserve Observe Already Active
E (554346) BT:  bta_dm_ble_observe start observe failed. status=0x6
I (554346) Wifi+BLE Crash: Last scan found 5 advertisements, Scan started event: 7
E (554356) BT: btc_search_callback  BLE observe complete. Num Resp 112
I (556356) Wifi+BLE Crash: Last scan found 1 advertisements, Scan started event: 7
I (558296) wifi: bcn_timout,ap_probe_send_start
E (558356) BT: BTM_BleObserve Observe Already Active
E (558356) BT:  bta_dm_ble_observe start observe failed. status=0x6
I (558356) Wifi+BLE Crash: Last scan found 0 advertisements, Scan started event: 7
E (558366) BT: btc_search_callback  BLE observe complete. Num Resp 112
I (560366) Wifi+BLE Crash: Last scan found 1 advertisements, Scan started event: 7
I (560796) wifi: ap_probe_send over, resett wifi status to disassoc
I (560796) wifi: state: run -> init (1)
I (560796) wifi: n:4 0, o:4 0, ap:255 255, sta:4 0, prof:1
I (560806) wifi: pm stop, total sleep time: 0/545926861
0x40132464: tcpip_adapter_down_api at /BEASTv3/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:801
D (560806) tcpip_adapter: check: local, if=0 fn=0x40132464
D (560816) tcpip_adapter: call api in lwip: ret=0x0, give sem
0x40132464: tcpip_adapter_down_api at /BEASTv3/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:801
D (560816) tcpip_adapter: check: remote, if=0 fn=0x40132464
E (560826) Wifi+BLE Crash: Wifi Disconnected!
E (562366) BT: BTM_BleObserve Observe Already Active
E (562366) BT:  bta_dm_ble_observe start observe failed. status=0x6
I (562366) Wifi+BLE Crash: Last scan found 0 advertisements, Scan started event: 7
E (562376) BT: btc_search_callback  BLE observe complete. Num Resp 112
0x40132464: tcpip_adapter_down_api at /BEASTv3/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:801
D (562506) tcpip_adapter: check: local, if=0 fn=0x40132464
D (562516) tcpip_adapter: call api in lwip: ret=0x0, give sem
0x40132464: tcpip_adapter_down_api at /BEASTv3/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:801
D (562516) tcpip_adapter: check: remote, if=0 fn=0x40132464
E (562516) Wifi+BLE Crash: Wifi Disconnected!
0x40132464: tcpip_adapter_down_api at /BEASTv3/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:801
D (564206) tcpip_adapter: check: local, if=0 fn=0x40132464
D (564206) tcpip_adapter: call api in lwip: ret=0x0, give sem
0x40132464: tcpip_adapter_down_api at /BEASTv3/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:801
D (564206) tcpip_adapter: check: remote, if=0 fn=0x40132464
E (564216) Wifi+BLE Crash: Wifi Disconnected!
I (564376) Wifi+BLE Crash: Last scan found 1 advertisements, Scan started event: 7
0x40132464: tcpip_adapter_down_api at /BEASTv3/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:801
D (565896) tcpip_adapter: check: local, if=0 fn=0x40132464
D (565896) tcpip_adapter: call api in lwip: ret=0x0, give sem
0x40132464: tcpip_adapter_down_api at /BEASTv3/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:801
D (565896) tcpip_adapter: check: remote, if=0 fn=0x40132464
E (565906) Wifi+BLE Crash: Wifi Disconnected!
E (566376) BT: BTM_BleObserve Observe Already Active
E (566376) BT:  bta_dm_ble_observe start observe failed. status=0x6
I (566376) Wifi+BLE Crash: Last scan found 0 advertisements, Scan started event: 7
E (566386) BT: btc_search_callback  BLE observe complete. Num Resp 112
0x40132464: tcpip_adapter_down_api at /BEASTv3/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:801
D (567596) tcpip_adapter: check: local, if=0 fn=0x40132464
D (567596) tcpip_adapter: call api in lwip: ret=0x0, give sem
0x40132464: tcpip_adapter_down_api at /BEASTv3/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:801
D (567596) tcpip_adapter: check: remote, if=0 fn=0x40132464
E (567596) Wifi+BLE Crash: Wifi Disconnected!
I (568386) Wifi+BLE Crash: Last scan found 1 advertisements, Scan started event: 7
0x40132464: tcpip_adapter_down_api at /BEASTv3/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:801
D (569286) tcpip_adapter: check: local, if=0 fn=0x40132464

Full log Modified example

Resultfactory commented 7 years ago

We ran the test again with CONFIG_SW_COEXIST_ENABLE=y The results were very different from when we ran this test before with SW_COEXIST_ENABLE. We expected this to crash too. It has not crashed in 2 hours. This sdkconfig was used, in the test above the same SDKCONFIG was used except SW_COEXIST was disabled.

lixianyu commented 7 years ago

BLE scanner and Wifi work together for 12 hours, it is work fine....

Resultfactory commented 7 years ago

@lixianyu There is a difference.

This is with CONFIG_SW_COEXIST_ENABLE=y

D (240742510) Wifi+BLE Crash: time 1499078352 I (240742510) Wifi+BLE Crash: Last scan found 1 advertisements, Scan started event: 7 E (240744510) BT: btc_search_callback BLE observe complete. Num Resp 0

D (240744510) Wifi+BLE Crash: time 1499078354 I (240744510) Wifi+BLE Crash: Last scan found 1 advertisements, Scan started event: 7 E (240746510) BT: btc_search_callback BLE observe complete. Num Resp 0

not many advertisements are found, very long uptime though. See last few 100 bytes of log

This is with CONFIG_SW_COEXIST_ENABLE disabled

D (2790109) Wifi+BLE Crash: time 1499095001 I (2792119) Wifi+BLE Crash: Last scan found 1 advertisements, Scan started event: 7 D (2792119) Wifi+BLE Crash: time 1499095003 E (2794119) BT: BTM_BleObserve Observe Already Active E (2794119) BT: bta_dm_ble_observe start observe failed. status=0x6

I (2794119) Wifi+BLE Crash: Last scan found 12 advertisements, Scan started event: 7 E (2794129) BT: btc_search_callback BLE observe complete. Num Resp 84

Wifi also goes into a disconnect loop after some time see full (Log) and (Source)

kzyapkov commented 7 years ago

+1, identical behavior and symptoms

Alvin1Zhang commented 5 years ago

@Resultfactory Hi, sorry that get back to you soooooo late...... Has your issue been resolved already? Would you help share if any updates for the issue? Thanks.

Resultfactory commented 5 years ago

We don't have any coexistence issues anymore

Alvin1Zhang commented 5 years ago

Thanks.