Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Crash when restoring bonding #1052

Open
flonas955 opened this issue Oct 13, 2021 · 5 comments
Open

Crash when restoring bonding #1052

flonas955 opened this issue Oct 13, 2021 · 5 comments

Comments

@flonas955
Copy link

flonas955 commented Oct 13, 2021 •
edited

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:

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.
@flonas955 flonas955 mentioned this issue Oct 13, 2021
Open
@flonas955
Copy link
Author

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".

@flonas955
Copy link
Author

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?

@stevegrau-ayla
Copy link

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.

@flonas955 flonas955 mentioned this issue Nov 19, 2021
Closed
@mgagic
Copy link

mgagic commented Jun 22, 2022

Hi @flonas955, any luck with this? I think I'm facing the exact same issue.

@stephenglynch
Copy link

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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@stephenglynch @stevegrau-ayla @flonas955 @mgagic