Livelock in SMP pairing failed scenario

[nashif]

Reported by Vinayak Kariappa Chettimada:

Issue: Trying to get an encrypted security level 2 connection between two tests/bluetooth/shell application running in QEMU resulted in a livelock of SMP pairing failed PDUs exchanged between the two BLE connections.

Test setup:

• Two nRF52840 PDK with hci_uart application (1M baud rate UART, 2M PHY and 251 byte PDU support)
• one instance of "sudo btmon" in a terminal
• Two btattach instances in their own terminal: -- sudo btattach -B /dev/ttyACM0 -S 1000000 -R -- sudo btattach -B /dev/ttyACM1 -S 1000000 -R
• Two btproxy instances in their own terminal: -- sudo btproxy -i 1 --unix=/tmp/bt-server-bredr1 -- sudo btproxy -i 2 --unix=/tmp/bt-server-bredr2
• Two instances of QEMU (Makefile changed to select unix socket before executing): -- make -C tests/bluetooth/shell ZEPHYR_BASE=~/workspace/zephyr ZEPHYR_GCC_VARIANT=zephyr ZEPHYR_SDK_INSTALL_DIR=/opt/zephyr-sdk/ BOARD=qemu_x86 CONF_FILE=nrf5.conf qemu
• conf file additions compare to upstream/master: -- {code} CONFIG_BT_RX_BUF_LEN=258
  CONFIG_BT_L2CAP_RX_MTU=247
  CONFIG_BT_L2CAP_TX_MTU=247
  CONFIG_BT_ATT_TX_MAX=6 {code}

btmon log: {code} < ACL Data TX: Handle 0 flags 0x00 dlen 11 #107382 [hci2] 66690.567967 SMP: Pairing Request (0x01) len 6 IO capability: NoInputNoOutput (0x03) OOB data: Authentication data not present (0x00) Authentication requirement: Bonding, No MITM, SC, No Keypresses (0x09) Max encryption key size: 16 Initiator key distribution: EncKey IdKey Sign (0x07) Responder key distribution: EncKey IdKey Sign (0x07)

HCI Event: Number of Completed P.. (0x13) plen 5 #107383 [hci2] 66690.660520 Num handles: 1 Handle: 0 Count: 1 ACL Data RX: Handle 1 flags 0x02 dlen 11 #107437 [hci1] 66690.660527 SMP: Pairing Request (0x01) len 6 IO capability: NoInputNoOutput (0x03) OOB data: Authentication data not present (0x00) Authentication requirement: Bonding, No MITM, SC, No Keypresses (0x09) Max encryption key size: 16 Initiator key distribution: EncKey IdKey Sign (0x07) Responder key distribution: EncKey IdKey Sign (0x07) < HCI Command: Host Number... (0x03|0x0035) plen 5 #107438 [hci1] 66690.663167 Num handles: 1 Handle: 1 Count: 1 < ACL Data TX: Handle 1 flags 0x00 dlen 11 #107439 [hci1] 66690.663391 SMP: Pairing Response (0x02) len 6 IO capability: NoInputNoOutput (0x03) OOB data: Authentication data not present (0x00) Authentication requirement: Bonding, No MITM, SC, No Keypresses (0x09) Max encryption key size: 16 Initiator key distribution: IdKey Sign (0x06) Responder key distribution: IdKey Sign (0x06) ACL Data RX: Handle 0 flags 0x02 dlen 11 #107384 [hci2] 66690.760720 SMP: Pairing Response (0x02) len 6 IO capability: NoInputNoOutput (0x03) OOB data: Authentication data not present (0x00) Authentication requirement: Bonding, No MITM, SC, No Keypresses (0x09) Max encryption key size: 16 Initiator key distribution: IdKey Sign (0x06) Responder key distribution: IdKey Sign (0x06) < HCI Command: Host Number... (0x03|0x0035) plen 5 #107385 [hci2] 66690.763621 Num handles: 1 Handle: 0 Count: 1 < ACL Data TX: Handle 0 flags 0x00 dlen 69 #107386 [hci2] 66690.764314 SMP: Pairing Public Key (0x0c) len 64 X: 9f9c7f82c13fdae36907b0bc374ac12b328d2b99f7b1f428944f6a92dba5f60d Y: 323251977e6a68ff55569717f587ba563aa364872d0ebcd64b954afc41ab72d6 HCI Event: Number of Completed P.. (0x13) plen 5 #107387 [hci2] 66690.860752 Num handles: 1 Handle: 0 Count: 1 HCI Event: Number of Completed P.. (0x13) plen 5 #107440 [hci1] 66690.860751 Num handles: 1 Handle: 1 Count: 1 ACL Data RX: Handle 1 flags 0x02 dlen 69 #107441 [hci1] 66690.861653 SMP: Pairing Public Key (0x0c) len 64 X: 9f9c7f82c13fdae36907b0bc374ac12b328d2b99f7b1f428944f6a92dba5f60d Y: 323251977e6a68ff55569717f587ba563aa364872d0e0002030009100606ff52 < ACL Data TX: Handle 1 flags 0x00 dlen 69 #107442 [hci1] 66690.865240 SMP: Pairing Public Key (0x0c) len 64 X: 1b6bf77c4dcc532c2151ce929baf1cda55a277ca794cf5c4403b1f8c1429c501 Y: a53714ffed13d01bcfb3fb788109777ff92d544950488a5dd6fc1005c2a26ffe < ACL Data TX: Handle 1 flags 0x00 dlen 21 #107443 [hci1] 66690.865644 SMP: Pairing Confirm (0x03) len 16 Confim value: b651dc2baf1b46680b9a76a25ec67ced < HCI Command: Host Number... (0x03|0x0035) plen 5 #107444 [hci1] 66690.865838 Num handles: 1 Handle: 1 Count: 1 < ACL Data TX: Handle 1 flags 0x00 dlen 6 #107445 [hci1] 66690.867099 SMP: Pairing Failed (0x05) len 1 Reason: DHKey check failed (0x0b) HCI Event: Number of Completed P.. (0x13) plen 5 #107446 [hci1] 66690.961303 Num handles: 1 Handle: 1 Count: 1 HCI Event: Number of Completed P.. (0x13) plen 5 #107447 [hci1] 66690.961429 Num handles: 1 Handle: 1 Count: 1 ACL Data RX: Handle 0 flags 0x02 dlen 69 #107388 [hci2] 66690.961758 SMP: Pairing Public Key (0x0c) len 64 X: 1b6bf77c4dcc532c2151ce929baf1cda55a277ca794cf5c4403b1f8c1429c501 Y: a53714ffed13d01bcfb3fb788109777ff92d544950488a5dd6fc1005c2a26ffe ACL Data RX: Handle 0 flags 0x02 dlen 21 #107389 [hci2] 66690.962171 SMP: Pairing Confirm (0x03) len 16 Confim value: b651dc2baf1b46680b9a76a25ec67ced < HCI Command: Host Number... (0x03|0x0035) plen 5 #107390 [hci2] 66690.967056 Num handles: 1 Handle: 0 Count: 1 ACL Data RX: Handle 0 flags 0x02 dlen 6 #107391 [hci2] 66690.967519 SMP: Pairing Failed (0x05) len 1 Reason: DHKey check failed (0x0b) < HCI Command: Host Number... (0x03|0x0035) plen 5 #107392 [hci2] 66690.967601 Num handles: 1 Handle: 0 Count: 1 < ACL Data TX: Handle 0 flags 0x00 dlen 21 #107393 [hci2] 66690.968351 SMP: Pairing Random (0x04) len 16 Random value: f84f454b5de5c61776d33c49ccb2ae2c < HCI Command: Host Number... (0x03|0x0035) plen 5 #107394 [hci2] 66690.970179 Num handles: 1 Handle: 0 Count: 1 HCI Event: Number of Completed P.. (0x13) plen 5 #107448 [hci1] 66691.060547 Num handles: 1 Handle: 1 Count: 1 HCI Event: Number of Completed P.. (0x13) plen 5 #107395 [hci2] 66691.060558 Num handles: 1 Handle: 0 Count: 1 ACL Data RX: Handle 1 flags 0x02 dlen 21 #107449 [hci1] 66691.060936 SMP: Pairing Random (0x04) len 16 Random value: f84f454b5de5c61776d33c49ccb2ae2c < HCI Command: Host Number... (0x03|0x0035) plen 5 #107450 [hci1] 66691.062501 Num handles: 1 Handle: 1 Count: 1 < ACL Data TX: Handle 1 flags 0x00 dlen 6 #107451 [hci1] 66691.062622 SMP: Pairing Failed (0x05) len 1 Reason: Unspecified reason (0x08) ACL Data RX: Handle 0 flags 0x02 dlen 6 #107396 [hci2] 66691.160512 SMP: Pairing Failed (0x05) len 1 Reason: Unspecified reason (0x08) < HCI Command: Host Number... (0x03|0x0035) plen 5 #107397 [hci2] 66691.162807 Num handles: 1 Handle: 0 Count: 1 < ACL Data TX: Handle 0 flags 0x00 dlen 6 #107398 [hci2] 66691.162958 SMP: Pairing Failed (0x05) len 1 Reason: Unspecified reason (0x08) HCI Event: Number of Completed P.. (0x13) plen 5 #107452 [hci1] 66691.260497 Num handles: 1 Handle: 1 Count: 1 ACL Data RX: Handle 1 flags 0x02 dlen 6 #107453 [hci1] 66691.260527 SMP: Pairing Failed (0x05) len 1 Reason: Unspecified reason (0x08) HCI Event: Number of Completed P.. (0x13) plen 5 #107399 [hci2] 66691.260507 Num handles: 1 Handle: 0 Count: 1 < HCI Command: Host Number... (0x03|0x0035) plen 5 #107454 [hci1] 66691.263041 Num handles: 1 Handle: 1 Count: 1 < ACL Data TX: Handle 1 flags 0x00 dlen 6 #107455 [hci1] 66691.263156 SMP: Pairing Failed (0x05) len 1 Reason: Unspecified reason (0x08) ACL Data RX: Handle 0 flags 0x02 dlen 6 #107400 [hci2] 66691.360519 SMP: Pairing Failed (0x05) len 1 Reason: Unspecified reason (0x08) < HCI Command: Host Number... (0x03|0x0035) plen 5 #107401 [hci2] 66691.362849 Num handles: 1 Handle: 0 Count: 1 < ACL Data TX: Handle 0 flags 0x00 dlen 6 #107402 [hci2] 66691.363046 SMP: Pairing Failed (0x05) len 1 Reason: Unspecified reason (0x08) HCI Event: Number of Completed P.. (0x13) plen 5 #107403 [hci2] 66691.460607 Num handles: 1 Handle: 0 Count: 1 HCI Event: Number of Completed P.. (0x13) plen 5 #107456 [hci1] 66691.460617 Num handles: 1 Handle: 1 Count: 1 ACL Data RX: Handle 1 flags 0x02 dlen 6 #107457 [hci1] 66691.460620 SMP: Pairing Failed (0x05) len 1 Reason: Unspecified reason (0x08) < HCI Command: Host Number... (0x03|0x0035) plen 5 #107458 [hci1] 66691.464033 Num handles: 1 Handle: 1 Count: 1 < ACL Data TX: Handle 1 flags 0x00 dlen 6 #107459 [hci1] 66691.464229 SMP: Pairing Failed (0x05) len 1 Reason: Unspecified reason (0x08) ACL Data RX: Handle 0 flags 0x02 dlen 6 #107404 [hci2] 66691.560587 SMP: Pairing Failed (0x05) len 1 Reason: Unspecified reason (0x08) < HCI Command: Host Number... (0x03|0x0035) plen 5 #107405 [hci2] 66691.563047 Num handles: 1 Handle: 0 Count: 1 < ACL Data TX: Handle 0 flags 0x00 dlen 6 #107406 [hci2] 66691.563314 SMP: Pairing Failed (0x05) len 1 Reason: Unspecified reason (0x08) {code}

(Imported from Jira ZEP-2620)

[nashif]

by Johan Hedberg:

I suspect this might be because the flow control events happen "before their time" on an emulated setup (i.e. a btvirt bug), however something like the following should fix the endless repetition of failed messages:

--- a/subsys/bluetooth/host/smp.c
+++ b/subsys/bluetooth/host/smp.c
@@ -3432,7 +3432,10 @@ static void bt_smp_recv(struct bt_l2cap_chan *chan, struct net_buf *buf)

        if (!atomic_test_and_clear_bit(&smp->allowed_cmds, hdr->code)) {
                BT_WARN("Unexpected SMP code 0x%02x", hdr->code);
-               smp_error(smp, BT_SMP_ERR_UNSPECIFIED);
+               /* Don't send error responses to error PDUs */
+               if (hdr->code != BT_SMP_CMD_PAIRING_FAIL) {
+                       smp_error(smp, BT_SMP_ERR_UNSPECIFIED);
+               }
                return;
        }