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)
