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

Issue 719289 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Last visit > 30 days ago
Closed: May 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Mac
Pri: 2
Type: Bug

Blocking:
issue 518942



Sign in to add a comment

getPrimaryService() not resolving appropriately

Reported by nallre...@gmail.com, May 8 2017

Issue description

Chrome Version       :  58.0.3029.96 (64-bit)

What steps will reproduce the problem?
(1) Make the initial connection to the device
(2) Once the connection is completely finished refresh the page. (I've started notifications and setup listeners, the device is ready to use at this point) 
(3) Immediately try to connect to the device again.
(4) This connection may succeed or may hang.  If it hangs, keep trying until it hangs.
(5) Once it hangs, the device must be powered off and powered back on.

What is the expected result?
The promise returned from getPrimaryService() should reject immediately and not require the device to be powered off and powered back on and the connection tried again.


What happens instead?
When the connection hangs, it is because the promise returned from getPrimaryService() does not resolve.  At this point I disconnect the device and try to connect again.  When I call device.gatt.connect() the hung promise from getPrimaryService() then resolves with error "NetworkError: GATT Server is disconnected. Cannot retrieve services. (Re)connect first with device.gatt.connect.".  After that promise resolves, the promise returned from the most recent call to device.gatt.connect() resolves with error "GATT Server disconnected while retrieving characteristics.".

At this point, I attempt to connect again and the connection appears to always be successful.


Please provide any additional information below. Attach a screenshot if
possible.

I've made a note in the chrome logs where I powered off my device and powered it back on.
I've also written a description of this bug here https://github.com/WebBluetoothCG/web-bluetooth/issues/367

These particular logs took my several tries to reproduce the bug, but the bug often occurs after only one refresh of the page.

My platform is a macbook pro.  I attempted to collect system logs, but when using BluetoothExplorer and the PacketLogger my device did not respond to commands.  I was also unable to reproduce the bug with BluetoothExplorer and PacketLogger running.

 
ChromeLogs.txt
75.8 KB View Download
I'm not sure if it is clear in those logs where I am refreshing the browser.  Please let me know if you need new logs where I log something when the page loads.
Yes please! Also when getPrimaryServices() resolves (when it resolves).
"Unable to connect: NetworkError: GATT Server is disconnected. Cannot retrieve services. (Re)connect first with `device.gatt.connect`." Is the error when getPrimaryServices() resolves.

"NetworkError: GATT Server disconnected while retrieving characteristics." is the error when device.gatt.connect resolves after I power off/on my device.

Look at the logs immediately after the "ERROR!!!!" log.  The logs following the "callback" log are just logging the same thing.
ChromeLogs2.txt
45.0 KB View Download
In these logs I uploaded I refreshed once and had the issue.  Then it is followed by a successful connection.
Its also worth noting, my connection process involves making two calls to getPrimaryServices().  That is why you see it being called twice at the start of the logs and also twice at the end.
Thanks for the logs! Hmm seems like a problem we've fixed in the past. Could you try reproducing your issue with Chrome Canary? We've added more logging statements and fixed bugs around that area in the past couple of weeks so the problem might be already be fixed.

Chrome Canary: https://www.google.com/chrome/browser/canary.html
 I've tested with Canary earlier today and got the same results.  I'm having trouble starting logs for Canary though...

Tried this:

/Applications/Google\ Chrome\ Canary.app/Contents/MacOS/Google\ Chrome --enable-logging=stderr --vmodule=*bluetooth*=2

I get: "No such file or directory", even though canary is in my applications directory.

Is there another command for this?
Also, I haven't been able to confirm, but I think this issue causes chrome to crash when I close my laptop and leave it for awhile.  This happens fairly frequently when I'm working with bluetooth but I haven't yet confirmed it is only when this issue comes up.  I'll keep an eye on that for the future.
It's:

/Applications/Google\ Chrome\ Canary.app/Contents/MacOS/Google\ Chrome\ Canary --enable-logging=stderr --vmodule=*bluetooth*=2

Note the "\ Canary" before "enable-logging".

If you experience a crash you can go to:

about:crashes and click on provide more information which will open an issue here.
Thanks.  I'll be sure to report the crash next time.

Here are my logs from Canary.  60.0.3091.0
chromeLogs3.txt
685 KB View Download
Blocking: 518942
Cc: jlebel@chromium.org
Labels: -Pri-3 OS-Mac Pri-2
Status: Available (was: Unconfirmed)
+jlebel in case he has any ideas.

The cause of the problem might be at a lower layer. From the logs I see that we stopped getting responses for descriptors after discovering the descriptors for the characteristic with UUID 9a66fa00-0800-9191-11e4-012d1540cb8e. We never receive the next response for characteristic with UUID 9a66fa0b-0800-9191-11e4-012d1540cb8e.

I'll take a look at the errors we are returning tomorrow.
Do you by any chance call gatt.disconnect() when the getPrimaryServices() promise rejects after disconnecting and reconnecting?

I see that we start disconnecting right after the promise rejects at 

[5205:1547:0507/235638.967697:VERBOSE1:bluetooth_adapter_mac.mm(661)] <BluetoothLowEnergyDeviceMac A1:FC:B8:1F:7F:06/0x7f7fe9d082e0, GATT connected, "Mambo_288329">: Disconnect gatt.

Seems like the connection succeeded, then getPrimaryServices() succeeded and then since you called disconnect() the getCharacteristics() call failed.

The promise rejecting after reconnecting is because when you call getPrimaryServices() we queue a task to be run after Services are discovered, which only happens after reconnecting. That's a bug on our side.
Yes, you are correct.

I have a catch that is calling my cleanup method and the cleanup method always calls gatt.disconnect() on the device if it has a device available.

Sorry about that.  I'd been trying strange things in my code trying to get a work around for needing to restart my device.
Ok! That gets rid of some of the weird errors. So we have two problems:

1. Discovery doesn't complete.
2. getPrimaryServices() calls are dispatched after a device reconnects.

I'm still investigating 1. You mentioned that you were "unable to reproduce the bug with BluetoothExplorer and PacketLogger running." Did you try reproducing the bug with Chrome and PacketLogger running? Those logs would be useful to see if the problem is at a lower layer.

Also if possible could you provide more information about the device you are using? I might be able to get my hands on one or try to replicate its characteristics. I've been trying to reproduce the bug with some of our devices but I have been unable to do so.
When I ran with the BluetoothExplorer and PacketLogger running my device didn't respond when I sent it commands.  I only tried a few times but I can give it another go.

I'm using a Parrot Mambo mini drone.

Comment 16 Deleted

Running PacketLogger in the background and reproducing the issue with Chrome Canary should be enough. No need to run Bluetooth Explorer.
I've attached chrome logs and packet logs.  Let me know if those packet logs are what you're after.

Chrome version is Version 60.0.3094.0 (Official Build) canary (64-bit)
ChromeLogs4.txt
390 KB View Download
PacketLogs.pklg
1.3 MB Download
In these logs it took me two attempts to reproduce the bug.

Comment 20 Deleted

Would the following work to get around the problem?

function retrieveServicesForBuggyDevices(device) {
  return Promise.race([
      device.gatt.getPrimaryServices(),
      new Promise(resolve => setTimeout(resolve, GET_PRIMARY_SERVICES_TIMEOUT))
    ])
    .then(services => {
      if (services === undefined) {
        console.log('getPrimaryServices is taking too long.');
        device.gatt.disconnect();
        // wait for disconnection and try connecting again.
        return new Promise(resolve => setTimeout(resolve, 1000))
          .then(() => device.gatt.connect())
          .then(() => retrieveServicesForBuggyDevices(device))
      }
      return services;
    });
}


navigator.bluetooth.requestDevice(...)
  .then(device => device.gatt.connect())
  .then(gatt => retrieveServicesForBuggyDevices(gatt.device))
  .then(services => ...);

Unfortunately, that won't work either.  I gave it a try to verify.

Once the device is in this state it seems like the only option is to restart the device.  I've tried calling device.gatt.disconnect() and reconnecting.  Calling disconnect and refreshing the page doesn't make it resolve either.

Once the device reaches that state, I haven't been able to get any gatt promises to resolve until I restart the device.  For example, if I try multiple times to call device.gatt.connect() all attempts will hang.  Then, when I restart my device and try to connect all of my promises resolve.

It seems that the best I can do while this is still an issue is recognize that it has occurred and let the user know they need to restart their device.  Your code here with Promise.race is more elegant than what I was doing.
hmm there might be a bug in there as well. I'll update once I get my hands on a device.
A bug in the device?
Hard to say at this point i.e. might be an apple bug or a chrome bug as well.
I'll try to reproduce this on an android device tomorrow.
Can you reproduce with https://webdro.ne?
I got a Rolling Spider device I can try if that might help.
Chrome Canary 60.0.3095.0
MacBook Air (13-inch, Early 2015) Mac OS X (10.12.4)
Device: Parrot Rolling Spider

1) Go to https://googlechrome.github.io/samples/web-bluetooth/discover-services-and-characteristics-async-await.html?optionalServices=9a66fa00-0800-9191-11e4-012d1540cb8e
2) Press "Discover services & characteristics" button
3) Notice device gets connected and that service's characteristics are discovered
4) Refresh web page
5) Repeat Step #2 to #4 several times.

After 9 tries, I wasn't able to reproduce sadly ;(

nallred91@, may you try to reproduce with these steps?
Your link to https://webdro.ne doesn't take me anywhere.  I will try to reproduce with a rolling spider in a few hours though.

Using the connection utility link you sent me I can also not reproduce.

The difference between that connection utility and my code is that I am also making a few calls to characteristic.startNotifications() and two calls to characteristic.addEventListener('characteristicvaluechanged', ...)
Argh! I meant https://webdr.one  not https://webdro.ne. It comes from https://github.com/poshaughnessy/web-bluetooth-parrot-drone

Please let me know what is the outcome with the Rolling Spider.
Ah yea, I've seen that before.  webdr.one is buggy in general for me...  I get errors right away on the initial connection.

I've created a repo you can check out that simply allows you to connect and then begins pinging the drone.  I thought it'd be helpful to just pull some of the relevant connection code out of my project. 

https://github.com/NAllred91/ParrotConnectionText

I thought we had a rolling spider in the office but all we have at the moment is a Mambo and Mars.  But I was able to reproduce the issue on both the Mambo and Mars, so this doesn't seem to be limited to just my specific Mambo.

Can you try to reproduce using the repo I created?

If you open the console I'm logging all the steps as I go through them.  Once you see 'Pinging began' your drone is connected.
I've used your code with my Rolling Spider and was able to get primary services 9 times in a row without any issue.

Do I need a special version of the firmware?
I don't believe so.  I updated my firmware this morning and it hasn't made any difference.

Also, when I refresh the page if I wait about 3-5 seconds before trying to connect again I can keep going through this process without issue as well.

The hang only appears to happen when I refresh and the immediately start reconnecting.
It also hangs if I press the disconnect button and then immediately press the connect button and try to connect again.

Comment 35 Deleted

@ortuno

Your code snippet did help me.  Instead of `calling disconnect() -> connect() -> getPrimaryService()`
I tried just calling `connect() -> getPrimaryService()` again.  When I do this after it times out, without trying to disconnect and reconnect, it is successful.

This work around appears to make my user experience acceptable.

For the record, my Rolling Spider info are:

  Product Type: Classic
  Hardware Version: HW_05
  Software Version: 1.99.2

I also tried several times pressing the disconnect button and then immediately press the connect button and it worked perfectly fine for me.


What are your results on Android?
I tested on Android 6.0.1, Chrome 58.0.3029.83

When I refresh and quickly reconnect I get error "No Services matching UUID 9a66fa00-0800-9191-11e4-012d1540cb8e found in Device."  Then, if I try to connect again it connects successfully.

Also, my Mambo info:

Product Type: Mambo
Hardware Version: HW_02
Software Version: 2.6.6
Project Member

Comment 40 by bugdroid1@chromium.org, May 20 2017

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

commit 8688a0dbe08b343fb8f0b736a506f79953e658e2
Author: Giovanni Ortuño Urquidi <ortuno@chromium.org>
Date: Sat May 20 09:34:29 2017

bluetooth: Reject pending getPrimaryService(s) calls when the device disconnects

This was causing getPrimaryService(s) promises to reject.

Bug:  719289 
Change-Id: I0860e53778cb6c8d1d69564bcbdd5438052769e8
Reviewed-on: https://chromium-review.googlesource.com/510055
Commit-Queue: Giovanni Ortuño Urquidi <ortuno@chromium.org>
Reviewed-by: Vincent Scheib <scheib@chromium.org>
Cr-Commit-Position: refs/heads/master@{#473430}
[modify] https://crrev.com/8688a0dbe08b343fb8f0b736a506f79953e658e2/content/browser/bluetooth/bluetooth_metrics.h
[modify] https://crrev.com/8688a0dbe08b343fb8f0b736a506f79953e658e2/content/browser/bluetooth/web_bluetooth_service_impl.cc
[modify] https://crrev.com/8688a0dbe08b343fb8f0b736a506f79953e658e2/content/browser/bluetooth/web_bluetooth_service_impl.h
[modify] https://crrev.com/8688a0dbe08b343fb8f0b736a506f79953e658e2/content/shell/browser/layout_test/layout_test_bluetooth_adapter_provider.cc
[add] https://crrev.com/8688a0dbe08b343fb8f0b736a506f79953e658e2/third_party/WebKit/LayoutTests/bluetooth/script-tests/server/device-disconnects-during.js
[add] https://crrev.com/8688a0dbe08b343fb8f0b736a506f79953e658e2/third_party/WebKit/LayoutTests/bluetooth/server/getPrimaryService/gen-device-disconnects-during.html
[add] https://crrev.com/8688a0dbe08b343fb8f0b736a506f79953e658e2/third_party/WebKit/LayoutTests/bluetooth/server/getPrimaryServices/gen-device-disconnects-during-with-uuid.html
[add] https://crrev.com/8688a0dbe08b343fb8f0b736a506f79953e658e2/third_party/WebKit/LayoutTests/bluetooth/server/getPrimaryServices/gen-device-disconnects-during.html
[modify] https://crrev.com/8688a0dbe08b343fb8f0b736a506f79953e658e2/tools/metrics/histograms/enums.xml

Could you try this again with the latest Canary?
Using 60.0.3107.0.

The promise returned from getPrimaryService() does not seem to hang any more.  When I refresh the page and try to connect immediately, it immediately resolves with the error 'GATT Server is disconnected. Cannot retrieve services. (Re)connect first with `device.gatt.connect`' with error code 19.

While doing the testing my browser was crashing a lot though, Crash Report ID's 1e89ec7d70000000 and e81e9c7d70000000 both occurred while testing this.


Status: Fixed (was: Available)
Great! I tested it with a Mambo and it seems the mambo disconnects after reconnecting so there might be an issue in the mambo's software. Let me know if you see any other promises hanging.

Thanks for the crash Ids. They seem to be the same issue you reported earlier i.e. chrome crashes when closing the laptop. I'm currently working on a fix.

Owner: ortuno@chromium.org
fyi you can follow the progress on the other bug in  Issue 724300 .

Sign in to add a comment