Crash when restoring bonding
- Dominant language
- C
- Stars
- 893
- Forks
- 512
- Avg merge
- 13d 31m
- Merged PRs (30d)
- 7
Description
### 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](https://github.com/espressif/esp-nimble/tree/nimble-1.3.0-idf)
### 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](https://github.com/espressif/esp-nimble/issues/8).
### 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](https://github.com/espressif/esp-idf/tree/master/examples/bluetooth/nimble/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:
[bleprph.zip](https://github.com/apache/mynewt-nimble/files/7337616/bleprph.zip)
### Steps to reproduce
1. Connect the iPhone to the ESP32 using the nRF Connect app.
2. Read the encrypted characteristic so that pairing is requested.
3. After pairing is done, disconnect.
4. Try to reconnect several times until the error/crash appears.
### Logs
1. I noticed that `ble_hs_util_ensure_addr()` does not always succeed in ensuring a random (1) address and sets a public one instead.
2. 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
3. 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.
Contributor guide
No contributing guide indexed for this repository
Research direction
Start with ble_hs_util_ensure_addr() and the crash location at nimble/host/src/ble_hs_hci.c:213, then trace the reset path through ble_hs_startup.c. Reproduce with the attached bleprph project by bonding and reconnecting an iPhone with RPA resolution enabled. Done means repeated reconnects no longer crash or fail to configure the restored IRK.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- c
- Domain
- embedded-iot, networking
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100