Latest Intel driver connection issue

[piseek]

We're using nRF Connect with SDK v2.4.0 (Zephyr). 
Central and peripheral roles combined.

Custom hardware, with Fanstels module BT840

All was working well, but after extensive testing, we encountered a problem connecting our hardware to the certain integrated BLE Intel chipset on some of the Laptops.
The connection gets rejected, it looks like some security issue.
We tried different sets of drivers and it looks like only new drivers have this issue.

• We cannot connect if the Intel driver version is 22.250.0 or newer.
• We can connect with a laptop if the Intel driver version is 22.240.0 or less.

We tried to downgrade the driver on affected laptops and then we were able to establish a Bluetooth connection.

Intel driver list and corresponding release notes can be found here:
https://www.intel.com/content/www/us/en/download/18649/787935/intel-wireless-bluetooth-for-windows-10-and-windows-11.html

We are about to release the product, but first, we need to solve this issue, any advice will be much appreciated.

Best Regards
Andrej

[RM]

Hi,

Do you get any specific code on rejection cause, try using the BLE sniffer with wireshark to get insights at which stage it is rejected.

https://www.nordicsemi.com/Products/Development-tools/nrf-sniffer-for-bluetooth-le

also, which direction is got rejected ?

Thanks,
Reuven

[piseek]

We are using "BluetoothLEAdvertisementWatcher". Device is visible, we try to read its gatt services. By reading services, Bluetooth device connection status changes to Connected. If the service reading is successful, Bluetooth device stays connected. If reading was not successful, we receive a message "GATT communication status is UNREACHABLE" and Bluetooth status changes to Disconnected.

For reading GATT services, we are using BluetootLEDevice class.

I thought it was a security issue from the changes noted in the Release notes of the latest Intel driver. But now looking at the differences seen by nRF Sniffer I'd guess it's related to Timeout or perhaps Window Offset.

Bad (new) driver on the left and good (older) driver to the right:

0000 13 35 00 03 32 71 02 0a 01 25 28 00 00 a1 e8 9d .5..2q...%(..... 0010 05 d6 be 89 8e 25 22 de d6 3f 58 33 2c 0e 29 4e .....%"..?X3,.)N 0020 56 45 46 d4 cc 22 70 5a 9f 6f 01 07 00 24 00 00 VEF.."pZ.o...$.. 0030 00 2a 00 ff ff ff ff 1f 27 dc 1e 14 .*......'... Frame 1769: 60 bytes on wire (480 bits), 60 bytes captured (480 bits) on interface COM19-4.2, id 0 nRF Sniffer for Bluetooth LE Board: 19 Header Version: 3, Packet counter: 28978 Length of packet: 10 Flags: 0x01 Channel Index: 37 RSSI: -40 dBm Event counter: 0 Timestamp: 94234785µs [Packet time (start to end): 352µs] [Delta time (end to start): 150µs] [Delta time (start to start): 382µs] Bluetooth Low Energy Link Layer Access Address: 0x8e89bed6 Packet Header: 0x2225 (PDU Type: CONNECT_IND, ChSel: #2, TxAdd: Public, RxAdd: Public) .... 0101 = PDU Type: 0x5 CONNECT_IND ...0 .... = Reserved: 0 ..1. .... = Channel Selection Algorithm: #2 .0.. .... = Tx Address: Public 0... .... = Rx Address: Public Length: 34 Initiator Address: Intel_3f:d6:de (2c:33:58:3f:d6:de) Advertising Address: 46:45:56:4e:29:0e (46:45:56:4e:29:0e) Link Layer Data Access Address: 0x7022ccd4 CRC Init: 0x6f9f5a Window Size: 1 (1.25 msec) Window Offset: 7 (8.75 msec) Interval: 36 (45 msec) Latency: 0 Timeout: 42 (420 msec) Channel Map: ffffffff1f ...0 0111 = Hop: 7 001. .... = Sleep Clock Accuracy: 151 ppm to 250 ppm (1) CRC: 0x3b7828

0000 13 35 00 03 49 7a 02 0a 01 26 34 00 00 17 fd c5 .5..Iz...&4..... 0010 69 d6 be 89 8e 25 22 de d6 3f 58 33 2c 0e 29 4e i....%"..?X3,.)N 0020 56 45 46 d6 46 52 a9 aa 8e 99 01 2c 00 30 00 00 VEF.FR.....,.0.. 0030 00 c0 03 ff ff ff ff 1f 29 a9 83 f5 ........)... Frame 2234: 60 bytes on wire (480 bits), 60 bytes captured (480 bits) on interface COM19-4.2, id 0 nRF Sniffer for Bluetooth LE Board: 19 Header Version: 3, Packet counter: 31305 Length of packet: 10 Flags: 0x01 Channel Index: 38 RSSI: -52 dBm Event counter: 0 Timestamp: 1774583063µs [Packet time (start to end): 352µs] [Delta time (end to start): 150µs] [Delta time (start to start): 382µs] Bluetooth Low Energy Link Layer Access Address: 0x8e89bed6 Packet Header: 0x2225 (PDU Type: CONNECT_IND, ChSel: #2, TxAdd: Public, RxAdd: Public) .... 0101 = PDU Type: 0x5 CONNECT_IND ...0 .... = Reserved: 0 ..1. .... = Channel Selection Algorithm: #2 .0.. .... = Tx Address: Public 0... .... = Rx Address: Public Length: 34 Initiator Address: Intel_3f:d6:de (2c:33:58:3f:d6:de) Advertising Address: 46:45:56:4e:29:0e (46:45:56:4e:29:0e) Link Layer Data Access Address: 0xa95246d6 CRC Init: 0x998eaa Window Size: 1 (1.25 msec) Window Offset: 44 (55 msec) Interval: 48 (60 msec) Latency: 0 Timeout: 960 (9600 msec) Channel Map: ffffffff1f ...0 1001 = Hop: 9 001. .... = Sleep Clock Accuracy: 151 ppm to 250 ppm (1) CRC: 0x95c1af

From the RTT logs on Zephyr's side, we get "Disconnected: 00:93:37:EE:90:5C (public) (reason 35)"
This is the log:

00> rtt:~$ rtt:~$ [00:06:29.228,973] <inf> bt_connection_log: MTU exchange done, current value: 498
00> rtt:~$ [00:06:29.634,521] <inf> bt_connection_log: Disconnected: 00:93:37:EE:90:5C (public) (reason 35)
00> rtt:~$ [00:06:29.634,552] <inf> bt_connection_log: Disconnected from NUS connection
00> rtt:~$ [00:06:29.636,138] <inf> bt_advertise_log: Advertising succesfull started!
00> rtt:~$ rtt:~$ [00:06:35.708,312] <wrn> bt_hci_core: opcode 0x200a status 0x0d
00> rtt:~$ [00:06:35.708,709] <inf> bt_connection_log: Connected: 00:93:37:EE:90:5C (public), mtu=23
00> rtt:~$ [00:06:35.708,770] <inf> bt_connection_log: Peripheral connection - MTU exchange done, current value: 23
00> rtt:~$ [00:06:35.708,801] <inf> bt_connection_log: Peripheral state in connection cb
00> rtt:~$ [00:06:35.843,902] <inf> bt_connection_log: MTU exchange done, current value: 498
00> rtt:~$ [00:06:36.249,542] <inf> bt_connection_log: Disconnected: 00:93:37:EE:90:5C (public) (reason 35)
00> rtt:~$ [00:06:36.249,542] <inf> bt_connection_log: Disconnected from NUS connection
00> rtt:~$ [00:06:36.251,129] <inf> bt_advertise_log: Advertising succesfull started!
00> rtt:~$ rtt:~$ [00:06:37.209,930] <wrn> bt_hci_core: opcode 0x200a status 0x0d
00> rtt:~$ [00:06:37.210,327] <inf> bt_connection_log: Connected: 00:93:37:EE:90:5C (public), mtu=23
00> rtt:~$ [00:06:37.210,388] <inf> bt_connection_log: Peripheral connection - MTU exchange done, current value: 23
00> rtt:~$ [00:06:37.210,418] <inf> bt_connection_log: Peripheral state in connection cb
00> rtt:~$ [00:06:37.328,887] <inf> bt_connection_log: MTU exchange done, current value: 498
00> rtt:~$ [00:06:37.734,466] <inf> bt_connection_log: Disconnected: 00:93:37:EE:90:5C (public) (reason 35)
00> rtt:~$ [00:06:37.734,497] <inf> bt_connection_log: Disconnected from NUS connection
00> rtt:~$ [00:06:37.736,053] <inf> bt_advertise_log: Advertising succesfull started!
00> rtt:~$ [00:06:38.171,630] <wrn> bt_hci_core: opcode 0x200a status 0x0d

This can go on for minutes and sometimes they connect and stay connected for a while.

Probably you could reproduce the issue with Windows driving Intel chipset and your example for the Peripheral role on nRF52840.

Thank you for support.
Andrej

 

[piseek]

We found the workaround for this driver issue. 
The problem was that immediately after the connection happened, we terminated advertising, in short something like this:

static void connected(struct bt_conn* conn, uint8_t conn_err)
{
 bt_gatt_exchange_mtu(conn, &exchange_params);
 stop_advertising();
}

When we add delay:

static void connected(struct bt_conn* conn, uint8_t conn_err)
{
	bt_gatt_exchange_mtu(conn, &exchange_params);
	k_msleep(1000);
	stop_advertising();
}

This solves the issue for Intel.

But now we have an issue with a specific Realtek driver - 1.10.1061.3001

It could be that the delay is too long, it is hard to solve this by guessing.
We would appreciate some advice.

Regards,

Andrej

[Vidar Berg]

Hello Andrej,

Do you see any errors now reported in the debug log? Also, are you  using multiple advertisement sets in your application? A connectable advertiser will stop automatically once a connection is established.

Best regards,

Vidar

[piseek]

Hi Vidar,

We're only using a single advertising set:

static const struct bt_data ad[] = {
    BT_DATA_BYTES(BT_DATA_FLAGS, (BT_LE_AD_GENERAL | BT_LE_AD_NO_BREDR)),
    BT_DATA(BT_DATA_NAME_COMPLETE, DEVICE_NAME, DEVICE_NAME_LEN),
};

static const struct bt_data sd[] = {
    BT_DATA_BYTES(BT_DATA_UUID128_ALL, BT_UUID_NUS_VAL),
};

void advertising_entry()
{
    struct bt_le_adv_param adv_param_conn = BT_LE_ADV_PARAM_INIT(BT_LE_ADV_OPT_CONNECTABLE | BT_LE_ADV_OPT_NOTIFY_SCAN_REQ, BT_GAP_ADV_FAST_INT_MIN_1, BT_GAP_ADV_FAST_INT_MIN_1, NULL);
    err = bt_le_adv_start(&adv_param_conn, ad, ARRAY_SIZE(ad), sd, ARRAY_SIZE(sd));
}

We've tried removing `stop_advertising();` as you suggested, it didn't solve the issue for Realtek.
It is still working for Intel - the original issue of this post. 

this is RTT log of problematic Realtek driver:

00> rtt:~$ [00:00:15.570,343] <inf> bt_advertise_log: Advertising succesfull started!
00> rtt:~$ [00:00:15.570,373] <inf> perypheral_controller: Entry
00> rtt:~$ rtt:~$ [00:00:45.183,837] <wrn> bt_hci_core: opcode 0x200a status 0x0d
00> rtt:~$ [00:00:45.184,234] <inf> bt_connection_log: Connected: D8:80:83:DA:41:CA (public), mtu=23
00> rtt:~$ [00:00:45.184,295] <inf> bt_connection_log: Peripheral connection - MTU exchange done, current value: 23
00> rtt:~$ rtt:~$ [00:00:46.184,448] <inf> bt_connection_log: Peripheral state in connection cb
00> rtt:~$ [00:00:46.185,577] <inf> bt_connection_log: MTU exchange done, current value: 498
00> rtt:~$ rtt:~$ [00:00:56.801,361] <inf> bt_connection_log: Disconnected: D8:80:83:DA:41:CA (public) (reason 8)
00> rtt:~$ [00:00:56.801,391] <inf> bt_connection_log: Disconnected from NUS connection
00> rtt:~$ [00:00:56.802,978] <inf> bt_advertise_log: Advertising succesfull started!
00> rtt:~$ rtt:~$ [00:01:05.190,734] <wrn> bt_hci_core: opcode 0x200a status 0x0d
00> rtt:~$ [00:01:05.191,192] <inf> bt_connection_log: Connected: D8:80:83:DA:41:CA (public), mtu=23
00> rtt:~$ [00:01:05.191,253] <inf> bt_connection_log: Peripheral connection - MTU exchange done, current value: 23
00> rtt:~$ rtt:~$ [00:01:06.191,406] <inf> bt_connection_log: Peripheral state in connection cb
00> rtt:~$ [00:01:06.192,443] <inf> bt_connection_log: MTU exchange done, current value: 498
00> rtt:~$ rtt:~$ [00:01:16.688,140] <inf> bt_connection_log: Disconnected: D8:80:83:DA:41:CA (public) (reason 8)
00> rtt:~$ [00:01:16.688,171] <inf> bt_connection_log: Disconnected from NUS connection
00> rtt:~$ [00:01:16.689,727] <inf> bt_advertise_log: Advertising succesfull started!
00> rtt:~$ rtt:~$ [00:01:23.957,794] <wrn> bt_hci_core: opcode 0x200a status 0x0d
00> rtt:~$ [00:01:23.958,221] <inf> bt_connection_log: Connected: D8:80:83:DA:41:CA (public), mtu=23
00> rtt:~$ [00:01:23.958,312] <inf> bt_connection_log: Peripheral connection - MTU exchange done, current value: 23
00> rtt:~$ rtt:~$ [00:01:24.958,404] <inf> bt_connection_log: Peripheral state in connection cb
00> rtt:~$ [00:01:24.959,442] <inf> bt_connection_log: MTU exchange done, current value: 498
00> rtt:~$ rtt:~$ [00:01:35.514,984] <inf> bt_connection_log: Disconnected: D8:80:83:DA:41:CA (public) (reason 8)
00> rtt:~$ [00:01:35.515,014] <inf> bt_connection_log: Disconnected from NUS connection
00> rtt:~$ [00:01:35.516,632] <inf> bt_advertise_log: Advertising succesfull started!
00> rtt:~$ [00:01:36.256,988] <wrn> bt_hci_core: opcode 0x200a status 0x0d
00> rtt:~$ [00:01:36.257,324] <inf> bt_connection_log: Connected: D8:80:83:DA:41:CA (public), mtu=23
00> rtt:~$ [00:01:36.257,385] <inf> bt_connection_log: Peripheral connection - MTU exchange done, current value: 23
00> rtt:~$ rtt:~$ [00:01:37.257,659] <inf> bt_connection_log: Peripheral state in connection cb
00> rtt:~$ [00:01:37.258,789] <inf> bt_connection_log: MTU exchange done, current value: 498

Best Regards,
Andrej