* 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).