Connectivity issues with HID example

[i_4556]

Hello and thanks for reading. Also happy holidays.

We are using an NRF5340, and are having some issues with connectivity. I would therefore welcome any suggestions you may have. We are using Zephyr SDK 2.5.0, and a windows 11 laptop.

Our product, among other functions, acts as a wireless mouse via HID over GATT. With most of the laptops we have tested with, everything works well. We have one laptop however where there are persistent and debilitating connectivity issues.

After much head-scratching, and wanting to isolate the problem, we decided to test with an nrf5340DK, and the Nordic example code for an HID mouse. The only change we made was adding a call to

bt_unpair(BT_ID_DEFAULT,NULL);

in the disconnected function, as the problem occurs when we try to reconnect after the laptop forgets the device.

The problem persists, which is why I am now turning to you for any suggestions you may have.

The problem manifests like this: we start with a freshly booted laptop, and a newly programmed device. We connect to the device from windows, and it works perfectly. We then go to the laptop bluetooth settings and select "delete device" (forget this device on older versions of windows). The device disappears as expected, but from here on the bug occurs and although we can see the device if we then scan for it, we can almost never reconnect. When the issue occurs, we never get to the stage where the laptop asks us to enter the pin; we simply get the please try again error message. Power cycling the device will not fix the issue, although power cycling the laptop will, as will sometimes reprogramming the device.

I have included below the log from the serial port: As you can see, I connect successfully, then am unable to connect, then connect successfully, then have multiple failed attempts.

*** Booting nRF Connect SDK v2.5.0 ***
[00:00:00.416,900] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.416,900] <inf> fs_nvs: alloc wra: 0, fe8
[00:00:00.416,900] <inf> fs_nvs: data wra: 0, 0
Bluetooth authentication callbacks registered.
[00:00:00.438,507] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.438,537] <inf> bt_hci_core: HW Variant: nRF53x (0x0003)
[00:00:00.438,568] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 197.47763 Build 2370639017
[00:00:00.439,361] <inf> bt_hci_core: No ID address. App must call settings_load()
Bluetooth initialized
[00:00:00.440,246] <inf> bt_hci_core: Identity: DE:C1:62:6E:0C:34 (random)
[00:00:00.440,277] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x2102, manufacturer 0x0059
[00:00:00.440,307] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0x2102
Advertising successfully started
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 168782
Security changed: 00:D4:9E:B3:49:E3 (public) level 4
[00:02:18.406,524] <inf> bas: BAS Notifications enabled
[00:02:41.837,036] <inf> bas: BAS Notifications disabled
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x13)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 436605
[00:02:58.307,434] <wrn> bt_smp: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 064518
Security changed: 00:D4:9E:B3:49:E3 (public) level 4
[00:03:29.822,479] <inf> bas: BAS Notifications enabled
[00:03:50.867,980] <inf> bas: BAS Notifications disabled
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x13)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 739262
[00:04:01.985,992] <wrn> bt_hci_core: Not reporting packet for non-connected conn
[00:04:01.986,083] <wrn> bt_smp: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 330312
[00:04:20.478,424] <wrn> bt_smp: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x2a)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 324202
[00:04:47.343,658] <wrn> bt_smp: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 150110
Security changed: 00:D4:9E:B3:49:E3 (public) level 4
[00:05:18.078,643] <inf> bas: BAS Notifications enabled
[00:05:30.588,897] <inf> bas: BAS Notifications disabled
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x13)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 523576
[00:05:52.819,366] <wrn> bt_smp: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 727059
[00:06:14.644,531] <wrn> bt_smp: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 440553
[00:06:18.379,547] <wrn> bt_smp: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 003510
[00:06:32.779,724] <wrn> bt_smp: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x2a)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 642024
[00:06:35.974,700] <wrn> bt_smp: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 698805
[00:06:51.319,854] <wrn> bt_smp: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x2a)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 236151
[00:07:04.414,916] <wrn> bt_smp: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 533490
[00:07:10.714,965] <wrn> bt_smp: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)

I do also have several NRF52840 dongles, and can use one to sniff the packets if you think that would be usefull.

Thank you for all your time!

[Hung Bui]

Hi, 
Please try to capture the communication with the sniffer dongle. I think it will be very useful. We have a guide on how to use the sniffer here. 

What I can see from this log: 

Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 698805
[00:06:51.319,854] <wrn> bt_smp: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x2a)

Is that the connection actually established. The issue was with the pairing. Security failed with error 9 (BT_SECURITY_ERR_UNSPECIFIED). I would guess that for some reason the central didn't want to do a normal passkey pairing but maybe try to use the bond information it stored earlier (even though you removed the device on PC)

After the issue happen, how did you recover the board so that it can be pair with the laptop again ? Or it's not possible and you need to test with a new board ? 

[i_4556]

Hello, here is the sniffer and console logs:

. @@*** Booting nRF Connect SDK v2.5.0 ***
[00:00:00.358,245] <inf> fs_nvs: nvs_mount: 2 Sectors of 4096 bytes
[00:00:00.358,245] <inf> fs_nvs: nvs_mount: alloc wra: 0, ed0
[00:00:00.358,276] <inf> fs_nvs: nvs_mount: data wra: 0, 1e4
Bluetooth authentication callbacks registered.
[00:00:00.380,523] <inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.380,554] <inf> bt_hci_core: hci_vs_init: HW Variant: nRF53x (0x0003)
[00:00:00.380,584] <inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 197.47763 Build 2370639017
[00:00:00.381,347] <inf> bt_hci_core: bt_init: No ID address. App must call settings_load()
Bluetooth initialized
[00:00:00.383,026] <inf> bt_hci_core: bt_dev_show_info: Identity: DE:C1:62:6E:0C:34 (random)
[00:00:00.383,056] <inf> bt_hci_core: bt_dev_show_info: HCI: version 5.4 (0x0d) revision 0x2102, manufacturer 0x0059
[00:00:00.383,056] <inf> bt_hci_core: bt_dev_show_info: LMP: version 5.4 (0x0d) subver 0x2102
Advertising successfully started
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 176302
Security changed: 00:D4:9E:B3:49:E3 (public) level 4
[00:00:39.348,266] <inf> bt_keys: bt_keys_show_sniffer_info: SC LTK: 0x51bcfd25fa1d44a8f14c6fc9870abb72
[00:00:40.441,894] <inf> bas: blvl_ccc_cfg_changed: BAS Notifications enabled
[00:00:52.262,207] <inf> bas: blvl_ccc_cfg_changed: BAS Notifications disabled
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x13)
Connected 00:D4:9E:B3:49:E3 (public)
[00:01:08.181,121] <wrn> bt_smp: smp_pairing_complete: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x13)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 172417
[00:01:12.774,047] <wrn> bt_hci_core: bt_hci_host_num_completed_packets: Not reporting packet for non-connected conn
[00:01:12.774,139] <wrn> bt_smp: smp_pairing_complete: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 541176
[00:01:21.422,607] <wrn> bt_smp: smp_pairing_complete: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)

NRF trace laptop not working.pcapng

[Hung Bui]

Hi, 

Could you clarify if the trace is recorded with the nRF53 running the default peripheral_hids_mouse ? 
What I can see from the trace is that the peripheral tried to request pairing. This is not so common as usually the peripheral should not request pairing and let the central to connect, discovery service, try to read characteristics and then start request pairing (after the read get rejected due to security level) 
You can see here how it look when I test with the default peripheral_hids_mouse: 

The peripheral doesn't send a Security request at the beginning like in your trace: 

Could you capture a full trace where it was first managed to bond and then after deleting it not able to reconnect ? 

Please also try to capture the same trace with a "good" laptop so we can compare. 

[i_4556]

Hello and thanks for your time!

This trace is recorded with the default example, the only change being the addition of a call to bt_unpair(...) in the disconnected callback.

The trace shows an initial successful connection, and then several failed attempts to reconnect.

I will get you a trace with a known good laptop later today, thank you for your help.

[i_4556]

Hello and Happy Holidays!

Here is the sniffer capture and console from a known good laptop.

[00:00:00.410,034] <inf> bt_hci_core: bt_dev_show_info: Identity: DE:C1:62:6E:0C:34 (random)
[00:00:00.410,064] <inf> bt_hci_core: bt_dev_show_info: HCI: version 5.4 (0x0d) revision 0x2102, manufacturer 0x0059
[00:00:00.410,064] <inf> bt_hci_core: bt_dev_show_info: LMP: version 5.4 (0x0d) subver 0x2102
Advertising successfully started
Connected 20:79:18:5D:55:60 (public)
Passkey for 20:79:18:5D:55:60 (public): 143181
Security changed: 20:79:18:5D:55:60 (public) level 4
[00:08:01.815,155] <inf> bt_keys: bt_keys_show_sniffer_info: SC LTK: 0x60c85f82b5239cfc54be083c6b2dbad4
[00:08:03.302,734] <inf> bas: blvl_ccc_cfg_changed: BAS Notifications enabled
[00:08:34.184,295] <inf> bas: blvl_ccc_cfg_changed: BAS Notifications disabled
Disconnected from 20:79:18:5D:55:60 (public) (reason 0x13)
Connected 20:79:18:5D:55:60 (public)
Passkey for 20:79:18:5D:55:60 (public): 779519
Security changed: 20:79:18:5D:55:60 (public) level 4
[00:08:56.513,336] <inf> bt_keys: bt_keys_show_sniffer_info: SC LTK: 0x0993714a7b292eb0eabf48f600097cf3
[00:08:57.903,320] <inf> bas: blvl_ccc_cfg_changed: BAS Notifications enabled
[00:09:24.202,392] <inf> bas: blvl_ccc_cfg_changed: BAS Notifications disabled
Disconnected from 20:79:18:5D:55:60 (public) (reason 0x13)

good capture.pcapng

[Hung Bui]

Hi,

Sorry for late response. 

Thanks for the trace. From what I can see I suspect that the issue with the laptop was the collision of the PHY update. You can see this from the trace: 

The LL_PHY_REQ came after LL_PHY_UPDATE_IND which is very strange. Normally a central can send a PHY_REQ and then wait for PHY_RESpond then send PHY_UPDATE after that. 

Could you please capture another trace with the problematic laptop. Please make sure to capture the initial connection when everything works ( I assume the mouse works fine on the first connection). 
In the first trace you sent, I don't see them managed to finish the bonding process. 

[i_4556]

Hello,

Thank you for your reply; I hope you had a great holidays. I will get another capture for you today. In the interim, if the issue is a packet collision with the phy update request, should I test with the config for auto phy update set to N? (CONFIG_BT_AUTO_PHY_UPDATE=n)

[Hung Bui]

Hi, 
You can test with that. But then you need to implement the handler in the code to handle the PHY request. 
I think what you can also try is to add CONFIG_BT_CTLR_PHY_2M=n. But you need to add that into the firmware of the controller. Not the application. The controller is in ipc_radio or hci_rpmsg project for the netcore. 

[i_4556]

Hello and thank you for your patience. I have done some more testing, and the results are interesting.

When I added CONFIG_BT_CTLR_PHY_2M=n the problem seems to go away. This isnt ideal in the long term, as we do eventually want to use 2M phy for greater data bandwidth, but as a workaround for now this is fine.

I then commented out the change, rebooted the laptop, reflashed the nrf, and the problem returned.

I have attached a new set of logs, per your request. The first connection has success, the next few dont, I then seem to luck out and randomly get a good connection, but then have a few more consecutive failures.

The first connection has a pin of 683101 and the second 649105 in case that helps.

Thanks for your time!

*** Booting nRF Connect SDK v2.5.0 ***
[00:00:00.403,259] <inf> fs_nvs: nvs_mount: 2 Sectors of 4096 bytes
[00:00:00.403,259] <inf> fs_nvs: nvs_mount: alloc wra: 0, fe8
[00:00:00.403,289] <inf> fs_nvs: nvs_mount: data wra: 0, 0
Bluetooth authentication callbacks registered.
[00:00:00.424,865] <inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.424,896] <inf> bt_hci_core: hci_vs_init: HW Variant: nRF53x (0x0003)
[00:00:00.424,926] <inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 197.47763 Build 2370639017
[00:00:00.425,689] <inf> bt_hci_core: bt_init: No ID address. App must call settings_load()
Bluetooth initialized
[00:00:00.426,605] <inf> bt_hci_core: bt_dev_show_info: Identity: DE:C1:62:6E:0C:34 (random)
[00:00:00.426,635] <inf> bt_hci_core: bt_dev_show_info: HCI: version 5.4 (0x0d) revision 0x2102, manufacturer 0x0059
[00:00:00.426,666] <inf> bt_hci_core: bt_dev_show_info: LMP: version 5.4 (0x0d) subver 0x2102
Advertising successfully started
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 683101
Security changed: 00:D4:9E:B3:49:E3 (public) level 4
[00:00:46.153,045] <inf> bt_keys: bt_keys_show_sniffer_info: SC LTK: 0x83165b859ed31e456795ee0996ae1c10
[00:00:47.201,721] <inf> bas: blvl_ccc_cfg_changed: BAS Notifications enabled
[00:01:36.327,545] <inf> bas: blvl_ccc_cfg_changed: BAS Notifications disabled
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x13)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 182725
[00:02:04.947,967] <wrn> bt_smp: smp_pairing_complete: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x2a)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 141435
[00:02:17.593,688] <wrn> bt_smp: smp_pairing_complete: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 649105
Security changed: 00:D4:9E:B3:49:E3 (public) level 4
[00:02:48.914,276] <inf> bt_keys: bt_keys_show_sniffer_info: SC LTK: 0x23d65aaf3fbdbaa7b730538b04c747b9
[00:02:49.647,888] <inf> bas: blvl_ccc_cfg_changed: BAS Notifications enabled
[00:03:06.913,665] <inf> bas: blvl_ccc_cfg_changed: BAS Notifications disabled
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x13)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 887275
[00:03:19.738,555] <wrn> bt_smp: smp_pairing_complete: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 733181
[00:03:24.013,580] <wrn> bt_smp: smp_pairing_complete: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 909407
[00:03:39.268,646] <wrn> bt_smp: smp_pairing_complete: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 966501
[00:03:47.188,659] <wrn> bt_smp: smp_pairing_complete: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x2a)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 537477
[00:04:12.793,823] <wrn> bt_smp: smp_pairing_complete: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 432633
[00:04:17.023,864] <wrn> bt_smp: smp_pairing_complete: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)
Connected 00:D4:9E:B3:49:E3 (public)
Passkey for 00:D4:9E:B3:49:E3 (public): 291362
[00:04:25.168,792] <wrn> bt_smp: smp_pairing_complete: Not connected!
Security failed: 00:D4:9E:B3:49:E3 (public) level 1 err 9
Disconnected from 00:D4:9E:B3:49:E3 (public) (reason 0x23)

longer capture ble con error.pcapng