@stevenjb: Please confirm the issue

This suggests that the Bluetooth adapter is becoming unavailable. Can you reproduce this and file + link a feedback report?

@scheib: Could the fix for  issue 746132  have caused this?

This is a known issue. Komal, could you dup this into the appropriate bug? I've sorta lost track of them all :)

Are we sure this is a known issue? kebalaji@, how consistently can you reproduce this? We are seeing similar symptoms on 64 and other platforms (not very frequently). Are you sure this is a regression and you can't repro on 64?

@Kobbad: As per comment#6, Issue seems to be regressed in different range for different devices.

Kip: 62.0.3202.101/9901.79.0 stable is good
     63.0.3239.116/ 10032.75.0 stable is bad.
Reks: 63.0.3239.116/ 10032.75.0 stable is good 
      64.0.3282.39/10176.21.0 Beta is bad.
Daisy: 64.0.3282.39/10176.21.0 Beta is good.

Thanks!
     

Can you try to reproduce this on collect logs?

I have checked on bob and Kevin devices on M-64 , the toggle works fine.

kebalaji@ --  do you see the toggle issue on all the devices ??

pbathini@: Iam able to reproduce the issue in most of the priority devices like Kip, Daisy, Reks, Candy, Gnawty, Quawks, Celes, Paine, Glimmer, Blaze, Swanky, Minnie, Cyan. 

Unable to reproduce the issue on Peppy & Falco devices.

Thanks!

"Available" bugs tend to get lost, please mark high priority bugs "Untriaged" if you are going to unassign yourself.

->rkc@ to investigate or find an owner. Settings is just reflecting the lower level device bug. (This may be a duplicate?)

Reproduced the issue on minnie 10275.0.0 build

Deleted: bt_messages 36.2 KB

bt_messages 36.2 KB View Download

Deleted: user_chrome.log 80.9 KB

user_chrome.log 80.9 KB View Download

Deleted: ui.LATEST 9.0 KB

ui.LATEST 9.0 KB Download

Deleted: messages 576 KB

messages 576 KB View Download

Deleted: dmesg.log 64.0 KB

dmesg.log 64.0 KB View Download

Deleted: chrome 28.8 KB

chrome 28.8 KB View Download

Deleted: btmon.log 2.9 KB

btmon.log 2.9 KB View Download

Joseph, could you take a look at this?
If this turns out to be a UI issue, please re-assign to Sarah(xiaoyinh@).

Hi rkc@,

I took a look at logs from #15.

In messages, the last boot time started at 2018-01-03T16:39:32.956419-08:00, and the power state changes of bluetoothd were as follows. There is no suspicious behaviors around the change of power setting. Both dmesg.log and btmon.log do not indicate any error in bluetoothd and kernel.

2018-01-03T16:39:42.393106-08:00 INFO bluetoothd[2657]: adapter /org/bluez/hci0 has been enabled
2018-01-03T16:40:20.922718-08:00 DEBUG bluetoothd[2657]: src/adapter.c:property_set_mode() sending Set Powered command for index 0
2018-01-03T16:40:25.925780-08:00 DEBUG bluetoothd[2657]: src/adapter.c:property_set_mode_complete() Success (0x00)
2018-01-03T16:40:25.966537-08:00 INFO bluetoothd[2657]: adapter /org/bluez/hci0 has been disabled
2018-01-03T16:41:40.984625-08:00 DEBUG bluetoothd[2657]: src/adapter.c:property_set_mode() sending Set Powered command for index 0
2018-01-03T16:41:41.201541-08:00 DEBUG bluetoothd[2657]: src/adapter.c:property_set_mode_complete() Success (0x00)
2018-01-03T16:41:41.211343-08:00 INFO bluetoothd[2657]: adapter /org/bluez/hci0 has been enabled

However in user_chrome.log, there is only one set of messages for applying primary user pref bluetooth power to 1 around 16:41:40. Somehow the power change around 16:40:20 was not recorded.

mcchou0 ~/Downloads$ grep -i "blue" user_chrome.log 
[3908:3908:0103/164139.966221:VERBOSE1:bluetooth_agent_service_provider.cc(35)] Creating Bluetooth Agent: /org/chromium/bluetooth_agent
[3908:3908:0103/164139.966388:VERBOSE1:device_event_log_impl.cc(158)] [16:41:39.966] Bluetooth: EVENT: bluetooth_adapter_bluez.cc:285 BlueZ Adapter Initialized.
[3908:3908:0103/164139.966456:VERBOSE1:device_event_log_impl.cc(158)] [16:41:39.966] Bluetooth: EVENT: bluetooth_power_controller.cc:127 Bluetooth adapter ready, IsPresent = 0
[3908:3908:0103/164140.217739:VERBOSE1:device_event_log_impl.cc(158)] [16:41:40.217] Bluetooth: EVENT: bluetooth_adapter_bluez.cc:980 /org/bluez/hci0: using adapter.
[3908:3908:0103/164140.217797:VERBOSE1:device_event_log_impl.cc(158)] [16:41:40.217] Bluetooth: DEBUG: bluetooth_adapter_bluez.cc:982 Registering pairing agent
[3908:3908:0103/164140.219307:VERBOSE1:device_event_log_impl.cc(158)] [16:41:40.219] Bluetooth: EVENT: bluetooth_power_controller.cc:176 Bluetooth adapter present changed = 1
[3908:3908:0103/164140.350888:VERBOSE1:device_event_log_impl.cc(158)] [16:41:40.350] Bluetooth: EVENT: bluetooth_adapter_bluez.cc:878 Pairing agent registered, requesting to be made default
[3908:3908:0103/164140.426276:VERBOSE1:device_event_log_impl.cc(158)] [16:41:40.426] Bluetooth: EVENT: bluetooth_api.cc:68 BluetoothAPI: 0xdf1b000
[3908:3908:0103/164140.430367:VERBOSE1:bluetooth_low_energy_event_router.cc(248)] Initializing BluetoothLowEnergyEventRouter.
[3908:3908:0103/164140.663084:VERBOSE1:device_event_log_impl.cc(158)] [16:41:40.663] Bluetooth: EVENT: bluetooth_adapter_bluez.cc:903 Pairing agent now default
[3908:3908:0103/164140.980378:VERBOSE1:device_event_log_impl.cc(158)] [16:41:40.980] Bluetooth: EVENT: bluetooth_power_controller.cc:209 Applying primary user pref bluetooth power: 1
[3908:3908:0103/164140.980480:VERBOSE1:device_event_log_impl.cc(158)] [16:41:40.980] Bluetooth: EVENT: bluetooth_adapter_bluez.cc:370 SetPowered: 1

Therefore, I think this is likely an UI issue.

It's been reported on Eve V62 and V63.

Pixelbook 2017 Keeps shutting off Bluetooth - Google Product Forums
https://productforums.google.com/forum/#!topic/pixelbook/GvZ4QjZ4q_w

Escalated to 

[Ted Inoue]: "Pixelbook 2017 Keeps shutting off Bluetooth" - Google Product Forums
https://productforums.google.com/forum/#!private-topic/pixelbook+rs-mentor/Po9wB9oxk0c;context-place=private-forum/pixelbook+rs-mentor

Is this issue always reproducible? I just tried on cyan with 65.0.3294.0 and couldn't repro.

I have a minnie on 65.0.3299.0 build. I can reproduce the issue always on this device

@xiaoyinh, you can stop by and debug using the minnie we have. The issue reproduces very reliably. 

Once we toggle the bluetooth button, UI send a request to power on/off the adapter, and bluetooth adapter takes about 5 seconds to power down.

During that time, bluetooth settings is waiting for an adapter status updated signal and any toggles happened in this time frame does not have any effects(won't call bluetoothd to set the adapter again.)
In the UI side, I think it's better to disable the toggle button entirely so user cannot toggle button when an adapter change is in process.

+ mcchou@ Is it normal that adapter power down takes 5 seconds, and power on is usually within 1 second.

It would be nice if the model layer were to handle this debouncing, i.e. report immediately that bluetooth is "off" and queue any subsequent on/off requests, passing them to the device when it is ready.

However, IIRC we currently only have a very thin layer between the UI and DBus calls to the device (i.e. there is no Bluettoth equivalent to NetworkHandler).

From personal experience, trying to robustly do this sort of debouncing in the UI is tricky to get right.

Hi Steven, thanks for the idea. Looks like BluetoothPowerController already does that for the bluetooth button in system tray. Maybe we could do similar thing for settings UI, like in the bluetooth extension API layer?
Or this could move to the common layer which you suggest earlier, that both system tray and settings could use. What do you think?

A temporary fix for this issue would be just disable the toggle button when a change is in process.

Ideally I would love to see us introduce a shared layer that both the extension API and the system tray can use.

We could put this in the extension API layer, but that seems like it would be a bit awkward. Possibly we could introduce an intermediate layer that (for now) just the extension API uses.

I am concertned that a temporary fix would have its own edge case issues, e.g. we could end up in a state where the toggle remains disabled and Bluetooth can not be re-enabled. the JS UI is not ideal for making this sort of thing robust, I would be more confident of a C++ solution. That said if you think there is a robust short term solution that will work, I will do my best to review it carefully.

Just for info: This is actually not a UI regression because the UI bug has been there since 9 months ago: https://codereview.chromium.org/2801403002 didn't handle the disabled button case correctly.

This bug was not visible in 63/64 because powering off bluetooth didn't take that long. And the reason why in 63/64 it didn't take long is because Instant Tether was enabled by default but not in 64/65: https://crrev.com/254daaabb8 (I have no idea why enabling instant tether could make powering off bluetooth fast). A simple experiment can prove this: go to chrome://flags and set Instant Tether to enabled, then this bug will not be visible. Set instant tether to disabled and this bug will be visible.

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

commit 0d695d34099eccab5f150a70b84c0fb0f443d0bd
Author: Sonny Sasaka <sonnysasaka@chromium.org>
Date: Wed Jan 24 03:51:27 2018

Fix toggleable disabled bluetooth button.

Currently the bluetooth toggle is toggleable even though it's disabled
(i.e. property disabled=true and grayed). This is due to
bluetoothToggleState_ is set in js without checking whether the button
is currently disabled. This CL fixes this by always guarding it each
time bluetoothToggleState_ is to be set.

Additionally, this CL also fixes how the "in-progress" flag is cleared.
The right way to clear the flag is at the callback of
bluetoothPrivate.setAdapterState instead of at
onBluetoothAdapterStateChanged_ because onBluetoothAdapterStateChanged_
may not happen at all if the setAdapterState operation fails, whereas
the callback is always called reliably after setAdapterState finishes
its work regardless error or success.

Note: Ideally, though, the disabled property of the button should be
decided by a model layer instead of the UI, and this requires much
larger refactoring and is tracked in http://crbug.com/804494.

BUG= 795190 
TEST=Simulate delay of bluetooth power change, open the settings page
and click the bluetooth toggle button twice rapidly, the second click
should be ignored.

Cq-Include-Trybots: master.tryserver.chromium.linux:closure_compilation
Change-Id: Ieb172495f76e543957bdebde179dccf89dbac1a2
Reviewed-on: https://chromium-review.googlesource.com/877413
Commit-Queue: Sonny Sasaka <sonnysasaka@chromium.org>
Reviewed-by: Devlin <rdevlin.cronin@chromium.org>
Reviewed-by: Steven Bennetts <stevenjb@chromium.org>
Cr-Commit-Position: refs/heads/master@{#531425}
[modify] https://crrev.com/0d695d34099eccab5f150a70b84c0fb0f443d0bd/chrome/browser/resources/settings/bluetooth_page/bluetooth_page.html
[modify] https://crrev.com/0d695d34099eccab5f150a70b84c0fb0f443d0bd/chrome/browser/resources/settings/bluetooth_page/bluetooth_page.js
[modify] https://crrev.com/0d695d34099eccab5f150a70b84c0fb0f443d0bd/chrome/browser/resources/settings/bluetooth_page/bluetooth_subpage.html
[modify] https://crrev.com/0d695d34099eccab5f150a70b84c0fb0f443d0bd/chrome/browser/resources/settings/bluetooth_page/bluetooth_subpage.js
[modify] https://crrev.com/0d695d34099eccab5f150a70b84c0fb0f443d0bd/chrome/test/data/webui/settings/bluetooth_page_tests.js
[modify] https://crrev.com/0d695d34099eccab5f150a70b84c0fb0f443d0bd/extensions/common/api/bluetooth_private.idl

The UI has been fixed to handle the case where turning off bluetooth takes very long. However, even when the UI handles this gracefully, it is still very weird that turning off bluetooth takes very long. The real regression is the lower level layer (bluez/kernel/firmware) that made turning off bluetooth take more than 5 seconds. I did a bisect and found that between 10111.0.0 and 10112.0.0 there was a drastic time taken for turning off bluetooth (https://crosland.corp.google.com/log/10111.0.0..10112.0.0). The suspected CL is https://chromium.googlesource.com/chromiumos/third_party/kernel/+/762fa6509dd8c8b5a2e41dcfd51e413e8bd2492a. I created another bug specifically tracking this issue:  crbug.com/805329  and tentatively assigned to Joseph.

The UI should be fixed by CL in comment#28. 

[Auto-generated comment by a script] We noticed that this issue is targeted for M-65; it appears the fix may have landed after branch point, meaning a merge might be required. Please confirm if a merge is required here - if so add Merge-Request-65 label, otherwise remove Merge-TBD label. Thanks.

Your change meets the bar and is auto-approved for M65. Please go ahead and merge the CL to branch 3325 manually. Please contact milestone owner if you have questions.
Owners: cmasso@(Android), cmasso@(iOS), bhthompson@(ChromeOS), govind@(Desktop)

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

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

commit 3273a7ba53056e5b759e49c9d81691cda18382ce
Author: Sarah Hu <xiaoyinh@chromium.org>
Date: Wed Feb 07 18:40:58 2018

[Merge to M65]Fix toggleable disabled bluetooth button.

Merge to M65 on behave of sonnysasaka@.
Currently the bluetooth toggle is toggleable even though it's disabled
(i.e. property disabled=true and grayed). This is due to
bluetoothToggleState_ is set in js without checking whether the button
is currently disabled. This CL fixes this by always guarding it each
time bluetoothToggleState_ is to be set.

Additionally, this CL also fixes how the "in-progress" flag is cleared.
The right way to clear the flag is at the callback of
bluetoothPrivate.setAdapterState instead of at
onBluetoothAdapterStateChanged_ because onBluetoothAdapterStateChanged_
may not happen at all if the setAdapterState operation fails, whereas
the callback is always called reliably after setAdapterState finishes
its work regardless error or success.

Note: Ideally, though, the disabled property of the button should be
decided by a model layer instead of the UI, and this requires much
larger refactoring and is tracked in http://crbug.com/804494.

BUG= 795190 
TBR=stevenjb@chromium.org,rdevlin.cronin@chromium.org
TEST=Simulate delay of bluetooth power change, open the settings page
and click the bluetooth toggle button twice rapidly, the second click
should be ignored.

(cherry picked from commit 0d695d34099eccab5f150a70b84c0fb0f443d0bd)

Cq-Include-Trybots: master.tryserver.chromium.linux:closure_compilation
Change-Id: Ieb172495f76e543957bdebde179dccf89dbac1a2
Reviewed-on: https://chromium-review.googlesource.com/877413
Commit-Queue: Sonny Sasaka <sonnysasaka@chromium.org>
Reviewed-by: Devlin <rdevlin.cronin@chromium.org>
Reviewed-by: Steven Bennetts <stevenjb@chromium.org>
Cr-Original-Commit-Position: refs/heads/master@{#531425}
Reviewed-on: https://chromium-review.googlesource.com/907308
Reviewed-by: Xiaoyin Hu <xiaoyinh@chromium.org>
Cr-Commit-Position: refs/branch-heads/3325@{#364}
Cr-Branched-From: bc084a8b5afa3744a74927344e304c02ae54189f-refs/heads/master@{#530369}
[modify] https://crrev.com/3273a7ba53056e5b759e49c9d81691cda18382ce/chrome/browser/resources/settings/bluetooth_page/bluetooth_page.html
[modify] https://crrev.com/3273a7ba53056e5b759e49c9d81691cda18382ce/chrome/browser/resources/settings/bluetooth_page/bluetooth_page.js
[modify] https://crrev.com/3273a7ba53056e5b759e49c9d81691cda18382ce/chrome/browser/resources/settings/bluetooth_page/bluetooth_subpage.html
[modify] https://crrev.com/3273a7ba53056e5b759e49c9d81691cda18382ce/chrome/browser/resources/settings/bluetooth_page/bluetooth_subpage.js
[modify] https://crrev.com/3273a7ba53056e5b759e49c9d81691cda18382ce/chrome/test/data/webui/settings/bluetooth_page_tests.js
[modify] https://crrev.com/3273a7ba53056e5b759e49c9d81691cda18382ce/extensions/common/api/bluetooth_private.idl

verified on minnie device on 66.0.3344.0 / 10399.0.0 build