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

BT_GATT is crashing if gattServer didn't reply for notification subsctiption. (IDFGH-1077) #3398

Closed elf128 closed 4 years ago

elf128 commented 5 years ago

Environment

Problem Description

Seems like I accidentaly found a bug in BT_APPL. I have to mention that it caused by unexpected behaviour of remote device, but nevertheless it should not cause the crash.

I have two esp32 chip talking to each other over GATT. One act as a Client and another act as Server. Server advertise several attributes and some of them support notifications. When Client discover attributes with notification support it tries to subscribe for notifications. In my case, After discover of coresponding character descriptor it issue following command to register notification.

esp_ble_gattc_write_char_descr( gattc_if,
                                conn_id,
                                descr_elem_result[0].handle,
                                sizeof(notify_en),
                                (uint8_t *)&notify_en,
                                ESP_GATT_WRITE_TYPE_RSP,
                                ESP_GATT_AUTH_REQ_NONE);

On Server side, I'm getting GATT_WRITE_EVT. This one is taking care of subscription requests, and send confirmation back using:

esp_ble_gatts_send_response(gatts_if, 
                param->write.conn_id, 
                param->write.trans_id,
                status, 
                NULL);

This in turn cause ESP_GATTC_WRITE_DESCR_EVT on Client side. At this point, Client know whether write command succeed or failed.

This sequence was working pretty well across couple of month of development using diferent versions of IDF and xtensa. Until today. I made a mistake in servers code, such as it ignore incoming 2 bytes from Client and simply doen't send response back. Meanwhile Client just keep waiting for conection. It's alive and kicking. After a while, since client wait for response timeout triggers and instead of WRITE_DESCR_EVT with error Client bruttaly crash in BT_APPL

W (35049) BT_GATT: gatt_rsp_timeout disconnecting...
W (35051) BT_APPL: bta_gattc_conn_cback() - cif=3 connected=0 conn_id=3 reason=0x0016
E (35055) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35059) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35066) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35073) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35079) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.
Core 0 register dump:
PC      : 0x40091259  PS      : 0x00060333  A0      : 0x80090a4e  A1      : 0x3ffdf0f0  
0x40091259: uxListRemove at /home/vlad/usr/esp-idf-master/components/freertos/list.c:214

A2      : 0x3ffdf168  A3      : 0x00000001  A4      : 0x00060520  A5      : 0x00000001  
A6      : 0x00060320  A7      : 0x00000002  A8      : 0x00000001  A9      : 0x00060b20  
A10     : 0x00000004  A11     : 0x00000000  A12     : 0x00060520  A13     : 0x00000001  
A14     : 0x00060323  A15     : 0x00000024  SAR     : 0x00000010  EXCCAUSE: 0x0000001d  
EXCVADDR: 0x0000000c  LBEG    : 0x4000c28c  LEND    : 0x4000c296  LCOUNT  : 0x00000000  

ELF file SHA256: 7bafb8262a8744c51c4bc78965e93d0dc59787c5b51daced8ec7118ccdd3821b

Backtrace: 0x40091259:0x3ffdf0f0 0x40090a4b:0x3ffdf110 0x4008e70a:0x3ffdf130 0x4008eb50:0x3ffdf150 0x4008eca1:0x3ffdf190 0x4008533a:0x3ffdf1b0 0x4008540d:0x3ffdf1e0 0x4000be85:0x3ffdf200 0x40001e32:0x3ffdf220 0x40001e8a:0x3ffdf240 0x400e5333:0x3ffdf260 0x40085125:0x3ffdf290 0x401010f1:0x3ffdf2e0 0x4011477f:0x3ffdf310 0x40111e02:0x3ffdf5a0 0x40113871:0x3ffdf5c0 0x40114792:0x3ffdf850 0x40111e02:0x3ffdfae0 0x40113871:0x3ffdfb00 0x40114792:0x3ffdfd90 0x40111e02:0x3ffe0020 0x40113871:0x3ffe0040 0x40114792:0x3ffe02d0 0x40111e02:0x3ffe0560 0x40113871:0x3ffe0580 0x40114792:0x3ffe0810 0x40111e02:0x3ffe0aa0 0x40113871:0x3ffe0ac0 0x40114792:0x3ffe0d50 0x40111e02:0x3ffe0fe0 0x40113871:0x3ffe1000 0x40114a01:0x3ffe1290 0x40114bb7:0x3ffe1520 0x40111e02:0x3ffe1550 0x40111f65:0x3ffe1570 0x40116216:0x3ffe1590 0x400fc622:0x3ffe15b0 0x4008f0c9:0x3ffe15e0
0x40091259: uxListRemove at /home/vlad/usr/esp-idf-master/components/freertos/list.c:214
0x40090a4b: xTaskPriorityDisinherit at /home/vlad/usr/esp-idf-master/components/freertos/tasks.c:4145
0x4008e70a: prvCopyDataToQueue at /home/vlad/usr/esp-idf-master/components/freertos/queue.c:1882
0x4008eb50: xQueueGenericSend at /home/vlad/usr/esp-idf-master/components/freertos/queue.c:749
0x4008eca1: xQueueGiveMutexRecursive at /home/vlad/usr/esp-idf-master/components/freertos/queue.c:590
0x4008533a: lock_release_generic at /home/vlad/usr/esp-idf-master/components/newlib/locks.c:205
0x4008540d: _lock_release_recursive at /home/vlad/usr/esp-idf-master/components/newlib/locks.c:217
0x400e5333: vprintf at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vprintf.c:38 (discriminator 2)
0x40085125: esp_log_write at /home/vlad/usr/esp-idf-master/components/log/log.c:215
0x401010f1: GATTC_Write at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/stack/gatt/gatt_api.c:1009 (discriminator 1)
0x4011477f: bta_gattc_write at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1168
0x40111e02: bta_gattc_sm_execute at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_main.c:292
0x40113871: bta_gattc_pop_command_to_send at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1524
0x40114792: bta_gattc_write at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1175
0x40111e02: bta_gattc_sm_execute at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_main.c:292
0x40113871: bta_gattc_pop_command_to_send at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1524
0x40114792: bta_gattc_write at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1175
0x40111e02: bta_gattc_sm_execute at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_main.c:292
0x40113871: bta_gattc_pop_command_to_send at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1524
0x40114792: bta_gattc_write at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1175
0x40111e02: bta_gattc_sm_execute at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_main.c:292
0x40113871: bta_gattc_pop_command_to_send at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1524
0x40114792: bta_gattc_write at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1175
0x40111e02: bta_gattc_sm_execute at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_main.c:292
0x40113871: bta_gattc_pop_command_to_send at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1524
0x40114792: bta_gattc_write at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1175
0x40111e02: bta_gattc_sm_execute at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_main.c:292
0x40113871: bta_gattc_pop_command_to_send at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1524
0x40114a01: bta_gattc_write_cmpl at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1307
0x40114bb7: bta_gattc_op_cmpl at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_act.c:1428
0x40111e02: bta_gattc_sm_execute at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_main.c:292
0x40111f65: bta_gattc_hdl_event at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/gatt/bta_gattc_main.c:404
0x40116216: bta_sys_event at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/bta/sys/bta_sys_main.c:496
0x400fc622: btu_task_thread_handler at /home/vlad/usr/esp-idf-master/components/bt/bluedroid/stack/btu/btu_task.c:233
0x4008f0c9: vPortTaskWrapper at /home/vlad/usr/esp-idf-master/components/freertos/port.c:143
Rebooting...
elf128 commented 5 years ago

Oh, I forgot to add. In this particular case there was 10 characteristics available on Server and 3 of them support notifications. So Client issue esp_ble_gattc_write_char_descr three times: Here is log prior the crash:

I (3586) APP: Start connection for profile[ 0 ]...
I (3586) GATTC_PROFILE: connect to the remote device.
W (3733) BT_L2CAP: l2cble_start_conn_update, the last connection update command still pending.
I (3737) GATTC_PROFILE: CONNECT conn_id 0, if 3
I (3738) GATTC_PROFILE: REMOTE BDA: 30:AE:A4:01:1E:0A
I (3742) GATTC_PROFILE: open success
I (4083) gattC_Base: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 32,latency = 0, timeout = 500
I (4525) gattC_Base: update connetion params status = 0, min_int = 6, max_int = 6,conn_int = 6,latency = 0, timeout = 600
I (4810) GATTC_PROFILE: ESP_GATTC_CFG_MTU_EVT, Status 0, MTU 517, conn_id 0
I (4811) GATTC_PROFILE: ESP_GATTC_SEARCH_RES_EVT
I (4812) GATTC_PROFILE: service found
I (4817) GATTC_PROFILE: UUID16: ff
I (4822) GATTC_PROFILE: Profile search_complete.
I (4826) GATTC_PROFILE: Initialise gatt data.
I (4831) GATTC_PROFILE: Found 10 characteristics.
I (4837) GATTC_PROFILE: Found one characteristic for uuid:ff01.
I (4843) GATTC_PROFILE: Registering notification
I (4849) GATTC_PROFILE: Found one characteristic for uuid:ff02.
I (4855) GATTC_PROFILE: No notification support
I (4860) GATTC_PROFILE: Found one characteristic for uuid:ff03.
I (4867) GATTC_PROFILE: No notification support
I (4872) GATTC_PROFILE: Found one characteristic for uuid:ff04.
I (4879) GATTC_PROFILE: No notification support
I (4884) GATTC_PROFILE: Found one characteristic for uuid:ff0b.
I (4891) GATTC_PROFILE: No notification support
I (4896) GATTC_PROFILE: Found one characteristic for uuid:ff0c.
I (4902) GATTC_PROFILE: No notification support
I (4908) GATTC_PROFILE: Found one characteristic for uuid:ff07.
I (4914) GATTC_PROFILE: Registering notification
I (4920) GATTC_PROFILE: Found one characteristic for uuid:ff08.
I (4926) GATTC_PROFILE: Registering notification
I (4932) GATTC_PROFILE: Found one characteristic for uuid:ff09.
I (4938) GATTC_PROFILE: No notification support
I (4943) GATTC_PROFILE: Found one characteristic for uuid:ff0a.
I (4950) GATTC_PROFILE: No notification support
I (4955) GATTC_PROFILE: No more characteristics.....  Waiting for 3 registartions.
I (4963) GATTC_PROFILE: ESP_GATTC_REG_FOR_NOTIFY_EVT. Waiting for 2 events at the moment
I (4972) GATTC_PROFILE: Found descriptor with handle 002b for char's handle 002a
I (4980) GATTC_PROFILE: Waiting for 3 events.
I (4985) gattC_Base: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 32,latency = 0, timeout = 500
I (4997) GATTC_PROFILE: ESP_GATTC_REG_FOR_NOTIFY_EVT. Waiting for 2 events at the moment
I (5006) GATTC_PROFILE: Found descriptor with handle 003d for char's handle 003c
I (5014) GATTC_PROFILE: Waiting for 3 events.
I (5019) GATTC_PROFILE: ESP_GATTC_REG_FOR_NOTIFY_EVT. Waiting for 2 events at the moment
I (5028) GATTC_PROFILE: Found descriptor with handle 0040 for char's handle 003f
I (5036) GATTC_PROFILE: Waiting for 3 events.
I (29588) APP: Connection Failure
W (35043) BT_GATT: gatt_rsp_timeout disconnecting...
W (35045) BT_APPL: bta_gattc_conn_cback() - cif=3 connected=0 conn_id=3 reason=0x0016
E (35048) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35053) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35060) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35066) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35073) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.
chegewara commented 5 years ago

It seems to be problem in your code. Before you are trying to read/write characteristic or descriptor you should check if you are still connected. Here you have log that you failed to connect: I (29588) APP: Connection Failure and following logs shows you still trying to perform write operation:

E (35048) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35053) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35060) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35066) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35073) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,

Same here:

W (35049) BT_GATT: gatt_rsp_timeout disconnecting...
W (35051) BT_APPL: bta_gattc_conn_cback() - cif=3 connected=0 conn_id=3 reason=0x0016
E (35055) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35059) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35066) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35073) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
E (35079) BT_GATT: GATT_Write Illegal param: conn_id 3, type 02,
elf128 commented 5 years ago

Please don't get confused by that line.

I (29588) APP: Connection Failure

Feel free to ignore this line. It's for UI. Log line you are referring send by my code. It doesn't come from GATT. It's based on 25 sec timeout of current operation. All INFO logs send by my code and has nothing to do with ESP-IDF. Request have been sent at 4980. 30 seconds later at 35049 GATT has his internal timeout triggered and it SHOULD call WRITE_DESCR_EVT with error flag set.

That's what it does in v3.1.2, but master is crashing.

Weijian-Espressif commented 5 years ago

@elf128 Sorry, I can't reproduce this issue, here is the log:

I (304) phy: phy_version: 4100, 2a5dd04, Jan 23 2019, 21:00:07, 0, 0
I (654) GATTC_DEMO: REG_EVT
I (664) GATTC_DEMO: scan start success
I (804) GATTC_DEMO: searched device ESP_GATTS_DEMO

I (804) GATTC_DEMO: connect to the remote device.
I (814) GATTC_DEMO: stop scan successfully
I (944) GATTC_DEMO: ESP_GATTC_CONNECT_EVT conn_id 0, if 4
I (944) GATTC_DEMO: REMOTE BDA:
I (944) GATTC_DEMO: 30 ae a4 80 59 22 
I (944) GATTC_DEMO: open success
I (1144) GATTC_DEMO: update connection params status = 0, min_int = 16, max_int = 32,conn_int = 32,latency = 0, timeout = 400
I (2274) GATTC_DEMO: discover service complete conn_id 0
I (2274) GATTC_DEMO: SEARCH RES: conn_id = 0 is primary service 1
I (2274) GATTC_DEMO: start handle 40 end handle 43 current handle value 40
I (2284) GATTC_DEMO: service found
I (2284) GATTC_DEMO: UUID16: ff
I (2284) GATTC_DEMO: Get service information from remote device
I (2294) GATTC_DEMO: ESP_GATTC_SEARCH_CMPL_EVT
I (2304) GATTC_DEMO: ESP_GATTC_REG_FOR_NOTIFY_EVT
I (2354) GATTC_DEMO: ESP_GATTC_CFG_MTU_EVT, Status 0, MTU 500, conn_id 0
W (32424) BT_GATT: gatt_rsp_timeout disconnecting...
W (32434) BT_APPL: bta_gattc_conn_cback() - cif=3 connected=0 conn_id=3 reason=0x0016
W (32434) BT_APPL: bta_gattc_conn_cback() - cif=4 connected=0 conn_id=4 reason=0x0016
E (32444) GATTC_DEMO: write descr failed, error status = 85
I (32444) GATTC_DEMO: ===ESP_GATTC_DISCONNECT_EVT, reason = 22
elf128 commented 5 years ago
  1. Did you patch GATTS_DEMO as well?
  2. Are you using gcc8.2?
  3. Can you, please, give me revision number of both esp_idf and xtensa you're compiling it with, so I can confirm it on my side as well. There is a chance it's been fixed already.

Thank you.

Weijian-Espressif commented 5 years ago
elf128 commented 5 years ago

Well, that's the thing. crosstool-ng-1.22 is based on gcc 5.2 I'm using crosstool-NG esp32-2018r1) 8.2.0 AFAIK it's 1.23.xxx

Weijian-Espressif commented 5 years ago

@elf128, How do you know that it is caused by gcc ?

Alvin1Zhang commented 5 years ago

@elf128 Hi, thanks for reporting the issue. Would you help share if any updates for the issue? Thanks.

Alvin1Zhang commented 5 years ago

@elf128 Hi, thanks for reporting the issue. Would you help share if any updates for the issue? Thanks.

Alvin1Zhang commented 4 years ago

@elf128 Thanks for reporting. Will close due to not enough feedback and details, feel free to reopen with more details. Thanks.