search

espressif / esp-idf

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

Getting GATTC_OPEN event for interface that's already connected (IDFGH-2083) #4254

Closed wcauchois closed 4 years ago

wcauchois commented 4 years ago

Environment

Problem Description

I have a program that's acting as a GATT client and connecting to up to 3 peripherals, as well as acting as a GATT server with 3 services (note: that adds up to 6 GATT "interfaces"). The program is constantly scanning and connecting to peripherals as they appear and maintaining long-lived connections to them.

We recently upgraded our ESP-IDF version from v3.2 to v3.3 and I believe the behavior I'm about to describe is new with the version upgrade.

Our normal flow for connection is:

The behavior I'm seeing is that I'm getting a GATTC_OPEN event for a GATT interface that is already connected to a peripheral. This causes my code to attempt to re-start scanning, but since this is outside of the normal flow I described above it turns out that my program is already scanning, and so the start scan command fails (BTM_BleScan scan already active) because we are already scanning.

I have a profile_tab structure (similar to the examples) that keeps track of the different GATT client interfaces and their associated current connection ID. The connection ID is set on GATTC_OPEN and cleared on GATTC_CLOSE.

The full logs demonstrating the issue are quite complex, but I wrote a task that prints out the current state of the profile_tab:

I (355328) GATTC: STATUS: App 0, if=3, conn_id=1
I (355328) GATTC: STATUS: App 1, if=4, conn_id=2
I (355328) GATTC: STATUS: App 2, if=5, conn_id=3
I (355808) GATTC: ESP_GATTC_OPEN_EVT, if=5, conn_id=1

What you see here is that according to my bookkeeping, interface 5 is associated with connection ID 3. However I get the GATTC_OPEN event for interface 5 connection ID 1. Weirdly, conn 1 is already associated with interface 3.

Expected Behavior

Don't receive a GATTC_OPEN event for an interface that's currently connected to a peripheral.

Actual Behavior

Receives a GATTC_OPEN event for an interface that's currently connected.

Steps to reproduce

Continuously scan for and connect to multiple peripherals.

Code to reproduce this issue

I don't have a minimal code repro but I could probably come up with one. This might be hard to reproduce locally unless you have multiple peripherals lying about.

Debug Logs

GYC-Espressif commented 4 years ago

Hi, Sorry for the late reply. can you provide some code to reproduce this problem? I didn't find similar problems here. Thank you.

q7777777hk commented 4 years ago

@wcauchois Any update on this, I got the similar issue. My code is modified from esp-idf\examples\bluetooth\gattc_multi_connect At the end I can only connect 1 peripheral at the same time

GYC-Espressif commented 4 years ago

Hello @q7777777hk , Could you provide your code to help us to reproduce this issue? Thank you.

q7777777hk commented 4 years ago

I can only provide the ESP32 side, my peripheral side use Nordic gattc_multi_connect.zip

Below is my log [ESP32 scan my peripheral 2] I (18529) GATTC_MULTIPLE: Searched Device Name Len 20 I (18529) GATTC_MULTIPLE: ABCDE_BCEA73CACCDB

[my peripheral 1 finish communication and disconnect from ESP32, I don't know why everytime disconnect, I see below] W (18529) BT_APPL: bta_gattc_conn_cback() - cif=3 connected=0 conn_id=3 reason=0x0013 W (18539) BT_APPL: bta_gattc_conn_cback() - cif=4 connected=0 conn_id=4 reason=0x0013 W (18549) BT_APPL: bta_gattc_conn_cback() - cif=5 connected=0 conn_id=5 reason=0x0013 W (18559) BT_APPL: bta_gattc_conn_cback() - cif=6 connected=0 conn_id=6 reason=0x0013 W (18569) BT_APPL: bta_gattc_conn_cback() - cif=7 connected=0 conn_id=7 reason=0x0013 W (18569) BT_APPL: bta_gattc_conn_cback() - cif=8 connected=0 conn_id=8 reason=0x0013

[ESP32 stop scan as already detected my peripheral 2, and call open] I (18589) GATTC_MULTIPLE: esp_ble_gap_stop_scanning() I (18589) GATTC_MULTIPLE: esp_ble_gattc_open()

[my peripheral 1 disconnection event] I (18589) GATTC_MULTIPLE: Profile Event : 41 I (18599) GATTC_MULTIPLE: device 0 disconnect (conn_id 0, gattc_if 3/3) I (18609) GATTC_MULTIPLE: Profile Event : 5

I (18649) GATTC_MULTIPLE: Gap Event : 18 I (18649) GATTC_MULTIPLE: Stop scan successfully

[ESP_GATTC_CONNECT_EVT event to my peripheral 2] I (18669) GATTC_MULTIPLE: Profile Event : 40

[ESP_GATTC_OPEN_EVT event to my peripheral 2] I (18669) GATTC_MULTIPLE: Profile Event : 2 I (18679) GATTC_MULTIPLE: >> connect device ok app_id 1 I (18689) GATTC_MULTIPLE: ESP_GATTC_OPEN_EVT conn_id 0, if 4, status 0, mtu 23 I (18689) GATTC_MULTIPLE: REMOTE BDA: I (18699) GATTC_MULTIPLE: db cc ca 73 ea bc <==

[ESP_GATTC_CFG_MTU_EVT event to my peripheral 2] I (19129) GATTC_MULTIPLE: Profile Event : 18 I (19129) GATTC_MULTIPLE: Status 0, MTU 200, conn_id 0 I (19129) GATTC_MULTIPLE: esp_ble_gattc_search_service()

[ESP_GATTC_SEARCH_RES_EVT event to my peripheral 2] I (19139) GATTC_MULTIPLE: Profile Event : 7 I (19149) GATTC_MULTIPLE: SEARCH RES: conn_id = 0 is primary service 1 I (19149) GATTC_MULTIPLE: start handle 11 end handle 65535 current handle value 11 I (19159) GATTC_MULTIPLE: UUID128: 9e ca dc 24 e e5 a9 e0 93 f3 a3 b5 1 0 40 6e

[ESP_GATTC_SEARCH_CMPL_EVT event to my peripheral 2] I (19169) GATTC_MULTIPLE: Profile Event : 6 I (19179) GATTC_MULTIPLE: esp_ble_gattc_get_attr_count (H:11 to 65535) I (19179) GATTC_MULTIPLE: esp_ble_gattc_get_char_by_uuid 1 (P:28 H:13) I (19189) GATTC_MULTIPLE: esp_ble_gattc_register_for_notify() ....

[ESP_GATTC_REG_FOR_NOTIFY_EVT event to my peripheral 2] I (19199) GATTC_MULTIPLE: Profile Event : 38 I (19199) GATTC_MULTIPLE: esp_ble_gattc_get_attr_count() 1 .... I (19209) GATTC_MULTIPLE: esp_ble_gattc_get_descr_by_char_handle() 1 2 .... I (19219) GATTC_MULTIPLE: esp_ble_gattc_write_char_descr() ....

[ESP_GATTC_WRITE_DESCR_EVT event to my peripheral 2, ESP32 will write AE 03 to peripheral when connected at this stage] I (19249) GATTC_MULTIPLE: Profile Event : 9 I (19249) GATTC_MULTIPLE: write descr success 1 I (19249) GATTC_MULTIPLE: write_char_data_connected 1 I (19259) GATTC_MULTIPLE: esp_ble_gattc_write_char() .... write_char_data_connected 1 I (19269) GATTC_MULTIPLE: ae 03

[This is the problem part : ESP_GATTC_OPEN_EVT event to my peripheral 2, again !?] I (19299) GATTC_MULTIPLE: Profile Event : 2 I (19299) GATTC_MULTIPLE: >> connect device ok app_id 0 I (19299) GATTC_MULTIPLE: ESP_GATTC_OPEN_EVT conn_id 0, if 3, status 0, mtu 200 I (19309) GATTC_MULTIPLE: REMOTE BDA: I (19309) GATTC_MULTIPLE: db cc ca 73 ea bc <==

[ESP_GATTC_NOTIFY_EVT to peripheral 2. In normal situation after ESP32 sent AE 03 to peripheral 2, peripheral will reply ea 03 ef 2f 00 01 00 3f to ESP32. However this responses to above strange connection, and from the log here, even this connection is correct, I have not send anything at this stage to peripheral. Is this a ghost event from previous disconnected peripheral 1] I (19319) GATTC_MULTIPLE: Profile Event : 10 I (19329) GATTC_MULTIPLE: ESP_GATTC_NOTIFY_EVT, Receive notify value: (device 0 conn_id 0, gattc _if 3/3) I (19339) GATTC_MULTIPLE: ea 03 ef 2f 00 01 00 3f I (19339) GATTC_MULTIPLE: write_char_data_ack 0

[ESP_GATTC_NOTIFY_EVT to peripheral 2. After ESP32 sent AE 03 to peripheral 2, peripheral will reply ea 03 ef 2f 00 01 00 3f to ESP32. And ESP32 will reply AA to the peripheral] I (19349) GATTC_MULTIPLE: Profile Event : 10 I (19349) GATTC_MULTIPLE: ESP_GATTC_NOTIFY_EVT, Receive notify value: (device 1 conn_id 0, gattc _if 4/4) I (19359) GATTC_MULTIPLE: ea 03 ef 2f 00 01 00 3f I (19369) GATTC_MULTIPLE: write_char_data_ack 1 I (19369) GATTC_MULTIPLE: esp_ble_gattc_write_char() .... write_char_data_ack 1 I (19379) GATTC_MULTIPLE: aa

[ESP_GATTC_WRITE_CHAR_EVT to peripheral 2 to confirm AA is sent] I (19379) GATTC_MULTIPLE: Profile Event : 4 I (19389) GATTC_MULTIPLE: write char success 1

[In normal case, peripheral 2 will disconnect at this moment. And scan will be trigger again] E (19399) BT_BTM: BTM_BleScan scan already active W (19399) BT_APPL: bta_dm_ble_scan start scan failed. status=0x6 I (19409) GATTC_MULTIPLE: Gap Event : 7 I (19409) GATTC_MULTIPLE: Scan start success

[Instead of seeing disconnection, I see below HEAP corrupt. Mayybe it connect twice as above and always cause below] CORRUPT HEAP: multi_heap.c:477 detected at 0x3ffdce0c abort() was called at PC 0x40092b0d on core 0 0x40092b0d: multi_heap_assert at C:/work/Boiler/msys32/opt/esp/esp-idf/components/heap/multi_hea p.c:380 (inlined by) multi_heap_free_impl at C:/work/Boiler/msys32/opt/esp/esp-idf/components/heap/mult i_heap.c:477 ELF file SHA256: 847dee8695a0ed50425e553e0cc967e444cff9c96a45596a255f7dc29f76435f Backtrace: 0x4008dd7c:0x3ffdaa70 0x4008dfc9:0x3ffdaa90 0x40092b0d:0x3ffdaab0 0x40082976:0x3ffdaa d0 0x40082e21:0x3ffdaaf0 0x4000bec7:0x3ffdab10 0x4011d026:0x3ffdab30 0x4011d29a:0x3ffdab60 0x401 1b71e:0x3ffdaba0 0x4011b9ae:0x3ffdabc0 0x40122ef7:0x3ffdabe0 0x40113f48:0x3ffdac20 0x40114176:0x 3ffdac40 0x4009125d:0x3ffdac70 0x4008dd7c: invoke_abort at C:/work/Boiler/msys32/opt/esp/esp-idf/components/esp32/panic.c:715

0x4008dfc9: abort at C:/work/Boiler/msys32/opt/esp/esp-idf/components/esp32/panic.c:715

0x40092b0d: multi_heap_assert at C:/work/Boiler/msys32/opt/esp/esp-idf/components/heap/multi_hea p.c:380 (inlined by) multi_heap_free_impl at C:/work/Boiler/msys32/opt/esp/esp-idf/components/heap/mult i_heap.c:477

q7777777hk commented 4 years ago

My SDK is v3.3-202-gefdddbb25-dirty

GYC-Espressif commented 4 years ago

For peripheral 1, the disconnect reason is 0x13, code 0x13 is connection terminate by peer user. So I don't know what's happened with the peer device. For the next problem, I checked your code. And you shouldn't set readyForNextScan = true; when got ESP_GAP_BLE_SCAN_STOP_COMPLETE_EVT . You should enable the next scan when one connection has been connected, such as after ESP_GATTC_SEARCH_CMPL_EVT event. And another problem is you should only call esp_ble_gap_set_scan_params one time, rather than call it on every ESP_GATTC_REG_EVT.

q7777777hk commented 4 years ago

Hi GYC

Thanks for your quick reply 1) You should only call esp_ble_gap_set_scan_params one time, rather than call it on every ESP_GATTC_REG_EVT

I will modify and do the test again

2) You should enable the next scan when one connection has been connected

From my above log, scan stop during my peripheral 2's connection and data communication. And before scan resume, peripheral 2 has another ESP_GATTC_OPEN_EVT (but no ESP_GATTC_CONNECT_EVT). Is there any idea on this ?

GYC-Espressif commented 4 years ago

Hello, about another ESP_GATTC_OPEN_EVT, I test two devices to be the server, the one is our esp32, the other one is my smartphone, which has two different actions. The esp32 stop adv after connection established, but the smartphone still advertising. And your code will try to connect the devices every times when a device advertising the name "ABCDE_". So my esp32 connect and only open once, and the smartphone tries to open many times. I don't know how the peer device work, so please try to check if it has the same behavior as my smartphone. And maybe you need to change your code.

q7777777hk commented 4 years ago

Thanks for your information Can I ask one more question, how to make esp_ble_gap_start_scanning() scan forever ? I only want it to stop scanning when I call esp_ble_gap_stop_scanning()

chegewara commented 4 years ago

@q7777777hk Did you change number of max simultaneous BLE connections in menuconfig? By default it is 3. You need to change 2 settings:

CONFIG_BT_ACL_CONNECTIONS:
Maximum BT/BLE connection count

and

CONFIG_BTDM_CONTROLLER_BLE_MAX_CONN:
BLE maximum connections of bluetooth controller.
Each connection uses 1KB static DRAM whenever the BT controller is enabled

I am assuming you have the same issue:

I (355328) GATTC: STATUS: App 0, if=3, conn_id=1
I (355328) GATTC: STATUS: App 1, if=4, conn_id=2
I (355328) GATTC: STATUS: App 2, if=5, conn_id=3
I (355808) GATTC: ESP_GATTC_OPEN_EVT, if=5, conn_id=1

or you just hijacked issue.

PS to scan forever use scan time = 0

chegewara commented 4 years ago

Its just guessing, but i think this is what you have here:

[ESP_GATTC_NOTIFY_EVT to peripheral 2. In normal situation after ESP32 sent AE 03 to peripheral 2, peripheral will reply ea 03 ef 2f 00 01 00 3f to ESP32. However this responses to above strange connection, and from the log here, even this connection is correct, I have not send anything at this stage to peripheral. Is this a ghost event from previous disconnected peripheral 1]

https://docs.espressif.com/projects/esp-idf/en/latest/api-reference/bluetooth/esp_gattc.html#_CPPv419esp_ble_gattc_close13esp_gatt_if_t8uint16_t

Close the virtual connection to the GATT server. gattc may have multiple virtual GATT server connections when multiple app_id registered, this API only close one virtual GATT server connection. if there exist other virtual GATT server connections, it does not disconnect the physical connection. if you want to disconnect the physical connection directly, you can use esp_ble_gap_disconnect(esp_bd_addr_t remote_device).

Which means you can have bug in your app that is opening new virtual connection to device you already are connected and:

[Instead of seeing disconnection, I see below HEAP corrupt. Mayybe it connect twice as above and always cause below] CORRUPT HEAP: multi_heap.c:477 detected at 0x3ffdce0c

another bug in your app or bug in esp-idf.

q7777777hk commented 4 years ago

@q7777777hk Did you change number of max simultaneous BLE connections in menuconfig? By default it is 3. You need to change 2 settings:

CONFIG_BT_ACL_CONNECTIONS:
Maximum BT/BLE connection count

and

CONFIG_BTDM_CONTROLLER_BLE_MAX_CONN:
BLE maximum connections of bluetooth controller.
Each connection uses 1KB static DRAM whenever the BT controller is enabled

I am assuming you have the same issue:

I (355328) GATTC: STATUS: App 0, if=3, conn_id=1
I (355328) GATTC: STATUS: App 1, if=4, conn_id=2
I (355328) GATTC: STATUS: App 2, if=5, conn_id=3
I (355808) GATTC: ESP_GATTC_OPEN_EVT, if=5, conn_id=1

or you just hijacked issue.

PS to scan forever use scan time = 0

CONFIG_BT_ACL_CONNECTIONS=7 But I cannot find CONFIG_BTDM_CONTROLLER_BLE_MAX_CONN in my sdkconfig (my sdk is 3.3)

My situation is like I (789) GATTC_MULTIPLE: Reg app ok, app_id 0000, status 0, gattc_if 3 I (789) GATTC_MULTIPLE: Reg app ok, app_id 0001, status 0, gattc_if 4 I (809) GATTC_MULTIPLE: Reg app ok, app_id 0002, status 0, gattc_if 5 I (829) GATTC_MULTIPLE: Reg app ok, app_id 0003, status 0, gattc_if 6 I (839) GATTC_MULTIPLE: Reg app ok, app_id 0004, status 0, gattc_if 7 I (859) GATTC_MULTIPLE: Reg app ok, app_id 0005, status 0, gattc_if 8 a device connect to I (18689) GATTC_MULTIPLE: ESP_GATTC_OPEN_EVT conn_id 0, app_id 1, if 4, status 0, mtu 23 I (18689) GATTC_MULTIPLE: REMOTE BDA: db cc ca 73 ea bc but it connect again before above is disconnected (my scan is already disabled when above connection starts) I (19299) GATTC_MULTIPLE: ESP_GATTC_OPEN_EVT conn_id 0, app_id 0, if 3, status 0, mtu 200 I (19309) GATTC_MULTIPLE: REMOTE BDA: db cc ca 73 ea bc

I am studying you 2nd reply, thanks

q7777777hk commented 4 years ago

2 more questions

GYC-Espressif commented 4 years ago

Not have that API, the scan time is set by the function esp_ble_gap_start_scanning(uint32_t duration), the param "duration" is the keeping scanning time. But if you don't open the duplicate scan, you can get the scan result event every time when scanning an adv. That means the scan is still working. The max interval of connection is 0x0C80, you can find related comments in our source code.

Alvin1Zhang commented 4 years ago

@wcauchois @q7777777hk Thanks for reporting, will close due to short of feedback, feel free to reopen with more details. Thanks.