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