* Security block and Bluez - connection issue with Android @ 2018-09-25 16:08 fabien dvlt 2018-09-26 11:03 ` fabien dvlt 2018-09-26 11:28 ` Johan Hedberg 0 siblings, 2 replies; 6+ messages in thread From: fabien dvlt @ 2018-09-25 16:08 UTC (permalink / raw) To: linux-bluetooth Hello, After trying 42 connections, 30% of my attempts are failing on authentication (bluez 5.47). This happens with multiple (all?) Android phones. Below are the btmon logs which I am finding interesting after that you will find the complete logs. For all of my failing connection, I saw that an L2CAP connection requests with PSM 0x19 is processed just before 'Encryption Change' event. But, for all successful attempts this L2CAP connection request is made after "Encryption Change' event. So I made a patch to postpone the involved ACL packet after the Encryption Change event and now I have 100% of success but it is still a little hackish. May be this is also related to https://www.spinics.net/lists/linux-bluetooth/msg72827.html Thank you ------------------------------ > HCI Event: Link Key Request (0x17) plen 6 #195 [hci0] 21.708115 Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) < HCI Command: Link Key Request Reply (0x01|0x000b) plen 22 #196 [hci0] 21.708397 Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) Link key: feff6b48c953f119c1579913be0c0f65 > HCI Event: Command Complete (0x0e) plen 10 #197 [hci0] 21.710115 Link Key Request Reply (0x01|0x000b) ncmd 1 Status: Success (0x00) Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > ACL Data RX: Handle 13 flags 0x02 dlen 12 #198 [hci0] 21.813116 L2CAP: Connection Request (0x02) ident 7 len 4 PSM: 25 (0x0019) Source CID: 75 > HCI Event: Encryption Change (0x08) plen 4 #199 [hci0] 21.813155 Status: Success (0x00) Handle: 13 Encryption: Enabled with AES-CCM (0x02) < ACL Data TX: Handle 13 flags 0x00 dlen 16 #200 [hci0] 21.813256 L2CAP: Connection Response (0x03) ident 7 len 8 Destination CID: 0 Source CID: 75 Result: Connection refused - security block (0x0003) Status: No further information available (0x0000) ------------------------------ # COMPLETE BTMON LOGS > HCI Event: Connect Request (0x04) plen 10 #152 [hci0] 21.335093 Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) Class: 0x5a020c Major class: Phone (cellular, cordless, payphone, modem) Minor class: Smart phone Networking (LAN, Ad hoc) Capturing (Scanner, Microphone) Object Transfer (v-Inbox, v-Folder) Telephony (Cordless telephony, Modem, Headset) Link type: ACL (0x01) < HCI Command: Accept Connection Request (0x01|0x0009) plen 7 #153 [hci0] 21.335196 Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) Role: Master (0x00) > HCI Event: Command Status (0x0f) plen 4 #154 [hci0] 21.337107 Accept Connection Request (0x01|0x0009) ncmd 1 Status: Success (0x00) > HCI Event: Role Change (0x12) plen 8 #155 [hci0] 21.589092 Status: Success (0x00) Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) Role: Master (0x00) > HCI Event: Connect Complete (0x03) plen 11 #156 [hci0] 21.596088 Status: Success (0x00) Handle: 13 Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) Link type: ACL (0x01) Encryption: Disabled (0x00) < HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2 #157 [hci0] 21.596328 Handle: 13 > HCI Event: Command Status (0x0f) plen 4 #158 [hci0] 21.607116 Read Remote Supported Features (0x01|0x001b) ncmd 1 Status: Success (0x00) > HCI Event: Page Scan Repetition Mode Change (0x20) plen 7 #159 [hci0] 21.608112 Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) Page scan repetition mode: R1 (0x01) > HCI Event: Max Slots Change (0x1b) plen 3 #160 [hci0] 21.609114 Handle: 13 Max slots: 5 > HCI Event: Read Remote Supported Features (0x0b) plen 11 #161 [hci0] 21.612116 Status: Success (0x00) Handle: 13 Features: 0xff 0xfe 0x8f 0xfe 0xd8 0x3f 0x5b 0x87 3 slot packets 5 slot packets Encryption Slot offset Timing accuracy Role switch Hold mode Sniff mode Power control requests Channel quality driven data rate (CQDDR) SCO link HV2 packets HV3 packets u-law log synchronous data A-law log synchronous data CVSD synchronous data Paging parameter negotiation Power control Transparent synchronous data Broadcast Encryption Enhanced Data Rate ACL 2 Mbps mode Enhanced Data Rate ACL 3 Mbps mode Enhanced inquiry scan Interlaced inquiry scan Interlaced page scan RSSI with inquiry results Extended SCO link (EV3 packets) AFH capable slave AFH classification slave LE Supported (Controller) 3-slot Enhanced Data Rate ACL packets 5-slot Enhanced Data Rate ACL packets Sniff subrating Pause encryption AFH capable master AFH classification master Enhanced Data Rate eSCO 2 Mbps mode Extended Inquiry Response Simultaneous LE and BR/EDR (Controller) Secure Simple Pairing Encapsulated PDU Non-flushable Packet Boundary Flag Link Supervision Timeout Changed Event Inquiry TX Power Level Enhanced Power Control Extended features < HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3 #162 [hci0] 21.612211 Handle: 13 Page: 1 > HCI Event: Command Status (0x0f) plen 4 #163 [hci0] 21.614113 Read Remote Extended Features (0x01|0x001c) ncmd 1 Status: Success (0x00) > ACL Data RX: Handle 13 flags 0x02 dlen 10 #164 [hci0] 21.617110 L2CAP: Information Request (0x0a) ident 2 len 2 Type: Extended features supported (0x0002) > HCI Event: Read Remote Extended Features (0x23) plen 13 #165 [hci0] 21.617139 Status: Success (0x00) Handle: 13 Page: 1/2 Features: 0x0f 0x00 0x00 0x00 0x00 0x00 0x00 0x00 Secure Simple Pairing (Host Support) LE Supported (Host) Simultaneous LE and BR/EDR (Host) Secure Connections (Host Support) < HCI Command: Remote Name Request (0x01|0x0019) plen 10 #166 [hci0] 21.617258 Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) Page scan repetition mode: R2 (0x02) Page scan mode: Mandatory (0x00) Clock offset: 0x0000 < ACL Data TX: Handle 13 flags 0x00 dlen 10 #167 [hci0] 21.617284 L2CAP: Information Request (0x0a) ident 1 len 2 Type: Extended features supported (0x0002) < ACL Data TX: Handle 13 flags 0x00 dlen 16 #168 [hci0] 21.617307 L2CAP: Information Response (0x0b) ident 2 len 8 Type: Extended features supported (0x0002) Result: Success (0x0000) Features: 0x000002b8 Enhanced Retransmission Mode Streaming Mode FCS Option Fixed Channels Unicast Connectionless Data Reception > HCI Event: Command Status (0x0f) plen 4 #169 [hci0] 21.619110 Remote Name Request (0x01|0x0019) ncmd 1 Status: Success (0x00) > HCI Event: Number of Completed Packets (0x13) plen 5 #170 [hci0] 21.620114 Num handles: 1 Handle: 13 Count: 1 > ACL Data RX: Handle 13 flags 0x02 dlen 16 #171 [hci0] 21.622116 L2CAP: Information Response (0x0b) ident 1 len 8 Type: Extended features supported (0x0002) Result: Success (0x0000) Features: 0x000000b8 Enhanced Retransmission Mode Streaming Mode FCS Option Fixed Channels < ACL Data TX: Handle 13 flags 0x00 dlen 10 #172 [hci0] 21.622208 L2CAP: Information Request (0x0a) ident 2 len 2 Type: Fixed channels supported (0x0003) > HCI Event: Number of Completed Packets (0x13) plen 5 #173 [hci0] 21.626110 Num handles: 1 Handle: 13 Count: 1 > ACL Data RX: Handle 13 flags 0x02 dlen 10 #174 [hci0] 21.628106 L2CAP: Information Request (0x0a) ident 3 len 2 Type: Fixed channels supported (0x0003) < ACL Data TX: Handle 13 flags 0x00 dlen 20 #175 [hci0] 21.628386 L2CAP: Information Response (0x0b) ident 3 len 12 Type: Fixed channels supported (0x0003) Result: Success (0x0000) Channels: 0x0000000000000086 L2CAP Signaling (BR/EDR) Connectionless reception Security Manager (BR/EDR) > ACL Data RX: Handle 13 flags 0x02 dlen 20 #176 [hci0] 21.636079 L2CAP: Information Response (0x0b) ident 2 len 12 Type: Fixed channels supported (0x0003) Result: Success (0x0000) Channels: 0x0000000000000082 L2CAP Signaling (BR/EDR) Security Manager (BR/EDR) > ACL Data RX: Handle 13 flags 0x02 dlen 12 #177 [hci0] 21.638082 L2CAP: Connection Request (0x02) ident 4 len 4 PSM: 1 (0x0001) Source CID: 74 @ MGMT Event: Device Connected (0x000b) plen 18 {0x0002} [hci0] 21.638158 BR/EDR Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) Flags: 0x00000000 Data length: 5 Class: 0x5a020c Major class: Phone (cellular, cordless, payphone, modem) Minor class: Smart phone Networking (LAN, Ad hoc) Capturing (Scanner, Microphone) Object Transfer (v-Inbox, v-Folder) Telephony (Cordless telephony, Modem, Headset) @ MGMT Event: Device Connected (0x000b) plen 18 {0x0001} [hci0] 21.638158 BR/EDR Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) Flags: 0x00000000 Data length: 5 Class: 0x5a020c Major class: Phone (cellular, cordless, payphone, modem) Minor class: Smart phone Networking (LAN, Ad hoc) Capturing (Scanner, Microphone) Object Transfer (v-Inbox, v-Folder) Telephony (Cordless telephony, Modem, Headset) < ACL Data TX: Handle 13 flags 0x00 dlen 16 #178 [hci0] 21.638233 L2CAP: Connection Response (0x03) ident 4 len 8 Destination CID: 64 Source CID: 74 Result: Connection successful (0x0000) Status: No further information available (0x0000) < ACL Data TX: Handle 13 flags 0x00 dlen 23 #179 [hci0] 21.638251 L2CAP: Configure Request (0x04) ident 3 len 15 Destination CID: 74 Flags: 0x0000 Option: Retransmission and Flow Control (0x04) [mandatory] Mode: Basic (0x00) TX window size: 0 Max transmit: 0 Retransmission timeout: 0 Monitor timeout: 0 Maximum PDU size: 0 > HCI Event: Remote Name Req Complete (0x07) plen 255 #180 [hci0] 21.643122 Status: Success (0x00) Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) Name: OnePlus 6 > HCI Event: Number of Completed Packets (0x13) plen 5 #181 [hci0] 21.644131 Num handles: 1 Handle: 13 Count: 1 > HCI Event: Number of Completed Packets (0x13) plen 5 #182 [hci0] 21.645124 Num handles: 1 Handle: 13 Count: 1 > HCI Event: Number of Completed Packets (0x13) plen 5 #183 [hci0] 21.648116 Num handles: 1 Handle: 13 Count: 1 > HCI Event: Number of Completed Packets (0x13) plen 5 #184 [hci0] 21.649120 Num handles: 1 Handle: 13 Count: 1 > ACL Data RX: Handle 13 flags 0x02 dlen 16 #185 [hci0] 21.658113 L2CAP: Configure Request (0x04) ident 5 len 8 Destination CID: 64 Flags: 0x0000 Option: Maximum Transmission Unit (0x01) [mandatory] MTU: 672 < ACL Data TX: Handle 13 flags 0x00 dlen 18 #186 [hci0] 21.658194 L2CAP: Configure Response (0x05) ident 5 len 10 Source CID: 74 Flags: 0x0000 Result: Success (0x0000) Option: Maximum Transmission Unit (0x01) [mandatory] MTU: 672 > ACL Data RX: Handle 13 flags 0x02 dlen 14 #187 [hci0] 21.659124 L2CAP: Configure Response (0x05) ident 3 len 6 Source CID: 64 Flags: 0x0000 Result: Success (0x0000) > HCI Event: Number of Completed Packets (0x13) plen 5 #188 [hci0] 21.661118 Num handles: 1 Handle: 13 Count: 1 > ACL Data RX: Handle 13 flags 0x02 dlen 28 #189 [hci0] 21.663116 Channel: 64 len 24 [PSM 1 mode 0] {chan 0} SDP: Service Search Attribute Request (0x06) tid 0 len 19 Search pattern: [len 5] Sequence (6) with 3 bytes [8 extra bits] len 5 UUID (3) with 2 bytes [0 extra bits] len 3 Audio Sink (0x110b) Max record count: 656 Attribute list: [len 11] Sequence (6) with 9 bytes [8 extra bits] len 11 Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 0x0001 Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 0x0004 Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 0x0009 Continuation state: 0 < ACL Data TX: Handle 13 flags 0x00 dlen 58 #190 [hci0] 21.663513 Channel: 74 len 54 [PSM 1 mode 0] {chan 0} SDP: Service Search Attribute Response (0x07) tid 0 len 49 Attribute bytes: 46 Attribute list: [len 42] {position 0} Attribute: Service Class ID List (0x0001) [len 2] UUID (3) with 2 bytes [0 extra bits] len 3 Audio Sink (0x110b) Attribute: Protocol Descriptor List (0x0004) [len 2] Sequence (6) with 6 bytes [8 extra bits] len 8 UUID (3) with 2 bytes [0 extra bits] len 3 L2CAP (0x0100) Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 0x0019 Sequence (6) with 6 bytes [8 extra bits] len 8 UUID (3) with 2 bytes [0 extra bits] len 3 AVDTP (0x0019) Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 0x0103 Attribute: Bluetooth Profile Descriptor List (0x0009) [len 2] Sequence (6) with 6 bytes [8 extra bits] len 8 UUID (3) with 2 bytes [0 extra bits] len 3 Advanced Audio Distribution (0x110d) Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 0x0103 Continuation state: 0 > HCI Event: Number of Completed Packets (0x13) plen 5 #191 [hci0] 21.670123 Num handles: 1 Handle: 13 Count: 1 > ACL Data RX: Handle 13 flags 0x02 dlen 12 #192 [hci0] 21.682116 L2CAP: Disconnection Request (0x06) ident 6 len 4 Destination CID: 64 Source CID: 74 < ACL Data TX: Handle 13 flags 0x00 dlen 12 #193 [hci0] 21.682230 L2CAP: Disconnection Response (0x07) ident 6 len 4 Destination CID: 64 Source CID: 74 > HCI Event: Number of Completed Packets (0x13) plen 5 #194 [hci0] 21.685121 Num handles: 1 Handle: 13 Count: 1 > HCI Event: Link Key Request (0x17) plen 6 #195 [hci0] 21.708115 Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) < HCI Command: Link Key Request Reply (0x01|0x000b) plen 22 #196 [hci0] 21.708397 Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) Link key: feff6b48c953f119c1579913be0c0f65 > HCI Event: Command Complete (0x0e) plen 10 #197 [hci0] 21.710115 Link Key Request Reply (0x01|0x000b) ncmd 1 Status: Success (0x00) Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > ACL Data RX: Handle 13 flags 0x02 dlen 12 #198 [hci0] 21.813116 L2CAP: Connection Request (0x02) ident 7 len 4 PSM: 25 (0x0019) Source CID: 75 > HCI Event: Encryption Change (0x08) plen 4 #199 [hci0] 21.813155 Status: Success (0x00) Handle: 13 Encryption: Enabled with AES-CCM (0x02) < ACL Data TX: Handle 13 flags 0x00 dlen 16 #200 [hci0] 21.813256 L2CAP: Connection Response (0x03) ident 7 len 8 Destination CID: 0 Source CID: 75 Result: Connection refused - security block (0x0003) Status: No further information available (0x0000) < HCI Command: Read Encryption Key Size (0x05|0x0008) plen 2 #201 [hci0] 21.813277 Handle: 13 > HCI Event: Command Complete (0x0e) plen 7 #202 [hci0] 21.815118 Read Encryption Key Size (0x05|0x0008) ncmd 1 Status: Success (0x00) Handle: 13 Key size: 16 > HCI Event: Number of Completed Packets (0x13) plen 5 #203 [hci0] 21.816118 Num handles: 1 Handle: 13 Count: 1 < HCI Command: Disconnect (0x01|0x0006) plen 3 #204 [hci0] 25.727125 Handle: 13 Reason: Authentication Failure (0x05) > HCI Event: Command Status (0x0f) plen 4 #205 [hci0] 25.729069 Disconnect (0x01|0x0006) ncmd 1 Status: Success (0x00) > HCI Event: Disconnect Complete (0x05) plen 4 #206 [hci0] 25.738073 Status: Success (0x00) Handle: 13 Reason: Connection Terminated By Local Host (0x16) @ MGMT Event: Device Disconnected (0x000c) plen 8 {0x0002} [hci0] 25.738149 BR/EDR Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) Reason: Connection terminated by local host (0x02) @ MGMT Event: Device Disconnected (0x000c) plen 8 {0x0001} [hci0] 25.738149 BR/EDR Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) Reason: Connection terminated by local host (0x02) ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Security block and Bluez - connection issue with Android 2018-09-25 16:08 Security block and Bluez - connection issue with Android fabien dvlt @ 2018-09-26 11:03 ` fabien dvlt 2018-09-26 11:23 ` Luiz Augusto von Dentz 2018-09-26 11:28 ` Johan Hedberg 1 sibling, 1 reply; 6+ messages in thread From: fabien dvlt @ 2018-09-26 11:03 UTC (permalink / raw) To: linux-bluetooth Hi, Here is an ugly patch only for understanding or testing purpose. It did correct my connections issues but there might side effects (like a deadlock although I did not have any). If you have any advise on how to fix this connection issue in a clean way, I would be glad to know it. I will be trying to do something cleaner in the next days. Thank you, Fabien --- --- linux-4.9.109/net/bluetooth/hci_core.c 2018-09-26 11:09:46.313308347 +0200 +++ linux/net/bluetooth/hci_core.c 2018-09-26 11:08:40.633482950 +0200 @@ -4038,6 +4038,32 @@ kfree_skb(skb); } +static int hci_acldata_packet_has_pending_sec_level(struct hci_dev *hdev, + struct sk_buff *skb) +{ + struct hci_acl_hdr *hdr = (void *) skb->data; + struct hci_conn *hcon; + __u16 handle; + + handle = __le16_to_cpu(hdr->handle); + handle = hci_handle(handle); + + BT_DBG("#hci_acldata_packet_has_pending_sec_level: before lock"); + hci_dev_lock(hdev); + BT_DBG("#hci_acldata_packet_has_pending_sec_level: after lock"); + + hcon = hci_conn_hash_lookup_handle(hdev, handle); + + hci_dev_unlock(hdev); + + if (hcon) { + return hcon->pending_sec_level != hcon->sec_level; + } + + return 0; +} + + /* SCO data packet */ static void hci_scodata_packet(struct hci_dev *hdev, struct sk_buff *skb) { @@ -4164,6 +4190,39 @@ spin_unlock_irqrestore(&hdev->cmd_q.lock, flags); } +static struct sk_buff *hci_dequeue_rx_packet(struct hci_dev *hdev) +{ + unsigned long flags; + struct sk_buff *skb; + struct sk_buff_head *list = &hdev->rx_q; + + BT_DBG("#hci_dequeue_rx_packet: before lock"); + spin_lock_irqsave(&list->lock, flags); + BT_DBG("#hci_dequeue_rx_packet: after lock"); + + skb = skb_peek(list); + + while (skb) { + if (hci_skb_pkt_type(skb) != HCI_ACLDATA_PKT) { + break; + } + + if (!hci_acldata_packet_has_pending_sec_level(hdev, skb)) { + break; + } + + BT_DBG("skipping ACL packet (delayed because of pending sec level)"); + skb = skb_peek_next(skb, list); + } + + if (skb) + __skb_unlink(skb, list); + + spin_unlock_irqrestore(&list->lock, flags); + + return skb; +} + static void hci_rx_work(struct work_struct *work) { struct hci_dev *hdev = container_of(work, struct hci_dev, rx_work); @@ -4171,7 +4230,7 @@ BT_DBG("%s", hdev->name); - while ((skb = skb_dequeue(&hdev->rx_q))) { + while ((skb = hci_dequeue_rx_packet(hdev))) { /* Send copy to monitor */ hci_send_to_monitor(hdev, skb); On Tue, Sep 25, 2018 at 06:08:32PM +0200, fabien dvlt wrote: > Hello, > > After trying 42 connections, 30% of my attempts are failing on > authentication (bluez 5.47). This happens with multiple (all?) Android > phones. > > Below are the btmon logs which I am finding interesting after that you > will find the complete logs. > > For all of my failing connection, I saw that an L2CAP connection > requests with PSM 0x19 is processed just before 'Encryption Change' > event. But, for all successful attempts this L2CAP connection request > is made after "Encryption Change' event. > So I made a patch to postpone the involved ACL packet after the > Encryption Change event and now I have 100% of success but it is still > a little hackish. > > May be this is also related to > https://www.spinics.net/lists/linux-bluetooth/msg72827.html > > Thank you > > ------------------------------ > > > HCI Event: Link Key Request (0x17) plen 6 #195 [hci0] 21.708115 > Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > < HCI Command: Link Key Request Reply (0x01|0x000b) plen 22 > > > > #196 [hci0] > 21.708397 > Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > Link key: feff6b48c953f119c1579913be0c0f65 > > HCI Event: Command Complete (0x0e) plen 10 #197 [hci0] 21.710115 > Link Key Request Reply (0x01|0x000b) ncmd 1 > Status: Success (0x00) > Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > > ACL Data RX: Handle 13 flags 0x02 dlen 12 #198 [hci0] 21.813116 > L2CAP: Connection Request (0x02) ident 7 len 4 > PSM: 25 (0x0019) > Source CID: 75 > > HCI Event: Encryption Change (0x08) plen 4 #199 [hci0] 21.813155 > Status: Success (0x00) > Handle: 13 > Encryption: Enabled with AES-CCM (0x02) > < ACL Data TX: Handle 13 flags 0x00 dlen 16 > > > > #200 [hci0] > 21.813256 > L2CAP: Connection Response (0x03) ident 7 len 8 > Destination CID: 0 > Source CID: 75 > Result: Connection refused - security block (0x0003) > Status: No further information available (0x0000) > > ------------------------------ > > # COMPLETE BTMON LOGS > > > HCI Event: Connect Request (0x04) plen 10 #152 [hci0] 21.335093 > Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > Class: 0x5a020c > Major class: Phone (cellular, cordless, payphone, modem) > Minor class: Smart phone > Networking (LAN, Ad hoc) > Capturing (Scanner, Microphone) > Object Transfer (v-Inbox, v-Folder) > Telephony (Cordless telephony, Modem, Headset) > Link type: ACL (0x01) > < HCI Command: Accept Connection Request (0x01|0x0009) plen 7 > > > > #153 [hci0] > 21.335196 > Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > Role: Master (0x00) > > HCI Event: Command Status (0x0f) plen 4 #154 [hci0] 21.337107 > Accept Connection Request (0x01|0x0009) ncmd 1 > Status: Success (0x00) > > HCI Event: Role Change (0x12) plen 8 #155 [hci0] 21.589092 > Status: Success (0x00) > Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > Role: Master (0x00) > > HCI Event: Connect Complete (0x03) plen 11 #156 [hci0] 21.596088 > Status: Success (0x00) > Handle: 13 > Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > Link type: ACL (0x01) > Encryption: Disabled (0x00) > < HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2 > > > > #157 [hci0] > 21.596328 > Handle: 13 > > HCI Event: Command Status (0x0f) plen 4 #158 [hci0] 21.607116 > Read Remote Supported Features (0x01|0x001b) ncmd 1 > Status: Success (0x00) > > HCI Event: Page Scan Repetition Mode Change (0x20) plen 7 #159 [hci0] 21.608112 > Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > Page scan repetition mode: R1 (0x01) > > HCI Event: Max Slots Change (0x1b) plen 3 #160 [hci0] 21.609114 > Handle: 13 > Max slots: 5 > > HCI Event: Read Remote Supported Features (0x0b) plen 11 #161 [hci0] 21.612116 > Status: Success (0x00) > Handle: 13 > Features: 0xff 0xfe 0x8f 0xfe 0xd8 0x3f 0x5b 0x87 > 3 slot packets > 5 slot packets > Encryption > Slot offset > Timing accuracy > Role switch > Hold mode > Sniff mode > Power control requests > Channel quality driven data rate (CQDDR) > SCO link > HV2 packets > HV3 packets > u-law log synchronous data > A-law log synchronous data > CVSD synchronous data > Paging parameter negotiation > Power control > Transparent synchronous data > Broadcast Encryption > Enhanced Data Rate ACL 2 Mbps mode > Enhanced Data Rate ACL 3 Mbps mode > Enhanced inquiry scan > Interlaced inquiry scan > Interlaced page scan > RSSI with inquiry results > Extended SCO link (EV3 packets) > AFH capable slave > AFH classification slave > LE Supported (Controller) > 3-slot Enhanced Data Rate ACL packets > 5-slot Enhanced Data Rate ACL packets > Sniff subrating > Pause encryption > AFH capable master > AFH classification master > Enhanced Data Rate eSCO 2 Mbps mode > Extended Inquiry Response > Simultaneous LE and BR/EDR (Controller) > Secure Simple Pairing > Encapsulated PDU > Non-flushable Packet Boundary Flag > Link Supervision Timeout Changed Event > Inquiry TX Power Level > Enhanced Power Control > Extended features > < HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3 > > > > #162 [hci0] > 21.612211 > Handle: 13 > Page: 1 > > HCI Event: Command Status (0x0f) plen 4 #163 [hci0] 21.614113 > Read Remote Extended Features (0x01|0x001c) ncmd 1 > Status: Success (0x00) > > ACL Data RX: Handle 13 flags 0x02 dlen 10 #164 [hci0] 21.617110 > L2CAP: Information Request (0x0a) ident 2 len 2 > Type: Extended features supported (0x0002) > > HCI Event: Read Remote Extended Features (0x23) plen 13 #165 [hci0] 21.617139 > Status: Success (0x00) > Handle: 13 > Page: 1/2 > Features: 0x0f 0x00 0x00 0x00 0x00 0x00 0x00 0x00 > Secure Simple Pairing (Host Support) > LE Supported (Host) > Simultaneous LE and BR/EDR (Host) > Secure Connections (Host Support) > < HCI Command: Remote Name Request (0x01|0x0019) plen 10 > > > > #166 [hci0] > 21.617258 > Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > Page scan repetition mode: R2 (0x02) > Page scan mode: Mandatory (0x00) > Clock offset: 0x0000 > < ACL Data TX: Handle 13 flags 0x00 dlen 10 > > > > #167 [hci0] > 21.617284 > L2CAP: Information Request (0x0a) ident 1 len 2 > Type: Extended features supported (0x0002) > < ACL Data TX: Handle 13 flags 0x00 dlen 16 > > > > #168 [hci0] > 21.617307 > L2CAP: Information Response (0x0b) ident 2 len 8 > Type: Extended features supported (0x0002) > Result: Success (0x0000) > Features: 0x000002b8 > Enhanced Retransmission Mode > Streaming Mode > FCS Option > Fixed Channels > Unicast Connectionless Data Reception > > HCI Event: Command Status (0x0f) plen 4 #169 [hci0] 21.619110 > Remote Name Request (0x01|0x0019) ncmd 1 > Status: Success (0x00) > > HCI Event: Number of Completed Packets (0x13) plen 5 #170 [hci0] 21.620114 > Num handles: 1 > Handle: 13 > Count: 1 > > ACL Data RX: Handle 13 flags 0x02 dlen 16 #171 [hci0] 21.622116 > L2CAP: Information Response (0x0b) ident 1 len 8 > Type: Extended features supported (0x0002) > Result: Success (0x0000) > Features: 0x000000b8 > Enhanced Retransmission Mode > Streaming Mode > FCS Option > Fixed Channels > < ACL Data TX: Handle 13 flags 0x00 dlen 10 > > > > #172 [hci0] > 21.622208 > L2CAP: Information Request (0x0a) ident 2 len 2 > Type: Fixed channels supported (0x0003) > > HCI Event: Number of Completed Packets (0x13) plen 5 #173 [hci0] 21.626110 > Num handles: 1 > Handle: 13 > Count: 1 > > ACL Data RX: Handle 13 flags 0x02 dlen 10 #174 [hci0] 21.628106 > L2CAP: Information Request (0x0a) ident 3 len 2 > Type: Fixed channels supported (0x0003) > < ACL Data TX: Handle 13 flags 0x00 dlen 20 > > > > #175 [hci0] > 21.628386 > L2CAP: Information Response (0x0b) ident 3 len 12 > Type: Fixed channels supported (0x0003) > Result: Success (0x0000) > Channels: 0x0000000000000086 > L2CAP Signaling (BR/EDR) > Connectionless reception > Security Manager (BR/EDR) > > ACL Data RX: Handle 13 flags 0x02 dlen 20 #176 [hci0] 21.636079 > L2CAP: Information Response (0x0b) ident 2 len 12 > Type: Fixed channels supported (0x0003) > Result: Success (0x0000) > Channels: 0x0000000000000082 > L2CAP Signaling (BR/EDR) > Security Manager (BR/EDR) > > ACL Data RX: Handle 13 flags 0x02 dlen 12 #177 [hci0] 21.638082 > L2CAP: Connection Request (0x02) ident 4 len 4 > PSM: 1 (0x0001) > Source CID: 74 > @ MGMT Event: Device Connected (0x000b) plen 18 > > > > {0x0002} [hci0] > 21.638158 > BR/EDR Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > Flags: 0x00000000 > Data length: 5 > Class: 0x5a020c > Major class: Phone (cellular, cordless, payphone, modem) > Minor class: Smart phone > Networking (LAN, Ad hoc) > Capturing (Scanner, Microphone) > Object Transfer (v-Inbox, v-Folder) > Telephony (Cordless telephony, Modem, Headset) > @ MGMT Event: Device Connected (0x000b) plen 18 > > > > {0x0001} [hci0] > 21.638158 > BR/EDR Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > Flags: 0x00000000 > Data length: 5 > Class: 0x5a020c > Major class: Phone (cellular, cordless, payphone, modem) > Minor class: Smart phone > Networking (LAN, Ad hoc) > Capturing (Scanner, Microphone) > Object Transfer (v-Inbox, v-Folder) > Telephony (Cordless telephony, Modem, Headset) > < ACL Data TX: Handle 13 flags 0x00 dlen 16 > > > > #178 [hci0] > 21.638233 > L2CAP: Connection Response (0x03) ident 4 len 8 > Destination CID: 64 > Source CID: 74 > Result: Connection successful (0x0000) > Status: No further information available (0x0000) > < ACL Data TX: Handle 13 flags 0x00 dlen 23 > > > > #179 [hci0] > 21.638251 > L2CAP: Configure Request (0x04) ident 3 len 15 > Destination CID: 74 > Flags: 0x0000 > Option: Retransmission and Flow Control (0x04) [mandatory] > Mode: Basic (0x00) > TX window size: 0 > Max transmit: 0 > Retransmission timeout: 0 > Monitor timeout: 0 > Maximum PDU size: 0 > > HCI Event: Remote Name Req Complete (0x07) plen 255 #180 [hci0] 21.643122 > Status: Success (0x00) > Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > Name: OnePlus 6 > > HCI Event: Number of Completed Packets (0x13) plen 5 #181 [hci0] 21.644131 > Num handles: 1 > Handle: 13 > Count: 1 > > HCI Event: Number of Completed Packets (0x13) plen 5 #182 [hci0] 21.645124 > Num handles: 1 > Handle: 13 > Count: 1 > > HCI Event: Number of Completed Packets (0x13) plen 5 #183 [hci0] 21.648116 > Num handles: 1 > Handle: 13 > Count: 1 > > HCI Event: Number of Completed Packets (0x13) plen 5 #184 [hci0] 21.649120 > Num handles: 1 > Handle: 13 > Count: 1 > > ACL Data RX: Handle 13 flags 0x02 dlen 16 #185 [hci0] 21.658113 > L2CAP: Configure Request (0x04) ident 5 len 8 > Destination CID: 64 > Flags: 0x0000 > Option: Maximum Transmission Unit (0x01) [mandatory] > MTU: 672 > < ACL Data TX: Handle 13 flags 0x00 dlen 18 > > > > #186 [hci0] > 21.658194 > L2CAP: Configure Response (0x05) ident 5 len 10 > Source CID: 74 > Flags: 0x0000 > Result: Success (0x0000) > Option: Maximum Transmission Unit (0x01) [mandatory] > MTU: 672 > > ACL Data RX: Handle 13 flags 0x02 dlen 14 #187 [hci0] 21.659124 > L2CAP: Configure Response (0x05) ident 3 len 6 > Source CID: 64 > Flags: 0x0000 > Result: Success (0x0000) > > HCI Event: Number of Completed Packets (0x13) plen 5 #188 [hci0] 21.661118 > Num handles: 1 > Handle: 13 > Count: 1 > > ACL Data RX: Handle 13 flags 0x02 dlen 28 #189 [hci0] 21.663116 > Channel: 64 len 24 [PSM 1 mode 0] {chan 0} > SDP: Service Search Attribute Request (0x06) tid 0 len 19 > Search pattern: [len 5] > Sequence (6) with 3 bytes [8 extra bits] len 5 > UUID (3) with 2 bytes [0 extra bits] len 3 > Audio Sink (0x110b) > Max record count: 656 > Attribute list: [len 11] > Sequence (6) with 9 bytes [8 extra bits] len 11 > Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 > 0x0001 > Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 > 0x0004 > Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 > 0x0009 > Continuation state: 0 > < ACL Data TX: Handle 13 flags 0x00 dlen 58 > > > > #190 [hci0] > 21.663513 > Channel: 74 len 54 [PSM 1 mode 0] {chan 0} > SDP: Service Search Attribute Response (0x07) tid 0 len 49 > Attribute bytes: 46 > Attribute list: [len 42] {position 0} > Attribute: Service Class ID List (0x0001) [len 2] > UUID (3) with 2 bytes [0 extra bits] len 3 > Audio Sink (0x110b) > Attribute: Protocol Descriptor List (0x0004) [len 2] > Sequence (6) with 6 bytes [8 extra bits] len 8 > UUID (3) with 2 bytes [0 extra bits] len 3 > L2CAP (0x0100) > Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 > 0x0019 > Sequence (6) with 6 bytes [8 extra bits] len 8 > UUID (3) with 2 bytes [0 extra bits] len 3 > AVDTP (0x0019) > Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 > 0x0103 > Attribute: Bluetooth Profile Descriptor List (0x0009) [len 2] > Sequence (6) with 6 bytes [8 extra bits] len 8 > UUID (3) with 2 bytes [0 extra bits] len 3 > Advanced Audio Distribution (0x110d) > Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 > 0x0103 > Continuation state: 0 > > HCI Event: Number of Completed Packets (0x13) plen 5 #191 [hci0] 21.670123 > Num handles: 1 > Handle: 13 > Count: 1 > > ACL Data RX: Handle 13 flags 0x02 dlen 12 #192 [hci0] 21.682116 > L2CAP: Disconnection Request (0x06) ident 6 len 4 > Destination CID: 64 > Source CID: 74 > < ACL Data TX: Handle 13 flags 0x00 dlen 12 > > > > #193 [hci0] > 21.682230 > L2CAP: Disconnection Response (0x07) ident 6 len 4 > Destination CID: 64 > Source CID: 74 > > HCI Event: Number of Completed Packets (0x13) plen 5 #194 [hci0] 21.685121 > Num handles: 1 > Handle: 13 > Count: 1 > > HCI Event: Link Key Request (0x17) plen 6 #195 [hci0] 21.708115 > Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > < HCI Command: Link Key Request Reply (0x01|0x000b) plen 22 > > > > #196 [hci0] > 21.708397 > Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > Link key: feff6b48c953f119c1579913be0c0f65 > > HCI Event: Command Complete (0x0e) plen 10 #197 [hci0] 21.710115 > Link Key Request Reply (0x01|0x000b) ncmd 1 > Status: Success (0x00) > Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > > ACL Data RX: Handle 13 flags 0x02 dlen 12 #198 [hci0] 21.813116 > L2CAP: Connection Request (0x02) ident 7 len 4 > PSM: 25 (0x0019) > Source CID: 75 > > HCI Event: Encryption Change (0x08) plen 4 #199 [hci0] 21.813155 > Status: Success (0x00) > Handle: 13 > Encryption: Enabled with AES-CCM (0x02) > < ACL Data TX: Handle 13 flags 0x00 dlen 16 > > > > #200 [hci0] > 21.813256 > L2CAP: Connection Response (0x03) ident 7 len 8 > Destination CID: 0 > Source CID: 75 > Result: Connection refused - security block (0x0003) > Status: No further information available (0x0000) > < HCI Command: Read Encryption Key Size (0x05|0x0008) plen 2 > > > > #201 [hci0] > 21.813277 > Handle: 13 > > HCI Event: Command Complete (0x0e) plen 7 #202 [hci0] 21.815118 > Read Encryption Key Size (0x05|0x0008) ncmd 1 > Status: Success (0x00) > Handle: 13 > Key size: 16 > > HCI Event: Number of Completed Packets (0x13) plen 5 #203 [hci0] 21.816118 > Num handles: 1 > Handle: 13 > Count: 1 > > < HCI Command: Disconnect (0x01|0x0006) plen 3 > > > > #204 [hci0] > 25.727125 > Handle: 13 > Reason: Authentication Failure (0x05) > > HCI Event: Command Status (0x0f) plen 4 #205 [hci0] 25.729069 > Disconnect (0x01|0x0006) ncmd 1 > Status: Success (0x00) > > HCI Event: Disconnect Complete (0x05) plen 4 #206 [hci0] 25.738073 > Status: Success (0x00) > Handle: 13 > Reason: Connection Terminated By Local Host (0x16) > @ MGMT Event: Device Disconnected (0x000c) plen 8 > > > > {0x0002} [hci0] > 25.738149 > BR/EDR Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > Reason: Connection terminated by local host (0x02) > @ MGMT Event: Device Disconnected (0x000c) plen 8 > > > > {0x0001} [hci0] > 25.738149 > BR/EDR Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) > Reason: Connection terminated by local host (0x02) ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Security block and Bluez - connection issue with Android 2018-09-26 11:03 ` fabien dvlt @ 2018-09-26 11:23 ` Luiz Augusto von Dentz 0 siblings, 0 replies; 6+ messages in thread From: Luiz Augusto von Dentz @ 2018-09-26 11:23 UTC (permalink / raw) To: fabien dvlt; +Cc: linux-bluetooth Hi Fabien, On Wed, Sep 26, 2018 at 2:03 PM, fabien dvlt <fabiendvlt@gmail.com> wrote: > Hi, > > Here is an ugly patch only for understanding or testing purpose. > > It did correct my connections issues but there might side effects (like a > deadlock although I did not have any). > > If you have any advise on how to fix this connection issue in a clean way, > I would be glad to know it. I will be trying to do something cleaner in the > next days. Usually this short of problem is race condition between the USB endpoints, the controller send the encryption change on the command endpoint along with ACL packets on the data endpoint but the data endpoint endup being picked first thus causing the problem. > --- > > --- linux-4.9.109/net/bluetooth/hci_core.c 2018-09-26 11:09:46.313308347 +0200 > +++ linux/net/bluetooth/hci_core.c 2018-09-26 11:08:40.633482950 +0200 > @@ -4038,6 +4038,32 @@ > kfree_skb(skb); > } > > +static int hci_acldata_packet_has_pending_sec_level(struct hci_dev *hdev, > + struct sk_buff *skb) > +{ > + struct hci_acl_hdr *hdr = (void *) skb->data; > + struct hci_conn *hcon; > + __u16 handle; > + > + handle = __le16_to_cpu(hdr->handle); > + handle = hci_handle(handle); > + > + BT_DBG("#hci_acldata_packet_has_pending_sec_level: before lock"); > + hci_dev_lock(hdev); > + BT_DBG("#hci_acldata_packet_has_pending_sec_level: after lock"); > + > + hcon = hci_conn_hash_lookup_handle(hdev, handle); > + > + hci_dev_unlock(hdev); > + > + if (hcon) { > + return hcon->pending_sec_level != hcon->sec_level; > + } > + > + return 0; > +} > + > + > /* SCO data packet */ > static void hci_scodata_packet(struct hci_dev *hdev, struct sk_buff *skb) > { > @@ -4164,6 +4190,39 @@ > spin_unlock_irqrestore(&hdev->cmd_q.lock, flags); > } > > +static struct sk_buff *hci_dequeue_rx_packet(struct hci_dev *hdev) > +{ > + unsigned long flags; > + struct sk_buff *skb; > + struct sk_buff_head *list = &hdev->rx_q; > + > + BT_DBG("#hci_dequeue_rx_packet: before lock"); > + spin_lock_irqsave(&list->lock, flags); > + BT_DBG("#hci_dequeue_rx_packet: after lock"); > + > + skb = skb_peek(list); > + > + while (skb) { > + if (hci_skb_pkt_type(skb) != HCI_ACLDATA_PKT) { > + break; > + } > + > + if (!hci_acldata_packet_has_pending_sec_level(hdev, skb)) { > + break; > + } > + > + BT_DBG("skipping ACL packet (delayed because of pending sec level)"); > + skb = skb_peek_next(skb, list); > + } > + > + if (skb) > + __skb_unlink(skb, list); > + > + spin_unlock_irqrestore(&list->lock, flags); > + > + return skb; > +} > + > static void hci_rx_work(struct work_struct *work) > { > struct hci_dev *hdev = container_of(work, struct hci_dev, rx_work); > @@ -4171,7 +4230,7 @@ > > BT_DBG("%s", hdev->name); > > - while ((skb = skb_dequeue(&hdev->rx_q))) { > + while ((skb = hci_dequeue_rx_packet(hdev))) { > /* Send copy to monitor */ > hci_send_to_monitor(hdev, skb); I think someone tried this before but it was considered too much of a hack since with this sort of logic we would not garanteed that all packets were actually encrypted over the air. > > > On Tue, Sep 25, 2018 at 06:08:32PM +0200, fabien dvlt wrote: >> Hello, >> >> After trying 42 connections, 30% of my attempts are failing on >> authentication (bluez 5.47). This happens with multiple (all?) Android >> phones. >> >> Below are the btmon logs which I am finding interesting after that you >> will find the complete logs. >> >> For all of my failing connection, I saw that an L2CAP connection >> requests with PSM 0x19 is processed just before 'Encryption Change' >> event. But, for all successful attempts this L2CAP connection request >> is made after "Encryption Change' event. >> So I made a patch to postpone the involved ACL packet after the >> Encryption Change event and now I have 100% of success but it is still >> a little hackish. >> >> May be this is also related to >> https://www.spinics.net/lists/linux-bluetooth/msg72827.html >> >> Thank you >> >> ------------------------------ >> >> > HCI Event: Link Key Request (0x17) plen 6 #195 [hci0] 21.708115 >> Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> < HCI Command: Link Key Request Reply (0x01|0x000b) plen 22 >> >> >> >> #196 [hci0] >> 21.708397 >> Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> Link key: feff6b48c953f119c1579913be0c0f65 >> > HCI Event: Command Complete (0x0e) plen 10 #197 [hci0] 21.710115 >> Link Key Request Reply (0x01|0x000b) ncmd 1 >> Status: Success (0x00) >> Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> > ACL Data RX: Handle 13 flags 0x02 dlen 12 #198 [hci0] 21.813116 >> L2CAP: Connection Request (0x02) ident 7 len 4 >> PSM: 25 (0x0019) >> Source CID: 75 >> > HCI Event: Encryption Change (0x08) plen 4 #199 [hci0] 21.813155 >> Status: Success (0x00) >> Handle: 13 >> Encryption: Enabled with AES-CCM (0x02) >> < ACL Data TX: Handle 13 flags 0x00 dlen 16 >> >> >> >> #200 [hci0] >> 21.813256 >> L2CAP: Connection Response (0x03) ident 7 len 8 >> Destination CID: 0 >> Source CID: 75 >> Result: Connection refused - security block (0x0003) >> Status: No further information available (0x0000) >> >> ------------------------------ >> >> # COMPLETE BTMON LOGS >> >> > HCI Event: Connect Request (0x04) plen 10 #152 [hci0] 21.335093 >> Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> Class: 0x5a020c >> Major class: Phone (cellular, cordless, payphone, modem) >> Minor class: Smart phone >> Networking (LAN, Ad hoc) >> Capturing (Scanner, Microphone) >> Object Transfer (v-Inbox, v-Folder) >> Telephony (Cordless telephony, Modem, Headset) >> Link type: ACL (0x01) >> < HCI Command: Accept Connection Request (0x01|0x0009) plen 7 >> >> >> >> #153 [hci0] >> 21.335196 >> Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> Role: Master (0x00) >> > HCI Event: Command Status (0x0f) plen 4 #154 [hci0] 21.337107 >> Accept Connection Request (0x01|0x0009) ncmd 1 >> Status: Success (0x00) >> > HCI Event: Role Change (0x12) plen 8 #155 [hci0] 21.589092 >> Status: Success (0x00) >> Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> Role: Master (0x00) >> > HCI Event: Connect Complete (0x03) plen 11 #156 [hci0] 21.596088 >> Status: Success (0x00) >> Handle: 13 >> Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> Link type: ACL (0x01) >> Encryption: Disabled (0x00) >> < HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2 >> >> >> >> #157 [hci0] >> 21.596328 >> Handle: 13 >> > HCI Event: Command Status (0x0f) plen 4 #158 [hci0] 21.607116 >> Read Remote Supported Features (0x01|0x001b) ncmd 1 >> Status: Success (0x00) >> > HCI Event: Page Scan Repetition Mode Change (0x20) plen 7 #159 [hci0] 21.608112 >> Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> Page scan repetition mode: R1 (0x01) >> > HCI Event: Max Slots Change (0x1b) plen 3 #160 [hci0] 21.609114 >> Handle: 13 >> Max slots: 5 >> > HCI Event: Read Remote Supported Features (0x0b) plen 11 #161 [hci0] 21.612116 >> Status: Success (0x00) >> Handle: 13 >> Features: 0xff 0xfe 0x8f 0xfe 0xd8 0x3f 0x5b 0x87 >> 3 slot packets >> 5 slot packets >> Encryption >> Slot offset >> Timing accuracy >> Role switch >> Hold mode >> Sniff mode >> Power control requests >> Channel quality driven data rate (CQDDR) >> SCO link >> HV2 packets >> HV3 packets >> u-law log synchronous data >> A-law log synchronous data >> CVSD synchronous data >> Paging parameter negotiation >> Power control >> Transparent synchronous data >> Broadcast Encryption >> Enhanced Data Rate ACL 2 Mbps mode >> Enhanced Data Rate ACL 3 Mbps mode >> Enhanced inquiry scan >> Interlaced inquiry scan >> Interlaced page scan >> RSSI with inquiry results >> Extended SCO link (EV3 packets) >> AFH capable slave >> AFH classification slave >> LE Supported (Controller) >> 3-slot Enhanced Data Rate ACL packets >> 5-slot Enhanced Data Rate ACL packets >> Sniff subrating >> Pause encryption >> AFH capable master >> AFH classification master >> Enhanced Data Rate eSCO 2 Mbps mode >> Extended Inquiry Response >> Simultaneous LE and BR/EDR (Controller) >> Secure Simple Pairing >> Encapsulated PDU >> Non-flushable Packet Boundary Flag >> Link Supervision Timeout Changed Event >> Inquiry TX Power Level >> Enhanced Power Control >> Extended features >> < HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3 >> >> >> >> #162 [hci0] >> 21.612211 >> Handle: 13 >> Page: 1 >> > HCI Event: Command Status (0x0f) plen 4 #163 [hci0] 21.614113 >> Read Remote Extended Features (0x01|0x001c) ncmd 1 >> Status: Success (0x00) >> > ACL Data RX: Handle 13 flags 0x02 dlen 10 #164 [hci0] 21.617110 >> L2CAP: Information Request (0x0a) ident 2 len 2 >> Type: Extended features supported (0x0002) >> > HCI Event: Read Remote Extended Features (0x23) plen 13 #165 [hci0] 21.617139 >> Status: Success (0x00) >> Handle: 13 >> Page: 1/2 >> Features: 0x0f 0x00 0x00 0x00 0x00 0x00 0x00 0x00 >> Secure Simple Pairing (Host Support) >> LE Supported (Host) >> Simultaneous LE and BR/EDR (Host) >> Secure Connections (Host Support) >> < HCI Command: Remote Name Request (0x01|0x0019) plen 10 >> >> >> >> #166 [hci0] >> 21.617258 >> Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> Page scan repetition mode: R2 (0x02) >> Page scan mode: Mandatory (0x00) >> Clock offset: 0x0000 >> < ACL Data TX: Handle 13 flags 0x00 dlen 10 >> >> >> >> #167 [hci0] >> 21.617284 >> L2CAP: Information Request (0x0a) ident 1 len 2 >> Type: Extended features supported (0x0002) >> < ACL Data TX: Handle 13 flags 0x00 dlen 16 >> >> >> >> #168 [hci0] >> 21.617307 >> L2CAP: Information Response (0x0b) ident 2 len 8 >> Type: Extended features supported (0x0002) >> Result: Success (0x0000) >> Features: 0x000002b8 >> Enhanced Retransmission Mode >> Streaming Mode >> FCS Option >> Fixed Channels >> Unicast Connectionless Data Reception >> > HCI Event: Command Status (0x0f) plen 4 #169 [hci0] 21.619110 >> Remote Name Request (0x01|0x0019) ncmd 1 >> Status: Success (0x00) >> > HCI Event: Number of Completed Packets (0x13) plen 5 #170 [hci0] 21.620114 >> Num handles: 1 >> Handle: 13 >> Count: 1 >> > ACL Data RX: Handle 13 flags 0x02 dlen 16 #171 [hci0] 21.622116 >> L2CAP: Information Response (0x0b) ident 1 len 8 >> Type: Extended features supported (0x0002) >> Result: Success (0x0000) >> Features: 0x000000b8 >> Enhanced Retransmission Mode >> Streaming Mode >> FCS Option >> Fixed Channels >> < ACL Data TX: Handle 13 flags 0x00 dlen 10 >> >> >> >> #172 [hci0] >> 21.622208 >> L2CAP: Information Request (0x0a) ident 2 len 2 >> Type: Fixed channels supported (0x0003) >> > HCI Event: Number of Completed Packets (0x13) plen 5 #173 [hci0] 21.626110 >> Num handles: 1 >> Handle: 13 >> Count: 1 >> > ACL Data RX: Handle 13 flags 0x02 dlen 10 #174 [hci0] 21.628106 >> L2CAP: Information Request (0x0a) ident 3 len 2 >> Type: Fixed channels supported (0x0003) >> < ACL Data TX: Handle 13 flags 0x00 dlen 20 >> >> >> >> #175 [hci0] >> 21.628386 >> L2CAP: Information Response (0x0b) ident 3 len 12 >> Type: Fixed channels supported (0x0003) >> Result: Success (0x0000) >> Channels: 0x0000000000000086 >> L2CAP Signaling (BR/EDR) >> Connectionless reception >> Security Manager (BR/EDR) >> > ACL Data RX: Handle 13 flags 0x02 dlen 20 #176 [hci0] 21.636079 >> L2CAP: Information Response (0x0b) ident 2 len 12 >> Type: Fixed channels supported (0x0003) >> Result: Success (0x0000) >> Channels: 0x0000000000000082 >> L2CAP Signaling (BR/EDR) >> Security Manager (BR/EDR) >> > ACL Data RX: Handle 13 flags 0x02 dlen 12 #177 [hci0] 21.638082 >> L2CAP: Connection Request (0x02) ident 4 len 4 >> PSM: 1 (0x0001) >> Source CID: 74 >> @ MGMT Event: Device Connected (0x000b) plen 18 >> >> >> >> {0x0002} [hci0] >> 21.638158 >> BR/EDR Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> Flags: 0x00000000 >> Data length: 5 >> Class: 0x5a020c >> Major class: Phone (cellular, cordless, payphone, modem) >> Minor class: Smart phone >> Networking (LAN, Ad hoc) >> Capturing (Scanner, Microphone) >> Object Transfer (v-Inbox, v-Folder) >> Telephony (Cordless telephony, Modem, Headset) >> @ MGMT Event: Device Connected (0x000b) plen 18 >> >> >> >> {0x0001} [hci0] >> 21.638158 >> BR/EDR Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> Flags: 0x00000000 >> Data length: 5 >> Class: 0x5a020c >> Major class: Phone (cellular, cordless, payphone, modem) >> Minor class: Smart phone >> Networking (LAN, Ad hoc) >> Capturing (Scanner, Microphone) >> Object Transfer (v-Inbox, v-Folder) >> Telephony (Cordless telephony, Modem, Headset) >> < ACL Data TX: Handle 13 flags 0x00 dlen 16 >> >> >> >> #178 [hci0] >> 21.638233 >> L2CAP: Connection Response (0x03) ident 4 len 8 >> Destination CID: 64 >> Source CID: 74 >> Result: Connection successful (0x0000) >> Status: No further information available (0x0000) >> < ACL Data TX: Handle 13 flags 0x00 dlen 23 >> >> >> >> #179 [hci0] >> 21.638251 >> L2CAP: Configure Request (0x04) ident 3 len 15 >> Destination CID: 74 >> Flags: 0x0000 >> Option: Retransmission and Flow Control (0x04) [mandatory] >> Mode: Basic (0x00) >> TX window size: 0 >> Max transmit: 0 >> Retransmission timeout: 0 >> Monitor timeout: 0 >> Maximum PDU size: 0 >> > HCI Event: Remote Name Req Complete (0x07) plen 255 #180 [hci0] 21.643122 >> Status: Success (0x00) >> Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> Name: OnePlus 6 >> > HCI Event: Number of Completed Packets (0x13) plen 5 #181 [hci0] 21.644131 >> Num handles: 1 >> Handle: 13 >> Count: 1 >> > HCI Event: Number of Completed Packets (0x13) plen 5 #182 [hci0] 21.645124 >> Num handles: 1 >> Handle: 13 >> Count: 1 >> > HCI Event: Number of Completed Packets (0x13) plen 5 #183 [hci0] 21.648116 >> Num handles: 1 >> Handle: 13 >> Count: 1 >> > HCI Event: Number of Completed Packets (0x13) plen 5 #184 [hci0] 21.649120 >> Num handles: 1 >> Handle: 13 >> Count: 1 >> > ACL Data RX: Handle 13 flags 0x02 dlen 16 #185 [hci0] 21.658113 >> L2CAP: Configure Request (0x04) ident 5 len 8 >> Destination CID: 64 >> Flags: 0x0000 >> Option: Maximum Transmission Unit (0x01) [mandatory] >> MTU: 672 >> < ACL Data TX: Handle 13 flags 0x00 dlen 18 >> >> >> >> #186 [hci0] >> 21.658194 >> L2CAP: Configure Response (0x05) ident 5 len 10 >> Source CID: 74 >> Flags: 0x0000 >> Result: Success (0x0000) >> Option: Maximum Transmission Unit (0x01) [mandatory] >> MTU: 672 >> > ACL Data RX: Handle 13 flags 0x02 dlen 14 #187 [hci0] 21.659124 >> L2CAP: Configure Response (0x05) ident 3 len 6 >> Source CID: 64 >> Flags: 0x0000 >> Result: Success (0x0000) >> > HCI Event: Number of Completed Packets (0x13) plen 5 #188 [hci0] 21.661118 >> Num handles: 1 >> Handle: 13 >> Count: 1 >> > ACL Data RX: Handle 13 flags 0x02 dlen 28 #189 [hci0] 21.663116 >> Channel: 64 len 24 [PSM 1 mode 0] {chan 0} >> SDP: Service Search Attribute Request (0x06) tid 0 len 19 >> Search pattern: [len 5] >> Sequence (6) with 3 bytes [8 extra bits] len 5 >> UUID (3) with 2 bytes [0 extra bits] len 3 >> Audio Sink (0x110b) >> Max record count: 656 >> Attribute list: [len 11] >> Sequence (6) with 9 bytes [8 extra bits] len 11 >> Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 >> 0x0001 >> Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 >> 0x0004 >> Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 >> 0x0009 >> Continuation state: 0 >> < ACL Data TX: Handle 13 flags 0x00 dlen 58 >> >> >> >> #190 [hci0] >> 21.663513 >> Channel: 74 len 54 [PSM 1 mode 0] {chan 0} >> SDP: Service Search Attribute Response (0x07) tid 0 len 49 >> Attribute bytes: 46 >> Attribute list: [len 42] {position 0} >> Attribute: Service Class ID List (0x0001) [len 2] >> UUID (3) with 2 bytes [0 extra bits] len 3 >> Audio Sink (0x110b) >> Attribute: Protocol Descriptor List (0x0004) [len 2] >> Sequence (6) with 6 bytes [8 extra bits] len 8 >> UUID (3) with 2 bytes [0 extra bits] len 3 >> L2CAP (0x0100) >> Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 >> 0x0019 >> Sequence (6) with 6 bytes [8 extra bits] len 8 >> UUID (3) with 2 bytes [0 extra bits] len 3 >> AVDTP (0x0019) >> Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 >> 0x0103 >> Attribute: Bluetooth Profile Descriptor List (0x0009) [len 2] >> Sequence (6) with 6 bytes [8 extra bits] len 8 >> UUID (3) with 2 bytes [0 extra bits] len 3 >> Advanced Audio Distribution (0x110d) >> Unsigned Integer (1) with 2 bytes [0 extra bits] len 3 >> 0x0103 >> Continuation state: 0 >> > HCI Event: Number of Completed Packets (0x13) plen 5 #191 [hci0] 21.670123 >> Num handles: 1 >> Handle: 13 >> Count: 1 >> > ACL Data RX: Handle 13 flags 0x02 dlen 12 #192 [hci0] 21.682116 >> L2CAP: Disconnection Request (0x06) ident 6 len 4 >> Destination CID: 64 >> Source CID: 74 >> < ACL Data TX: Handle 13 flags 0x00 dlen 12 >> >> >> >> #193 [hci0] >> 21.682230 >> L2CAP: Disconnection Response (0x07) ident 6 len 4 >> Destination CID: 64 >> Source CID: 74 >> > HCI Event: Number of Completed Packets (0x13) plen 5 #194 [hci0] 21.685121 >> Num handles: 1 >> Handle: 13 >> Count: 1 >> > HCI Event: Link Key Request (0x17) plen 6 #195 [hci0] 21.708115 >> Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> < HCI Command: Link Key Request Reply (0x01|0x000b) plen 22 >> >> >> >> #196 [hci0] >> 21.708397 >> Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> Link key: feff6b48c953f119c1579913be0c0f65 >> > HCI Event: Command Complete (0x0e) plen 10 #197 [hci0] 21.710115 >> Link Key Request Reply (0x01|0x000b) ncmd 1 >> Status: Success (0x00) >> Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> > ACL Data RX: Handle 13 flags 0x02 dlen 12 #198 [hci0] 21.813116 >> L2CAP: Connection Request (0x02) ident 7 len 4 >> PSM: 25 (0x0019) >> Source CID: 75 >> > HCI Event: Encryption Change (0x08) plen 4 #199 [hci0] 21.813155 >> Status: Success (0x00) >> Handle: 13 >> Encryption: Enabled with AES-CCM (0x02) >> < ACL Data TX: Handle 13 flags 0x00 dlen 16 >> >> >> >> #200 [hci0] >> 21.813256 >> L2CAP: Connection Response (0x03) ident 7 len 8 >> Destination CID: 0 >> Source CID: 75 >> Result: Connection refused - security block (0x0003) >> Status: No further information available (0x0000) >> < HCI Command: Read Encryption Key Size (0x05|0x0008) plen 2 >> >> >> >> #201 [hci0] >> 21.813277 >> Handle: 13 >> > HCI Event: Command Complete (0x0e) plen 7 #202 [hci0] 21.815118 >> Read Encryption Key Size (0x05|0x0008) ncmd 1 >> Status: Success (0x00) >> Handle: 13 >> Key size: 16 >> > HCI Event: Number of Completed Packets (0x13) plen 5 #203 [hci0] 21.816118 >> Num handles: 1 >> Handle: 13 >> Count: 1 >> >> < HCI Command: Disconnect (0x01|0x0006) plen 3 >> >> >> >> #204 [hci0] >> 25.727125 >> Handle: 13 >> Reason: Authentication Failure (0x05) >> > HCI Event: Command Status (0x0f) plen 4 #205 [hci0] 25.729069 >> Disconnect (0x01|0x0006) ncmd 1 >> Status: Success (0x00) >> > HCI Event: Disconnect Complete (0x05) plen 4 #206 [hci0] 25.738073 >> Status: Success (0x00) >> Handle: 13 >> Reason: Connection Terminated By Local Host (0x16) >> @ MGMT Event: Device Disconnected (0x000c) plen 8 >> >> >> >> {0x0002} [hci0] >> 25.738149 >> BR/EDR Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> Reason: Connection terminated by local host (0x02) >> @ MGMT Event: Device Disconnected (0x000c) plen 8 >> >> >> >> {0x0001} [hci0] >> 25.738149 >> BR/EDR Address: 64:A2:F9:XX:XX:XX (OUI 64-A2-F9) >> Reason: Connection terminated by local host (0x02) -- Luiz Augusto von Dentz ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Security block and Bluez - connection issue with Android 2018-09-25 16:08 Security block and Bluez - connection issue with Android fabien dvlt 2018-09-26 11:03 ` fabien dvlt @ 2018-09-26 11:28 ` Johan Hedberg 2018-10-03 14:20 ` fabien dvlt 1 sibling, 1 reply; 6+ messages in thread From: Johan Hedberg @ 2018-09-26 11:28 UTC (permalink / raw) To: fabien dvlt; +Cc: linux-bluetooth Hi Fabien, On Tue, Sep 25, 2018, fabien dvlt wrote: > > ACL Data RX: Handle 13 flags 0x02 dlen 12 #198 [hci0] 21.813116 > L2CAP: Connection Request (0x02) ident 7 len 4 > PSM: 25 (0x0019) > Source CID: 75 > > HCI Event: Encryption Change (0x08) plen 4 #199 [hci0] 21.813155 > Status: Success (0x00) > Handle: 13 > Encryption: Enabled with AES-CCM (0x02) > < ACL Data TX: Handle 13 flags 0x00 dlen 16 #200 [hci0] > L2CAP: Connection Response (0x03) ident 7 len 8 > Destination CID: 0 > Source CID: 75 > Result: Connection refused - security block (0x0003) > Status: No further information available (0x0000) This looks like the well-known race condition for ACL data and HCI events on USB where the two come through different endpoints. From the host perspective there's not much we can do since we can't make assumptions that the connection request was sent over an encrypted connection if we haven't seen the encryption change request at that point. Johan ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Security block and Bluez - connection issue with Android 2018-09-26 11:28 ` Johan Hedberg @ 2018-10-03 14:20 ` fabien dvlt 2018-12-11 17:12 ` fabien dvlt 0 siblings, 1 reply; 6+ messages in thread From: fabien dvlt @ 2018-10-03 14:20 UTC (permalink / raw) To: Johan Hedberg; +Cc: linux-bluetooth Thank you both for your reply. Since you and Luiz answered, I have been trying to do a better workaround at USB/HCI level instead of L2CAP. I understand this issue is more related to the firmware implementation but for those who really need it, I think the patch below is a better approach than the first I have submitted. It will start queueing ACL packets when link key exchange begins until the next HCI event. It still have some limitations I wish to fix soon (see patch below). I have a question about what I have read in bluetooth specifications: Version 5.0, Vol 2, Part C, - 4.2.5.1 Encryption Mode "ACL-U logical link traffic shall only be resumed after the attempt to encrypt or decrypt the logical transport is completed" I was wondering if this would guarantee that no unencrypted connection request could be forwarded to other layer once the link key exchange has started. Thank you --- From bd17d5e519c2ad76ef1761b2d066d98ec4c723d1 Mon Sep 17 00:00:00 2001 From: fabien filhol <fabien.filhol@devialet.com> Date: Wed, 3 Oct 2018 12:06:30 +0200 Subject: [PATCH] Bluetooth: btusb: Fix race condition between BT events and ACL Workaround for a race condition observed with Android phones which makes fail some connections (30% with a Oneplus 6). After link key reply it is expected that HCI_EV_ENCRYPT_CHANGE is received before any ACL connection request or it will be dropped by bluez L2CAP layer. The events are received from usb interrupt transfer and ACL packet from usb bulk transfer. I guess the bluetooth controller does not handle correctly write ordering between those two transfer types. The workaround will start queueing ACL packets when link key are exchanged until the next real event (other than HCI_EV_CMD_COMPLETE) is received, it should be HCI_EV_ENCRYPT_CHANGE. LIMITATIONS: An unencrypted connection request forwarded by the controller at "ACL queueing time" could pass. Bluetooth specification says that ACL transfer is paused until encryption is setup so I hope it is safe to queue ACL between HCI_EV_LINK_KEY_REQ and HCI_EV_CMD_COMPLETE. With concurrent connections from multiple bluetooth devices the workaround could not work as any event from any device would flush the queue. --- drivers/bluetooth/btusb.c | 50 ++++++++++++++++++++++++++++++++++++++- 1 file changed, 49 insertions(+), 1 deletion(-) diff --git a/drivers/bluetooth/btusb.c b/drivers/bluetooth/btusb.c index bff67c5a5fe7..c55096fa8c4e 100644 --- a/drivers/bluetooth/btusb.c +++ b/drivers/bluetooth/btusb.c @@ -406,6 +406,9 @@ struct btusb_data { struct sk_buff *acl_skb; struct sk_buff *sco_skb; + struct sk_buff_head acl_deferred_q; + int acl_deferred; + struct usb_endpoint_descriptor *intr_ep; struct usb_endpoint_descriptor *bulk_tx_ep; struct usb_endpoint_descriptor *bulk_rx_ep; @@ -449,6 +452,7 @@ static int btusb_recv_intr(struct btusb_data *data, void *buffer, int count) { struct sk_buff *skb; int err = 0; + int event = HCI_OP_NOP; spin_lock(&data->rxlock); skb = data->evt_skb; @@ -488,6 +492,9 @@ static int btusb_recv_intr(struct btusb_data *data, void *buffer, int count) } if (!hci_skb_expect(skb)) { + struct hci_event_hdr *hdr = (struct hci_event_hdr *)skb->data; + event = hdr->evt; + /* Complete frame */ data->recv_event(data->hdev, skb); skb = NULL; @@ -495,6 +502,39 @@ static int btusb_recv_intr(struct btusb_data *data, void *buffer, int count) } data->evt_skb = skb; + + /* + * Workaround for a race condition observed with Android phones. After link + * key reply it is expected that HCI_EV_ENCRYPT_CHANGE is received before + * any ACL connection request or it will be dropped by bluez L2CAP layer. + * + * The events are received from usb interrupt transfer and ACL packet from + * usb bulk transfer. I guess the bluetooth controller does not handle + * correctly write ordering between those two transfer types. + * + * The workaround will start queueing ACL packets when link key are exchanged + * until the next real event (not an HCI_EV_CMD_COMPLETE) is received, it + * should be HCI_EV_ENCRYPT_CHANGE. + * + * LIMITATIONS: + * + * An unencrypted connection request forwarded by the controller at + * "ACL queueing time" would pass. Bluetooth specification says that ACL + * transfer is paused until encryption is setup so I hope it is safe to queue + * ACL between HCI_EV_LINK_KEY_REQ and HCI_EV_CMD_COMPLETE. + * + * With concurrent connections from multiple bluetooth devices the workaround + * could not work as any event from any device would flush the queue. + */ + if (event == HCI_EV_LINK_KEY_REQ) { + data->acl_deferred = 1; + } else if (data->acl_deferred && event != HCI_EV_CMD_COMPLETE) { + while ((skb = skb_dequeue(&data->acl_deferred_q))) + hci_recv_frame(data->hdev, skb); + skb = NULL; + data->acl_deferred = 0; + } + spin_unlock(&data->rxlock); return err; @@ -546,7 +586,10 @@ static int btusb_recv_bulk(struct btusb_data *data, void *buffer, int count) if (!hci_skb_expect(skb)) { /* Complete frame */ - hci_recv_frame(data->hdev, skb); + if (data->acl_deferred) + skb_queue_tail(&data->acl_deferred_q, skb); + else + hci_recv_frame(data->hdev, skb); skb = NULL; } } @@ -2815,6 +2858,9 @@ static int btusb_probe(struct usb_interface *intf, data->udev = interface_to_usbdev(intf); data->intf = intf; + data->acl_deferred = 0; + skb_queue_head_init(&data->acl_deferred_q); + INIT_WORK(&data->work, btusb_work); INIT_WORK(&data->waker, btusb_waker); init_usb_anchor(&data->deferred); @@ -3051,6 +3097,8 @@ static void btusb_disconnect(struct usb_interface *intf) if (!data) return; + skb_queue_purge(&data->acl_deferred_q); + hdev = data->hdev; usb_set_intfdata(data->intf, NULL); -- 2.17.1 On Wed, Sep 26, 2018 at 02:28:01PM +0300, Johan Hedberg wrote: > Hi Fabien, > > On Tue, Sep 25, 2018, fabien dvlt wrote: > > > ACL Data RX: Handle 13 flags 0x02 dlen 12 #198 [hci0] 21.813116 > > L2CAP: Connection Request (0x02) ident 7 len 4 > > PSM: 25 (0x0019) > > Source CID: 75 > > > HCI Event: Encryption Change (0x08) plen 4 #199 [hci0] 21.813155 > > Status: Success (0x00) > > Handle: 13 > > Encryption: Enabled with AES-CCM (0x02) > > < ACL Data TX: Handle 13 flags 0x00 dlen 16 #200 [hci0] > > L2CAP: Connection Response (0x03) ident 7 len 8 > > Destination CID: 0 > > Source CID: 75 > > Result: Connection refused - security block (0x0003) > > Status: No further information available (0x0000) > > This looks like the well-known race condition for ACL data and HCI > events on USB where the two come through different endpoints. From the > host perspective there's not much we can do since we can't make > assumptions that the connection request was sent over an encrypted > connection if we haven't seen the encryption change request at that > point. > > Johan ^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: Security block and Bluez - connection issue with Android 2018-10-03 14:20 ` fabien dvlt @ 2018-12-11 17:12 ` fabien dvlt 0 siblings, 0 replies; 6+ messages in thread From: fabien dvlt @ 2018-12-11 17:12 UTC (permalink / raw) To: linux-bluetooth I am aware some are using previous patch, here is an update that improves connections made while other devices are already connected. It tracks bdaddr and handles from connection event to disconnection event. See comments in patch for more details. If you have any trouble or remarks please let me know. Fabien --- --- linux-4.9.137/drivers/bluetooth/btusb.c 2018-12-11 16:42:10.897859304 +0100 +++ linux/drivers/bluetooth/btusb.c 2018-12-11 17:32:02.938800781 +0100 @@ -383,6 +383,21 @@ #define BTUSB_DIAG_RUNNING 10 #define BTUSB_OOB_WAKE_ENABLED 11 +struct hci_peer { + struct list_head list; + + bdaddr_t bdaddr; + __le16 handle; + int acl_deferred; + struct sk_buff_head acl_deferred_q; +}; + +struct hci_peer_hash { + struct list_head list; + + unsigned int peer_num; +}; + struct btusb_data { struct hci_dev *hdev; struct usb_device *udev; @@ -410,6 +425,9 @@ struct sk_buff *acl_skb; struct sk_buff *sco_skb; + struct hci_peer_hash peer_hash; + int acl_deferred_peer; + struct usb_endpoint_descriptor *intr_ep; struct usb_endpoint_descriptor *bulk_tx_ep; struct usb_endpoint_descriptor *bulk_rx_ep; @@ -431,6 +449,93 @@ int (*setup_on_usb)(struct hci_dev *hdev); }; +static inline void hci_peer_hash_add(struct btusb_data *data, + struct hci_peer *p) +{ + struct hci_peer_hash *h = &data->peer_hash; + + list_add(&p->list, &h->list); + + h->peer_num++; +} + +static inline void hci_peer_hash_del(struct btusb_data *data, + struct hci_peer *p) +{ + struct hci_peer_hash *h = &data->peer_hash; + + h->peer_num--; + + list_del(&p->list); +} + +static inline struct hci_peer *hci_peer_hash_lookup_ba(struct btusb_data *data, + bdaddr_t *bdaddr) +{ + struct hci_peer *p; + struct hci_peer_hash *h = &data->peer_hash; + + list_for_each_entry(p, &h->list, list) + if (!bacmp(&p->bdaddr, bdaddr)) + return p; + + return NULL; +} + +static inline struct hci_peer * +hci_peer_hash_lookup_handle(struct btusb_data *data, __le16 handle) +{ + struct hci_peer_hash *h = &data->peer_hash; + struct hci_peer *p; + + list_for_each_entry(p, &h->list, list) + if (p->handle == handle) + return p; + + return NULL; +} + +struct hci_peer *hci_peer_add(struct btusb_data *data, bdaddr_t *bdaddr, + __le16 handle) +{ + struct hci_peer *peer; + + peer = kzalloc(sizeof(*peer), GFP_KERNEL); + if (!peer) + return NULL; + + bacpy(&peer->bdaddr, bdaddr); + peer->handle = handle; + + skb_queue_head_init(&peer->acl_deferred_q); + + hci_peer_hash_add(data, peer); + + return peer; +}; + +void hci_peer_remove(struct btusb_data *data, struct hci_peer *peer) +{ + hci_peer_hash_del(data, peer); + + if (peer->acl_deferred) + data->acl_deferred_peer--; + + skb_queue_purge(&peer->acl_deferred_q); + + kfree(peer); + peer = NULL; +} + +static inline void hci_peer_purge(struct btusb_data *data) +{ + struct hci_peer_hash *h = &data->peer_hash; + struct hci_peer *p, *next; + + list_for_each_entry_safe(p, next, &h->list, list) + hci_peer_remove(data, p); +} + static inline void btusb_free_frags(struct btusb_data *data) { unsigned long flags; @@ -449,6 +554,119 @@ spin_unlock_irqrestore(&data->rxlock, flags); } +/* + * Workaround for a race condition observed with Android phones which makes fail + * some connections (30% with my device). + * + * After link key reply it is expected that HCI_EV_ENCRYPT_CHANGE is received + * before any ACL connection request or it will be dropped by bluez L2CAP layer. + * + * The events are received from usb interrupt transfer and ACL packet from usb + * bulk transfer. I guess the bluetooth controller does not handle correctly + * write ordering between those two transfer types. + * + * The connection/disconnection are tracked so the workaround can apply with a + * per device logic. It will start queueing ACL packets when link key are + * exchanged until the HCI_EV_ENCRYPT_CHANGE event or a disconnection. + * + * POSSIBLE LIMITATIONS: + * + * - Connection requests made between LINK_KEY_REQ and ENCRYPT_CHANGE events + * will be forwarded to the L2CAP layer and will be seen as legitimate. However, + * bluetooth specification says that ACL transfer is paused until encryption is + * fully setup. I guess this is the responsability of the controller to filter + * any rogue connection request until ENCRYPT_CHANGE event. + * + * - This workaround is not enough to fix a similar issue with pairing. + */ +static void btusb_update_deferred(struct btusb_data *data, struct sk_buff *skb) +{ + struct hci_peer *peer = NULL; + const int evt = ((struct hci_event_hdr *)skb->data)->evt; + + BT_DBG("%s, event 0x%x, peers %d, deferred peers %d", + data->hdev->name, + evt, + data->peer_hash.peer_num, + data->acl_deferred_peer); + + skb_pull(skb, HCI_EVENT_HDR_SIZE); + + switch (evt) { + case HCI_EV_CONN_COMPLETE: { + struct hci_ev_conn_complete *event; + __le16 handle; + + event = (struct hci_ev_conn_complete *)skb->data; + handle = hci_handle(__le16_to_cpu(event->handle)); + peer = hci_peer_hash_lookup_ba(data, &event->bdaddr); + if (peer) { + hci_peer_remove(data, peer); + peer = NULL; + } + + /* Track only peers on successful connections */ + if (event->status == 0) + hci_peer_add(data, &event->bdaddr, handle); + + break; + } + + case HCI_EV_DISCONN_COMPLETE: { + struct hci_ev_disconn_complete *event; + __le16 handle; + + event = (struct hci_ev_disconn_complete *)skb->data; + handle = hci_handle(__le16_to_cpu(event->handle)); + + peer = hci_peer_hash_lookup_handle(data, handle); + if (peer) { + hci_peer_remove(data, peer); + peer = NULL; + } + break; + } + + case HCI_EV_LINK_KEY_REQ: { + struct hci_ev_link_key_req *event; + + event = (struct hci_ev_link_key_req *)skb->data; + + peer = hci_peer_hash_lookup_ba(data, &event->bdaddr); + if (peer && !peer->acl_deferred) { + peer->acl_deferred = 1; + data->acl_deferred_peer++; + } + break; + } + + case HCI_EV_ENCRYPT_CHANGE: { + struct hci_ev_encrypt_change *event; + __le16 handle; + + event = (struct hci_ev_encrypt_change *)skb->data; + handle = hci_handle(__le16_to_cpu(event->handle)); + + peer = hci_peer_hash_lookup_handle(data, handle); + if (peer && peer->acl_deferred) { + struct sk_buff *frame; + + while ((frame = skb_dequeue(&peer->acl_deferred_q))) + hci_recv_frame(data->hdev, frame); + frame = NULL; + + peer->acl_deferred = 0; + data->acl_deferred_peer--; + } + break; + } + + default: + BT_ERR("Unexpected event"); + break; + } +} + static int btusb_recv_intr(struct btusb_data *data, void *buffer, int count) { struct sk_buff *skb; @@ -492,9 +710,29 @@ } if (!hci_skb_expect(skb)) { + struct sk_buff *evt_skb = NULL; + struct hci_event_hdr *hdr = (struct hci_event_hdr *) + skb->data; + + if (hdr->evt == HCI_EV_CONN_COMPLETE || + hdr->evt == HCI_EV_DISCONN_COMPLETE || + hdr->evt == HCI_EV_LINK_KEY_REQ || + hdr->evt == HCI_EV_ENCRYPT_CHANGE) { + evt_skb = skb_clone(skb, GFP_KERNEL); + if (!evt_skb) + BT_ERR("Out of memory"); + } + /* Complete frame */ data->recv_event(data->hdev, skb); skb = NULL; + + if (evt_skb) { + btusb_update_deferred(data, evt_skb); + + kfree_skb(evt_skb); + evt_skb = NULL; + } } } @@ -550,7 +788,23 @@ if (!hci_skb_expect(skb)) { /* Complete frame */ - hci_recv_frame(data->hdev, skb); + if (data->acl_deferred_peer) { + struct hci_peer *p; + struct hci_acl_hdr *hdr; + __le16 handle; + + hdr = (struct hci_acl_hdr *)skb->data; + handle = hci_handle(__le16_to_cpu(hdr->handle)); + + p = hci_peer_hash_lookup_handle(data, handle); + if (p && p->acl_deferred) + skb_queue_tail(&p->acl_deferred_q, skb); + else + hci_recv_frame(data->hdev, skb); + } else { + hci_recv_frame(data->hdev, skb); + } + skb = NULL; } } @@ -2819,6 +3073,9 @@ data->udev = interface_to_usbdev(intf); data->intf = intf; + data->acl_deferred_peer = 0; + INIT_LIST_HEAD(&data->peer_hash.list); + INIT_WORK(&data->work, btusb_work); INIT_WORK(&data->waker, btusb_waker); init_usb_anchor(&data->deferred); @@ -3055,6 +3312,8 @@ if (!data) return; + hci_peer_purge(data); + hdev = data->hdev; usb_set_intfdata(data->intf, NULL); -- On Wed, Oct 03, 2018 at 04:19:59PM +0200, fabien dvlt wrote: > Thank you both for your reply. Since you and Luiz answered, I have > been trying to do a better workaround at USB/HCI level instead of > L2CAP. > > I understand this issue is more related to the firmware implementation > but for those who really need it, I think the patch below is a better > approach than the first I have submitted. > > It will start queueing ACL packets when link key exchange begins until > the next HCI event. It still have some limitations I wish to fix soon > (see patch below). > > I have a question about what I have read in bluetooth specifications: > > Version 5.0, Vol 2, Part C, - 4.2.5.1 Encryption Mode > > "ACL-U logical link traffic shall only be resumed after the attempt > to encrypt or decrypt the logical transport is completed" > > I was wondering if this would guarantee that no unencrypted connection > request could be forwarded to other layer once the link key exchange > has started. > > Thank you > > --- > > From bd17d5e519c2ad76ef1761b2d066d98ec4c723d1 Mon Sep 17 00:00:00 2001 > From: fabien filhol <fabien.filhol@devialet.com> > Date: Wed, 3 Oct 2018 12:06:30 +0200 > Subject: [PATCH] Bluetooth: btusb: Fix race condition between BT events and > ACL > > Workaround for a race condition observed with Android phones which makes > fail some connections (30% with a Oneplus 6). > > After link key reply it is expected that HCI_EV_ENCRYPT_CHANGE is received > before any ACL connection request or it will be dropped by bluez L2CAP > layer. > > The events are received from usb interrupt transfer and ACL packet from usb > bulk transfer. I guess the bluetooth controller does not handle correctly > write ordering between those two transfer types. > > The workaround will start queueing ACL packets when link key are exchanged until > the next real event (other than HCI_EV_CMD_COMPLETE) is received, it should > be HCI_EV_ENCRYPT_CHANGE. > > LIMITATIONS: > > An unencrypted connection request forwarded by the controller at > "ACL queueing time" could pass. Bluetooth specification says that ACL > transfer is paused until encryption is setup so I hope it is safe to queue > ACL between HCI_EV_LINK_KEY_REQ and HCI_EV_CMD_COMPLETE. > > With concurrent connections from multiple bluetooth devices the workaround > could not work as any event from any device would flush the queue. > --- > drivers/bluetooth/btusb.c | 50 ++++++++++++++++++++++++++++++++++++++- > 1 file changed, 49 insertions(+), 1 deletion(-) > > diff --git a/drivers/bluetooth/btusb.c b/drivers/bluetooth/btusb.c > index bff67c5a5fe7..c55096fa8c4e 100644 > --- a/drivers/bluetooth/btusb.c > +++ b/drivers/bluetooth/btusb.c > @@ -406,6 +406,9 @@ struct btusb_data { > struct sk_buff *acl_skb; > struct sk_buff *sco_skb; > > + struct sk_buff_head acl_deferred_q; > + int acl_deferred; > + > struct usb_endpoint_descriptor *intr_ep; > struct usb_endpoint_descriptor *bulk_tx_ep; > struct usb_endpoint_descriptor *bulk_rx_ep; > @@ -449,6 +452,7 @@ static int btusb_recv_intr(struct btusb_data *data, void *buffer, int count) > { > struct sk_buff *skb; > int err = 0; > + int event = HCI_OP_NOP; > > spin_lock(&data->rxlock); > skb = data->evt_skb; > @@ -488,6 +492,9 @@ static int btusb_recv_intr(struct btusb_data *data, void *buffer, int count) > } > > if (!hci_skb_expect(skb)) { > + struct hci_event_hdr *hdr = (struct hci_event_hdr *)skb->data; > + event = hdr->evt; > + > /* Complete frame */ > data->recv_event(data->hdev, skb); > skb = NULL; > @@ -495,6 +502,39 @@ static int btusb_recv_intr(struct btusb_data *data, void *buffer, int count) > } > > data->evt_skb = skb; > + > + /* > + * Workaround for a race condition observed with Android phones. After link > + * key reply it is expected that HCI_EV_ENCRYPT_CHANGE is received before > + * any ACL connection request or it will be dropped by bluez L2CAP layer. > + * > + * The events are received from usb interrupt transfer and ACL packet from > + * usb bulk transfer. I guess the bluetooth controller does not handle > + * correctly write ordering between those two transfer types. > + * > + * The workaround will start queueing ACL packets when link key are exchanged > + * until the next real event (not an HCI_EV_CMD_COMPLETE) is received, it > + * should be HCI_EV_ENCRYPT_CHANGE. > + * > + * LIMITATIONS: > + * > + * An unencrypted connection request forwarded by the controller at > + * "ACL queueing time" would pass. Bluetooth specification says that ACL > + * transfer is paused until encryption is setup so I hope it is safe to queue > + * ACL between HCI_EV_LINK_KEY_REQ and HCI_EV_CMD_COMPLETE. > + * > + * With concurrent connections from multiple bluetooth devices the workaround > + * could not work as any event from any device would flush the queue. > + */ > + if (event == HCI_EV_LINK_KEY_REQ) { > + data->acl_deferred = 1; > + } else if (data->acl_deferred && event != HCI_EV_CMD_COMPLETE) { > + while ((skb = skb_dequeue(&data->acl_deferred_q))) > + hci_recv_frame(data->hdev, skb); > + skb = NULL; > + data->acl_deferred = 0; > + } > + > spin_unlock(&data->rxlock); > > return err; > @@ -546,7 +586,10 @@ static int btusb_recv_bulk(struct btusb_data *data, void *buffer, int count) > > if (!hci_skb_expect(skb)) { > /* Complete frame */ > - hci_recv_frame(data->hdev, skb); > + if (data->acl_deferred) > + skb_queue_tail(&data->acl_deferred_q, skb); > + else > + hci_recv_frame(data->hdev, skb); > skb = NULL; > } > } > @@ -2815,6 +2858,9 @@ static int btusb_probe(struct usb_interface *intf, > data->udev = interface_to_usbdev(intf); > data->intf = intf; > > + data->acl_deferred = 0; > + skb_queue_head_init(&data->acl_deferred_q); > + > INIT_WORK(&data->work, btusb_work); > INIT_WORK(&data->waker, btusb_waker); > init_usb_anchor(&data->deferred); > @@ -3051,6 +3097,8 @@ static void btusb_disconnect(struct usb_interface *intf) > if (!data) > return; > > + skb_queue_purge(&data->acl_deferred_q); > + > hdev = data->hdev; > usb_set_intfdata(data->intf, NULL); > > -- > 2.17.1 > > > On Wed, Sep 26, 2018 at 02:28:01PM +0300, Johan Hedberg wrote: > > Hi Fabien, > > > > On Tue, Sep 25, 2018, fabien dvlt wrote: > > > > ACL Data RX: Handle 13 flags 0x02 dlen 12 #198 [hci0] 21.813116 > > > L2CAP: Connection Request (0x02) ident 7 len 4 > > > PSM: 25 (0x0019) > > > Source CID: 75 > > > > HCI Event: Encryption Change (0x08) plen 4 #199 [hci0] 21.813155 > > > Status: Success (0x00) > > > Handle: 13 > > > Encryption: Enabled with AES-CCM (0x02) > > > < ACL Data TX: Handle 13 flags 0x00 dlen 16 #200 [hci0] > > > L2CAP: Connection Response (0x03) ident 7 len 8 > > > Destination CID: 0 > > > Source CID: 75 > > > Result: Connection refused - security block (0x0003) > > > Status: No further information available (0x0000) > > > > This looks like the well-known race condition for ACL data and HCI > > events on USB where the two come through different endpoints. From the > > host perspective there's not much we can do since we can't make > > assumptions that the connection request was sent over an encrypted > > connection if we haven't seen the encryption change request at that > > point. > > > > Johan ^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2018-12-11 17:13 UTC | newest] Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2018-09-25 16:08 Security block and Bluez - connection issue with Android fabien dvlt 2018-09-26 11:03 ` fabien dvlt 2018-09-26 11:23 ` Luiz Augusto von Dentz 2018-09-26 11:28 ` Johan Hedberg 2018-10-03 14:20 ` fabien dvlt 2018-12-11 17:12 ` fabien dvlt
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).