New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 624400 link

Starred by 1 user

Issue metadata

Status: Verified
Owner:
Last visit > 30 days ago
Closed: Jul 2016
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Linux , Chrome
Pri: 1
Type: Bug

Blocking:
issue 616500



Sign in to add a comment

Get characteristic only work the first time

Reported by acas...@gmail.com, Jun 29 2016

Issue description

Chrome Version       : Chromium	53.0.2782.0 (Developer Build) (64-bit)
Revision	d63b5218dab7a9675f8de0842c0f3ac5febcb94f-refs/heads/master@{#402234}
OS	Linux Debian Sid kernel 4.6.0-1-amd64 and BlueZ 5.40

What steps will reproduce the problem?
(1) Open https://googlechrome.github.io/samples/web-bluetooth/discover-services-and-characteristics.html
(2) Put an UUID from a Service (I'm using the Nordic nRF51822 UART firmware the UUID is 6e400001-b5a3-f393-e0a9-e50e24dcca9e
(3) It will return the characteristic correctly for the first test.
(4) Close browser and try again and it fill fail

What is the expected result?

The listing of characteristics.

What happens instead?

> Name:             Nordic_UART
> Allowed Services: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
Connecting to GATT Server...
Getting Services...
Argh! NotFoundError: No Services found in device.

Please find attached the log for the first time (working situation), I'm going to repeat the test to create the fail situation log.
 
bluetoothd_firsttest_ok.log
12.3 KB View Download
chrome_debug.log
25.0 KB View Download

Comment 1 by acas...@gmail.com, Jun 29 2016

Please find attached the logs when the error is displayed.
bluetoothd.log
5.7 KB View Download
chrome_debug.log
23.2 KB View Download
It looks like your device gets disconnected. Could you share btmon logs as well for the second time?

$ sudo btmon

Comment 3 by acas...@gmail.com, Jun 29 2016

Please find attached my btmon.log when the issue happen.
btmon.log
28.4 KB View Download
Somehow your device triggers disconnection: 

< HCI Command: Disconnect (0x01|0x0006) plen 3                 [hci0] 24.264121
        Handle: 71
        Reason: Remote User Terminated Connection (0x13)

You might want to pair it first from bluetoothctl and see if that changes anything:

[bluetooth]# pair EC:F2:E5:CE:30:5B

If so, that means the pairing agent doesn't do its job properly.

Comment 5 by acas...@gmail.com, Jun 29 2016

Pair is not working:

[bluetooth]# pair EC:F2:E5:CE:30:5B
Attempting to pair with EC:F2:E5:CE:30:5B
[CHG] Device EC:F2:E5:CE:30:5B Connected: yes
Failed to pair: org.bluez.Error.AuthenticationFailed
[CHG] Device EC:F2:E5:CE:30:5B Connected: no

Comment 6 by acas...@gmail.com, Jun 29 2016

This is the same get characteristic test using TI SensorTag device instead of Nordic UART board.
btmon.log
28.4 KB View Download

Comment 7 by acas...@gmail.com, Jun 29 2016

Closing the TAB where the web bluetooth is loaded will disconnect the bluetooth, then opening a new TAB and trying to get characteristic will fail in the same way.

This is the log:

< HCI Command: LE Set Random Address (0x08|0x0005) plen 6     [hci0] 337.303019
        Address: 25:21:A1:83:24:C4 (Non-Resolvable)
> HCI Event: Command Complete (0x0e) plen 4                   [hci0] 337.304543
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7    [hci0] 337.304561
        Type: Active (0x01)
        Interval: 22.500 msec (0x0024)
        Window: 11.250 msec (0x0012)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement (0x00)
> HCI Event: Command Complete (0x0e) plen 4                   [hci0] 337.305542
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2        [hci0] 337.305554
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                   [hci0] 337.306558
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
< HCI Command: Inquiry (0x01|0x0001) plen 5                   [hci0] 337.306578
        Access code: 0x9e8b33 (General Inquiry)
        Length: 10.24s (0x08)
        Num responses: 0
> HCI Event: Command Status (0x0f) plen 4                     [hci0] 337.321563
      Inquiry (0x01|0x0001) ncmd 1
        Status: Success (0x00)
@ Discovering: 0x01 (7)
> HCI Event: LE Meta Event (0x3e) plen 28                     [hci0] 337.383582
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 16
        Name (complete): Nordic_UART
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        RSSI: -25 dBm (0xe7)
> HCI Event: LE Meta Event (0x3e) plen 30                     [hci0] 337.385581
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 18
        128-bit Service UUIDs (complete): 1 entry
          6e400001-b5a3-f393-e0a9-e50e24dcca9e
        RSSI: -25 dBm (0xe7)
@ Device Found: EC:F2:E5:CE:30:5B (2) rssi -25 flags 0x0000
        0c 09 4e 6f 72 64 69 63 5f 55 41 52 54 02 01 05  ..Nordic_UART...
        11 07 9e ca dc 24 0e e5 a9 e0 93 f3 a3 b5 01 00  .....$..........
        40 6e                                            @n              
> HCI Event: LE Meta Event (0x3e) plen 28                     [hci0] 337.605578
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 16
        Name (complete): Nordic_UART
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        RSSI: -25 dBm (0xe7)
> HCI Event: LE Meta Event (0x3e) plen 30                     [hci0] 337.607578
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 18
        128-bit Service UUIDs (complete): 1 entry
          6e400001-b5a3-f393-e0a9-e50e24dcca9e
        RSSI: -25 dBm (0xe7)
@ Device Found: EC:F2:E5:CE:30:5B (2) rssi -25 flags 0x0000
        0c 09 4e 6f 72 64 69 63 5f 55 41 52 54 02 01 05  ..Nordic_UART...
        11 07 9e ca dc 24 0e e5 a9 e0 93 f3 a3 b5 01 00  .....$..........
        40 6e                                            @n              
> HCI Event: LE Meta Event (0x3e) plen 28                     [hci0] 337.644579
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 16
        Name (complete): Nordic_UART
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        RSSI: -25 dBm (0xe7)
> HCI Event: LE Meta Event (0x3e) plen 30                     [hci0] 337.646581
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 18
        128-bit Service UUIDs (complete): 1 entry
          6e400001-b5a3-f393-e0a9-e50e24dcca9e
        RSSI: -25 dBm (0xe7)
@ Device Found: EC:F2:E5:CE:30:5B (2) rssi -25 flags 0x0000
        0c 09 4e 6f 72 64 69 63 5f 55 41 52 54 02 01 05  ..Nordic_UART...
        11 07 9e ca dc 24 0e e5 a9 e0 93 f3 a3 b5 01 00  .....$..........
        40 6e                                            @n              
> HCI Event: LE Meta Event (0x3e) plen 28                     [hci0] 337.954566
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 16
        Name (complete): Nordic_UART
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        RSSI: -25 dBm (0xe7)
> HCI Event: LE Meta Event (0x3e) plen 30                     [hci0] 337.956548
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 18
        128-bit Service UUIDs (complete): 1 entry
          6e400001-b5a3-f393-e0a9-e50e24dcca9e
        RSSI: -24 dBm (0xe8)
@ Device Found: EC:F2:E5:CE:30:5B (2) rssi -24 flags 0x0000
        0c 09 4e 6f 72 64 69 63 5f 55 41 52 54 02 01 05  ..Nordic_UART...
        11 07 9e ca dc 24 0e e5 a9 e0 93 f3 a3 b5 01 00  .....$..........
        40 6e                                            @n              
> HCI Event: LE Meta Event (0x3e) plen 28                     [hci0] 337.999564
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 16
        Name (complete): Nordic_UART
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        RSSI: -25 dBm (0xe7)
> HCI Event: LE Meta Event (0x3e) plen 30                     [hci0] 338.001567
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 18
        128-bit Service UUIDs (complete): 1 entry
          6e400001-b5a3-f393-e0a9-e50e24dcca9e
        RSSI: -25 dBm (0xe7)
@ Device Found: EC:F2:E5:CE:30:5B (2) rssi -25 flags 0x0000
        0c 09 4e 6f 72 64 69 63 5f 55 41 52 54 02 01 05  ..Nordic_UART...
        11 07 9e ca dc 24 0e e5 a9 e0 93 f3 a3 b5 01 00  .....$..........
        40 6e                                            @n              
> HCI Event: LE Meta Event (0x3e) plen 28                     [hci0] 338.044577
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 16
        Name (complete): Nordic_UART
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        RSSI: -25 dBm (0xe7)
> HCI Event: LE Meta Event (0x3e) plen 30                     [hci0] 338.046567
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 18
        128-bit Service UUIDs (complete): 1 entry
          6e400001-b5a3-f393-e0a9-e50e24dcca9e
        RSSI: -25 dBm (0xe7)
@ Device Found: EC:F2:E5:CE:30:5B (2) rssi -25 flags 0x0000
        0c 09 4e 6f 72 64 69 63 5f 55 41 52 54 02 01 05  ..Nordic_UART...
        11 07 9e ca dc 24 0e e5 a9 e0 93 f3 a3 b5 01 00  .....$..........
        40 6e                                            @n              
> HCI Event: LE Meta Event (0x3e) plen 28                     [hci0] 338.312610
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 16
        Name (complete): Nordic_UART
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        RSSI: -25 dBm (0xe7)
> HCI Event: LE Meta Event (0x3e) plen 30                     [hci0] 338.314610
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 18
        128-bit Service UUIDs (complete): 1 entry
          6e400001-b5a3-f393-e0a9-e50e24dcca9e
        RSSI: -25 dBm (0xe7)
@ Device Found: EC:F2:E5:CE:30:5B (2) rssi -25 flags 0x0000
        0c 09 4e 6f 72 64 69 63 5f 55 41 52 54 02 01 05  ..Nordic_UART...
        11 07 9e ca dc 24 0e e5 a9 e0 93 f3 a3 b5 01 00  .....$..........
        40 6e                                            @n              
> HCI Event: LE Meta Event (0x3e) plen 28                     [hci0] 338.630572
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 16
        Name (complete): Nordic_UART
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        RSSI: -25 dBm (0xe7)
> HCI Event: LE Meta Event (0x3e) plen 30                     [hci0] 338.632640
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 18
        128-bit Service UUIDs (complete): 1 entry
          6e400001-b5a3-f393-e0a9-e50e24dcca9e
        RSSI: -25 dBm (0xe7)
@ Device Found: EC:F2:E5:CE:30:5B (2) rssi -25 flags 0x0000
        0c 09 4e 6f 72 64 69 63 5f 55 41 52 54 02 01 05  ..Nordic_UART...
        11 07 9e ca dc 24 0e e5 a9 e0 93 f3 a3 b5 01 00  .....$..........
        40 6e                                            @n              
> HCI Event: LE Meta Event (0x3e) plen 28                     [hci0] 338.858626
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 16
        Name (complete): Nordic_UART
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        RSSI: -25 dBm (0xe7)
> HCI Event: LE Meta Event (0x3e) plen 30                     [hci0] 338.860626
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 18
        128-bit Service UUIDs (complete): 1 entry
          6e400001-b5a3-f393-e0a9-e50e24dcca9e
        RSSI: -26 dBm (0xe6)
@ Device Found: EC:F2:E5:CE:30:5B (2) rssi -26 flags 0x0000
        0c 09 4e 6f 72 64 69 63 5f 55 41 52 54 02 01 05  ..Nordic_UART...
        11 07 9e ca dc 24 0e e5 a9 e0 93 f3 a3 b5 01 00  .....$..........
        40 6e                                            @n              
> HCI Event: LE Meta Event (0x3e) plen 28                     [hci0] 338.902571
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 16
        Name (complete): Nordic_UART
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        RSSI: -25 dBm (0xe7)
> HCI Event: LE Meta Event (0x3e) plen 30                     [hci0] 338.904605
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 18
        128-bit Service UUIDs (complete): 1 entry
          6e400001-b5a3-f393-e0a9-e50e24dcca9e
        RSSI: -25 dBm (0xe7)
@ Device Found: EC:F2:E5:CE:30:5B (2) rssi -25 flags 0x0000
        0c 09 4e 6f 72 64 69 63 5f 55 41 52 54 02 01 05  ..Nordic_UART...
        11 07 9e ca dc 24 0e e5 a9 e0 93 f3 a3 b5 01 00  .....$..........
        40 6e                                            @n              
> HCI Event: LE Meta Event (0x3e) plen 28                     [hci0] 339.185534
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 16
        Name (complete): Nordic_UART
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        RSSI: -26 dBm (0xe6)
> HCI Event: LE Meta Event (0x3e) plen 30                     [hci0] 339.187559
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 18
        128-bit Service UUIDs (complete): 1 entry
          6e400001-b5a3-f393-e0a9-e50e24dcca9e
        RSSI: -26 dBm (0xe6)
@ Device Found: EC:F2:E5:CE:30:5B (2) rssi -26 flags 0x0000
        0c 09 4e 6f 72 64 69 63 5f 55 41 52 54 02 01 05  ..Nordic_UART...
        11 07 9e ca dc 24 0e e5 a9 e0 93 f3 a3 b5 01 00  .....$..........
        40 6e                                            @n              
< HCI Command: Inquiry Cancel (0x01|0x0002) plen 0            [hci0] 339.330876
> HCI Event: Command Complete (0x0e) plen 4                   [hci0] 339.338564
      Inquiry Cancel (0x01|0x0002) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2        [hci0] 339.338615
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                   [hci0] 339.351561
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7    [hci0] 339.351682
        Type: Passive (0x00)
        Interval: 60.000 msec (0x0060)
        Window: 30.000 msec (0x0030)
        Own address type: Public (0x00)
        Filter policy: Ignore not in white list (0x01)
@ Discovering: 0x00 (7)
> HCI Event: Command Complete (0x0e) plen 4                   [hci0] 339.355551
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2        [hci0] 339.355583
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                   [hci0] 339.359556
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 28                     [hci0] 339.372567
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: EC:F2:E5:CE:30:5B (Static)
        Data length: 16
        Name (complete): Nordic_UART
        Flags: 0x05
          LE Limited Discoverable Mode
          BR/EDR Not Supported
        RSSI: -25 dBm (0xe7)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2        [hci0] 339.372650
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                   [hci0] 339.377551
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Create Connection (0x08|0x000d) plen 25     [hci0] 339.377598
        Scan interval: 60.000 msec (0x0060)
        Scan window: 60.000 msec (0x0060)
        Filter policy: White list is not used (0x00)
        Peer address type: Random (0x01)
        Peer address: EC:F2:E5:CE:30:5B (Static)
        Own address type: Public (0x00)
        Min connection interval: 50.00 msec (0x0028)
        Max connection interval: 70.00 msec (0x0038)
        Connection latency: 0x0000
        Supervision timeout: 420 msec (0x002a)
        Min connection length: 0.000 msec (0x0000)
        Max connection length: 0.000 msec (0x0000)
> HCI Event: Command Status (0x0f) plen 4                     [hci0] 339.384526
      LE Create Connection (0x08|0x000d) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19                     [hci0] 339.430560
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 71
        Role: Master (0x00)
        Peer address type: Random (0x01)
        Peer address: EC:F2:E5:CE:30:5B (Static)
        Connection interval: 70.00 msec (0x0038)
        Connection latency: 0.00 msec (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Master clock accuracy: 0x00
< HCI Command: LE Read Remote Used Fe.. (0x08|0x0016) plen 2  [hci0] 339.430734
        Handle: 71
@ Device Connected: EC:F2:E5:CE:30:5B (2) flags 0x0000
        0c 09 4e 6f 72 64 69 63 5f 55 41 52 54 02 01 05  ..Nordic_UART...
> HCI Event: Command Status (0x0f) plen 4                     [hci0] 339.434558
      LE Read Remote Used Features (0x08|0x0016) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 12                     [hci0] 339.562558
      LE Read Remote Used Features (0x04)
        Status: Success (0x00)
        Handle: 71
        Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
          LE Encryption
< ACL Data TX: Handle 71 flags 0x00 dlen 7                    [hci0] 339.562784
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 517
> HCI Event: Number of Completed Packets (0x13) plen 5        [hci0] 339.632565
        Num handles: 1
        Handle: 71
        Count: 1
> ACL Data RX: Handle 71 flags 0x02 dlen 7                    [hci0] 339.708570
      ATT: Exchange MTU Response (0x03) len 2
        Server RX MTU: 23
< ACL Data TX: Handle 71 flags 0x00 dlen 11                   [hci0] 339.708859
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0001-0xffff
        Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5        [hci0] 339.772565
        Num handles: 1
        Handle: 71
        Count: 1
> ACL Data RX: Handle 71 flags 0x02 dlen 18                   [hci0] 339.842033
      ATT: Read By Group Type Response (0x11) len 13
        Attribute data length: 6
        Attribute group list: 2 entries
        Handle range: 0x0001-0x0007
        UUID: Generic Access Profile (0x1800)
        Handle range: 0x0008-0x0008
        UUID: Generic Attribute Profile (0x1801)
< ACL Data TX: Handle 71 flags 0x00 dlen 11                   [hci0] 339.842189
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0009-0xffff
        Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5        [hci0] 339.912536
        Num handles: 1
        Handle: 71
        Count: 1
> ACL Data RX: Handle 71 flags 0x02 dlen 26                   [hci0] 339.982052
      ATT: Read By Group Type Response (0x11) len 21
        Attribute data length: 20
        Attribute group list: 1 entry
        Handle range: 0x0009-0xffff
        UUID: Unknown (6e400001-b5a3-f393-e0a9-e50e24dcca9e)


I guess this is not a failure to discover the attributes as it works the first time, it is probably the enumeration of already existing attributes that doesn't work for some reason. This used to work but perhaps something has changed recently, perhaps the code is now cleaning up the attributes on disconnect?
OK. So to check if Chrome is culprit there, Alan please download chrome-linux.zip from http://commondatastorage.googleapis.com/chromium-browser-snapshots/index.html?prefix=Linux_x64/400610/

It it the same Chrome version I'm running now on my Chromebook which works fine. If you can reproduce the issue with this version, this means we'll have to check BlueZ.

Comment 10 by acas...@gmail.com, Jun 30 2016

Ok, tested with Chromium version:	53.0.2773.0 (Developer Build) (64-bit)

Tested page sample:
https://beaufortfrancois.github.io/samples/web-bluetooth/characteristic-properties.html

Same issue! First time (if BLE device address is not in the bluetoothctl cache) it is working fine:

Requesting Bluetooth Device...
Connecting to GATT Server...
Getting Service...
Getting Characteristic...
> Characteristic UUID:  6e400002-b5a3-f393-e0a9-e50e24dcca9e
> Broadcast:            false
> Read:                 false
> Write w/o response:   true
> Write:                true
> Notify:               false
> Indicate:             false
> Signed Write:         false
> Queued Write:         false
> Writable Auxiliaries: false

Second time it reports that the service doesn't exist:
Requesting Bluetooth Device...
Connecting to GATT Server...
Getting Service...
Argh! NotFoundError: No Services with specified UUID found in Device.

Can you try something for me Alan?

- Open chromium,
- Go to https://beaufortfrancois.github.io/samples/web-bluetooth/characteristic-properties.html
- Fill appropriate fields and click button (it should work fine)
- Open bluetoothctl
- Connect manually to the BLE device with "connect 12:34:56:78:90:12"
- Close chromium
- Reopen chromium
- Go to https://beaufortfrancois.github.io/samples/web-bluetooth/characteristic-properties.html
- Fill appropriate fields and click button

What happens now?

Comment 12 by acas...@gmail.com, Jun 30 2016

Please find the chrome logs for working and failing situations
chrome_working_debug.log
14.2 KB View Download
chrome_failing_debug.log
12.5 KB View Download

Comment 13 by acas...@gmail.com, Jun 30 2016

Initially Chromium is closed and device connection is in the cache

Let us to remove it:

[bluetooth]# remove EC:F2:E5:CE:30:5B
[DEL] Primary Service
	/org/bluez/hci0/dev_EC_F2_E5_CE_30_5B/service0008
	Generic Attribute Profile
[DEL] Descriptor
	/org/bluez/hci0/dev_EC_F2_E5_CE_30_5B/service0009/char000a/desc000c
	Client Characteristic Configuration
[DEL] Characteristic
	/org/bluez/hci0/dev_EC_F2_E5_CE_30_5B/service0009/char000a
	Vendor specific
[DEL] Characteristic
	/org/bluez/hci0/dev_EC_F2_E5_CE_30_5B/service0009/char000d
	Vendor specific
[DEL] Primary Service
	/org/bluez/hci0/dev_EC_F2_E5_CE_30_5B/service0009
	Vendor specific
[DEL] Device EC:F2:E5:CE:30:5B Nordic_UART
Device has been removed


Opened Chromium and executed a get characteristic:

[CHG] Controller 00:1A:7D:DA:71:10 Discovering: yes
[NEW] Device EC:F2:E5:CE:30:5B Nordic_UART
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI: -33
[CHG] Device EC:F2:E5:CE:30:5B RSSI is nil
[CHG] Controller 00:1A:7D:DA:71:10 Discovering: no
[CHG] Device EC:F2:E5:CE:30:5B Connected: yes
[CHG] Device EC:F2:E5:CE:30:5B Trusted: yes
[NEW] Primary Service
	/org/bluez/hci0/dev_EC_F2_E5_CE_30_5B/service0008
	Generic Attribute Profile
[NEW] Primary Service
	/org/bluez/hci0/dev_EC_F2_E5_CE_30_5B/service0009
	Vendor specific
[NEW] Characteristic
	/org/bluez/hci0/dev_EC_F2_E5_CE_30_5B/service0009/char000a
	Vendor specific
[NEW] Descriptor
	/org/bluez/hci0/dev_EC_F2_E5_CE_30_5B/service0009/char000a/desc000c
	Client Characteristic Configuration
[NEW] Characteristic
	/org/bluez/hci0/dev_EC_F2_E5_CE_30_5B/service0009/char000d
	Vendor specific
[CHG] Device EC:F2:E5:CE:30:5B UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Device EC:F2:E5:CE:30:5B UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Device EC:F2:E5:CE:30:5B UUIDs: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
[CHG] Device EC:F2:E5:CE:30:5B ServicesResolved: yes
[CHG] Device EC:F2:E5:CE:30:5B ServicesResolved: no

Closed Chromium:

[CHG] Device EC:F2:E5:CE:30:5B Connected: no


Now force a connection from bluetoothctl side:

[bluetooth]# connect EC:F2:E5:CE:30:5B
Attempting to connect to EC:F2:E5:CE:30:5B
[CHG] Device EC:F2:E5:CE:30:5B Connected: yes
Connection successful

Open chromium again and try to get characteristic (it will work second time because we connected from bluetoothctl)

[CHG] Device EC:F2:E5:CE:30:5B ServicesResolved: yes
[CHG] Controller 00:1A:7D:DA:71:10 Discovering: yes
[CHG] Controller 00:1A:7D:DA:71:10 Discovering: no
[CHG] Device EC:F2:E5:CE:30:5B ServicesResolved: no

Chromium read it from cache propably.

Closed chromium:

[CHG] Device EC:F2:E5:CE:30:5B Connected: no
[bluetooth]# 

Next time chomium don't get the characteristic:

[CHG] Controller 00:1A:7D:DA:71:10 Discovering: yes
[CHG] Controller 00:1A:7D:DA:71:10 Discovering: no
[CHG] Device EC:F2:E5:CE:30:5B Connected: yes
[CHG] Device EC:F2:E5:CE:30:5B ServicesResolved: yes

I saw this error message in the chromium:

Requesting Bluetooth Device...
Connecting to GATT Server...
Getting Service...
Argh! NotFoundError: No Services with specified UUID found in Device.
In chrome_working_debug.log, we get:

[23153:23153:0630/095220:VERBOSE1:web_bluetooth_service_impl.cc(255)] Services discovered for device: EC:F2:E5:CE:30:5B
[23153:23153:0630/095220:VERBOSE1:web_bluetooth_service_impl.cc(156)] Looking for service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e

[23153:23153:0630/095220:VERBOSE1:web_bluetooth_service_impl.cc(159)] Service in cache: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
[23153:23153:0630/095220:VERBOSE1:web_bluetooth_service_impl.cc(159)] Service in cache: 00001801-0000-1000-8000-00805f9b34fb
[23153:23153:0630/095220:VERBOSE1:web_bluetooth_service_impl.cc(732)] Services found in device.

[23153:23153:0630/095220:VERBOSE3:bluetooth_device_bluez.cc(572)] All services were discovered for device: /org/bluez/hci0/dev_EC_F2_E5_CE_30_5B


While in chrome_failing_debug.log, we get:

[23576:23576:0630/095319:VERBOSE1:web_bluetooth_service_impl.cc(255)] Services discovered for device: EC:F2:E5:CE:30:5B
[23576:23576:0630/095319:VERBOSE1:web_bluetooth_service_impl.cc(156)] Looking for service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e

[23576:23576:0630/095319:VERBOSE1:web_bluetooth_service_impl.cc(740)] Services not found in device.
[23576:23576:0630/095319:VERBOSE3:bluetooth_device_bluez.cc(572)] All services were discovered for device: /org/bluez/hci0/dev_EC_F2_E5_CE_30_5B


Does that mean BlueZ doesn't send us cached attributes?
Are we failing to update Chromium Bluetooth services/characteristics cache 
Could you also share dbus messages when it's working and not working?

sudo dbus-monitor --system "interface=org.freedesktop.DBus.Properties" "interface=org.freedesktop.DBus.ObjectManager"

Comment 16 by acas...@gmail.com, Jun 30 2016

Please find attached 4 logs:

1º = worked - device is not in the cache (remove dev_addr)
2º = failed for unkwnon reason
3º = failed with normal error (NotFoundError: No Services with specified UUID found in Device.)
4º = worked after issue a connection from bluetoothctl
dbus_working.log
16.7 KB View Download
dbus_failing.log
7.3 KB View Download
dbus_failing2.log
5.8 KB View Download
dbus_working_after_bluetoothctl_connect.log
3.3 KB View Download
Components: -Blink>Bluetooth IO>Bluetooth
Labels: -Pri-3 OS-Linux Pri-2
Owner: mcchou@chromium.org
Status: Available (was: Unconfirmed)
After much discussion on #bluez-users IRC, we think https://chromium.googlesource.com/chromium/src/+/da9047813fef5c79e536420281860c62606e8201 could be introducing a regression.

15:41 <fbeaufort> Could https://chromium.googlesource.com/chromium/src/+/da9047813fef5c79e536420281860c62606e8201 be the one in Chromium failing us...?
15:49 <vudentz> +  if (!IsGattServicesDiscoveryComplete()) {
15:49 <vudentz> +    VLOG(2) << "Gatt services have not been fully resolved for device "
15:49 <vudentz> +            << object_path_.value();
15:49 <vudentz> +    return;
15:49 <vudentz> +  }
15:49 <vudentz> This is probably false if the device is disconnected since ServicesResolved: no in that case
15:50 <vudentz> This would explain why it is not enumerating the service on InitializeGattServiceMap
15:50 <vudentz> +  // Notify on the discovery complete for each service which is found in the
15:50 <vudentz> +  // first discovery.
15:50 <vudentz> +  DCHECK(adapter());
15:50 <vudentz> +  for (const auto& iter : gatt_services_)
15:50 <vudentz> +    adapter()->NotifyGattDiscoveryComplete(iter.second);
15:51 <vudentz> This was also not in the original patch, why would we notify on the InitializeGattServiceMap, there should be any client waiting for it
Labels: -Pri-2 M-53 Pri-1
Owner: ortuno@chromium.org
Status: Started (was: Available)
I believe the code was written under the assumption that ObjectAdded would be called for cached services, which is not what happens. I'm currently refactoring the code to handle this scenario. We have a test for this but it also sends out a ObjectAdded event.
Hello Luiz,

Can you help with commenting on the following reply? Thank you so much.

5:49 <vudentz> +  if (!IsGattServicesDiscoveryComplete()) {
15:49 <vudentz> +    VLOG(2) << "Gatt services have not been fully resolved for device "
15:49 <vudentz> +            << object_path_.value();
15:49 <vudentz> +    return;
15:49 <vudentz> +  }
15:49 <vudentz> This is probably false if the device is disconnected since ServicesResolved: no in that case
15:50 <vudentz> This would explain why it is not enumerating the service on InitializeGattServiceMap

Indeed, when a device is created, it is unlikely that the device connected immediately, so ServicesResolved doesn't changed to true. This check will always return, so the following code can never be executed.

15:50 <vudentz> +  // Notify on the discovery complete for each service which is found in the
15:50 <vudentz> +  // first discovery.
15:50 <vudentz> +  DCHECK(adapter());
15:50 <vudentz> +  for (const auto& iter : gatt_services_)
15:50 <vudentz> +    adapter()->NotifyGattDiscoveryComplete(iter.second);
15:51 <vudentz> This was also not in the original patch, why would we notify on the InitializeGattServiceMap, there should be any client waiting for it
Since the rest of InitializeGattServiceMap will not be executed, NotifyGattDiscoveryComplete() will never be invoked. This block should be removed.
Instead of putting the initialization of the gatt_services_ list, it can be placed in BluetoothDeviceBlueZ::DevicePropertyChanged(). Then we simply check whether the list is empty or not, if so, initialize the list with a query to GATT services and notify the service added with BluetoothDeviceBlueZ::GattServiceAdded().
In this way, the services discovered in the first connection will be notified via the same function.

In the original patch, the GATT services are retrieved in the constructor of BluetoothDeviceBlue, where ServicesResolved is not yet toggled to true. In https://chromium.googlesource.com/chromium/src/+/da9047813fef5c79e536420281860c62606e8201, the goal is to make sure the service is fully discovered before retrieving any services. Unless retrieving the list of services before the service is fully discovered is the excepted usage, we can keep the current approach and correct the above check. :)

Cc: luiz.von...@intel.com fbeaufort@chromium.org
Labels: OS-Chrome
For info, I can reproduce this issue on Chrome OS - 53.0.2773.0 (Official Build) dev (64-bit)

- Go to https://googlechrome.github.io/samples/web-bluetooth/read-characteristic-value-changed.html
- Make sure nearby BLE device advertises battery service
- Click button
- Battery Service / Battery Level gets discovered
- Sign out from Chrome OS
- Sign in 
- Go back to https://googlechrome.github.io/samples/web-bluetooth/read-characteristic-value-changed.html
- Make sure same nearby BLE device advertises battery service
- Click button

Result:

Requesting Bluetooth Device...
Connecting to GATT Server...
Getting Battery Service...
Argh! NotFoundError: No Services with specified UUID found in Device.

Project Member

Comment 23 by sheriffbot@chromium.org, Jul 1 2016

Labels: -M-53 M-54 MovedFrom-53
Moving this nonessential bug to the next milestone.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
Blocking: 616500
Project Member

Comment 25 by bugdroid1@chromium.org, Jul 8 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/214ea3e270584ca53cebe4e3412bf7585fbd4807

commit 214ea3e270584ca53cebe4e3412bf7585fbd4807
Author: ortuno <ortuno@chromium.org>
Date: Fri Jul 08 19:44:57 2016

bluetooth: Update the map of GATT services when services resolve

Before we updated the map two times:

1. When constructing the device object *iff* the services had been resolved.
2. When a new service was added.

This meant that if there was a cached service before services resolved,
the service would never be added to the map.

There are a couple of changes:

1. No longer add BluetoothDeviceBluez as an observer of BluetoothDeviceClient.
   This follows the previous pattern of exposing a function that
   BluetoothAdapterClient will use to update the device.
2. When services are resolved we add all previously unknown services.
3. Modified 2 tests and added two extra ones to test all the following cases:

   1. Cached services exist and discovery hasn't completed.
   2. Cached services exist and discovery has completed.
   3. New service is exposed with no previous cached services.
   4. New service is exposed with previous cached service.

   Case 1 should cover this bug.

BUG= 624400 

Review-Url: https://codereview.chromium.org/2105423003
Cr-Commit-Position: refs/heads/master@{#404468}

[modify] https://crrev.com/214ea3e270584ca53cebe4e3412bf7585fbd4807/device/bluetooth/bluez/bluetooth_adapter_bluez.cc
[modify] https://crrev.com/214ea3e270584ca53cebe4e3412bf7585fbd4807/device/bluetooth/bluez/bluetooth_device_bluez.cc
[modify] https://crrev.com/214ea3e270584ca53cebe4e3412bf7585fbd4807/device/bluetooth/bluez/bluetooth_device_bluez.h
[modify] https://crrev.com/214ea3e270584ca53cebe4e3412bf7585fbd4807/device/bluetooth/bluez/bluetooth_gatt_bluez_unittest.cc
[modify] https://crrev.com/214ea3e270584ca53cebe4e3412bf7585fbd4807/device/bluetooth/dbus/fake_bluetooth_device_client.cc
[modify] https://crrev.com/214ea3e270584ca53cebe4e3412bf7585fbd4807/device/bluetooth/dbus/fake_bluetooth_device_client.h
[modify] https://crrev.com/214ea3e270584ca53cebe4e3412bf7585fbd4807/device/bluetooth/dbus/fake_bluetooth_gatt_service_client.cc
[modify] https://crrev.com/214ea3e270584ca53cebe4e3412bf7585fbd4807/device/bluetooth/dbus/fake_bluetooth_gatt_service_client.h

Status: Fixed (was: Started)
Status: Verified (was: Fixed)

Sign in to add a comment