espressif / esp-idf

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

crash after wifi_prov_mgr: Provisioning stopped when using the stock ble_prov example from IDF (IDFGH-11003) #12189

Open 0x0fe opened 10 months ago

0x0fe commented 10 months ago

Answers checklist.

IDF version.

5.0.2

Operating System used.

Windows

How did you build your project?

VS Code IDE

If you are using Windows, please specify command line type.

None

Development Kit.

ESP32D0WDR2

Power Supply used.

USB

What is the expected behavior?

No crash after wifi_prov_mgr: Provisioning stopped

What is the actual behavior?

Crashes after wifi_prov_mgr: Provisioning stopped

Steps to reproduce.

This is the stock BLE prov example from IDF, in an empty project. The only notable point is that i am in ADF (2.6) with IDF 5.0.2. But in this test the A2DP is not even started. Basically all it does is to start the PROV in BLE mode, and then connect the wifi. As soon as the prov_manager stops, it crashes. This is consistent and can be reproduced each time. Other than this the provisioning works fine, the pairing works normally, the wifi scan too, i can enter the password and it is received. The wifi also connects correctly.

the SDKconfig has nothing fancy, A2DP is enabled because we use it for the production firmware (not here). I tired to increase the max connection to 5, no difference (the connection ID is 3, so i assume it doesnt need more than 3 anyway).

image

the code ```cpp static void wifi_init_sta(void) { /* Start Wi-Fi in station mode */ ESP_ERROR_CHECK(esp_wifi_set_mode(WIFI_MODE_STA)); ESP_ERROR_CHECK(esp_wifi_start()); } static void event_handler(void* arg, esp_event_base_t event_base,int32_t event_id, void* event_data) { #ifdef CONFIG_EXAMPLE_RESET_PROV_MGR_ON_FAILURE static int retries; #endif if (event_base == WIFI_PROV_EVENT) { switch (event_id) { case WIFI_PROV_START: ESP_LOGI(TAG, "Provisioning started"); break; case WIFI_PROV_CRED_RECV: { wifi_sta_config_t *wifi_sta_cfg = (wifi_sta_config_t *)event_data; ESP_LOGI(TAG, "Received Wi-Fi credentials" "\n\tSSID : %s\n\tPassword : %s", (const char *) wifi_sta_cfg->ssid, (const char *) wifi_sta_cfg->password); break; } case WIFI_PROV_CRED_FAIL: { wifi_prov_sta_fail_reason_t *reason = (wifi_prov_sta_fail_reason_t *)event_data; ESP_LOGE(TAG, "Provisioning failed!\n\tReason : %s" "\n\tPlease reset to factory and retry provisioning", (*reason == WIFI_PROV_STA_AUTH_ERROR) ? "Wi-Fi station authentication failed" : "Wi-Fi access-point not found"); #ifdef CONFIG_EXAMPLE_RESET_PROV_MGR_ON_FAILURE retries++; if (retries >= CONFIG_EXAMPLE_PROV_MGR_MAX_RETRY_CNT) { ESP_LOGI(TAG, "Failed to connect with provisioned AP, reseting provisioned credentials"); wifi_prov_mgr_reset_sm_state_on_failure(); retries = 0; } #endif break; } case WIFI_PROV_CRED_SUCCESS: ESP_LOGI(TAG, "Provisioning successful"); #ifdef CONFIG_EXAMPLE_RESET_PROV_MGR_ON_FAILURE retries = 0; #endif break; case WIFI_PROV_END: /* De-initialize manager once provisioning is finished */ wifi_prov_mgr_deinit(); break; default: break; } } else if (event_base == WIFI_EVENT && event_id == WIFI_EVENT_STA_START) { esp_wifi_connect(); } else if (event_base == IP_EVENT && event_id == IP_EVENT_STA_GOT_IP) { ip_event_got_ip_t* event = (ip_event_got_ip_t*) event_data; ESP_LOGI(TAG, "Connected with IP Address:" IPSTR, IP2STR(&event->ip_info.ip)); //mqtt_app_start(); /* Signal main application to continue execution */ xEventGroupSetBits(wifi_event_group, WIFI_CONNECTED_EVENT); } else if (event_base == WIFI_EVENT && event_id == WIFI_EVENT_STA_DISCONNECTED) { ESP_LOGI(TAG, "Disconnected. Connecting to the AP again..."); esp_wifi_connect(); } } static void get_device_service_name(char *service_name, size_t max) { uint8_t eth_mac[6]; const char *ssid_prefix = "PROV_"; esp_wifi_get_mac(WIFI_IF_STA, eth_mac); snprintf(service_name, max, "%s%02X%02X%02X", ssid_prefix, eth_mac[3], eth_mac[4], eth_mac[5]); } esp_err_t custom_prov_data_handler(uint32_t session_id, const uint8_t *inbuf, ssize_t inlen,uint8_t **outbuf, ssize_t *outlen, void *priv_data) { if (inbuf) { ESP_LOGI(TAG, "Received data: %.*s", inlen, (char *)inbuf); } char response[] = "SUCCESS"; *outbuf = (uint8_t *)strdup(response); if (*outbuf == NULL) { ESP_LOGE(TAG, "System out of memory"); return ESP_ERR_NO_MEM; } *outlen = strlen(response) + 1; /* +1 for NULL terminating byte */ return ESP_OK; } void init_wifi_prov(void){ ESP_ERROR_CHECK(esp_netif_init()); ESP_ERROR_CHECK(esp_event_loop_create_default()); wifi_event_group = xEventGroupCreate(); ESP_ERROR_CHECK(esp_event_handler_register(WIFI_PROV_EVENT, ESP_EVENT_ANY_ID, &event_handler, NULL)); ESP_ERROR_CHECK(esp_event_handler_register(WIFI_EVENT, ESP_EVENT_ANY_ID, &event_handler, NULL)); ESP_ERROR_CHECK(esp_event_handler_register(IP_EVENT, IP_EVENT_STA_GOT_IP, &event_handler, NULL)); esp_netif_create_default_wifi_sta(); wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT(); ESP_ERROR_CHECK(esp_wifi_init(&cfg)); wifi_prov_mgr_config_t config = { .scheme = wifi_prov_scheme_ble, .scheme_event_handler = WIFI_PROV_SCHEME_BLE_EVENT_HANDLER_FREE_BTDM }; ESP_ERROR_CHECK(wifi_prov_mgr_init(config)); bool provisioned = false; wifi_prov_mgr_reset_provisioning(); ESP_ERROR_CHECK(wifi_prov_mgr_is_provisioned(&provisioned)); if (!provisioned) { ESP_LOGI(TAG, "Starting provisioning"); char service_name[12]; get_device_service_name(service_name, sizeof(service_name)); #ifdef CONFIG_EXAMPLE_PROV_SECURITY_VERSION_1 wifi_prov_security_t security = WIFI_PROV_SECURITY_1; const char *pop = "abcd1234"; wifi_prov_security1_params_t *sec_params = pop; const char *username = NULL; #elif CONFIG_EXAMPLE_PROV_SECURITY_VERSION_2 wifi_prov_security_t security = WIFI_PROV_SECURITY_2; #if CONFIG_EXAMPLE_PROV_SEC2_DEV_MODE const char *username = EXAMPLE_PROV_SEC2_USERNAME; const char *pop = EXAMPLE_PROV_SEC2_PWD; #elif CONFIG_EXAMPLE_PROV_SEC2_PROD_MODE const char *username = NULL; const char *pop = NULL; #endif wifi_prov_security2_params_t sec2_params = {}; ESP_ERROR_CHECK(example_get_sec2_salt(&sec2_params.salt, &sec2_params.salt_len)); ESP_ERROR_CHECK(example_get_sec2_verifier(&sec2_params.verifier, &sec2_params.verifier_len)); wifi_prov_security2_params_t *sec_params = &sec2_params; #endif const char *service_key = NULL; #ifdef CONFIG_EXAMPLE_PROV_TRANSPORT_BLE uint8_t custom_service_uuid[] = { /* LSB <--------------------------------------- * ---------------------------------------> MSB */ 0xb4, 0xdf, 0x5a, 0x1c, 0x3f, 0x6b, 0xf4, 0xbf, 0xea, 0x4a, 0x82, 0x03, 0x04, 0x90, 0x1a, 0x02, }; wifi_prov_scheme_ble_set_service_uuid(custom_service_uuid); #endif wifi_prov_mgr_endpoint_create("custom-data"); ESP_ERROR_CHECK(wifi_prov_mgr_start_provisioning(security, (const void *) sec_params, service_name, service_key)); wifi_prov_mgr_endpoint_register("custom-data", custom_prov_data_handler, NULL); // wifi_prov_mgr_wait(); // wifi_prov_mgr_deinit(); //wifi_prov_print_qr(service_name, username, pop, PROV_TRANSPORT_BLE); } else { ESP_LOGI(TAG, "Already provisioned, starting Wi-Fi STA"); wifi_prov_mgr_deinit(); wifi_init_sta(); } } void app_main(void) { ESP_LOGI(TAG, "[APP] Startup.."); ESP_LOGI(TAG, "[APP] Free memory: %" PRIu32 " bytes", esp_get_free_heap_size()); ESP_LOGI(TAG, "[APP] IDF version: %s", esp_get_idf_version()); esp_log_level_set("*", ESP_LOG_INFO); esp_log_level_set("esp-tls", ESP_LOG_VERBOSE); esp_log_level_set("MQTT_CLIENT", ESP_LOG_VERBOSE); esp_log_level_set("MQTT_EXAMPLE", ESP_LOG_VERBOSE); esp_log_level_set("TRANSPORT_BASE", ESP_LOG_VERBOSE); esp_log_level_set("TRANSPORT", ESP_LOG_VERBOSE); esp_log_level_set("OUTBOX", ESP_LOG_VERBOSE); esp_err_t err = nvs_flash_init(); if (err == ESP_ERR_NVS_NO_FREE_PAGES) { ESP_ERROR_CHECK(nvs_flash_erase()); err = nvs_flash_init(); } ESP_ERROR_CHECK(err); ESP_LOGI(TAG, "[1.0] Initialize peripherals management"); esp_periph_config_t periph_cfg = DEFAULT_ESP_PERIPH_SET_CONFIG(); esp_periph_set_handle_t set = esp_periph_set_init(&periph_cfg); init_wifi_prov(); } ```

Debug Logs.

I (980) cpu_start: App version:      1
I (984) cpu_start: Compile time:     Sep  4 2023 18:14:19
I (989) cpu_start: ELF file SHA256:  dd58384b55be1fb2...
I (994) cpu_start: ESP-IDF:          5.0.2
I (998) cpu_start: Min chip rev:     v3.0
I (1001) cpu_start: Max chip rev:     v3.99
I (1005) cpu_start: Chip rev:         v3.1
I (1009) heap_init: Initializing. RAM available for dynamic allocation:
I (1016) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1021) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1026) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1031) heap_init: At 3FFC57F8 len 0001A808 (106 KiB): DRAM
I (1037) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1042) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1048) heap_init: At 40099720 len 000068E0 (26 KiB): IRAM
I (1053) esp_psram: Adding pool of 2037K of PSRAM memory to heap allocator
I (1060) spi_flash: detected chip: generic
I (1064) spi_flash: flash io: qio
I (1067) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1079) esp_psram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1087) MQTTS_OTA_TEST: [APP] Startup..
I (1090) MQTTS_OTA_TEST: [APP] Free memory: 2289124 bytes
I (1095) MQTTS_OTA_TEST: [APP] IDF version: 5.0.2
I (1139) MQTTS_OTA_TEST: [1.0] Initialize peripherals management
I (1143) wifi:wifi driver task: 3ffd30d8, prio:23, stack:6656, core=0
I (1143) system_api: Base MAC address is not set
I (1145) system_api: read default base MAC address from EFUSE
I (1168) wifi:wifi firmware version: 57982fe
I (1168) wifi:wifi certification version: v7.0
I (1168) wifi:config NVS flash: enabled
I (1169) wifi:config nano formating: disabled
I (1173) wifi:Init data frame dynamic rx buffer num: 32
I (1178) wifi:Init management frame dynamic rx buffer num: 32
I (1183) wifi:Init management short buffer num: 32
I (1188) wifi:Init static tx buffer num: 16
I (1192) wifi:Init tx cache buffer num: 32
I (1196) wifi:Init static rx buffer size: 1600
I (1200) wifi:Init static rx buffer num: 10
I (1204) wifi:Init dynamic rx buffer num: 32
I (1209) wifi_init: rx ba win: 6
I (1211) wifi_init: tcpip mbox: 32
I (1214) wifi_init: udp mbox: 6
I (1217) wifi_init: tcp mbox: 6
I (1220) wifi_init: tcp tx win: 5744
I (1223) wifi_init: tcp rx win: 5744
I (1226) wifi_init: tcp mss: 1440
I (1229) wifi_init: WiFi/LWIP prefer SPIRAM
I (1264) MQTTS_OTA_TEST: Starting provisioning
I (1265) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1347) wifi:mode : sta (08:3a:8d:07:27:bc)
I (1348) wifi:enable tsf
I (1351) BTDM_INIT: BT controller compile version [2c56073]
I (1714) wifi_prov_mgr: Provisioning started with service name : PROV_0727BC
I (1715) MQTTS_OTA_TEST: Provisioning started
W (19901) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x8
W (19902) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x8
I (37071) MQTTS_OTA_TEST: Received Wi-Fi credentials
        SSID     : xxxxxxxxx
        Password : xxxxxxxx
I (38077) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (38502) wifi:state: init -> auth (b0)
I (38505) wifi:state: auth -> assoc (0)
I (38509) wifi:state: assoc -> run (10)
I (38542) wifi:<ba-add>idx:0 (ifx:0, 30:7e:cb:91:62:04), tid:0, ssn:0, winSize:64
I (38555) wifi:connected with xxxxxxxxx, aid = 3, channel 1, BW20, bssid = 30:7e:cb:91:62:04
I (38556) wifi:security: WPA2-PSK, phy: bgn, rssi: -43
I (38565) wifi:pm start, type: 1
I (38635) wifi:AP's beacon interval = 102400 us, DTIM period = 3
I (39567) MQTTS_OTA_TEST: Connected with IP Address:192.168.1.25
I (39568) esp_netif_handlers: sta ip: 192.168.1.25, mask: 255.255.255.0, gw: 192.168.1.1
I (39570) wifi_prov_mgr: STA Got IP
I (32519) MQTTS_OTA_TEST: Provisioning successful
I (36408) wifi_prov_mgr: Provisioning stopped
W (36409) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13
W (36409) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x401556ab  PS      : 0x00060130  A0      : 0x80173b2c  A1      : 0x3ffc6b40
A2      : 0x0000000f  A3      : 0x3ffc4038  A4      : 0x3ffc6b80  A5      : 0x3ffc6b88
A6      : 0x00bd769c  A7      : 0x00bd769c  A8      : 0x00000000  A9      : 0x3ffc6b50
A10     : 0x00000003  A11     : 0x00000004  A12     : 0x00060120  A13     : 0x3ffc6be8
A14     : 0x4019efc4  A15     : 0x3f817abc  SAR     : 0x00000018  EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000040  LBEG    : 0x4000c349  LEND    : 0x4000c36b  LCOUNT  : 0xffffffff

Backtrace: 0x401556a8:0x3ffc6b40 0x40173b29:0x3ffc6b80 0x4019eff5:0x3ffc6bc0 0x401a2d42:0x3ffc6be0 0x40094131:0x3ff
c6c10

  #0  0x401556a8:0x3ffc6b40 in gatts_profile_event_handler at C:\Users\xxxx\.platformio\packages\framework-espidf\c
omponents\protocomm\src\simple_ble/simple_ble.c:147 (discriminator 15)
  #1  0x40173b29:0x3ffc6b80 in btc_gatts_cb_to_app at C:/Users/xxxx/.platformio/packages/framework-espidf/component
s/bt/host/bluedroid/btc/profile/std/gatt/btc_gatts.c:38
      (inlined by) btc_gatts_cb_handler at C:/Users/xxxx/.platformio/packages/framework-espidf/components/bt/host/b
luedroid/btc/profile/std/gatt/btc_gatts.c:911
  #2  0x4019eff5:0x3ffc6bc0 in btc_thread_handler at C:/Users/xxxx/.platformio/packages/framework-espidf/components
/bt/common/btc/core/btc_task.c:207
  #3  0x401a2d42:0x3ffc6be0 in osi_thread_run at C:/Users/xxxx/.platformio/packages/framework-espidf/components/bt/
common/osi/thread.c:165 (discriminator 1)
  #4  0x40094131:0x3ffc6c10 in vPortTaskWrapper at C:\Users\xxxx\.platformio\packages\framework-espidf\components\f
reertos\FreeRTOS-Kernel\portable\xtensa/port.c:154

More Information.

Previously i had the MQTT connecting right after the wifi link is up, i removed that, but the crash still occurs at the same time. Currently there is only ble_prov and wifi connection to STA, and it crashes immediately when the prov_manager stops, which if few seconds after the wifi is connected. This issue doesnt seem to have anything to do with wifi or MQTT, besides we can see in the crash dump that the error occurs inside the bluetooth stack, with no link to the prov_manager api files.

rahult-github commented 10 months ago

Hi @0x0fe ,

Tried the default wifi prov app at tag v5.0.2 ( commit : 7dec1b2052ffa30541e42dbf6b2f6eb369e07ddf ) and don't see any issue.

I (38636) app: Connected with IP Address:192.168.31.231 I (38636) esp_netif_handlers: sta ip: 192.168.31.231, mask: 255.255.255.0, gw: 192.168.31.1 I (38636) wifi_prov_mgr: STA Got IP I (38636) app: Provisioning successful I (38646) app: Hello World! I (39646) app: Hello World! I (40646) app: Hello World! W (41576) BT_HCI: hci cmd send: disconnect: hdl 0x1, rsn:0x13 W (41616) BT_HCI: hcif disc complete: hdl 0x1, rsn 0x16 I (41646) app: Hello World! I (42616) wifi_prov_mgr: Provisioning stopped I (42616) wifi_prov_scheme_ble: BTDM memory released I (42646) app: Hello World! I (43646) app: Hello World!

Can you please help :

  1. Try only ESP-IDF at mentioned commit and check the example . If it works, it means some setup of ADF + IDF is causing this behaviour.
  2. Let me know your IDF commit , if it is not at the above mentioned commit
  3. Please also share the complete sdkconfig , so that we can check if there is any configuration change.
  4. Based on the line number in crash and codebase, i have tried to create a patch to handle the case. Can you please give it a try ? handle_disconn.txt
0x0fe commented 10 months ago

Hello @rahult-github 1) i'll have to create another project and i forgot how to force the IDF version to a specific commit in PIO, but i used the IDF example from the same close 5.0.2 version, so there is no reason it doesnt work right? It is almost certain the problem comes from SDKconfig, given the number of adjustements required to be able to run wifi + BT A2DP/SPP + BLE at the same time. or maybe the problem is related to ADF.

2) framework-espidf @ 3.50002.230601 (5.0.2)

3) SDKConfig attached sdkconfig.esp32dev.txt

4) Here is the log with your patch.

I (11) boot: ESP-IDF 5.0.2 2nd stage bootloader
I (11) boot: compile time 09:28:55
I (11) boot: chip revision: v3.1
I (11) qio_mode: Enabling default flash chip QIO
I (14) boot.esp32: SPI Speed      : 80MHz
I (18) boot.esp32: SPI Mode       : QIO
I (22) boot.esp32: SPI Flash Size : 8MB
I (25) boot: Enabling RNG early entropy source...
I (30) boot: Partition Table:
I (32) boot: ## Label            Usage          Type ST Offset   Length
I (39) boot:  0 nvs              WiFi data        01 02 00009000 00005000
I (45) boot:  1 otadata          OTA data         01 00 0000e000 00002000
I (52) boot:  2 app0             OTA app          00 10 00010000 00330000
I (58) boot:  3 app1             OTA app          00 11 00340000 00330000
I (65) boot:  4 spiffs           Unknown data     01 82 00670000 00190000
I (71) boot: End of partition table
I (75) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=4c914h (313620) map
I (168) esp_image: segment 1: paddr=0005c93c vaddr=3ffbdb60 size=036dch ( 14044) load
I (173) esp_image: segment 2: paddr=00060020 vaddr=400d0020 size=142448h (1320008) map
I (536) esp_image: segment 3: paddr=001a2470 vaddr=3ffc123c size=01e28h (  7720) load
I (538) esp_image: segment 4: paddr=001a42a0 vaddr=40080000 size=197e8h (104424) load
I (587) boot: Loaded app from partition at offset 0x10000
I (587) boot: Disabling RNG early entropy source...
I (596) quad_psram: This chip is ESP32-D0WDR2-V3
I (597) esp_psram: Found 2MB PSRAM device
I (597) esp_psram: Speed: 80MHz
I (597) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
I (603) cpu_start: Pro cpu up.
I (605) cpu_start: Starting app cpu, entry point is 0x40081f90
I (0) cpu_start: App cpu up.
I (877) esp_psram: SPI SRAM memory test OK
I (942) cpu_start: Pro cpu start user code
I (942) cpu_start: cpu freq: 240000000 Hz
I (942) cpu_start: Application information:
I (942) cpu_start: Project name:     IDF_ADF
I (946) cpu_start: App version:      1
I (949) cpu_start: Compile time:     Sep  4 2023 23:51:05
I (954) cpu_start: ELF file SHA256:  833cfad206af67fc...
I (959) cpu_start: ESP-IDF:          5.0.2
I (963) cpu_start: Min chip rev:     v3.0
I (967) cpu_start: Max chip rev:     v3.99
I (971) cpu_start: Chip rev:         v3.1
I (975) heap_init: Initializing. RAM available for dynamic allocation:
I (981) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (986) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (991) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (996) heap_init: At 3FFC5AC0 len 0001A540 (105 KiB): DRAM
I (1002) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1007) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1013) heap_init: At 400997E8 len 00006818 (26 KiB): IRAM
I (1018) esp_psram: Adding pool of 2036K of PSRAM memory to heap allocator
I (1025) spi_flash: detected chip: generic
I (1028) spi_flash: flash io: qio
I (1032) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1044) esp_psram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1052) MQTTS_OTA_TEST: [APP] Startup..
I (1055) MQTTS_OTA_TEST: [APP] Free memory: 2287156 bytes
I (1060) MQTTS_OTA_TEST: [APP] IDF version: 5.0.2
I (1105) MQTTS_OTA_TEST: [1.0] Initialize peripherals management
I (1108) wifi:wifi driver task: 3ffd33a0, prio:23, stack:6656, core=0
I (1108) system_api: Base MAC address is not set
I (1110) system_api: read default base MAC address from EFUSE
I (1133) wifi:wifi firmware version: 57982fe
I (1134) wifi:wifi certification version: v7.0
I (1134) wifi:config NVS flash: enabled
I (1134) wifi:config nano formating: disabled
I (1138) wifi:Init data frame dynamic rx buffer num: 32
I (1143) wifi:Init management frame dynamic rx buffer num: 32
I (1149) wifi:Init management short buffer num: 32
I (1154) wifi:Init static tx buffer num: 16
I (1158) wifi:Init tx cache buffer num: 32
I (1161) wifi:Init static rx buffer size: 1600
I (1165) wifi:Init static rx buffer num: 10
I (1169) wifi:Init dynamic rx buffer num: 32
I (1174) wifi_init: rx ba win: 6
I (1176) wifi_init: tcpip mbox: 32
I (1179) wifi_init: udp mbox: 6
I (1182) wifi_init: tcp mbox: 6
I (1185) wifi_init: tcp tx win: 5744
I (1188) wifi_init: tcp rx win: 5744
I (1191) wifi_init: tcp mss: 1440
I (1194) wifi_init: WiFi/LWIP prefer SPIRAM
I (1229) MQTTS_OTA_TEST: Starting provisioning
I (1231) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1311) wifi:mode : sta (08:3a:8d:07:27:bc)
I (1311) wifi:enable tsf
I (1315) BTDM_INIT: BT controller compile version [2c56073]
I (1686) wifi_prov_mgr: Provisioning started with service name : PROV_0727BC
I (1687) MQTTS_OTA_TEST: Provisioning started
W (43070) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x13
W (43071) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x13
E (43072) security1: Attempt to close invalid session
E (43074) protocomm_ble: error closing the session after disconnect
I (58730) MQTTS_OTA_TEST: Received Wi-Fi credentials
        SSID     : xxxxxxxx
        Password : xxxxxxxx
I (59736) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (60162) wifi:state: init -> auth (b0)
I (60165) wifi:state: auth -> assoc (0)
I (60169) wifi:state: assoc -> run (10)
I (60202) wifi:<ba-add>idx:0 (ifx:0, 30:7e:cb:91:62:04), tid:0, ssn:0, winSize:64
I (60216) wifi:connected with SFR_6200, aid = 3, channel 1, BW20, bssid = 30:7e:cb:91:62:04
I (60216) wifi:security: WPA2-PSK, phy: bgn, rssi: -37
I (60225) wifi:pm start, type: 1

I (60287) wifi:AP's beacon interval = 102400 us, DTIM period = 3
I (61229) MQTTS_OTA_TEST: Connected with IP Address:192.168.1.25
I (61229) MQTTS_OTA_TEST: MAC: 083a8d0727bc
I (61230) MQTTS_OTA_TEST: UUID: c89ffed9d50f751a0464403f239c810a
I (61233) MQTTS_OTA_TEST: [APP] Free memory: 2115220 bytes
I (61239) esp_netif_handlers: sta ip: 192.168.1.25, mask: 255.255.255.0, gw: 192.168.1.1
I (61239) MQTTS_OTA_TEST: Other event id:7
I (61246) wifi_prov_mgr: STA Got IP
I (61253) MQTTS_OTA_TEST: Provisioning successful
I (62646) MQTTS_OTA_TEST: sub to FABATEST/083a8d0727bc/CHAPTER/DOWNLOAD/+
I (62648) MQTTS_OTA_TEST: sub to FABATEST/083a8d0727bc/FOTA/UPDATE
I (62650) MQTTS_OTA_TEST: sub to FABATEST/083a8d0727bc/control
I (62851) MQTTS_OTA_TEST: MQTT_EVENT_SUBSCRIBED, msg_id=21441
I (62991) MQTTS_OTA_TEST: MQTT_EVENT_SUBSCRIBED, msg_id=40591
I (62993) MQTTS_OTA_TEST: MQTT_EVENT_SUBSCRIBED, msg_id=4266
Calling simple_ble_deinit from protocomm_ble_stop
Inside simple_ble_deinit
I (65014) wifi_prov_mgr: Provisioning stopped
W (65015) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13
W (65018) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x4017418f  PS      : 0x00060b30  A0      : 0x801939c0  A1      : 0x3ffcab80
A2      : 0x0000000f  A3      : 0x3ffc4300  A4      : 0x3ffcabc0  A5      : 0x3ffcabc8
A6      : 0x0091a8fb  A7      : 0x0091a8fb  A8      : 0x00000000  A9      : 0x3ffcab90
A10     : 0x00000003  A11     : 0x00000004  A12     : 0x00060b20  A13     : 0x3ffcac28
A14     : 0x401bee58  A15     : 0x3f8185d8  SAR     : 0x00000018  EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000040  LBEG    : 0x4000c349  LEND    : 0x4000c36b  LCOUNT  : 0xffffffff

Backtrace: 0x4017418c:0x3ffcab80 0x401939bd:0x3ffcabc0 0x401bee89:0x3ffcac00 0x401c2bd6:0x3ffcac20 0x4009418d:0x3ffcac50

  #0  0x4017418c:0x3ffcab80 in gatts_profile_event_handler at C:\Users\hoel\.platformio\packages\framework-espidf\components\protocomm\sr
c\simple_ble/simple_ble.c:147 (discriminator 15)
  #1  0x401939bd:0x3ffcabc0 in btc_gatts_cb_to_app at C:/Users/hoel/.platformio/packages/framework-espidf/components/bt/host/bluedroid/bt
c/profile/std/gatt/btc_gatts.c:38
      (inlined by) btc_gatts_cb_handler at C:/Users/hoel/.platformio/packages/framework-espidf/components/bt/host/bluedroid/btc/profile/s
td/gatt/btc_gatts.c:911
  #2  0x401bee89:0x3ffcac00 in btc_thread_handler at C:/Users/hoel/.platformio/packages/framework-espidf/components/bt/common/btc/core/bt
c_task.c:207
  #3  0x401c2bd6:0x3ffcac20 in osi_thread_run at C:/Users/hoel/.platformio/packages/framework-espidf/components/bt/common/osi/thread.c:16
5 (discriminator 1)
  #4  0x4009418d:0x3ffcac50 in vPortTaskWrapper at C:\Users\hoel\.platformio\packages\framework-espidf\components\freertos\FreeRTOS-Kerne
l\portable\xtensa/port.c:154

ELF file SHA256: 833cfad206af67fc

Rebooting...
rahult-github commented 10 months ago

Hi @0x0fe ,

Thanks for the logs. Looks like before just when disconnect event is posted to stack, somehow there is a call to deinit the BLE from upper layer . When disconnect event is being handled, there is attempt to access pointers which were already freed up (as BLE Deinit will free up the resources) which results in this issue.. Will need to check more in the setup you have mentioned, as standalone IDF setup examples don't show this behaviour.

0x0fe commented 9 months ago

Hi @rahult-github I see, but what in the SDKconfig could cause the BLE to deinit? Because i tested the unmodified example from IDF (from 5.0) disabling all other source code, so as far as i know no ADF related API is used, and the crash still occurs exactly the same. So i tend to assume my SDKConfig is causing the issue.

Also i need to mention, i have this linker issue and had to apply the "fix" mentioned here (.lf file modification).

BT linker issue

My understanding is that this "fix" has the side effect of preventing part of the BT stack to be moved to SPIRAM, not ideal, but at least the linking works. N.B disregard my comment at the bottom of this other ticket, it was on a different configuration (IDF+arduino-esp32)

0x0fe commented 9 months ago

@rahult-github OK, so according to the information you provided, i tried something, which seems to confirm exactly what you told. I disabled the auto-stop function, and the crash did not occur, i suspect if i stop manually after a timeout it will be fine (since the access to pointers will be done already). If this confirms, i have a temporary workaround, but it would be worth checking into the root cause, because maybe it works by accident with the default SDKconfig, but there is some kind of race condition with my SDKConfig.

Here is the log when auto-stop is disabled

wifi_prov_mgr_disable_auto_stop(1000);

I (1255) app: Starting provisioning
I (1256) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1337) wifi:mode : sta (08:3a:8d:07:27:bc)
I (1338) wifi:enable tsf
I (1341) BTDM_INIT: BT controller compile version [2c56073]
I (1722) wifi_prov_mgr: Provisioning started with service name : PROV_0727BC
I (1722) app: Provisioning started
W (31660) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x13
W (31661) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x13
E (31662) security1: Attempt to close invalid session
E (31664) protocomm_ble: error closing the session after disconnect
I (46084) app: Received Wi-Fi credentials
        SSID     : xxxxxxxxxxx
        Password : xxxxxxxxxxxxx
I (47090) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (47515) wifi:state: init -> auth (b0)
I (47518) wifi:state: auth -> assoc (0)
I (47523) wifi:state: assoc -> run (10)
I (47546) wifi:<ba-add>idx:0 (ifx:0, 30:7e:cb:91:62:04), tid:0, ssn:0, winSize:64
I (47560) wifi:connected with SFR_6200, aid = 3, channel 1, BW20, bssid = 30:7e:cb:91:62:04
I (47561) wifi:security: WPA2-PSK, phy: bgn, rssi: -39
I (47570) wifi:pm start, type: 1

I (47592) wifi:AP's beacon interval = 102400 us, DTIM period = 3
I (49572) app: Connected with IP Address:192.168.1.25
I (49573) esp_netif_handlers: sta ip: 192.168.1.25, mask: 255.255.255.0, gw: 192.168.1.1
I (49574) wifi_prov_mgr: STA Got IP
I (49577) app: Provisioning successful
I (49581) app: Hello World!
I (50583) app: Hello World!
I (51583) app: Hello World!
I (52583) app: Hello World!
I (53583) app: Hello World!
I (54583) app: Hello World!

EDIT: SO i tried this, adding a 10 second delay then stopping provisioning, and the crash still occurs when the provisioning is stopped .

    /* Start main application now */

    while (1) {
        ESP_LOGI(TAG, "Hello World!");
        vTaskDelay(10000 / portTICK_PERIOD_MS);
        wifi_prov_mgr_stop_provisioning();
        //wifi_prov_mgr_deinit(); // will call wifi_prov_mgr_stop_provisioning first
    }
I (40692) app: Provisioning successful
I (40796) app: Hello World!
I (50796) app: Hello World!
Calling simple_ble_deinit from protocomm_ble_stop
Inside simple_ble_deinit
I (51797) wifi_prov_mgr: Provisioning stopped
W (51798) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13
W (51801) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x401552cf  PS      : 0x00060630  A0      : 0x80173450  A1      : 0x3ffdf950
A2      : 0x0000000f  A3      : 0x3ffc3ef0  A4      : 0x3ffdf990  A5      : 0x3ffdf998
A6      : 0x001218c3  A7      : 0x001218c3  A8      : 0x00000000  A9      : 0x3ffdf960
A10     : 0x00000003  A11     : 0x00000004  A12     : 0x00060620  A13     : 0x3ffdf9f8
A14     : 0x4019e8e8  A15     : 0x3f817ac4  SAR     : 0x00000018  EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000040  LBEG    : 0x4000c349  LEND    : 0x4000c36b  LCOUNT  : 0xffffffff

Backtrace: 0x401552cc:0x3ffdf950 0x4017344d:0x3ffdf990 0x4019e919:0x3ffdf9d0 0x401a2666:0x3ffdf9f0 0x40093e75:0x3ffdfa20

  #0  0x401552cc:0x3ffdf950 in gatts_profile_event_handler at C:\Users\xxxxx\.platformio\packages\framework-espidf\components\protocomm\src\simple_ble/simple_ble.c:147 (discrimina
tor 15)
  #1  0x4017344d:0x3ffdf990 in btc_gatts_cb_to_app at C:/Users/xxxxx/.platformio/packages/framework-espidf/components/bt/host/bluedroid/btc/profile/std/gatt/btc_gatts.c:38
      (inlined by) btc_gatts_cb_handler at C:/Users/xxxxxx/.platformio/packages/framework-espidf/components/bt/host/bluedroid/btc/profile/std/gatt/btc_gatts.c:911
  #2  0x4019e919:0x3ffdf9d0 in btc_thread_handler at C:/Users/xxxxx/.platformio/packages/framework-espidf/components/bt/common/btc/core/btc_task.c:207
  #3  0x401a2666:0x3ffdf9f0 in osi_thread_run at C:/Users/xxxxxx/.platformio/packages/framework-espidf/components/bt/common/osi/thread.c:165 (discriminator 1)
  #4  0x40093e75:0x3ffdfa20 in vPortTaskWrapper at C:\Users\xxxxx\.platformio\packages\framework-espidf\components\freertos\FreeRTOS-Kernel\portable\xtensa/port.c:154

but then, on a further attempt using wifi_prov_mgr_deinit(); after a 10s timeout the crash occured higher up in the manager during semaphore deletion

W (56687) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13
W (56688) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16
E (56689) security1: Attempt to close invalid session
E (56692) protocomm_ble: error closing the session after disconnect
Calling simple_ble_deinit from protocomm_ble_stop
Inside simple_ble_deinit
I (56707) wifi_prov_mgr: Provisioning stopped

assert failed: vQueueDelete IDF\components\freertos\FreeRTOS-Kernel\queue.c:2138 (pxQueue)

Backtrace: 0x400824a6:0x3ffbb950 0x40093a21:0x3ffbb970 0x40097751:0x3ffbb990 0x401ece11:0x3ffbbab0 0x400d42ed:0x3ffbbad0 0x400d2769:0x3ffbbaf0 0x401ecd4a:0x3ffbbc50 0x40093e75:0x
3ffbbc80

  #0  0x400824a6:0x3ffbb950 in panic_abort at C:\Users\xxxxx\.platformio\packages\framework-espidf\components\esp_system/panic.c:423
  #1  0x40093a21:0x3ffbb970 in esp_system_abort at C:\Users\xxxxx\.platformio\packages\framework-espidf\components\esp_system/esp_system.c:153
  #2  0x40097751:0x3ffbb990 in __assert_func at C:\Users\xxxxx\.platformio\packages\framework-espidf\components\newlib/assert.c:78
  #3  0x401ece11:0x3ffbbab0 in vQueueDelete at C:\Users\xxxxx\.platformio\packages\framework-espidf\components\freertos\FreeRTOS-Kernel/queue.c:2138 (discriminator 1)
  #4  0x400d42ed:0x3ffbbad0 in wifi_prov_mgr_deinit at C:\Users\xxxxx\.platformio\packages\framework-espidf\components\wifi_provisioning\src/manager.c:1447 (discriminator 15)
  #5  0x400d2769:0x3ffbbaf0 in app_main at src/ble_prov_test.c:416 (discriminator 13)
  #6  0x401ecd4a:0x3ffbbc50 in main_task at C:\Users\xxxxx\.platformio\packages\framework-espidf\components\freertos\FreeRTOS-Kernel\portable/port_common.c:131 (discriminator 2)
  #7  0x40093e75:0x3ffbbc80 in vPortTaskWrapper at C:\Users\xxxxx\.platformio\packages\framework-espidf\components\freertos\FreeRTOS-Kernel\portable\xtensa/port.c:154

Given that the error now occurs in prov manager i wrote a guard, to avoid calling delete if the semaphore is already null

line 1446 of manager.c

    if(prov_ctx_lock!=NULL) {
        vSemaphoreDelete(prov_ctx_lock);
        prov_ctx_lock = NULL;
    }

And this fixes the crash, so i have a temporary workaround, high enough in the API to not be problematic for other BT related functions.

I (55675) wifi:AP's beacon interval = 102400 us, DTIM period = 3
I (56661) app: Connected with IP Address:192.168.1.25
I (56662) esp_netif_handlers: sta ip: 192.168.1.25, mask: 255.255.255.0, gw: 192.168.1.1
I (56663) wifi_prov_mgr: STA Got IP
I (56666) app: Provisioning successful
W (67670) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13
W (67671) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16
E (67672) security1: Attempt to close invalid session
E (67675) protocomm_ble: error closing the session after disconnect
Calling simple_ble_deinit from protocomm_ble_stop
Inside simple_ble_deinit
I (67690) wifi_prov_mgr: Provisioning stopped
I (67692) app: Hello World!
I (68694) app: Hello World!
I (69694) app: Hello World!
I (70694) app: Hello World!
lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1)
W (71669) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x22
I (71694) app: Hello World!
I (72694) app: Hello World!

Beside this issue, i have one concern with BLE PROV, how can i integrate it correctly with ADF wifi service? The product FW is on ADF and uses wifi mp3 streaming, which requires wifi service. But BLE PROV does not use the wifi service. And i am not sure how to make the wifi service work correctly when the wifi connection has been established with BLE PROV since the APIs / event handlers are different. I cannot find any single reference using BLE PROV and wifi service at the same time in all github (and i searched).

The ADF wifi service implements some provisioning schemes, namely smartconfig via AP and BLUFI, but i am not allowed to use smartconfig (too unreliable), and while i proposed BLUFI it has not been approved simply because the only Espressif APP for evaluation (dating from 2017) is very outdated and non-functional, it cannot even scan the wifi network (tested on iphone with latest IOS, the scan button does nothing). As a consequence the APP team doesnt want to try implementing BLUFI.

I do not understand why BLUFI was integrated in ADF wifi service and not BLE PROV, at least it has a decent APP for evaluation, and it works (that is, when there is no crash).