mynewt-nimble
mynewt-nimble copied to clipboard
apache
Crash when restoring bonding
Setup
Phone: iPhone Xs iOS version: 14.1 Phone app: nRF Connect Target: ESP32 (NINA-W106) IDF: version 4.3 nimble-idf branch: latest nimble-1.3.0-idf branch
Description
I want to be able to bond with both Android and iPhone devices. As iPhones in particular have RPA addresses, I enabled privacy using guidelines from here.
Expected behavior
The stack should be able to resolve RPA addresses. After initially bonding the phone with the ESP32, no other pairing/bonding requests should be requested when reconnecting or during the active connection.
Problem Description
After initially bonding the iPhone with the target, the connection is stable and the bonding works. After reconnecting once or several times (the issue is not consistent), without clearing any bonding information, the board crashes and gets reset. In order to be able to reconnect again, the bonding information from the phone has to be deleted first.
Usually, after the crash, the phone manages to restore bonding, but sometimes it resets forever trying to connect. This behavior is only on the iPhone, my Android device, which uses a public address, does not trigger the crash.
I managed to reproduce the problem using the bleprph example. I have only added RPA address resolution to that example and increased the number of stored CCCD from 8 to 32. I have attached the project files:
Steps to reproduce
- Connect the iPhone to the ESP32 using the nRF Connect app.
- Read the encrypted characteristic so that pairing is requested.
- After pairing is done, disconnect.
- Try to reconnect several times until the error/crash appears.
Logs
-
I noticed that
ble_hs_util_ensure_addr()does not always succeed in ensuring a random (1) address and sets a public one instead. -
The crash description is shown below:
I (2653) NimBLE: GAP procedure initiated: advertise; I (2653) NimBLE: disc_mode=2 I (2653) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0 I (2663) NimBLE: D (2673) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0006 len=15 D (2673) NimBLE: 0x06 D (2683) NimBLE: 0x20 D (2683) NimBLE: 0x0f D (2683) NimBLE: 0x30 D (2683) NimBLE: 0x00 D (2693) NimBLE: 0x60 D (2693) NimBLE: 0x00 D (2693) NimBLE: 0x00 D (2693) NimBLE: 0x01 D (2703) NimBLE: 0x00 D (2703) NimBLE: 0x00 D (2703) NimBLE: 0x00 D (2703) NimBLE: 0x00 D (2703) NimBLE: 0x00 D (2713) NimBLE: 0x00 D (2713) NimBLE: 0x00 D (2713) NimBLE: 0x07 D (2713) NimBLE: 0x00 D (2723) NimBLE: D (2723) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000a len=1 D (2733) NimBLE: 0x0a D (2733) NimBLE: 0x20 D (2733) NimBLE: 0x01 D (2733) NimBLE: 0x01 D (2733) NimBLE: D (11483) NimBLE: 0x9c D (11483) NimBLE: 0x88 D (11483) NimBLE: 0x77 D (11483) NimBLE: 0x5b D (11493) NimBLE: 0x7e D (11493) NimBLE: 0x67 D (11493) NimBLE: I (11503) NimBLE: connection established; status=0 D (11513) NimBLE: Revised our id addr: D (11523) NimBLE: 0x9a D (11523) NimBLE: 0x5b D (11523) NimBLE: 0x47 D (11523) NimBLE: 0xc0 D (11533) NimBLE: 0xa7 D (11533) NimBLE: 0x70 D (11533) NimBLE: I (11543) NimBLE: handle=0 our_ota_addr_type=1 our_ota_addr= I (11553) NimBLE: 70:a7:c0:47:5b:9a I (11553) NimBLE: our_id_addr_type=0 our_id_addr= I (11563) NimBLE: 7c:9e:bd:c9:68:5e I (11563) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (11573) NimBLE: 50:7a:c5:5f:c3:38 I (11573) NimBLE: peer_id_addr_type=0 peer_id_addr= I (11583) NimBLE: 50:7a:c5:5f:c3:38 I (11583) NimBLE: conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0 I (11593) NimBLE: D (11593) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0016 len=2 D (11603) NimBLE: 0x16 D (11603) NimBLE: 0x20 D (11613) NimBLE: 0x02 D (11613) NimBLE: 0x00 D (11613) NimBLE: 0x00 D (11613) NimBLE: D (13623) NimBLE: Revised our id addr: D (13623) NimBLE: 0x9a D (13623) NimBLE: 0x5b D (13633) NimBLE: 0x47 D (13633) NimBLE: 0xc0 D (13633) NimBLE: 0xa7 D (13633) NimBLE: 0x70 D (13643) NimBLE: D (13643) NimBLE: looking up our sec; D (13653) NimBLE: peer_addr_type=0 peer_addr= D (13653) NimBLE: 0x38 D (13653) NimBLE: 0xc3 D (13663) NimBLE: 0x5f D (13663) NimBLE: 0xc5 D (13663) NimBLE: 0x7a D (13663) NimBLE: 0x50 D (13673) NimBLE: D (13673) NimBLE: ediv=0x00 rand=0x0 D (13673) NimBLE: D (13683) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x001a len=18 D (13693) NimBLE: 0x1a D (13693) NimBLE: 0x20 D (13693) NimBLE: 0x12 D (13703) NimBLE: 0x00 D (13703) NimBLE: 0x00 D (13703) NimBLE: 0x98 D (13703) NimBLE: 0x54 D (13713) NimBLE: 0xa7 D (13713) NimBLE: 0xbd D (13713) NimBLE: 0xb8 D (13713) NimBLE: 0xd2 D (13723) NimBLE: 0x80 D (13723) NimBLE: 0x1a D (13723) NimBLE: 0x31 D (13723) NimBLE: 0x3e D (13733) NimBLE: 0x7d D (13733) NimBLE: 0xc7 D (13733) NimBLE: 0x58 D (13733) NimBLE: 0x2e D (13743) NimBLE: 0x8b D (13743) NimBLE: 0x69 D (13743) NimBLE: D (13763) NimBLE: Revised our id addr: D (13763) NimBLE: 0x9a D (13763) NimBLE: 0x5b D (13763) NimBLE: 0x47 D (13773) NimBLE: 0xc0 D (13773) NimBLE: 0xa7 D (13773) NimBLE: 0x70 D (13783) NimBLE: I (13783) NimBLE: encryption change event; status=7 D (13803) NimBLE: Revised our id addr: D (13813) NimBLE: 0x9a D (13813) NimBLE: 0x5b D (13813) NimBLE: 0x47 D (13813) NimBLE: 0xc0 D (13823) NimBLE: 0xa7 D (13823) NimBLE: 0x70 D (13823) NimBLE: I (13833) NimBLE: handle=0 our_ota_addr_type=1 our_ota_addr= I (13843) NimBLE: 70:a7:c0:47:5b:9a I (13843) NimBLE: our_id_addr_type=0 our_id_addr= I (13853) NimBLE: 7c:9e:bd:c9:68:5e I (13853) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (13863) NimBLE: 50:7a:c5:5f:c3:38 I (13863) NimBLE: peer_id_addr_type=0 peer_id_addr= I (13873) NimBLE: 50:7a:c5:5f:c3:38 I (13873) NimBLE: conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0 I (13883) NimBLE: I (13883) NimBLE: disconnect; reason=19 I (13893) NimBLE: handle=0 our_ota_addr_type=1 our_ota_addr= I (13903) NimBLE: 70:a7:c0:47:5b:9a I (13903) NimBLE: our_id_addr_type=0 our_id_addr= I (13913) NimBLE: 7c:9e:bd:c9:68:5e I (13913) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (13923) NimBLE: 50:7a:c5:5f:c3:38 I (13923) NimBLE: peer_id_addr_type=0 peer_id_addr= I (13923) NimBLE: 50:7a:c5:5f:c3:38 I (13933) NimBLE: conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0 I (13943) NimBLE: E (13943) NimBLE: error setting advertisement data; rc=22 E (13953) NimBLE: Resetting state; reason=19 D (13953) NimBLE: ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0003 len=0 D (13963) NimBLE: 0x03 D (13963) NimBLE: 0x0c D (13973) NimBLE: 0x00 D (13973) NimBLE: Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled. Core 0 register dump: PC : 0x400e1e21 PS : 0x00060930 A0 : 0x800e1fdd A1 : 0x3ffca880 0x400e1e21: ble_hs_hci_process_ack at C:/Users/my_account/esp2/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_hci.c:213 A2 : 0x00000c03 A3 : 0x00000000 A4 : 0x00000000 A5 : 0x3ffca8a0 A6 : 0x3ffc2514 A7 : 0x3ffca760 A8 : 0x800e1e1c A9 : 0x3ffca870 A10 : 0x00000000 A11 : 0x00000000 A12 : 0x00000010 A13 : 0x3ffca8b0 A14 : 0x3ffb6149 A15 : 0x00000001 SAR : 0x00000019 EXCCAUSE: 0x0000001c EXCVADDR: 0x00000000 LBEG : 0x4000c46c LEND : 0x4000c477 LCOUNT : 0x00000000 Backtrace:0x400e1e1e:0x3ffca880 0x400e1fda:0x3ffca8a0 0x400dd705:0x3ffca8d0 0x400dd8c7:0x3ffca8f0 0x400da77c:0x3ffca910 0x400da7fe:0x3ffca930 0x400da80b:0x3ffca950 0x400e4246:0x3ffca970 0x400d77c6:0x3ffca990 0x40093b7d:0x3ffca9b0 0x400e1e1e: ble_hs_hci_process_ack at C:/Users/my_account/esp2/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_hci.c:213 0x400e1fda: ble_hs_hci_cmd_tx at C:/Users/my_account/esp2/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_hci.c:315 0x400dd705: ble_hs_startup_reset_tx at C:/Users/my_account/esp2/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_startup.c:301 0x400dd8c7: ble_hs_startup_go at C:/Users/my_account/esp2/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_startup.c:311 0x400da77c: ble_hs_sync at C:/Users/my_account/esp2/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:345 0x400da7fe: ble_hs_reset at C:/Users/my_account/esp2/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:400 0x400da80b: ble_hs_event_reset at C:/Users/my_account/esp2/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:538 0x400e4246: ble_npl_event_run at C:\Users\my_account\esp2\esp-idf\examples\bluetooth\nimble\bleprph\build/../../../../../components/bt/host/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:125 (inlined by) nimble_port_run at C:/Users/my_account/esp2/esp-idf/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:78 0x400d77c6: bleprph_host_task at C:\Users\my_account\esp2\esp-idf\examples\bluetooth\nimble\bleprph\build/../main/main.c:345 0x40093b7d: vPortTaskWrapper at C:/Users/my_account/esp2/esp-idf/components/freertos/port/xtensa/port.c:168 -
Occasionally, I don't get a crash, but I get this instead:
I (54627) NimBLE: connection established; status=0 I (54647) NimBLE: handle=0 our_ota_addr_type=1 our_ota_addr= I (54647) NimBLE: 75:23:dd:67:ec:80 I (54657) NimBLE: our_id_addr_type=1 our_id_addr= I (54657) NimBLE: 75:23:dd:67:ec:80 I (54667) NimBLE: peer_ota_addr_type=1 peer_ota_addr= I (54667) NimBLE: 49:e8:84:9d:a6:00 I (54677) NimBLE: peer_id_addr_type=1 peer_id_addr= I (54677) NimBLE: 49:e8:84:9d:a6:00 I (54687) NimBLE: conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0 I (56717) NimBLE: disconnect; reason=19 I (56717) NimBLE: handle=0 our_ota_addr_type=1 our_ota_addr= I (56727) NimBLE: 75:23:dd:67:ec:80 I (56727) NimBLE: our_id_addr_type=1 our_id_addr= I (56737) NimBLE: 75:23:dd:67:ec:80 I (56737) NimBLE: peer_ota_addr_type=1 peer_ota_addr= I (56747) NimBLE: 49:e8:84:9d:a6:00 I (56747) NimBLE: peer_id_addr_type=1 peer_id_addr= I (56757) NimBLE: 49:e8:84:9d:a6:00 I (56757) NimBLE: conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0 I (56767) NimBLE: E (56777) NimBLE: error setting advertisement data; rc=22 E (56777) NimBLE: Resetting state; reason=19 E (56817) NimBLE: failed to configure restored IRK
Please let me know if you need additional information.
The crash described at point 2 was caused by the Debug logs. Lowering the log level to Info fixed the bug. However, I still get the error with the IRK key described on point number 3 and the message "Peer removed pairing information".
Another problem is that some phones are not able to detect the ESP32 with RPA resolution active, while advertising. The solution is to disable and then reenable the Bluetooth on the phone regularly. Any ideas on this regard?
I have seen a similar issue. If the peer_dev_rec table is full, the ESP device can't resolve the remote device's random address into an identity address, which it needs to retrieve the keys for the bonded peer. This table in NVS does not get cleared by ble_store_clear. It is cleared by ble_rpa_peer_dev_rec_clear_all but this is a static function.
Hi, this seems to still be an issue. I can confirm this issue also occurs between an ESP32 and a MacBook Pro. I was also able to suppress the issue by eliminating logging that occurs in the callback function passed to ble_gap_adv_start. This would suggest to me a possible race condition?
