[PATCH 0/2] Quirk to enable QCA9377 to discover BLE devices

[PATCH 0/2] Quirk to enable QCA9377 to discover BLE devices

[João Paulo Rechi Vita]

As reported previously on [1], it is currently not possible to discover
BLE devices with QCA9377 controllers. When trying to start an active
scanning procedure with this controller, three commands are queued,
LE_SET_RANDOM_ADDR, LE_SET_SCAN_PARAM and LE_SET_SCAN_ENABLE. After the
first command is sent to the controller, a command complete event for it
is received, and the second command is sent, an extra command complete
for the first command is received. At this point the kernel sends the
next command and fails to process the command complete event for the
LE_SET_SCAN_PARAM command, because when it arrives it does not match the
last command that was sent. This makes hdev->le_scan_type never be
updated and the kernel behaves as if a passive scanning procedure was
being performed, thus no device found events are sent to userspace.

[1] https://www.spinics.net/lists/linux-bluetooth/msg79102.html

I have received no replies on the previous report and on further
attempts to contact the QCA addresses that have submitted Bluetooth
firmware blobs to linux-firmware upstream. This series avoids the
problem described above, but I believe ideally the controller should not
be sending this extra command complete event.

I'm not 100% sure if the approach taken here is the best way to work
around this problem in the kernel, as I am not super familiar with the
HCI layer. I'll be happy to hear suggestions of better approaches.

Full logs from btmon can be found bellow this message, and the extra
command complete event can be seen at timestamp 27.420131.

Best regards,

João Paulo Rechi Vita (2):
  Bluetooth: Create new HCI_QUIRK_WAIT_FOR_MATCHING_CC
  Bluetooth: Set HCI_QUIRK_WAIT_FOR_MATCHING_CC for QCA9377

 drivers/bluetooth/btusb.c        | 9 +++++++++
 include/net/bluetooth/hci.h      | 4 ++++
 include/net/bluetooth/hci_core.h | 1 +
 net/bluetooth/hci_core.c         | 3 +++
 net/bluetooth/hci_event.c        | 4 ++++
 5 files changed, 21 insertions(+)

-- 
2.20.1

Bluetooth monitor ver 5.50
= Note: Linux version 5.0.0+ (x86_64)                                  0.352340
= Note: Bluetooth subsystem version 2.22                               0.352343
= New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
= Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
= Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
@ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
@ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
@ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
@ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
        Address type: 0x06
          LE Public
          LE Random
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
        Type: Active (0x01)
        Interval: 11.250 msec (0x0012)
        Window: 11.250 msec (0x0012)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
@ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
      Start Discovery (0x0023) plen 1
        Status: Success (0x00)
        Address type: 0x06
          LE Public
          LE Random
@ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
> HCI Event: LE Meta Event (0x3e) plen 39                   #8 [hci0] 27.434978
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: E8:95:19:72:73:CC (Static)
        Data length: 27
        Name (complete): Designer Mouse
        Appearance: Mouse (0x03c2)
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Human Interface Device (0x1812)
        RSSI: -27 dBm (0xe5)
> HCI Event: LE Meta Event (0x3e) plen 12                   #9 [hci0] 27.435993
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: E8:95:19:72:73:CC (Static)
        Data length: 0
        RSSI: -27 dBm (0xe5)
> HCI Event: LE Meta Event (0x3e) plen 34                  #10 [hci0] 27.456126
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 80:7A:BF:E1:B7:42 (HTC Corporation)
        Data length: 22
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Unknown (0xcb00)
        Name (complete): HTC BS 424362
        RSSI: -78 dBm (0xb2)
> HCI Event: LE Meta Event (0x3e) plen 15                  #11 [hci0] 27.458091
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Public (0x00)
        Address: 80:7A:BF:E1:B7:42 (HTC Corporation)
        Data length: 3
        TX power: 4 dBm
        RSSI: -79 dBm (0xb1)
> HCI Event: LE Meta Event (0x3e) plen 36                  #12 [hci0] 27.466127
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 88:C6:26:BC:47:E0 (Logitech, Inc)
        Data length: 24
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        Name (short): 
        128-bit Service UUIDs (complete): 1 entry
          Vendor specific (72daa6c3-29c2-6283-0c4a-2818e4d37e75)
        RSSI: -89 dBm (0xa7)
> HCI Event: LE Meta Event (0x3e) plen 43                  #13 [hci0] 27.483060
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 3E:AA:03:39:AF:93 (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 0109200205f7919173c0503f361cb0bc3065cee7253049c23c8662
        RSSI: -86 dBm (0xaa)
> HCI Event: LE Meta Event (0x3e) plen 43                  #14 [hci0] 27.496132
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 2C:44:85:C3:1F:22 (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 010920028a9a16c0a22049fd76e5149c66d5703368ed3663413e54
        RSSI: -75 dBm (0xb5)
> HCI Event: LE Meta Event (0x3e) plen 43                  #15 [hci0] 27.500136
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 25:56:82:C6:5F:D4 (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 01092000318c08c684a9670c9e48b8594178670965955236d78ca8
        RSSI: -78 dBm (0xb2)
> HCI Event: LE Meta Event (0x3e) plen 43                  #16 [hci0] 27.521133
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 17:AD:7B:9D:81:0A (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 01092002bfe890ca48146f86fba1398c5baf6bd86df2f6b6b4cab3
        RSSI: -80 dBm (0xb0)
> HCI Event: LE Meta Event (0x3e) plen 34                  #17 [hci0] 27.524125
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 80:7A:BF:E1:B7:B2 (HTC Corporation)
        Data length: 22
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Unknown (0xcb00)
        Name (complete): HTC BS B23CE4
        RSSI: -72 dBm (0xb8)
> HCI Event: LE Meta Event (0x3e) plen 15                  #18 [hci0] 27.526031
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Public (0x00)
        Address: 80:7A:BF:E1:B7:B2 (HTC Corporation)
        Data length: 3
        TX power: 4 dBm
        RSSI: -72 dBm (0xb8)
> HCI Event: LE Meta Event (0x3e) plen 26                  #19 [hci0] 27.555065
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: 4C:31:90:6F:B8:ED (Resolvable)
        Data length: 14
        Flags: 0x1a
          LE General Discoverable Mode
          Simultaneous LE and BR/EDR (Controller)
          Simultaneous LE and BR/EDR (Host)
        Company: Apple, Inc. (76)
          Type: Unknown (16)
          Data: 0714add576
        RSSI: -94 dBm (0xa2)
> HCI Event: LE Meta Event (0x3e) plen 40                  #20 [hci0] 27.578973
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 7A:AE:04:2B:99:83 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -52 dBm (0xcc)
> HCI Event: LE Meta Event (0x3e) plen 22                  #21 [hci0] 27.581128
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: 7A:AE:04:2B:99:83 (Resolvable)
        Data length: 10
        Company: Google (224)
          Data: 0190ca3e7e6b
        RSSI: -52 dBm (0xcc)
> HCI Event: LE Meta Event (0x3e) plen 26                  #22 [hci0] 27.590133
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 50:32:37:8C:8E:8E (Apple, Inc.)
        Data length: 14
        Flags: 0x1a
          LE General Discoverable Mode
          Simultaneous LE and BR/EDR (Controller)
          Simultaneous LE and BR/EDR (Host)
        Company: Apple, Inc. (76)
          Type: Unknown (16)
          Data: 0114399c7d
        RSSI: -88 dBm (0xa8)
> HCI Event: LE Meta Event (0x3e) plen 43                  #23 [hci0] 27.604987
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 2C:44:85:C3:1F:22 (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 010920028a9a16c0a22049fd76e5149c66d5703368ed3663413e54
        RSSI: -81 dBm (0xaf)
> HCI Event: LE Meta Event (0x3e) plen 43                  #24 [hci0] 27.610981
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 17:AD:7B:9D:81:0A (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 01092002bfe890ca48146f86fba1398c5baf6bd86df2f6b6b4cab3
        RSSI: -82 dBm (0xae)
> HCI Event: LE Meta Event (0x3e) plen 39                  #25 [hci0] 27.646058
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: E8:95:19:72:73:CC (Static)
        Data length: 27
        Name (complete): Designer Mouse
        Appearance: Mouse (0x03c2)
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Human Interface Device (0x1812)
        RSSI: -29 dBm (0xe3)
> HCI Event: LE Meta Event (0x3e) plen 27                  #26 [hci0] 27.647986
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 02:95:02:1D:EC:CA (Non-Resolvable)
        Data length: 15
        Flags: 0x1b
          LE Limited Discoverable Mode
          LE General Discoverable Mode
          Simultaneous LE and BR/EDR (Controller)
          Simultaneous LE and BR/EDR (Host)
        Company: Apple, Inc. (76)
          Type: Apple TV (9)
          Data: 03090a000098
        RSSI: -82 dBm (0xae)
> HCI Event: LE Meta Event (0x3e) plen 40                  #27 [hci0] 27.658984
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 5B:16:F0:4E:F8:38 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -76 dBm (0xb4)
> HCI Event: LE Meta Event (0x3e) plen 34                  #28 [hci0] 27.669971
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 80:7A:BF:E1:B7:42 (HTC Corporation)
        Data length: 22
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Unknown (0xcb00)
        Name (complete): HTC BS 424362
        RSSI: -77 dBm (0xb3)
> HCI Event: LE Meta Event (0x3e) plen 27                  #29 [hci0] 27.685062
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: B0:34:95:32:11:FA (Apple, Inc.)
        Data length: 15
        Flags: 0x1a
          LE General Discoverable Mode
          Simultaneous LE and BR/EDR (Controller)
          Simultaneous LE and BR/EDR (Host)
        Company: Apple, Inc. (76)
          Type: Apple TV (9)
          Data: 035e0a0000d2
        RSSI: -89 dBm (0xa7)
> HCI Event: LE Meta Event (0x3e) plen 39                  #30 [hci0] 27.697970
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: E8:95:19:72:73:CC (Static)
        Data length: 27
        Name (complete): Designer Mouse
        Appearance: Mouse (0x03c2)
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Human Interface Device (0x1812)
        RSSI: -30 dBm (0xe2)
> HCI Event: LE Meta Event (0x3e) plen 43                  #31 [hci0] 27.706061
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 2C:44:85:C3:1F:22 (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 010920028a9a16c0a22049fd76e5149c66d5703368ed3663413e54
        RSSI: -80 dBm (0xb0)
> HCI Event: LE Meta Event (0x3e) plen 34                  #32 [hci0] 27.768055
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 80:7A:BF:E1:B7:42 (HTC Corporation)
        Data length: 22
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Unknown (0xcb00)
        Name (complete): HTC BS 424362
        RSSI: -74 dBm (0xb6)
> HCI Event: LE Meta Event (0x3e) plen 26                  #33 [hci0] 27.785060
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 50:32:37:8C:8E:8E (Apple, Inc.)
        Data length: 14
        Flags: 0x1a
          LE General Discoverable Mode
          Simultaneous LE and BR/EDR (Controller)
          Simultaneous LE and BR/EDR (Host)
        Company: Apple, Inc. (76)
          Type: Unknown (16)
          Data: 0114399c7d
        RSSI: -88 dBm (0xa8)
> HCI Event: LE Meta Event (0x3e) plen 40                  #34 [hci0] 27.792059
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 4A:97:99:08:9E:89 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -66 dBm (0xbe)
> HCI Event: LE Meta Event (0x3e) plen 22                  #35 [hci0] 27.794058
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: 4A:97:99:08:9E:89 (Resolvable)
        Data length: 10
        Company: Google (224)
          Data: 01daca61698f
        RSSI: -66 dBm (0xbe)
> HCI Event: LE Meta Event (0x3e) plen 43                  #36 [hci0] 27.814973
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 33:FB:A2:A0:68:4A (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 01092002928d2b061d019431be7639a37405f42054032d52d23bb8
        RSSI: -70 dBm (0xba)
> HCI Event: LE Meta Event (0x3e) plen 34                  #37 [hci0] 27.830967
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 80:7A:BF:E1:B7:B2 (HTC Corporation)
        Data length: 22
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Unknown (0xcb00)
        Name (complete): HTC BS B23CE4
        RSSI: -71 dBm (0xb9)
> HCI Event: LE Meta Event (0x3e) plen 40                  #38 [hci0] 27.847059
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 7A:AE:04:2B:99:83 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -57 dBm (0xc7)
> HCI Event: LE Meta Event (0x3e) plen 43                  #39 [hci0] 27.858061
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 0B:AC:03:90:E2:52 (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 010920028eaae368523854409d2335d8ae88bf82c1b6bc102ed5e7
        RSSI: -83 dBm (0xad)
> HCI Event: LE Meta Event (0x3e) plen 27                  #40 [hci0] 27.860041
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: B0:34:95:32:11:FA (Apple, Inc.)
        Data length: 15
        Flags: 0x1a
          LE General Discoverable Mode
          Simultaneous LE and BR/EDR (Controller)
          Simultaneous LE and BR/EDR (Host)
        Company: Apple, Inc. (76)
          Type: Apple TV (9)
          Data: 035e0a0000d2
        RSSI: -84 dBm (0xac)
> HCI Event: LE Meta Event (0x3e) plen 26                  #41 [hci0] 27.907985
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: 69:A1:40:C3:13:0A (Resolvable)
        Data length: 14
        Flags: 0x1a
          LE General Discoverable Mode
          Simultaneous LE and BR/EDR (Controller)
          Simultaneous LE and BR/EDR (Host)
        Company: Apple, Inc. (76)
          Type: Unknown (16)
          Data: 0a1ca19d89
        RSSI: -90 dBm (0xa6)
> HCI Event: LE Meta Event (0x3e) plen 40                  #42 [hci0] 27.916124
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 5B:16:F0:4E:F8:38 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -81 dBm (0xaf)
> HCI Event: LE Meta Event (0x3e) plen 43                  #43 [hci0] 27.919129
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 25:56:82:C6:5F:D4 (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 01092000318c08c684a9670c9e48b8594178670965955236d78ca8
        RSSI: -73 dBm (0xb7)
> HCI Event: LE Meta Event (0x3e) plen 34                  #44 [hci0] 27.928123
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 80:7A:BF:E1:B7:B2 (HTC Corporation)
        Data length: 22
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Unknown (0xcb00)
        Name (complete): HTC BS B23CE4
        RSSI: -71 dBm (0xb9)
> HCI Event: LE Meta Event (0x3e) plen 34                  #45 [hci0] 27.987233
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 80:7A:BF:E1:B7:42 (HTC Corporation)
        Data length: 22
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Unknown (0xcb00)
        Name (complete): HTC BS 424362
        RSSI: -69 dBm (0xbb)
> HCI Event: LE Meta Event (0x3e) plen 43                  #46 [hci0] 27.995132
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 3E:AA:03:39:AF:93 (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 0109200205f7919173c0503f361cb0bc3065cee7253049c23c8662
        RSSI: -85 dBm (0xab)
> HCI Event: LE Meta Event (0x3e) plen 43                  #47 [hci0] 28.027133
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 2C:44:85:C3:1F:22 (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 010920028a9a16c0a22049fd76e5149c66d5703368ed3663413e54
        RSSI: -81 dBm (0xaf)
> HCI Event: LE Meta Event (0x3e) plen 27                  #48 [hci0] 28.056066
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: B0:34:95:32:11:FA (Apple, Inc.)
        Data length: 15
        Flags: 0x1a
          LE General Discoverable Mode
          Simultaneous LE and BR/EDR (Controller)
          Simultaneous LE and BR/EDR (Host)
        Company: Apple, Inc. (76)
          Type: Apple TV (9)
          Data: 035e0a0000d2
        RSSI: -88 dBm (0xa8)
> HCI Event: LE Meta Event (0x3e) plen 40                  #49 [hci0] 28.122131
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 7A:AE:04:2B:99:83 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -56 dBm (0xc8)
> HCI Event: LE Meta Event (0x3e) plen 43                  #50 [hci0] 28.131132
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 33:FB:A2:A0:68:4A (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 01092002928d2b061d019431be7639a37405f42054032d52d23bb8
        RSSI: -86 dBm (0xaa)
> HCI Event: LE Meta Event (0x3e) plen 40                  #51 [hci0] 28.303237
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 4A:97:99:08:9E:89 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -67 dBm (0xbd)
> HCI Event: LE Meta Event (0x3e) plen 27                  #52 [hci0] 28.701239
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 2C:34:6D:48:3C:41 (Non-Resolvable)
        Data length: 15
        Flags: 0x1b
          LE Limited Discoverable Mode
          LE General Discoverable Mode
          Simultaneous LE and BR/EDR (Controller)
          Simultaneous LE and BR/EDR (Host)
        Company: Apple, Inc. (76)
          Type: Apple TV (9)
          Data: 030cc0a80036
        RSSI: -89 dBm (0xa7)
> HCI Event: LE Meta Event (0x3e) plen 34                  #53 [hci0] 28.741233
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 80:7A:BF:E1:B7:B2 (HTC Corporation)
        Data length: 22
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Unknown (0xcb00)
        Name (complete): HTC BS B23CE4
        RSSI: -71 dBm (0xb9)
> HCI Event: LE Meta Event (0x3e) plen 43                  #54 [hci0] 28.766131
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 2C:44:85:C3:1F:22 (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 010920028a9a16c0a22049fd76e5149c66d5703368ed3663413e54
        RSSI: -77 dBm (0xb3)
> HCI Event: LE Meta Event (0x3e) plen 40                  #55 [hci0] 28.829237
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 4A:97:99:08:9E:89 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -66 dBm (0xbe)
> HCI Event: LE Meta Event (0x3e) plen 43                  #56 [hci0] 28.946115
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 33:FB:A2:A0:68:4A (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 01092002928d2b061d019431be7639a37405f42054032d52d23bb8
        RSSI: -88 dBm (0xa8)
> HCI Event: LE Meta Event (0x3e) plen 40                  #57 [hci0] 28.949131
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 5B:16:F0:4E:F8:38 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -81 dBm (0xaf)
> HCI Event: LE Meta Event (0x3e) plen 22                  #58 [hci0] 28.951128
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: 5B:16:F0:4E:F8:38 (Resolvable)
        Data length: 10
        Company: Google (224)
          Data: 1dd9ca8e7047
        RSSI: -81 dBm (0xaf)
> HCI Event: LE Meta Event (0x3e) plen 27                  #59 [hci0] 28.973131
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: B0:34:95:32:11:FA (Apple, Inc.)
        Data length: 15
        Flags: 0x1a
          LE General Discoverable Mode
          Simultaneous LE and BR/EDR (Controller)
          Simultaneous LE and BR/EDR (Host)
        Company: Apple, Inc. (76)
          Type: Apple TV (9)
          Data: 035e0a0000d2
        RSSI: -84 dBm (0xac)
> HCI Event: LE Meta Event (0x3e) plen 43                  #60 [hci0] 30.553238
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 3D:93:75:B8:6E:09 (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 010920028e4b82ba058f2f37e060a1fa85e8a99c750384ec897b20
        RSSI: -91 dBm (0xa5)
> HCI Event: LE Meta Event (0x3e) plen 34                  #61 [hci0] 30.571128
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 80:7A:BF:E1:B7:B2 (HTC Corporation)
        Data length: 22
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Unknown (0xcb00)
        Name (complete): HTC BS B23CE4
        RSSI: -70 dBm (0xba)
> HCI Event: LE Meta Event (0x3e) plen 40                  #62 [hci0] 30.768238
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 5B:16:F0:4E:F8:38 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -77 dBm (0xb3)
> HCI Event: LE Meta Event (0x3e) plen 43                  #63 [hci0] 30.965238
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 33:FB:A2:A0:68:4A (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 01092002928d2b061d019431be7639a37405f42054032d52d23bb8
        RSSI: -74 dBm (0xb6)
> HCI Event: LE Meta Event (0x3e) plen 40                  #64 [hci0] 31.159237
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 4A:97:99:08:9E:89 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -65 dBm (0xbf)
> HCI Event: LE Meta Event (0x3e) plen 12                  #65 [hci0] 31.250241
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Public (0x00)
        Address: 50:32:37:8C:8E:8E (Apple, Inc.)
        Data length: 0
        RSSI: -82 dBm (0xae)
> HCI Event: LE Meta Event (0x3e) plen 23                  #66 [hci0] 31.766241
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: 4F:E2:1C:81:96:4D (Resolvable)
        Data length: 11
        Flags: 0x1a
          LE General Discoverable Mode
          Simultaneous LE and BR/EDR (Controller)
          Simultaneous LE and BR/EDR (Host)
        Company: Apple, Inc. (76)
          Type: Unknown (16)
          Data: 0304
        RSSI: -94 dBm (0xa2)
> HCI Event: LE Meta Event (0x3e) plen 34                  #67 [hci0] 31.789124
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 80:7A:BF:E1:B7:B2 (HTC Corporation)
        Data length: 22
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Unknown (0xcb00)
        Name (complete): HTC BS B23CE4
        RSSI: -70 dBm (0xba)
> HCI Event: LE Meta Event (0x3e) plen 40                  #68 [hci0] 31.803130
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 5B:16:F0:4E:F8:38 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -81 dBm (0xaf)
> HCI Event: LE Meta Event (0x3e) plen 43                  #69 [hci0] 31.917135
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 2C:44:85:C3:1F:22 (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 010920028a9a16c0a22049fd76e5149c66d5703368ed3663413e54
        RSSI: -61 dBm (0xc3)
> HCI Event: LE Meta Event (0x3e) plen 26                  #70 [hci0] 31.978239
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: 69:A1:40:C3:13:0A (Resolvable)
        Data length: 14
        Flags: 0x1a
          LE General Discoverable Mode
          Simultaneous LE and BR/EDR (Controller)
          Simultaneous LE and BR/EDR (Host)
        Company: Apple, Inc. (76)
          Type: Unknown (16)
          Data: 0a1ca19d89
        RSSI: -81 dBm (0xaf)
> HCI Event: LE Meta Event (0x3e) plen 43                  #71 [hci0] 32.169240
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
        Address type: Random (0x01)
        Address: 33:FB:A2:A0:68:4A (Non-Resolvable)
        Data length: 31
        Company: Microsoft (6)
          Data: 01092002928d2b061d019431be7639a37405f42054032d52d23bb8
        RSSI: -75 dBm (0xb5)
> HCI Event: LE Meta Event (0x3e) plen 40                  #72 [hci0] 32.214242
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 4A:97:99:08:9E:89 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -66 dBm (0xbe)
> HCI Event: LE Meta Event (0x3e) plen 26                  #73 [hci0] 34.032239
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: C2:A8:AB:46:C0:93 (Static)
        Data length: 14
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (partial): 1 entry
          Nest Labs Inc. (0xfeaf)
        Name (complete): N0BM6
        RSSI: -86 dBm (0xaa)
> HCI Event: LE Meta Event (0x3e) plen 33                  #74 [hci0] 34.035125
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: C2:A8:AB:46:C0:93 (Static)
        Data length: 21
        Service Data (UUID 0xfeaf): 100100025a230900de1bb2000030b41800
        RSSI: -85 dBm (0xab)
> HCI Event: LE Meta Event (0x3e) plen 34                  #75 [hci0] 34.125232
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: 80:7A:BF:E1:B7:B2 (HTC Corporation)
        Data length: 22
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Unknown (0xcb00)
        Name (complete): HTC BS B23CE4
        RSSI: -70 dBm (0xba)
> HCI Event: LE Meta Event (0x3e) plen 40                  #76 [hci0] 34.132131
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Random (0x01)
        Address: 5B:16:F0:4E:F8:38 (Resolvable)
        Data length: 28
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -78 dBm (0xb2)
> HCI Event: LE Meta Event (0x3e) plen 12                  #77 [hci0] 36.036242
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: 69:A1:40:C3:13:0A (Resolvable)
        Data length: 0
        RSSI: -81 dBm (0xaf)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2     #78 [hci0] 37.737722
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                #79 [hci0] 37.739124
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 37.739273
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Disabled (0x00)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 37.739273
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Disabled (0x00)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 37.739273
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Disabled (0x00)
@ MGMT Close: btmgmt                                         {0x0003} 37.739481

[PATCH 1/2] Bluetooth: Create new HCI_QUIRK_WAIT_FOR_MATCHING_CC

[João Paulo Rechi Vita]

This commit creates a new quirk, HCI_QUIRK_WAIT_FOR_MATCHING_CC, which
when set makes the kernel not send the next queued HCI command until a
command complete arrives for the last HCI command sent to the
controller.

This avoids a state of confusion where the kernel believes a passive
scanning procedure is being performed while in fact controller is
performing an active scanning procedure, as requested by userspace and
the kernel.

This state of confusion is achieved when some buggy controllers send an
extra command complete event for the LE_SET_RANDOM_ADDR after the kernel
already sent the next queued command (LE_SET_SCAN_PARAM, for starting an
active scanning procedure), as shown at timestamp 27.420131 on the btmon
logs bellow.

Bluetooth monitor ver 5.50
= Note: Linux version 5.0.0+ (x86_64)                                  0.352340
= Note: Bluetooth subsystem version 2.22                               0.352343
= New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
= Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
= Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
@ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
@ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
@ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
@ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
        Address type: 0x06
          LE Public
          LE Random
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
        Type: Active (0x01)
        Interval: 11.250 msec (0x0012)
        Window: 11.250 msec (0x0012)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
@ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
      Start Discovery (0x0023) plen 1
        Status: Success (0x00)
        Address type: 0x06
          LE Public
          LE Random
@ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)

In this situation the kernel ends up not processing the command complete
event for LE_SET_SCAN_PARAM, so hdev->le_scan_type is never updated to
active scanning and no device found events are generated for
ADV_SCAN_RSP PDUs. This makes impossible to discover BTLE devices with
these controllers.

Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
---
 include/net/bluetooth/hci.h      | 4 ++++
 include/net/bluetooth/hci_core.h | 1 +
 net/bluetooth/hci_core.c         | 3 +++
 net/bluetooth/hci_event.c        | 4 ++++
 4 files changed, 12 insertions(+)

diff --git a/include/net/bluetooth/hci.h b/include/net/bluetooth/hci.h
index fbba43e9bef5..f100e9d566a0 100644
--- a/include/net/bluetooth/hci.h
+++ b/include/net/bluetooth/hci.h
@@ -204,6 +204,10 @@ enum {
 	 *
 	 */
 	HCI_QUIRK_NON_PERSISTENT_SETUP,
+
+	/* When this quirk is set, no pending HCI commands will be sent until a
+	 * matching command complete for the last command is received. */
+	HCI_QUIRK_WAIT_FOR_MATCHING_CC,
 };
 
 /* HCI device flags */
diff --git a/include/net/bluetooth/hci_core.h b/include/net/bluetooth/hci_core.h
index 094e61e07030..85bed4e916d3 100644
--- a/include/net/bluetooth/hci_core.h
+++ b/include/net/bluetooth/hci_core.h
@@ -364,6 +364,7 @@ struct hci_dev {
 	struct sk_buff_head	cmd_q;
 
 	struct sk_buff		*sent_cmd;
+	__u8			sent_cmd_pending_cc;
 
 	struct mutex		req_lock;
 	wait_queue_head_t	req_wait_q;
diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
index d6b2540ba7f8..95ab8f9f2514 100644
--- a/net/bluetooth/hci_core.c
+++ b/net/bluetooth/hci_core.c
@@ -4383,6 +4383,8 @@ void hci_req_cmd_complete(struct hci_dev *hdev, u16 opcode, u8 status,
 		return;
 	}
 
+	hdev->sent_cmd_pending_cc = 0;
+
 	/* If the command succeeded and there's still more commands in
 	 * this request the request is not yet complete.
 	 */
@@ -4493,6 +4495,7 @@ static void hci_cmd_work(struct work_struct *work)
 
 		hdev->sent_cmd = skb_clone(skb, GFP_KERNEL);
 		if (hdev->sent_cmd) {
+			hdev->sent_cmd_pending_cc = 1;
 			atomic_dec(&hdev->cmd_cnt);
 			hci_send_frame(hdev, skb);
 			if (test_bit(HCI_RESET, &hdev->flags))
diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
index 609fd6871c5a..1abbca8ce1c2 100644
--- a/net/bluetooth/hci_event.c
+++ b/net/bluetooth/hci_event.c
@@ -3404,6 +3404,10 @@ static void hci_cmd_complete_evt(struct hci_dev *hdev, struct sk_buff *skb,
 	hci_req_cmd_complete(hdev, *opcode, *status, req_complete,
 			     req_complete_skb);
 
+	if (hdev->sent_cmd_pending_cc &&
+	    test_bit(HCI_QUIRK_WAIT_FOR_MATCHING_CC, &hdev->quirks))
+		return;
+
 	if (atomic_read(&hdev->cmd_cnt) && !skb_queue_empty(&hdev->cmd_q))
 		queue_work(hdev->workqueue, &hdev->cmd_work);
 }
-- 
2.20.1

[PATCH 2/2] Bluetooth: Set HCI_QUIRK_WAIT_FOR_MATCHING_CC for QCA9377

[João Paulo Rechi Vita]

The QCA9377 devices send an extra command complete for the
LE_SET_RANDOM_ADDR when trying to start an active scanning procedure. It
has to be ignored to avoid confusing the kernel into thinking a passive
scanning procedure is being performed instead, which makes impossible to
discover BTLE devices since no device found events are generated for
passive scanning.

Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
---
 drivers/bluetooth/btusb.c | 9 +++++++++
 1 file changed, 9 insertions(+)

diff --git a/drivers/bluetooth/btusb.c b/drivers/bluetooth/btusb.c
index ded198328f21..650ba4b7908a 100644
--- a/drivers/bluetooth/btusb.c
+++ b/drivers/bluetooth/btusb.c
@@ -70,6 +70,7 @@ static struct usb_driver btusb_driver;
 #define BTUSB_BCM2045		0x40000
 #define BTUSB_IFNUM_2		0x80000
 #define BTUSB_CW6622		0x100000
+#define BTUSB_QCA9377		0x200000
 
 static const struct usb_device_id btusb_table[] = {
 	/* Generic Bluetooth USB device */
@@ -394,6 +395,10 @@ static const struct usb_device_id blacklist_table[] = {
 	/* Silicon Wave based devices */
 	{ USB_DEVICE(0x0c10, 0x0000), .driver_info = BTUSB_SWAVE },
 
+	/* QCA9377 devices */
+	{ USB_DEVICE(0x13d3, 0x3491), .driver_info = BTUSB_QCA9377 },
+	{ USB_DEVICE(0x13d3, 0x3501), .driver_info = BTUSB_QCA9377 },
+
 	{ }	/* Terminating entry */
 };
 
@@ -3196,6 +3201,10 @@ static int btusb_probe(struct usb_interface *intf,
 		btusb_check_needs_reset_resume(intf);
 	}
 
+	if (id->driver_info & BTUSB_QCA9377) {
+		set_bit(HCI_QUIRK_WAIT_FOR_MATCHING_CC, &hdev->quirks);
+	}
+
 #ifdef CONFIG_BT_HCIBTUSB_RTL
 	if (id->driver_info & BTUSB_REALTEK) {
 		hdev->setup = btrtl_setup_realtek;
-- 
2.20.1

Re: [PATCH 0/2] Quirk to enable QCA9377 to discover BLE devices

[Marcel Holtmann]

Hi Joao Paulo,

> As reported previously on [1], it is currently not possible to discover
> BLE devices with QCA9377 controllers. When trying to start an active
> scanning procedure with this controller, three commands are queued,
> LE_SET_RANDOM_ADDR, LE_SET_SCAN_PARAM and LE_SET_SCAN_ENABLE. After the
> first command is sent to the controller, a command complete event for it
> is received, and the second command is sent, an extra command complete
> for the first command is received. At this point the kernel sends the
> next command and fails to process the command complete event for the
> LE_SET_SCAN_PARAM command, because when it arrives it does not match the
> last command that was sent. This makes hdev->le_scan_type never be
> updated and the kernel behaves as if a passive scanning procedure was
> being performed, thus no device found events are sent to userspace.
> 
> [1] https://www.spinics.net/lists/linux-bluetooth/msg79102.html
> 
> I have received no replies on the previous report and on further
> attempts to contact the QCA addresses that have submitted Bluetooth
> firmware blobs to linux-firmware upstream. This series avoids the
> problem described above, but I believe ideally the controller should not
> be sending this extra command complete event.
> 
> I'm not 100% sure if the approach taken here is the best way to work
> around this problem in the kernel, as I am not super familiar with the
> HCI layer. I'll be happy to hear suggestions of better approaches.
> 
> Full logs from btmon can be found bellow this message, and the extra
> command complete event can be seen at timestamp 27.420131.

so can we get a fixed firmware from Qualcomm? Or at least some ROM patches for it?

> Best regards,
> 
> João Paulo Rechi Vita (2):
>  Bluetooth: Create new HCI_QUIRK_WAIT_FOR_MATCHING_CC
>  Bluetooth: Set HCI_QUIRK_WAIT_FOR_MATCHING_CC for QCA9377
> 
> drivers/bluetooth/btusb.c        | 9 +++++++++
> include/net/bluetooth/hci.h      | 4 ++++
> include/net/bluetooth/hci_core.h | 1 +
> net/bluetooth/hci_core.c         | 3 +++
> net/bluetooth/hci_event.c        | 4 ++++
> 5 files changed, 21 insertions(+)
> 
> -- 
> 2.20.1
> 
> Bluetooth monitor ver 5.50
> = Note: Linux version 5.0.0+ (x86_64)                                  0.352340
> = Note: Bluetooth subsystem version 2.22                               0.352343
> = New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
> = Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
> = Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
> @ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
> @ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
> @ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
> @ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
>        Address type: 0x06
>          LE Public
>          LE Random
> < HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
>        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
>> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
>      LE Set Random Address (0x08|0x0005) ncmd 1
>        Status: Success (0x00)
> < HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
>        Type: Active (0x01)
>        Interval: 11.250 msec (0x0012)
>        Window: 11.250 msec (0x0012)
>        Own address type: Random (0x01)
>        Filter policy: Accept all advertisement (0x00)
>> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
>      LE Set Random Address (0x08|0x0005) ncmd 1
>        Status: Success (0x00)

so we really need to ignore this command complete and not start ahead with the next command. Especially since we really only support one command at a time right now.

> < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
>        Scanning: Enabled (0x01)
>        Filter duplicates: Enabled (0x01)
>> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
>      LE Set Scan Parameters (0x08|0x000b) ncmd 1
>        Status: Success (0x00)

We need for this command complete to arrive and only then continue with LE Set Scan Enable. We don’t need a quirk for it. Just add support for dealing with unexpected command complete opcodes. And print a big error if that happens.

>> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
>      LE Set Scan Enable (0x08|0x000c) ncmd 1
>        Status: Success (0x00)
> @ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
>      Start Discovery (0x0023) plen 1
>        Status: Success (0x00)
>        Address type: 0x06
>          LE Public
>          LE Random

Regards

Marcel

Re: [PATCH 0/2] Quirk to enable QCA9377 to discover BLE devices

[João Paulo Rechi Vita]

Hello Marcel, thanks for the quick response.

On Wed, Apr 24, 2019 at 12:17 AM Marcel Holtmann <marcel@holtmann.org> wrote:
>
> Hi Joao Paulo,
>
> > As reported previously on [1], it is currently not possible to discover
> > BLE devices with QCA9377 controllers. When trying to start an active
> > scanning procedure with this controller, three commands are queued,
> > LE_SET_RANDOM_ADDR, LE_SET_SCAN_PARAM and LE_SET_SCAN_ENABLE. After the
> > first command is sent to the controller, a command complete event for it
> > is received, and the second command is sent, an extra command complete
> > for the first command is received. At this point the kernel sends the
> > next command and fails to process the command complete event for the
> > LE_SET_SCAN_PARAM command, because when it arrives it does not match the
> > last command that was sent. This makes hdev->le_scan_type never be
> > updated and the kernel behaves as if a passive scanning procedure was
> > being performed, thus no device found events are sent to userspace.
> >
> > [1] https://www.spinics.net/lists/linux-bluetooth/msg79102.html
> >
> > I have received no replies on the previous report and on further
> > attempts to contact the QCA addresses that have submitted Bluetooth
> > firmware blobs to linux-firmware upstream. This series avoids the
> > problem described above, but I believe ideally the controller should not
> > be sending this extra command complete event.
> >
> > I'm not 100% sure if the approach taken here is the best way to work
> > around this problem in the kernel, as I am not super familiar with the
> > HCI layer. I'll be happy to hear suggestions of better approaches.
> >
> > Full logs from btmon can be found bellow this message, and the extra
> > command complete event can be seen at timestamp 27.420131.
>
> so can we get a fixed firmware from Qualcomm? Or at least some ROM patches for it?
>

That was my initial expectation as well -- maybe you can show the
problem to some Qualcomm contacts?

> > Best regards,
> >
> > João Paulo Rechi Vita (2):
> >  Bluetooth: Create new HCI_QUIRK_WAIT_FOR_MATCHING_CC
> >  Bluetooth: Set HCI_QUIRK_WAIT_FOR_MATCHING_CC for QCA9377
> >
> > drivers/bluetooth/btusb.c        | 9 +++++++++
> > include/net/bluetooth/hci.h      | 4 ++++
> > include/net/bluetooth/hci_core.h | 1 +
> > net/bluetooth/hci_core.c         | 3 +++
> > net/bluetooth/hci_event.c        | 4 ++++
> > 5 files changed, 21 insertions(+)
> >
> > --
> > 2.20.1
> >
> > Bluetooth monitor ver 5.50
> > = Note: Linux version 5.0.0+ (x86_64)                                  0.352340
> > = Note: Bluetooth subsystem version 2.22                               0.352343
> > = New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
> > = Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
> > = Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
> > @ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
> > @ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
> > @ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
> > @ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> > < HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
> >        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
> >> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
> >      LE Set Random Address (0x08|0x0005) ncmd 1
> >        Status: Success (0x00)
> > < HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
> >        Type: Active (0x01)
> >        Interval: 11.250 msec (0x0012)
> >        Window: 11.250 msec (0x0012)
> >        Own address type: Random (0x01)
> >        Filter policy: Accept all advertisement (0x00)
> >> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
> >      LE Set Random Address (0x08|0x0005) ncmd 1
> >        Status: Success (0x00)
>
> so we really need to ignore this command complete and not start ahead with the next command. Especially since we really only support one command at a time right now.
>

Agreed.

> > < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
> >        Scanning: Enabled (0x01)
> >        Filter duplicates: Enabled (0x01)
> >> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
> >      LE Set Scan Parameters (0x08|0x000b) ncmd 1
> >        Status: Success (0x00)
>
> We need for this command complete to arrive and only then continue with LE Set Scan Enable. We don’t need a quirk for it. Just add support for dealing with unexpected command complete opcodes. And print a big error if that happens.
>

Makes sense, I'm sending an updated version ignoring unexpected CC
events on all hardware. Looking at the code it seems the only
exception is a CC event for HCI_OP_RESET on some CSR controllers,
which is handled in hci_req_cmd_complete, so I'm letting that flow
through.

--
João Paulo Rechi Vita
http://about.me/jprvita

[PATCH] Bluetooth: Ignore CC events not matching the last HCI command

[João Paulo Rechi Vita]

This commit makes the kernel not send the next queued HCI command until
a command complete arrives for the last HCI command sent to the
controller. This change avoids a problem with some buggy controllers
(seen on two SKUs of QCA9377) that send an extra command complete event
for the previous command after the kernel had already sent a new HCI
command to the controller.

The problem was reproduced when starting an active scanning procedure,
where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
command. When this happends the kernel ends up not processing the
command complete for the following commmand, LE_SET_SCAN_PARAM, and
ultimately behaving as if a passive scanning procedure was being
performed, when in fact controller is performing an active scanning
procedure. This makes it impossible to discover BLE devices as no device
found events are sent to userspace.

This problem is reproducible on 100% of the attempts on the affected
controllers. The extra command complete event can be seen at timestamp
27.420131 on the btmon logs bellow.

Bluetooth monitor ver 5.50
= Note: Linux version 5.0.0+ (x86_64)                                  0.352340
= Note: Bluetooth subsystem version 2.22                               0.352343
= New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
= Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
= Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
@ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
@ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
@ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
@ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
        Address type: 0x06
          LE Public
          LE Random
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
        Type: Active (0x01)
        Interval: 11.250 msec (0x0012)
        Window: 11.250 msec (0x0012)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
@ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
      Start Discovery (0x0023) plen 1
        Status: Success (0x00)
        Address type: 0x06
          LE Public
          LE Random
@ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)

Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
---
 net/bluetooth/hci_event.c | 13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
index 609fd6871c5a..13fb124d04a4 100644
--- a/net/bluetooth/hci_event.c
+++ b/net/bluetooth/hci_event.c
@@ -3071,6 +3071,19 @@ static void hci_cmd_complete_evt(struct hci_dev *hdev, struct sk_buff *skb,
 	*opcode = __le16_to_cpu(ev->opcode);
 	*status = skb->data[sizeof(*ev)];
 
+	if (opcode != HCI_OP_RESET && !hci_sent_cmd_data(hdev, *opcode)) {
+		/* Some buggy controllers generate an extra command complete
+		 * event for the previous command after a new commend was
+		 * already sent, so if the opcode does not match the last sent
+		 * command we should ignore this event.
+		 *
+		 * HCI_OP_RESET is a special case handled in
+		 * hci_req_cmd_complete.
+		 */
+		bt_dev_err(hdev, "unexpected CC event opcode 0x%4.4x", *opcode);
+		return;
+	}
+
 	skb_pull(skb, sizeof(*ev));
 
 	switch (*opcode) {
-- 
2.20.1

[PATCH] Bluetooth: Ignore CC events not matching the last HCI command

[João Paulo Rechi Vita]

This commit makes the kernel not send the next queued HCI command until
a command complete arrives for the last HCI command sent to the
controller. This change avoids a problem with some buggy controllers
(seen on two SKUs of QCA9377) that send an extra command complete event
for the previous command after the kernel had already sent a new HCI
command to the controller.

The problem was reproduced when starting an active scanning procedure,
where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
command. When this happends the kernel ends up not processing the
command complete for the following commmand, LE_SET_SCAN_PARAM, and
ultimately behaving as if a passive scanning procedure was being
performed, when in fact controller is performing an active scanning
procedure. This makes it impossible to discover BLE devices as no device
found events are sent to userspace.

This problem is reproducible on 100% of the attempts on the affected
controllers. The extra command complete event can be seen at timestamp
27.420131 on the btmon logs bellow.

Bluetooth monitor ver 5.50
= Note: Linux version 5.0.0+ (x86_64)                                  0.352340
= Note: Bluetooth subsystem version 2.22                               0.352343
= New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
= Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
= Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
@ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
@ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
@ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
@ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
        Address type: 0x06
          LE Public
          LE Random
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
        Type: Active (0x01)
        Interval: 11.250 msec (0x0012)
        Window: 11.250 msec (0x0012)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
@ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
      Start Discovery (0x0023) plen 1
        Status: Success (0x00)
        Address type: 0x06
          LE Public
          LE Random
@ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)

Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
---
 net/bluetooth/hci_event.c | 13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
index 609fd6871c5a..b349fc2b4123 100644
--- a/net/bluetooth/hci_event.c
+++ b/net/bluetooth/hci_event.c
@@ -3071,6 +3071,19 @@ static void hci_cmd_complete_evt(struct hci_dev *hdev, struct sk_buff *skb,
 	*opcode = __le16_to_cpu(ev->opcode);
 	*status = skb->data[sizeof(*ev)];
 
+	if (*opcode != HCI_OP_RESET && !hci_sent_cmd_data(hdev, *opcode)) {
+		/* Some buggy controllers generate an extra command complete
+		 * event for the previous command after a new commend was
+		 * already sent, so if the opcode does not match the last sent
+		 * command we should ignore this event.
+		 *
+		 * HCI_OP_RESET is a special case handled in
+		 * hci_req_cmd_complete.
+		 */
+		bt_dev_err(hdev, "unexpected CC event opcode 0x%4.4x", *opcode);
+		return;
+	}
+
 	skb_pull(skb, sizeof(*ev));
 
 	switch (*opcode) {
-- 
2.20.1

Re: [PATCH] Bluetooth: Ignore CC events not matching the last HCI command

[Marcel Holtmann]

Hi Joao Paulo,

> This commit makes the kernel not send the next queued HCI command until
> a command complete arrives for the last HCI command sent to the
> controller. This change avoids a problem with some buggy controllers
> (seen on two SKUs of QCA9377) that send an extra command complete event
> for the previous command after the kernel had already sent a new HCI
> command to the controller.
> 
> The problem was reproduced when starting an active scanning procedure,
> where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
> command. When this happends the kernel ends up not processing the
> command complete for the following commmand, LE_SET_SCAN_PARAM, and
> ultimately behaving as if a passive scanning procedure was being
> performed, when in fact controller is performing an active scanning
> procedure. This makes it impossible to discover BLE devices as no device
> found events are sent to userspace.
> 
> This problem is reproducible on 100% of the attempts on the affected
> controllers. The extra command complete event can be seen at timestamp
> 27.420131 on the btmon logs bellow.
> 
> Bluetooth monitor ver 5.50
> = Note: Linux version 5.0.0+ (x86_64)                                  0.352340
> = Note: Bluetooth subsystem version 2.22                               0.352343
> = New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
> = Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
> = Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
> @ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
> @ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
> @ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
> @ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
>        Address type: 0x06
>          LE Public
>          LE Random
> < HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
>        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
>> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
>      LE Set Random Address (0x08|0x0005) ncmd 1
>        Status: Success (0x00)
> < HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
>        Type: Active (0x01)
>        Interval: 11.250 msec (0x0012)
>        Window: 11.250 msec (0x0012)
>        Own address type: Random (0x01)
>        Filter policy: Accept all advertisement (0x00)
>> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
>      LE Set Random Address (0x08|0x0005) ncmd 1
>        Status: Success (0x00)
> < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
>        Scanning: Enabled (0x01)
>        Filter duplicates: Enabled (0x01)
>> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
>      LE Set Scan Parameters (0x08|0x000b) ncmd 1
>        Status: Success (0x00)
>> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
>      LE Set Scan Enable (0x08|0x000c) ncmd 1
>        Status: Success (0x00)
> @ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
>      Start Discovery (0x0023) plen 1
>        Status: Success (0x00)
>        Address type: 0x06
>          LE Public
>          LE Random
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> 
> Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
> ---
> net/bluetooth/hci_event.c | 13 +++++++++++++
> 1 file changed, 13 insertions(+)
> 
> diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
> index 609fd6871c5a..b349fc2b4123 100644
> --- a/net/bluetooth/hci_event.c
> +++ b/net/bluetooth/hci_event.c
> @@ -3071,6 +3071,19 @@ static void hci_cmd_complete_evt(struct hci_dev *hdev, struct sk_buff *skb,
> 	*opcode = __le16_to_cpu(ev->opcode);
> 	*status = skb->data[sizeof(*ev)];
> 
> +	if (*opcode != HCI_OP_RESET && !hci_sent_cmd_data(hdev, *opcode)) {
> +		/* Some buggy controllers generate an extra command complete
> +		 * event for the previous command after a new commend was
> +		 * already sent, so if the opcode does not match the last sent
> +		 * command we should ignore this event.
> +		 *
> +		 * HCI_OP_RESET is a special case handled in
> +		 * hci_req_cmd_complete.
> +		 */
> +		bt_dev_err(hdev, "unexpected CC event opcode 0x%4.4x", *opcode);
> +		return;
> +	}
> +

the return; here is not going to fly. You need to go through the switch statement since it actually does bookkeeping for a lot of features even if the command is not executed by hci_req and instead comes from user space or someone else.

What is the problem with handling this in hci_req_cmd_complete. We have hci_sent_cmd_data check there already. Lets extend this to ensure that command complete for random commands don’t trigger us to continue with the request.

Regards

Marcel

Re: [PATCH] Bluetooth: Ignore CC events not matching the last HCI command

[João Paulo Rechi Vita]

On Wed, Apr 24, 2019 at 2:45 PM Marcel Holtmann <marcel@holtmann.org> wrote:
>
> Hi Joao Paulo,
>
> > This commit makes the kernel not send the next queued HCI command until
> > a command complete arrives for the last HCI command sent to the
> > controller. This change avoids a problem with some buggy controllers
> > (seen on two SKUs of QCA9377) that send an extra command complete event
> > for the previous command after the kernel had already sent a new HCI
> > command to the controller.
> >
> > The problem was reproduced when starting an active scanning procedure,
> > where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
> > command. When this happends the kernel ends up not processing the
> > command complete for the following commmand, LE_SET_SCAN_PARAM, and
> > ultimately behaving as if a passive scanning procedure was being
> > performed, when in fact controller is performing an active scanning
> > procedure. This makes it impossible to discover BLE devices as no device
> > found events are sent to userspace.
> >
> > This problem is reproducible on 100% of the attempts on the affected
> > controllers. The extra command complete event can be seen at timestamp
> > 27.420131 on the btmon logs bellow.
> >
> > Bluetooth monitor ver 5.50
> > = Note: Linux version 5.0.0+ (x86_64)                                  0.352340
> > = Note: Bluetooth subsystem version 2.22                               0.352343
> > = New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
> > = Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
> > = Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
> > @ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
> > @ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
> > @ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
> > @ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> > < HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
> >        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
> >> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
> >      LE Set Random Address (0x08|0x0005) ncmd 1
> >        Status: Success (0x00)
> > < HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
> >        Type: Active (0x01)
> >        Interval: 11.250 msec (0x0012)
> >        Window: 11.250 msec (0x0012)
> >        Own address type: Random (0x01)
> >        Filter policy: Accept all advertisement (0x00)
> >> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
> >      LE Set Random Address (0x08|0x0005) ncmd 1
> >        Status: Success (0x00)
> > < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
> >        Scanning: Enabled (0x01)
> >        Filter duplicates: Enabled (0x01)
> >> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
> >      LE Set Scan Parameters (0x08|0x000b) ncmd 1
> >        Status: Success (0x00)
> >> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
> >      LE Set Scan Enable (0x08|0x000c) ncmd 1
> >        Status: Success (0x00)
> > @ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
> >      Start Discovery (0x0023) plen 1
> >        Status: Success (0x00)
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> > @ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> >        Discovery: Enabled (0x01)
> > @ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> >        Discovery: Enabled (0x01)
> > @ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> >        Discovery: Enabled (0x01)
> >
> > Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
> > ---
> > net/bluetooth/hci_event.c | 13 +++++++++++++
> > 1 file changed, 13 insertions(+)
> >
> > diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
> > index 609fd6871c5a..b349fc2b4123 100644
> > --- a/net/bluetooth/hci_event.c
> > +++ b/net/bluetooth/hci_event.c
> > @@ -3071,6 +3071,19 @@ static void hci_cmd_complete_evt(struct hci_dev *hdev, struct sk_buff *skb,
> >       *opcode = __le16_to_cpu(ev->opcode);
> >       *status = skb->data[sizeof(*ev)];
> >
> > +     if (*opcode != HCI_OP_RESET && !hci_sent_cmd_data(hdev, *opcode)) {
> > +             /* Some buggy controllers generate an extra command complete
> > +              * event for the previous command after a new commend was
> > +              * already sent, so if the opcode does not match the last sent
> > +              * command we should ignore this event.
> > +              *
> > +              * HCI_OP_RESET is a special case handled in
> > +              * hci_req_cmd_complete.
> > +              */
> > +             bt_dev_err(hdev, "unexpected CC event opcode 0x%4.4x", *opcode);
> > +             return;
> > +     }
> > +
>
> the return; here is not going to fly. You need to go through the switch statement since it actually does bookkeeping for a lot of features even if the command is not executed by hci_req and instead comes from user space or someone else.
>

Ok, so you want the same approach I had before but not bound to a
quirk. Sorry, when you previously said "ignore this command complete
and not start ahead with the next command" I thought you meant to also
avoid going through that switch statement.

> What is the problem with handling this in hci_req_cmd_complete. We have hci_sent_cmd_data check there already. Lets extend this to ensure that command complete for random commands don’t trigger us to continue with the request.
>

I'll send an updated revision soon.

--
João Paulo Rechi Vita
http://about.me/jprvita

[PATCH] Bluetooth: Ignore CC events not matching the last HCI command

[João Paulo Rechi Vita]

This commit makes the kernel not send the next queued HCI command until
a command complete arrives for the last HCI command sent to the
controller. This change avoids a problem with some buggy controllers
(seen on two SKUs of QCA9377) that send an extra command complete event
for the previous command after the kernel had already sent a new HCI
command to the controller.

The problem was reproduced when starting an active scanning procedure,
where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
command. When this happends the kernel ends up not processing the
command complete for the following commmand, LE_SET_SCAN_PARAM, and
ultimately behaving as if a passive scanning procedure was being
performed, when in fact controller is performing an active scanning
procedure. This makes it impossible to discover BLE devices as no device
found events are sent to userspace.

This problem is reproducible on 100% of the attempts on the affected
controllers. The extra command complete event can be seen at timestamp
27.420131 on the btmon logs bellow.

Bluetooth monitor ver 5.50
= Note: Linux version 5.0.0+ (x86_64)                                  0.352340
= Note: Bluetooth subsystem version 2.22                               0.352343
= New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
= Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
= Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
@ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
@ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
@ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
@ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
        Address type: 0x06
          LE Public
          LE Random
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
        Type: Active (0x01)
        Interval: 11.250 msec (0x0012)
        Window: 11.250 msec (0x0012)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
@ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
      Start Discovery (0x0023) plen 1
        Status: Success (0x00)
        Address type: 0x06
          LE Public
          LE Random
@ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)

Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
---
 include/net/bluetooth/hci_core.h | 1 +
 net/bluetooth/hci_core.c         | 5 +++++
 net/bluetooth/hci_event.c        | 3 +++
 3 files changed, 9 insertions(+)

diff --git a/include/net/bluetooth/hci_core.h b/include/net/bluetooth/hci_core.h
index 094e61e07030..85bed4e916d3 100644
--- a/include/net/bluetooth/hci_core.h
+++ b/include/net/bluetooth/hci_core.h
@@ -364,6 +364,7 @@ struct hci_dev {
 	struct sk_buff_head	cmd_q;
 
 	struct sk_buff		*sent_cmd;
+	__u8			sent_cmd_pending_cc;
 
 	struct mutex		req_lock;
 	wait_queue_head_t	req_wait_q;
diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
index d6b2540ba7f8..37893b0c6077 100644
--- a/net/bluetooth/hci_core.c
+++ b/net/bluetooth/hci_core.c
@@ -4380,9 +4380,13 @@ void hci_req_cmd_complete(struct hci_dev *hdev, u16 opcode, u8 status,
 		if (test_bit(HCI_INIT, &hdev->flags) && opcode == HCI_OP_RESET)
 			hci_resend_last(hdev);
 
+		bt_dev_err(hdev,
+			   "unexpected CC event for opcode 0x%4.4x", opcode);
 		return;
 	}
 
+	hdev->sent_cmd_pending_cc = 0;
+
 	/* If the command succeeded and there's still more commands in
 	 * this request the request is not yet complete.
 	 */
@@ -4493,6 +4497,7 @@ static void hci_cmd_work(struct work_struct *work)
 
 		hdev->sent_cmd = skb_clone(skb, GFP_KERNEL);
 		if (hdev->sent_cmd) {
+			hdev->sent_cmd_pending_cc = 1;
 			atomic_dec(&hdev->cmd_cnt);
 			hci_send_frame(hdev, skb);
 			if (test_bit(HCI_RESET, &hdev->flags))
diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
index 609fd6871c5a..7541a4bc9444 100644
--- a/net/bluetooth/hci_event.c
+++ b/net/bluetooth/hci_event.c
@@ -3404,6 +3404,9 @@ static void hci_cmd_complete_evt(struct hci_dev *hdev, struct sk_buff *skb,
 	hci_req_cmd_complete(hdev, *opcode, *status, req_complete,
 			     req_complete_skb);
 
+	if (hdev->sent_cmd_pending_cc)
+		return;
+
 	if (atomic_read(&hdev->cmd_cnt) && !skb_queue_empty(&hdev->cmd_q))
 		queue_work(hdev->workqueue, &hdev->cmd_work);
 }
-- 
2.20.1

Re: [PATCH] Bluetooth: Ignore CC events not matching the last HCI command

[Marcel Holtmann]

Hi Joao,

> This commit makes the kernel not send the next queued HCI command until
> a command complete arrives for the last HCI command sent to the
> controller. This change avoids a problem with some buggy controllers
> (seen on two SKUs of QCA9377) that send an extra command complete event
> for the previous command after the kernel had already sent a new HCI
> command to the controller.
> 
> The problem was reproduced when starting an active scanning procedure,
> where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
> command. When this happends the kernel ends up not processing the
> command complete for the following commmand, LE_SET_SCAN_PARAM, and
> ultimately behaving as if a passive scanning procedure was being
> performed, when in fact controller is performing an active scanning
> procedure. This makes it impossible to discover BLE devices as no device
> found events are sent to userspace.
> 
> This problem is reproducible on 100% of the attempts on the affected
> controllers. The extra command complete event can be seen at timestamp
> 27.420131 on the btmon logs bellow.
> 
> Bluetooth monitor ver 5.50
> = Note: Linux version 5.0.0+ (x86_64)                                  0.352340
> = Note: Bluetooth subsystem version 2.22                               0.352343
> = New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
> = Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
> = Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
> @ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
> @ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
> @ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
> @ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
>        Address type: 0x06
>          LE Public
>          LE Random
> < HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
>        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
>> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
>      LE Set Random Address (0x08|0x0005) ncmd 1
>        Status: Success (0x00)
> < HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
>        Type: Active (0x01)
>        Interval: 11.250 msec (0x0012)
>        Window: 11.250 msec (0x0012)
>        Own address type: Random (0x01)
>        Filter policy: Accept all advertisement (0x00)
>> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
>      LE Set Random Address (0x08|0x0005) ncmd 1
>        Status: Success (0x00)
> < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
>        Scanning: Enabled (0x01)
>        Filter duplicates: Enabled (0x01)
>> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
>      LE Set Scan Parameters (0x08|0x000b) ncmd 1
>        Status: Success (0x00)
>> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
>      LE Set Scan Enable (0x08|0x000c) ncmd 1
>        Status: Success (0x00)
> @ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
>      Start Discovery (0x0023) plen 1
>        Status: Success (0x00)
>        Address type: 0x06
>          LE Public
>          LE Random
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> 
> Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
> ---
> include/net/bluetooth/hci_core.h | 1 +
> net/bluetooth/hci_core.c         | 5 +++++
> net/bluetooth/hci_event.c        | 3 +++
> 3 files changed, 9 insertions(+)
> 
> diff --git a/include/net/bluetooth/hci_core.h b/include/net/bluetooth/hci_core.h
> index 094e61e07030..85bed4e916d3 100644
> --- a/include/net/bluetooth/hci_core.h
> +++ b/include/net/bluetooth/hci_core.h
> @@ -364,6 +364,7 @@ struct hci_dev {
> 	struct sk_buff_head	cmd_q;
> 
> 	struct sk_buff		*sent_cmd;
> +	__u8			sent_cmd_pending_cc;

is there anything wrong with a bool type? And frankly using a flag seems more safe than just a boolean.

> 
> 	struct mutex		req_lock;
> 	wait_queue_head_t	req_wait_q;
> diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
> index d6b2540ba7f8..37893b0c6077 100644
> --- a/net/bluetooth/hci_core.c
> +++ b/net/bluetooth/hci_core.c
> @@ -4380,9 +4380,13 @@ void hci_req_cmd_complete(struct hci_dev *hdev, u16 opcode, u8 status,
> 		if (test_bit(HCI_INIT, &hdev->flags) && opcode == HCI_OP_RESET)
> 			hci_resend_last(hdev);
> 
> +		bt_dev_err(hdev,
> +			   "unexpected CC event for opcode 0x%4.4x", opcode);

Have you tested this? This will cause many error from tools like hciconfig or hcitool.

> 		return;
> 	}
> 
> +	hdev->sent_cmd_pending_cc = 0;
> +
> 	/* If the command succeeded and there's still more commands in
> 	 * this request the request is not yet complete.
> 	 */
> @@ -4493,6 +4497,7 @@ static void hci_cmd_work(struct work_struct *work)
> 
> 		hdev->sent_cmd = skb_clone(skb, GFP_KERNEL);
> 		if (hdev->sent_cmd) {
> +			hdev->sent_cmd_pending_cc = 1;
> 			atomic_dec(&hdev->cmd_cnt);
> 			hci_send_frame(hdev, skb);
> 			if (test_bit(HCI_RESET, &hdev->flags))

Fun part is actually that even commands injected via hcitool etc. will be added to the sent_cmd queue unless they are vendor specific commands. However some manufactures choose to use command complete for their vendor commands as well (others don’t).

> diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
> index 609fd6871c5a..7541a4bc9444 100644
> --- a/net/bluetooth/hci_event.c
> +++ b/net/bluetooth/hci_event.c
> @@ -3404,6 +3404,9 @@ static void hci_cmd_complete_evt(struct hci_dev *hdev, struct sk_buff *skb,
> 	hci_req_cmd_complete(hdev, *opcode, *status, req_complete,
> 			     req_complete_skb);
> 
> +	if (hdev->sent_cmd_pending_cc)
> +		return;
> +
> 	if (atomic_read(&hdev->cmd_cnt) && !skb_queue_empty(&hdev->cmd_q))
> 		queue_work(hdev->workqueue, &hdev->cmd_work);

I rather see this done super cleanly. We have a pending cmd request from the kernel, make sure it gets answered with the corresponding command complete or command status and not just some other event. If there is a command complete or command status for a command that we don’t have pending, then ignore.

Frankly, you are just hacking around here.

Regards

Marcel

Re: [PATCH] Bluetooth: Ignore CC events not matching the last HCI command

[João Paulo Rechi Vita]

On Thu, Apr 25, 2019 at 7:08 PM Marcel Holtmann <marcel@holtmann.org> wrote:
>
> Hi Joao,
>
> > This commit makes the kernel not send the next queued HCI command until
> > a command complete arrives for the last HCI command sent to the
> > controller. This change avoids a problem with some buggy controllers
> > (seen on two SKUs of QCA9377) that send an extra command complete event
> > for the previous command after the kernel had already sent a new HCI
> > command to the controller.
> >
> > The problem was reproduced when starting an active scanning procedure,
> > where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
> > command. When this happends the kernel ends up not processing the
> > command complete for the following commmand, LE_SET_SCAN_PARAM, and
> > ultimately behaving as if a passive scanning procedure was being
> > performed, when in fact controller is performing an active scanning
> > procedure. This makes it impossible to discover BLE devices as no device
> > found events are sent to userspace.
> >
> > This problem is reproducible on 100% of the attempts on the affected
> > controllers. The extra command complete event can be seen at timestamp
> > 27.420131 on the btmon logs bellow.
> >
> > Bluetooth monitor ver 5.50
> > = Note: Linux version 5.0.0+ (x86_64)                                  0.352340
> > = Note: Bluetooth subsystem version 2.22                               0.352343
> > = New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
> > = Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
> > = Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
> > @ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
> > @ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
> > @ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
> > @ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> > < HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
> >        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
> >> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
> >      LE Set Random Address (0x08|0x0005) ncmd 1
> >        Status: Success (0x00)
> > < HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
> >        Type: Active (0x01)
> >        Interval: 11.250 msec (0x0012)
> >        Window: 11.250 msec (0x0012)
> >        Own address type: Random (0x01)
> >        Filter policy: Accept all advertisement (0x00)
> >> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
> >      LE Set Random Address (0x08|0x0005) ncmd 1
> >        Status: Success (0x00)
> > < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
> >        Scanning: Enabled (0x01)
> >        Filter duplicates: Enabled (0x01)
> >> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
> >      LE Set Scan Parameters (0x08|0x000b) ncmd 1
> >        Status: Success (0x00)
> >> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
> >      LE Set Scan Enable (0x08|0x000c) ncmd 1
> >        Status: Success (0x00)
> > @ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
> >      Start Discovery (0x0023) plen 1
> >        Status: Success (0x00)
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> > @ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> >        Discovery: Enabled (0x01)
> > @ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> >        Discovery: Enabled (0x01)
> > @ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> >        Discovery: Enabled (0x01)
> >
> > Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
> > ---
> > include/net/bluetooth/hci_core.h | 1 +
> > net/bluetooth/hci_core.c         | 5 +++++
> > net/bluetooth/hci_event.c        | 3 +++
> > 3 files changed, 9 insertions(+)
> >
> > diff --git a/include/net/bluetooth/hci_core.h b/include/net/bluetooth/hci_core.h
> > index 094e61e07030..85bed4e916d3 100644
> > --- a/include/net/bluetooth/hci_core.h
> > +++ b/include/net/bluetooth/hci_core.h
> > @@ -364,6 +364,7 @@ struct hci_dev {
> >       struct sk_buff_head     cmd_q;
> >
> >       struct sk_buff          *sent_cmd;
> > +     __u8                    sent_cmd_pending_cc;
>
> is there anything wrong with a bool type? And frankly using a flag seems more safe than just a boolean.
>

Ok, I'll change it into a flag.

> >
> >       struct mutex            req_lock;
> >       wait_queue_head_t       req_wait_q;
> > diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
> > index d6b2540ba7f8..37893b0c6077 100644
> > --- a/net/bluetooth/hci_core.c
> > +++ b/net/bluetooth/hci_core.c
> > @@ -4380,9 +4380,13 @@ void hci_req_cmd_complete(struct hci_dev *hdev, u16 opcode, u8 status,
> >               if (test_bit(HCI_INIT, &hdev->flags) && opcode == HCI_OP_RESET)
> >                       hci_resend_last(hdev);
> >
> > +             bt_dev_err(hdev,
> > +                        "unexpected CC event for opcode 0x%4.4x", opcode);
>
> Have you tested this? This will cause many error from tools like hciconfig or hcitool.
>

I have tested this, but not with hciconfig or hcitool custom commands.
Do you have an example that I could use to verify this?

> >               return;
> >       }
> >
> > +     hdev->sent_cmd_pending_cc = 0;
> > +
> >       /* If the command succeeded and there's still more commands in
> >        * this request the request is not yet complete.
> >        */
> > @@ -4493,6 +4497,7 @@ static void hci_cmd_work(struct work_struct *work)
> >
> >               hdev->sent_cmd = skb_clone(skb, GFP_KERNEL);
> >               if (hdev->sent_cmd) {
> > +                     hdev->sent_cmd_pending_cc = 1;
> >                       atomic_dec(&hdev->cmd_cnt);
> >                       hci_send_frame(hdev, skb);
> >                       if (test_bit(HCI_RESET, &hdev->flags))
>
> Fun part is actually that even commands injected via hcitool etc. will be added to the sent_cmd queue unless they are vendor specific commands. However some manufactures choose to use command complete for their vendor commands as well (others don’t).
>

So injected commands and vendor-specific commands are not part of an
hci_request, but end up in this same hdev->cmd_q somehow. Is that
correct?

> > diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
> > index 609fd6871c5a..7541a4bc9444 100644
> > --- a/net/bluetooth/hci_event.c
> > +++ b/net/bluetooth/hci_event.c
> > @@ -3404,6 +3404,9 @@ static void hci_cmd_complete_evt(struct hci_dev *hdev, struct sk_buff *skb,
> >       hci_req_cmd_complete(hdev, *opcode, *status, req_complete,
> >                            req_complete_skb);
> >
> > +     if (hdev->sent_cmd_pending_cc)
> > +             return;
> > +
> >       if (atomic_read(&hdev->cmd_cnt) && !skb_queue_empty(&hdev->cmd_q))
> >               queue_work(hdev->workqueue, &hdev->cmd_work);
>
> I rather see this done super cleanly. We have a pending cmd request from the kernel, make sure it gets answered with the corresponding command complete or command status and not just some other event. If there is a command complete or command status for a command that we don’t have pending, then ignore.
>

So, just to make this clear: are you saying we should only try to
match commands with events if the command is part of a hci_request?
IIUC the way to verify if a command is part of a request is to check
if hdev->req_status == HCI_REQ_PEND.

> Frankly, you are just hacking around here.
>

Well, I tried to make this point on my first submission -- I am not
familiar with the HCI layer, but having identified the bug and have
the affected hardware at hand, I thought I might as well try to fix it
so users with this controller can use BLE devices. I am happy to keep
working on it some guidance, but I would not mind testing patches
either if you think that would be easier.

> Regards
>
> Marcel
>

Thanks for the reviews so far. I'm sending a new revision
incorporating my understanding of the feedback above,

Best regards,

--
João Paulo Rechi Vita
http://about.me/jprvita

[PATCH v3] Bluetooth: Ignore CC events not matching the last HCI command

[João Paulo Rechi Vita]

This commit makes the kernel not send the next queued HCI command until
a command complete arrives for the last HCI command sent to the
controller. This change avoids a problem with some buggy controllers
(seen on two SKUs of QCA9377) that send an extra command complete event
for the previous command after the kernel had already sent a new HCI
command to the controller.

The problem was reproduced when starting an active scanning procedure,
where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
command. When this happends the kernel ends up not processing the
command complete for the following commmand, LE_SET_SCAN_PARAM, and
ultimately behaving as if a passive scanning procedure was being
performed, when in fact controller is performing an active scanning
procedure. This makes it impossible to discover BLE devices as no device
found events are sent to userspace.

This problem is reproducible on 100% of the attempts on the affected
controllers. The extra command complete event can be seen at timestamp
27.420131 on the btmon logs bellow.

Bluetooth monitor ver 5.50
= Note: Linux version 5.0.0+ (x86_64)                                  0.352340
= Note: Bluetooth subsystem version 2.22                               0.352343
= New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
= Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
= Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
@ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
@ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
@ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
@ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
        Address type: 0x06
          LE Public
          LE Random
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
        Type: Active (0x01)
        Interval: 11.250 msec (0x0012)
        Window: 11.250 msec (0x0012)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
@ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
      Start Discovery (0x0023) plen 1
        Status: Success (0x00)
        Address type: 0x06
          LE Public
          LE Random
@ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)

Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
---
 include/net/bluetooth/hci.h |  2 ++
 net/bluetooth/hci_core.c    |  5 +++++
 net/bluetooth/hci_event.c   | 12 ++++++++++++
 net/bluetooth/hci_request.c |  4 ----
 net/bluetooth/hci_request.h |  4 ++++
 5 files changed, 23 insertions(+), 4 deletions(-)

diff --git a/include/net/bluetooth/hci.h b/include/net/bluetooth/hci.h
index fbba43e9bef5..883a8c25ccfb 100644
--- a/include/net/bluetooth/hci.h
+++ b/include/net/bluetooth/hci.h
@@ -221,6 +221,8 @@ enum {
 	HCI_RAW,
 
 	HCI_RESET,
+
+	HCI_CMD_PENDING,
 };
 
 /* HCI socket flags */
diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
index d6b2540ba7f8..4b7f20286e1a 100644
--- a/net/bluetooth/hci_core.c
+++ b/net/bluetooth/hci_core.c
@@ -4383,6 +4383,9 @@ void hci_req_cmd_complete(struct hci_dev *hdev, u16 opcode, u8 status,
 		return;
 	}
 
+	/* If we reach this point this event matches the last command sent */
+	clear_bit(HCI_CMD_PENDING, &hdev->flags);
+
 	/* If the command succeeded and there's still more commands in
 	 * this request the request is not yet complete.
 	 */
@@ -4493,6 +4496,8 @@ static void hci_cmd_work(struct work_struct *work)
 
 		hdev->sent_cmd = skb_clone(skb, GFP_KERNEL);
 		if (hdev->sent_cmd) {
+			if (hdev->req_status == HCI_REQ_PEND)
+				set_bit(HCI_CMD_PENDING, &hdev->flags);
 			atomic_dec(&hdev->cmd_cnt);
 			hci_send_frame(hdev, skb);
 			if (test_bit(HCI_RESET, &hdev->flags))
diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
index 609fd6871c5a..cac13f674474 100644
--- a/net/bluetooth/hci_event.c
+++ b/net/bluetooth/hci_event.c
@@ -3404,6 +3404,12 @@ static void hci_cmd_complete_evt(struct hci_dev *hdev, struct sk_buff *skb,
 	hci_req_cmd_complete(hdev, *opcode, *status, req_complete,
 			     req_complete_skb);
 
+	if (test_bit(HCI_CMD_PENDING, &hdev->flags)) {
+		bt_dev_err(hdev,
+			   "unexpected event for opcode 0x%4.4x", *opcode);
+		return;
+	}
+
 	if (atomic_read(&hdev->cmd_cnt) && !skb_queue_empty(&hdev->cmd_q))
 		queue_work(hdev->workqueue, &hdev->cmd_work);
 }
@@ -3511,6 +3517,12 @@ static void hci_cmd_status_evt(struct hci_dev *hdev, struct sk_buff *skb,
 		hci_req_cmd_complete(hdev, *opcode, ev->status, req_complete,
 				     req_complete_skb);
 
+	if (test_bit(HCI_CMD_PENDING, &hdev->flags)) {
+		bt_dev_err(hdev,
+			   "unexpected event for opcode 0x%4.4x", *opcode);
+		return;
+	}
+
 	if (atomic_read(&hdev->cmd_cnt) && !skb_queue_empty(&hdev->cmd_q))
 		queue_work(hdev->workqueue, &hdev->cmd_work);
 }
diff --git a/net/bluetooth/hci_request.c b/net/bluetooth/hci_request.c
index ca73d36cc149..5b3838a3bdc1 100644
--- a/net/bluetooth/hci_request.c
+++ b/net/bluetooth/hci_request.c
@@ -30,10 +30,6 @@
 #include "smp.h"
 #include "hci_request.h"
 
-#define HCI_REQ_DONE	  0
-#define HCI_REQ_PEND	  1
-#define HCI_REQ_CANCELED  2
-
 void hci_req_init(struct hci_request *req, struct hci_dev *hdev)
 {
 	skb_queue_head_init(&req->cmd_q);
diff --git a/net/bluetooth/hci_request.h b/net/bluetooth/hci_request.h
index 692cc8b13368..d0cea517d66e 100644
--- a/net/bluetooth/hci_request.h
+++ b/net/bluetooth/hci_request.h
@@ -22,6 +22,10 @@
 
 #include <asm/unaligned.h>
 
+#define HCI_REQ_DONE	  0
+#define HCI_REQ_PEND	  1
+#define HCI_REQ_CANCELED  2
+
 #define hci_req_sync_lock(hdev)   mutex_lock(&hdev->req_lock)
 #define hci_req_sync_unlock(hdev) mutex_unlock(&hdev->req_lock)
 
-- 
2.20.1

Re: [PATCH v3] Bluetooth: Ignore CC events not matching the last HCI command

[Marcel Holtmann]

Hi Joao,

> This commit makes the kernel not send the next queued HCI command until
> a command complete arrives for the last HCI command sent to the
> controller. This change avoids a problem with some buggy controllers
> (seen on two SKUs of QCA9377) that send an extra command complete event
> for the previous command after the kernel had already sent a new HCI
> command to the controller.
> 
> The problem was reproduced when starting an active scanning procedure,
> where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
> command. When this happends the kernel ends up not processing the
> command complete for the following commmand, LE_SET_SCAN_PARAM, and
> ultimately behaving as if a passive scanning procedure was being
> performed, when in fact controller is performing an active scanning
> procedure. This makes it impossible to discover BLE devices as no device
> found events are sent to userspace.
> 
> This problem is reproducible on 100% of the attempts on the affected
> controllers. The extra command complete event can be seen at timestamp
> 27.420131 on the btmon logs bellow.
> 
> Bluetooth monitor ver 5.50
> = Note: Linux version 5.0.0+ (x86_64)                                  0.352340
> = Note: Bluetooth subsystem version 2.22                               0.352343
> = New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
> = Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
> = Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
> @ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
> @ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
> @ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
> @ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
>        Address type: 0x06
>          LE Public
>          LE Random
> < HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
>        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
>> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
>      LE Set Random Address (0x08|0x0005) ncmd 1
>        Status: Success (0x00)
> < HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
>        Type: Active (0x01)
>        Interval: 11.250 msec (0x0012)
>        Window: 11.250 msec (0x0012)
>        Own address type: Random (0x01)
>        Filter policy: Accept all advertisement (0x00)
>> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
>      LE Set Random Address (0x08|0x0005) ncmd 1
>        Status: Success (0x00)
> < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
>        Scanning: Enabled (0x01)
>        Filter duplicates: Enabled (0x01)
>> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
>      LE Set Scan Parameters (0x08|0x000b) ncmd 1
>        Status: Success (0x00)
>> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
>      LE Set Scan Enable (0x08|0x000c) ncmd 1
>        Status: Success (0x00)
> @ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
>      Start Discovery (0x0023) plen 1
>        Status: Success (0x00)
>        Address type: 0x06
>          LE Public
>          LE Random
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> 
> Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
> ---
> include/net/bluetooth/hci.h |  2 ++
> net/bluetooth/hci_core.c    |  5 +++++
> net/bluetooth/hci_event.c   | 12 ++++++++++++
> net/bluetooth/hci_request.c |  4 ----
> net/bluetooth/hci_request.h |  4 ++++
> 5 files changed, 23 insertions(+), 4 deletions(-)
> 
> diff --git a/include/net/bluetooth/hci.h b/include/net/bluetooth/hci.h
> index fbba43e9bef5..883a8c25ccfb 100644
> --- a/include/net/bluetooth/hci.h
> +++ b/include/net/bluetooth/hci.h
> @@ -221,6 +221,8 @@ enum {
> 	HCI_RAW,
> 
> 	HCI_RESET,
> +
> +	HCI_CMD_PENDING,
> };

no new flags here please. This is userspace visible use the hdev->dev_flags.

Regards

Marcel

Re: [PATCH v3] Bluetooth: Ignore CC events not matching the last HCI command

[João Paulo Rechi Vita]

On Sat, Apr 27, 2019 at 1:01 AM Marcel Holtmann <marcel@holtmann.org> wrote:
>
> Hi Joao,
>
> > This commit makes the kernel not send the next queued HCI command until
> > a command complete arrives for the last HCI command sent to the
> > controller. This change avoids a problem with some buggy controllers
> > (seen on two SKUs of QCA9377) that send an extra command complete event
> > for the previous command after the kernel had already sent a new HCI
> > command to the controller.
> >
> > The problem was reproduced when starting an active scanning procedure,
> > where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
> > command. When this happends the kernel ends up not processing the
> > command complete for the following commmand, LE_SET_SCAN_PARAM, and
> > ultimately behaving as if a passive scanning procedure was being
> > performed, when in fact controller is performing an active scanning
> > procedure. This makes it impossible to discover BLE devices as no device
> > found events are sent to userspace.
> >
> > This problem is reproducible on 100% of the attempts on the affected
> > controllers. The extra command complete event can be seen at timestamp
> > 27.420131 on the btmon logs bellow.
> >
> > Bluetooth monitor ver 5.50
> > = Note: Linux version 5.0.0+ (x86_64)                                  0.352340
> > = Note: Bluetooth subsystem version 2.22                               0.352343
> > = New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
> > = Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
> > = Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
> > @ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
> > @ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
> > @ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
> > @ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> > < HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
> >        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
> >> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
> >      LE Set Random Address (0x08|0x0005) ncmd 1
> >        Status: Success (0x00)
> > < HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
> >        Type: Active (0x01)
> >        Interval: 11.250 msec (0x0012)
> >        Window: 11.250 msec (0x0012)
> >        Own address type: Random (0x01)
> >        Filter policy: Accept all advertisement (0x00)
> >> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
> >      LE Set Random Address (0x08|0x0005) ncmd 1
> >        Status: Success (0x00)
> > < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
> >        Scanning: Enabled (0x01)
> >        Filter duplicates: Enabled (0x01)
> >> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
> >      LE Set Scan Parameters (0x08|0x000b) ncmd 1
> >        Status: Success (0x00)
> >> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
> >      LE Set Scan Enable (0x08|0x000c) ncmd 1
> >        Status: Success (0x00)
> > @ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
> >      Start Discovery (0x0023) plen 1
> >        Status: Success (0x00)
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> > @ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> >        Discovery: Enabled (0x01)
> > @ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> >        Discovery: Enabled (0x01)
> > @ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
> >        Address type: 0x06
> >          LE Public
> >          LE Random
> >        Discovery: Enabled (0x01)
> >
> > Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
> > ---
> > include/net/bluetooth/hci.h |  2 ++
> > net/bluetooth/hci_core.c    |  5 +++++
> > net/bluetooth/hci_event.c   | 12 ++++++++++++
> > net/bluetooth/hci_request.c |  4 ----
> > net/bluetooth/hci_request.h |  4 ++++
> > 5 files changed, 23 insertions(+), 4 deletions(-)
> >
> > diff --git a/include/net/bluetooth/hci.h b/include/net/bluetooth/hci.h
> > index fbba43e9bef5..883a8c25ccfb 100644
> > --- a/include/net/bluetooth/hci.h
> > +++ b/include/net/bluetooth/hci.h
> > @@ -221,6 +221,8 @@ enum {
> >       HCI_RAW,
> >
> >       HCI_RESET,
> > +
> > +     HCI_CMD_PENDING,
> > };
>
> no new flags here please. This is userspace visible use the hdev->dev_flags.
>

Ok, moved to hdev->dev_flags. Sending new revision now.

--
João Paulo Rechi Vita
http://about.me/jprvita

[PATCH v4] Bluetooth: Ignore CC events not matching the last HCI command

[João Paulo Rechi Vita]

This commit makes the kernel not send the next queued HCI command until
a command complete arrives for the last HCI command sent to the
controller. This change avoids a problem with some buggy controllers
(seen on two SKUs of QCA9377) that send an extra command complete event
for the previous command after the kernel had already sent a new HCI
command to the controller.

The problem was reproduced when starting an active scanning procedure,
where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
command. When this happends the kernel ends up not processing the
command complete for the following commmand, LE_SET_SCAN_PARAM, and
ultimately behaving as if a passive scanning procedure was being
performed, when in fact controller is performing an active scanning
procedure. This makes it impossible to discover BLE devices as no device
found events are sent to userspace.

This problem is reproducible on 100% of the attempts on the affected
controllers. The extra command complete event can be seen at timestamp
27.420131 on the btmon logs bellow.

Bluetooth monitor ver 5.50
= Note: Linux version 5.0.0+ (x86_64)                                  0.352340
= Note: Bluetooth subsystem version 2.22                               0.352343
= New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
= Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
= Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
@ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
@ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
@ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
@ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
        Address type: 0x06
          LE Public
          LE Random
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
        Type: Active (0x01)
        Interval: 11.250 msec (0x0012)
        Window: 11.250 msec (0x0012)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
@ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
      Start Discovery (0x0023) plen 1
        Status: Success (0x00)
        Address type: 0x06
          LE Public
          LE Random
@ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)

Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
---
 include/net/bluetooth/hci.h |  1 +
 net/bluetooth/hci_core.c    |  5 +++++
 net/bluetooth/hci_event.c   | 12 ++++++++++++
 net/bluetooth/hci_request.c |  4 ----
 net/bluetooth/hci_request.h |  4 ++++
 5 files changed, 22 insertions(+), 4 deletions(-)

diff --git a/include/net/bluetooth/hci.h b/include/net/bluetooth/hci.h
index fbba43e9bef5..9a5330eed794 100644
--- a/include/net/bluetooth/hci.h
+++ b/include/net/bluetooth/hci.h
@@ -282,6 +282,7 @@ enum {
 	HCI_FORCE_BREDR_SMP,
 	HCI_FORCE_STATIC_ADDR,
 	HCI_LL_RPA_RESOLUTION,
+	HCI_CMD_PENDING,
 
 	__HCI_NUM_FLAGS,
 };
diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
index d6b2540ba7f8..d654476c8d62 100644
--- a/net/bluetooth/hci_core.c
+++ b/net/bluetooth/hci_core.c
@@ -4383,6 +4383,9 @@ void hci_req_cmd_complete(struct hci_dev *hdev, u16 opcode, u8 status,
 		return;
 	}
 
+	/* If we reach this point this event matches the last command sent */
+	hci_dev_clear_flag(hdev, HCI_CMD_PENDING);
+
 	/* If the command succeeded and there's still more commands in
 	 * this request the request is not yet complete.
 	 */
@@ -4493,6 +4496,8 @@ static void hci_cmd_work(struct work_struct *work)
 
 		hdev->sent_cmd = skb_clone(skb, GFP_KERNEL);
 		if (hdev->sent_cmd) {
+			if (hdev->req_status == HCI_REQ_PEND)
+				hci_dev_set_flag(hdev, HCI_CMD_PENDING);
 			atomic_dec(&hdev->cmd_cnt);
 			hci_send_frame(hdev, skb);
 			if (test_bit(HCI_RESET, &hdev->flags))
diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
index 609fd6871c5a..8b893baf9bbe 100644
--- a/net/bluetooth/hci_event.c
+++ b/net/bluetooth/hci_event.c
@@ -3404,6 +3404,12 @@ static void hci_cmd_complete_evt(struct hci_dev *hdev, struct sk_buff *skb,
 	hci_req_cmd_complete(hdev, *opcode, *status, req_complete,
 			     req_complete_skb);
 
+	if (hci_dev_test_flag(hdev, HCI_CMD_PENDING)) {
+		bt_dev_err(hdev,
+			   "unexpected event for opcode 0x%4.4x", *opcode);
+		return;
+	}
+
 	if (atomic_read(&hdev->cmd_cnt) && !skb_queue_empty(&hdev->cmd_q))
 		queue_work(hdev->workqueue, &hdev->cmd_work);
 }
@@ -3511,6 +3517,12 @@ static void hci_cmd_status_evt(struct hci_dev *hdev, struct sk_buff *skb,
 		hci_req_cmd_complete(hdev, *opcode, ev->status, req_complete,
 				     req_complete_skb);
 
+	if (hci_dev_test_flag(hdev, HCI_CMD_PENDING)) {
+		bt_dev_err(hdev,
+			   "unexpected event for opcode 0x%4.4x", *opcode);
+		return;
+	}
+
 	if (atomic_read(&hdev->cmd_cnt) && !skb_queue_empty(&hdev->cmd_q))
 		queue_work(hdev->workqueue, &hdev->cmd_work);
 }
diff --git a/net/bluetooth/hci_request.c b/net/bluetooth/hci_request.c
index ca73d36cc149..5b3838a3bdc1 100644
--- a/net/bluetooth/hci_request.c
+++ b/net/bluetooth/hci_request.c
@@ -30,10 +30,6 @@
 #include "smp.h"
 #include "hci_request.h"
 
-#define HCI_REQ_DONE	  0
-#define HCI_REQ_PEND	  1
-#define HCI_REQ_CANCELED  2
-
 void hci_req_init(struct hci_request *req, struct hci_dev *hdev)
 {
 	skb_queue_head_init(&req->cmd_q);
diff --git a/net/bluetooth/hci_request.h b/net/bluetooth/hci_request.h
index 692cc8b13368..d0cea517d66e 100644
--- a/net/bluetooth/hci_request.h
+++ b/net/bluetooth/hci_request.h
@@ -22,6 +22,10 @@
 
 #include <asm/unaligned.h>
 
+#define HCI_REQ_DONE	  0
+#define HCI_REQ_PEND	  1
+#define HCI_REQ_CANCELED  2
+
 #define hci_req_sync_lock(hdev)   mutex_lock(&hdev->req_lock)
 #define hci_req_sync_unlock(hdev) mutex_unlock(&hdev->req_lock)
 
-- 
2.20.1

Re: [PATCH v4] Bluetooth: Ignore CC events not matching the last HCI command

[Marcel Holtmann]

Hi Joao Paulo,

> This commit makes the kernel not send the next queued HCI command until
> a command complete arrives for the last HCI command sent to the
> controller. This change avoids a problem with some buggy controllers
> (seen on two SKUs of QCA9377) that send an extra command complete event
> for the previous command after the kernel had already sent a new HCI
> command to the controller.
> 
> The problem was reproduced when starting an active scanning procedure,
> where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
> command. When this happends the kernel ends up not processing the
> command complete for the following commmand, LE_SET_SCAN_PARAM, and
> ultimately behaving as if a passive scanning procedure was being
> performed, when in fact controller is performing an active scanning
> procedure. This makes it impossible to discover BLE devices as no device
> found events are sent to userspace.
> 
> This problem is reproducible on 100% of the attempts on the affected
> controllers. The extra command complete event can be seen at timestamp
> 27.420131 on the btmon logs bellow.
> 
> Bluetooth monitor ver 5.50
> = Note: Linux version 5.0.0+ (x86_64)                                  0.352340
> = Note: Bluetooth subsystem version 2.22                               0.352343
> = New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
> = Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
> = Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
> @ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
> @ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
> @ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
> @ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
>        Address type: 0x06
>          LE Public
>          LE Random
> < HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
>        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
>> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
>      LE Set Random Address (0x08|0x0005) ncmd 1
>        Status: Success (0x00)
> < HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
>        Type: Active (0x01)
>        Interval: 11.250 msec (0x0012)
>        Window: 11.250 msec (0x0012)
>        Own address type: Random (0x01)
>        Filter policy: Accept all advertisement (0x00)
>> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
>      LE Set Random Address (0x08|0x0005) ncmd 1
>        Status: Success (0x00)
> < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
>        Scanning: Enabled (0x01)
>        Filter duplicates: Enabled (0x01)
>> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
>      LE Set Scan Parameters (0x08|0x000b) ncmd 1
>        Status: Success (0x00)
>> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
>      LE Set Scan Enable (0x08|0x000c) ncmd 1
>        Status: Success (0x00)
> @ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
>      Start Discovery (0x0023) plen 1
>        Status: Success (0x00)
>        Address type: 0x06
>          LE Public
>          LE Random
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> 
> Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
> ---
> include/net/bluetooth/hci.h |  1 +
> net/bluetooth/hci_core.c    |  5 +++++
> net/bluetooth/hci_event.c   | 12 ++++++++++++
> net/bluetooth/hci_request.c |  4 ----
> net/bluetooth/hci_request.h |  4 ++++
> 5 files changed, 22 insertions(+), 4 deletions(-)
> 
> diff --git a/include/net/bluetooth/hci.h b/include/net/bluetooth/hci.h
> index fbba43e9bef5..9a5330eed794 100644
> --- a/include/net/bluetooth/hci.h
> +++ b/include/net/bluetooth/hci.h
> @@ -282,6 +282,7 @@ enum {
> 	HCI_FORCE_BREDR_SMP,
> 	HCI_FORCE_STATIC_ADDR,
> 	HCI_LL_RPA_RESOLUTION,
> +	HCI_CMD_PENDING,
> 
> 	__HCI_NUM_FLAGS,
> };
> diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
> index d6b2540ba7f8..d654476c8d62 100644
> --- a/net/bluetooth/hci_core.c
> +++ b/net/bluetooth/hci_core.c
> @@ -4383,6 +4383,9 @@ void hci_req_cmd_complete(struct hci_dev *hdev, u16 opcode, u8 status,
> 		return;
> 	}
> 
> +	/* If we reach this point this event matches the last command sent */
> +	hci_dev_clear_flag(hdev, HCI_CMD_PENDING);
> +
> 	/* If the command succeeded and there's still more commands in
> 	 * this request the request is not yet complete.
> 	 */
> @@ -4493,6 +4496,8 @@ static void hci_cmd_work(struct work_struct *work)
> 
> 		hdev->sent_cmd = skb_clone(skb, GFP_KERNEL);
> 		if (hdev->sent_cmd) {
> +			if (hdev->req_status == HCI_REQ_PEND)
> +				hci_dev_set_flag(hdev, HCI_CMD_PENDING);

I think it is better to replace this with hci_req_status_pend(hdev) instead of trying to export HCI_REQ_* constants.

Regards

Marcel

[PATCH v5] Bluetooth: Ignore CC events not matching the last HCI command

[João Paulo Rechi Vita]

This commit makes the kernel not send the next queued HCI command until
a command complete arrives for the last HCI command sent to the
controller. This change avoids a problem with some buggy controllers
(seen on two SKUs of QCA9377) that send an extra command complete event
for the previous command after the kernel had already sent a new HCI
command to the controller.

The problem was reproduced when starting an active scanning procedure,
where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
command. When this happends the kernel ends up not processing the
command complete for the following commmand, LE_SET_SCAN_PARAM, and
ultimately behaving as if a passive scanning procedure was being
performed, when in fact controller is performing an active scanning
procedure. This makes it impossible to discover BLE devices as no device
found events are sent to userspace.

This problem is reproducible on 100% of the attempts on the affected
controllers. The extra command complete event can be seen at timestamp
27.420131 on the btmon logs bellow.

Bluetooth monitor ver 5.50
= Note: Linux version 5.0.0+ (x86_64)                                  0.352340
= Note: Bluetooth subsystem version 2.22                               0.352343
= New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
= Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
= Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
@ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
@ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
@ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
@ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
        Address type: 0x06
          LE Public
          LE Random
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
        Type: Active (0x01)
        Interval: 11.250 msec (0x0012)
        Window: 11.250 msec (0x0012)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
@ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
      Start Discovery (0x0023) plen 1
        Status: Success (0x00)
        Address type: 0x06
          LE Public
          LE Random
@ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)
@ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
        Address type: 0x06
          LE Public
          LE Random
        Discovery: Enabled (0x01)

Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
---
 include/net/bluetooth/hci.h |  1 +
 net/bluetooth/hci_core.c    |  5 +++++
 net/bluetooth/hci_event.c   | 12 ++++++++++++
 net/bluetooth/hci_request.c |  5 +++++
 net/bluetooth/hci_request.h |  1 +
 5 files changed, 24 insertions(+)

diff --git a/include/net/bluetooth/hci.h b/include/net/bluetooth/hci.h
index fbba43e9bef5..9a5330eed794 100644
--- a/include/net/bluetooth/hci.h
+++ b/include/net/bluetooth/hci.h
@@ -282,6 +282,7 @@ enum {
 	HCI_FORCE_BREDR_SMP,
 	HCI_FORCE_STATIC_ADDR,
 	HCI_LL_RPA_RESOLUTION,
+	HCI_CMD_PENDING,
 
 	__HCI_NUM_FLAGS,
 };
diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
index d6b2540ba7f8..f275c9905650 100644
--- a/net/bluetooth/hci_core.c
+++ b/net/bluetooth/hci_core.c
@@ -4383,6 +4383,9 @@ void hci_req_cmd_complete(struct hci_dev *hdev, u16 opcode, u8 status,
 		return;
 	}
 
+	/* If we reach this point this event matches the last command sent */
+	hci_dev_clear_flag(hdev, HCI_CMD_PENDING);
+
 	/* If the command succeeded and there's still more commands in
 	 * this request the request is not yet complete.
 	 */
@@ -4493,6 +4496,8 @@ static void hci_cmd_work(struct work_struct *work)
 
 		hdev->sent_cmd = skb_clone(skb, GFP_KERNEL);
 		if (hdev->sent_cmd) {
+			if (hci_req_status_pend(hdev))
+				hci_dev_set_flag(hdev, HCI_CMD_PENDING);
 			atomic_dec(&hdev->cmd_cnt);
 			hci_send_frame(hdev, skb);
 			if (test_bit(HCI_RESET, &hdev->flags))
diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
index 609fd6871c5a..8b893baf9bbe 100644
--- a/net/bluetooth/hci_event.c
+++ b/net/bluetooth/hci_event.c
@@ -3404,6 +3404,12 @@ static void hci_cmd_complete_evt(struct hci_dev *hdev, struct sk_buff *skb,
 	hci_req_cmd_complete(hdev, *opcode, *status, req_complete,
 			     req_complete_skb);
 
+	if (hci_dev_test_flag(hdev, HCI_CMD_PENDING)) {
+		bt_dev_err(hdev,
+			   "unexpected event for opcode 0x%4.4x", *opcode);
+		return;
+	}
+
 	if (atomic_read(&hdev->cmd_cnt) && !skb_queue_empty(&hdev->cmd_q))
 		queue_work(hdev->workqueue, &hdev->cmd_work);
 }
@@ -3511,6 +3517,12 @@ static void hci_cmd_status_evt(struct hci_dev *hdev, struct sk_buff *skb,
 		hci_req_cmd_complete(hdev, *opcode, ev->status, req_complete,
 				     req_complete_skb);
 
+	if (hci_dev_test_flag(hdev, HCI_CMD_PENDING)) {
+		bt_dev_err(hdev,
+			   "unexpected event for opcode 0x%4.4x", *opcode);
+		return;
+	}
+
 	if (atomic_read(&hdev->cmd_cnt) && !skb_queue_empty(&hdev->cmd_q))
 		queue_work(hdev->workqueue, &hdev->cmd_work);
 }
diff --git a/net/bluetooth/hci_request.c b/net/bluetooth/hci_request.c
index ca73d36cc149..e9a95ed65491 100644
--- a/net/bluetooth/hci_request.c
+++ b/net/bluetooth/hci_request.c
@@ -46,6 +46,11 @@ void hci_req_purge(struct hci_request *req)
 	skb_queue_purge(&req->cmd_q);
 }
 
+bool hci_req_status_pend(struct hci_dev *hdev)
+{
+	return hdev->req_status == HCI_REQ_PEND;
+}
+
 static int req_run(struct hci_request *req, hci_req_complete_t complete,
 		   hci_req_complete_skb_t complete_skb)
 {
diff --git a/net/bluetooth/hci_request.h b/net/bluetooth/hci_request.h
index 692cc8b13368..55b2050cc9ff 100644
--- a/net/bluetooth/hci_request.h
+++ b/net/bluetooth/hci_request.h
@@ -37,6 +37,7 @@ struct hci_request {
 
 void hci_req_init(struct hci_request *req, struct hci_dev *hdev);
 void hci_req_purge(struct hci_request *req);
+bool hci_req_status_pend(struct hci_dev *hdev);
 int hci_req_run(struct hci_request *req, hci_req_complete_t complete);
 int hci_req_run_skb(struct hci_request *req, hci_req_complete_skb_t complete);
 void hci_req_add(struct hci_request *req, u16 opcode, u32 plen,
-- 
2.20.1

Re: [PATCH v5] Bluetooth: Ignore CC events not matching the last HCI command

[Marcel Holtmann]

Hi Joao Paulo,

> This commit makes the kernel not send the next queued HCI command until
> a command complete arrives for the last HCI command sent to the
> controller. This change avoids a problem with some buggy controllers
> (seen on two SKUs of QCA9377) that send an extra command complete event
> for the previous command after the kernel had already sent a new HCI
> command to the controller.
> 
> The problem was reproduced when starting an active scanning procedure,
> where an extra command complete event arrives for the LE_SET_RANDOM_ADDR
> command. When this happends the kernel ends up not processing the
> command complete for the following commmand, LE_SET_SCAN_PARAM, and
> ultimately behaving as if a passive scanning procedure was being
> performed, when in fact controller is performing an active scanning
> procedure. This makes it impossible to discover BLE devices as no device
> found events are sent to userspace.
> 
> This problem is reproducible on 100% of the attempts on the affected
> controllers. The extra command complete event can be seen at timestamp
> 27.420131 on the btmon logs bellow.
> 
> Bluetooth monitor ver 5.50
> = Note: Linux version 5.0.0+ (x86_64)                                  0.352340
> = Note: Bluetooth subsystem version 2.22                               0.352343
> = New Index: 80:C5:F2:8F:87:84 (Primary,USB,hci0)               [hci0] 0.352344
> = Open Index: 80:C5:F2:8F:87:84                                 [hci0] 0.352345
> = Index Info: 80:C5:F2:8F:87:84 (Qualcomm)                      [hci0] 0.352346
> @ MGMT Open: bluetoothd (privileged) version 1.14             {0x0001} 0.352347
> @ MGMT Open: btmon (privileged) version 1.14                  {0x0002} 0.352366
> @ MGMT Open: btmgmt (privileged) version 1.14                {0x0003} 27.302164
> @ MGMT Command: Start Discovery (0x0023) plen 1       {0x0003} [hci0] 27.302310
>        Address type: 0x06
>          LE Public
>          LE Random
> < HCI Command: LE Set Random Address (0x08|0x0005) plen 6   #1 [hci0] 27.302496
>        Address: 15:60:F2:91:B2:24 (Non-Resolvable)
>> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 27.419117
>      LE Set Random Address (0x08|0x0005) ncmd 1
>        Status: Success (0x00)
> < HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #3 [hci0] 27.419244
>        Type: Active (0x01)
>        Interval: 11.250 msec (0x0012)
>        Window: 11.250 msec (0x0012)
>        Own address type: Random (0x01)
>        Filter policy: Accept all advertisement (0x00)
>> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 27.420131
>      LE Set Random Address (0x08|0x0005) ncmd 1
>        Status: Success (0x00)
> < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #5 [hci0] 27.420259
>        Scanning: Enabled (0x01)
>        Filter duplicates: Enabled (0x01)
>> HCI Event: Command Complete (0x0e) plen 4                 #6 [hci0] 27.420969
>      LE Set Scan Parameters (0x08|0x000b) ncmd 1
>        Status: Success (0x00)
>> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 27.421983
>      LE Set Scan Enable (0x08|0x000c) ncmd 1
>        Status: Success (0x00)
> @ MGMT Event: Command Complete (0x0001) plen 4        {0x0003} [hci0] 27.422059
>      Start Discovery (0x0023) plen 1
>        Status: Success (0x00)
>        Address type: 0x06
>          LE Public
>          LE Random
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0003} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0002} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> @ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 27.422067
>        Address type: 0x06
>          LE Public
>          LE Random
>        Discovery: Enabled (0x01)
> 
> Signed-off-by: João Paulo Rechi Vita <jprvita@endlessm.com>
> ---
> include/net/bluetooth/hci.h |  1 +
> net/bluetooth/hci_core.c    |  5 +++++
> net/bluetooth/hci_event.c   | 12 ++++++++++++
> net/bluetooth/hci_request.c |  5 +++++
> net/bluetooth/hci_request.h |  1 +
> 5 files changed, 24 insertions(+)

patch has been applied to bluetooth-next tree.

Regards

Marcel