MD Settings: Bluetooth: Fix adapter state and discovery

extensions/browser/api/bluetooth/bluetooth_event_router.cc

Index: extensions/browser/api/bluetooth/bluetooth_event_router.cc
diff --git a/extensions/browser/api/bluetooth/bluetooth_event_router.cc b/extensions/browser/api/bluetooth/bluetooth_event_router.cc
index 841935dc611615b087d5f8c52b8dd939911b3b0b..ee5b75ddddff87b73c265dd765cb607b934f29a1 100644
--- a/extensions/browser/api/bluetooth/bluetooth_event_router.cc
+++ b/extensions/browser/api/bluetooth/bluetooth_event_router.cc
@@ -16,6 +16,7 @@
 #include "base/stl_util.h"
 #include "base/strings/utf_string_conversions.h"
 #include "build/build_config.h"
+#include "components/device_event_log/device_event_log.h"
 #include "content/public/browser/notification_details.h"
 #include "content/public/browser/notification_source.h"
 #include "device/bluetooth/bluetooth_adapter.h"
@@ -56,15 +57,16 @@ BluetoothEventRouter::BluetoothEventRouter(content::BrowserContext* context)
       extension_registry_observer_(this),
       weak_ptr_factory_(this) {
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
+  BLUETOOTH_LOG(USER) << "BluetoothEventRouter()";
   DCHECK(browser_context_);
-  registrar_.Add(this,
-                 extensions::NOTIFICATION_EXTENSION_HOST_DESTROYED,
+  registrar_.Add(this, extensions::NOTIFICATION_EXTENSION_HOST_DESTROYED,
                  content::Source<content::BrowserContext>(browser_context_));
   extension_registry_observer_.Add(ExtensionRegistry::Get(browser_context_));
 }
 
 BluetoothEventRouter::~BluetoothEventRouter() {
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
+  BLUETOOTH_LOG(USER) << "~BluetoothEventRouter()";
   if (adapter_.get()) {
     adapter_->RemoveObserver(this);
     adapter_ = nullptr;
@@ -94,6 +96,7 @@ void BluetoothEventRouter::StartDiscoverySession(
     const std::string& extension_id,
     const base::Closure& callback,
     const base::Closure& error_callback) {
+  BLUETOOTH_LOG(USER) << "StartDiscoverySession";
   if (!adapter_.get() && IsBluetoothSupported()) {
     // If |adapter_| isn't set yet, call GetAdapter() which will synchronously
     // invoke the callback (StartDiscoverySessionImpl).
@@ -113,19 +116,20 @@ void BluetoothEventRouter::StartDiscoverySessionImpl(
     const base::Closure& callback,
     const base::Closure& error_callback) {
   if (!adapter_.get()) {
-    LOG(ERROR) << "Unable to get Bluetooth adapter.";
+    BLUETOOTH_LOG(ERROR) << "Unable to get Bluetooth adapter.";
     error_callback.Run();
     return;
   }
   if (adapter != adapter_.get()) {
-    LOG(ERROR) << "Bluetooth adapter mismatch.";
+    BLUETOOTH_LOG(ERROR) << "Bluetooth adapter mismatch.";
     error_callback.Run();
     return;
   }
   DiscoverySessionMap::iterator iter =
       discovery_session_map_.find(extension_id);
   if (iter != discovery_session_map_.end() && iter->second->IsActive()) {
-    DVLOG(1) << "An active discovery session exists for extension.";
+    BLUETOOTH_LOG(DEBUG) << "An active discovery session exists for extension: "
+                         << extension_id;
     error_callback.Run();
     return;
   }
@@ -159,10 +163,11 @@ void BluetoothEventRouter::StopDiscoverySession(
     error_callback.Run();
     return;
   }
+  BLUETOOTH_LOG(USER) << "StopDiscoverySession";
   DiscoverySessionMap::iterator iter =
       discovery_session_map_.find(extension_id);
   if (iter == discovery_session_map_.end() || !iter->second->IsActive()) {
-    DVLOG(1) << "No active discovery session exists for extension.";
+    BLUETOOTH_LOG(DEBUG) << "No active discovery session exists for extension.";
     error_callback.Run();
     return;
   }
@@ -176,7 +181,7 @@ void BluetoothEventRouter::SetDiscoveryFilter(
     const std::string& extension_id,
     const base::Closure& callback,
     const base::Closure& error_callback) {
-  DVLOG(1) << "SetDiscoveryFilter";
+  BLUETOOTH_LOG(USER) << "SetDiscoveryFilter";
   if (adapter != adapter_.get()) {
     error_callback.Run();
     return;
@@ -185,8 +190,8 @@ void BluetoothEventRouter::SetDiscoveryFilter(
   DiscoverySessionMap::iterator iter =
       discovery_session_map_.find(extension_id);
   if (iter == discovery_session_map_.end() || !iter->second->IsActive()) {
-    DVLOG(1) << "No active discovery session exists for extension, so caching "
-                "filter for later use.";
+    BLUETOOTH_LOG(DEBUG) << "No active discovery session exists for extension, "
+                         << "so caching filter for later use.";
     pre_set_filter_map_[extension_id] = discovery_filter.release();
     callback.Run();
     return;
@@ -218,7 +223,10 @@ void BluetoothEventRouter::OnAdapterInitialized(
 void BluetoothEventRouter::MaybeReleaseAdapter() {
   if (adapter_.get() && num_event_listeners_ == 0 &&
       pairing_delegate_map_.empty()) {
-    VLOG(1) << "Releasing Adapter.";
+    BLUETOOTH_LOG(EVENT) << "Releasing Adapter.";
+    // When a tab is closed, OnExtensionUnloaded may not get called, so when

[Devlin, 2017/04/08 00:22:28]

This comment strikes me as strange - why would we expect OnExtensionUnloaded to
be called when a tab closes?

[stevenjb, 2017/04/08 00:40:51]

The author assumed that it would (we call CleanUpForExtension() from
OnExtensionUnloaded()). If it is the last tab/window running the extension, that
seems potentially reasonable?

Looking at the history, it appears that originally it was observing both
NOTIFICATION_EXTENSION_UNLOADED and NOTIFICATION_EXTENSION_HOST_DESTROYED.

"host destroyed" sounds more like what we actually want to observe. I think we
probably actually want this to be a EventRouter::Observer. I will look into
that.

[Devlin, 2017/04/08 00:43:43]

Tabs don't really "run" extensions, so assuming that the extension stops
observing events when a tab is closed is pretty flawed.  Watching for host
destruction would probably work, but only coincidentally.  Your hunch of
EventRouter::Observer does indeed sound like what you want.

[stevenjb, 2017/04/08 02:26:15]

OK, so, I added some more logging so I have a better idea of what is going on
here and can improve the comment.

It turns out that we are receiving NOTIFICATION_EXTENSION_HOST_DESTROYED events,
just not for WebUI, which makes sense.

So, currently the only way this code knows that WebUI may be detached is here. I
couldn't find any other straightforward way to detect this, and since we are
releasing the adapter, cleaning up any discovery and filter maps is a good idea
anyway.

[Devlin, 2017/04/10 22:42:47]

This still doesn't quite make sense to me, but I'll defer to you as the
bluetooth owner.

+    // we release the adapter, also clean up any discovery sessions.
+    CleanUpAllExtensions();
     adapter_->RemoveObserver(this);
     adapter_ = nullptr;
   }
@@ -244,8 +252,8 @@ void BluetoothEventRouter::AddPairingDelegateImpl(
   if (base::ContainsKey(pairing_delegate_map_, extension_id)) {
     // For WebUI there may be more than one page open to the same url
     // (e.g. chrome://settings). These will share the same pairing delegate.
-    VLOG(1) << "Pairing delegate already exists for extension_id: "
-            << extension_id;
+    BLUETOOTH_LOG(EVENT) << "Pairing delegate already exists for extension_id: "
+                         << extension_id;
     return;
   }
   BluetoothApiPairingDelegate* delegate =
@@ -273,7 +281,8 @@ void BluetoothEventRouter::AdapterPresentChanged(
     bool present) {
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
   if (adapter != adapter_.get()) {
-    DVLOG(1) << "Ignoring event for adapter " << adapter->GetAddress();
+    BLUETOOTH_LOG(DEBUG) << "Ignoring event for adapter "
+                         << adapter->GetAddress();
     return;
   }
   DispatchAdapterStateEvent();
@@ -284,7 +293,8 @@ void BluetoothEventRouter::AdapterPoweredChanged(
     bool has_power) {
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
   if (adapter != adapter_.get()) {
-    DVLOG(1) << "Ignoring event for adapter " << adapter->GetAddress();
+    BLUETOOTH_LOG(DEBUG) << "Ignoring event for adapter "
+                         << adapter->GetAddress();
     return;
   }
   DispatchAdapterStateEvent();
@@ -295,7 +305,8 @@ void BluetoothEventRouter::AdapterDiscoveringChanged(
     bool discovering) {
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
   if (adapter != adapter_.get()) {
-    DVLOG(1) << "Ignoring event for adapter " << adapter->GetAddress();
+    BLUETOOTH_LOG(DEBUG) << "Ignoring event for adapter "
+                         << adapter->GetAddress();
     return;
   }
 
@@ -303,8 +314,7 @@ void BluetoothEventRouter::AdapterDiscoveringChanged(
     // If any discovery sessions are inactive, clean them up.
     DiscoverySessionMap active_session_map;
     for (DiscoverySessionMap::iterator iter = discovery_session_map_.begin();
-         iter != discovery_session_map_.end();
-         ++iter) {
+         iter != discovery_session_map_.end(); ++iter) {
       device::BluetoothDiscoverySession* session = iter->second;
       if (session->IsActive()) {
         active_session_map[iter->first] = session;
@@ -326,7 +336,8 @@ void BluetoothEventRouter::DeviceAdded(device::BluetoothAdapter* adapter,
                                        device::BluetoothDevice* device) {
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
   if (adapter != adapter_.get()) {
-    DVLOG(1) << "Ignoring event for adapter " << adapter->GetAddress();
+    BLUETOOTH_LOG(DEBUG) << "Ignoring event for adapter "
+                         << adapter->GetAddress();
     return;
   }
 
@@ -338,7 +349,8 @@ void BluetoothEventRouter::DeviceChanged(device::BluetoothAdapter* adapter,
                                          device::BluetoothDevice* device) {
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
   if (adapter != adapter_.get()) {
-    DVLOG(1) << "Ignoring event for adapter " << adapter->GetAddress();
+    BLUETOOTH_LOG(DEBUG) << "Ignoring event for adapter "
+                         << adapter->GetAddress();
     return;
   }
 
@@ -350,7 +362,8 @@ void BluetoothEventRouter::DeviceRemoved(device::BluetoothAdapter* adapter,
                                          device::BluetoothDevice* device) {
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
   if (adapter != adapter_.get()) {
-    DVLOG(1) << "Ignoring event for adapter " << adapter->GetAddress();
+    BLUETOOTH_LOG(DEBUG) << "Ignoring event for adapter "
+                         << adapter->GetAddress();
     return;
   }
 
@@ -402,6 +415,7 @@ void BluetoothEventRouter::DispatchDeviceEvent(
 
 void BluetoothEventRouter::CleanUpForExtension(
     const std::string& extension_id) {
+  BLUETOOTH_LOG(DEBUG) << "CleanUpForExtension: " << extension_id;
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
   RemovePairingDelegate(extension_id);
 
@@ -422,6 +436,7 @@ void BluetoothEventRouter::CleanUpForExtension(
 }
 
 void BluetoothEventRouter::CleanUpAllExtensions() {
+  BLUETOOTH_LOG(DEBUG) << "CleanUpAllExtensions";
   for (auto& it : pre_set_filter_map_)
     delete it.second;
 
@@ -441,6 +456,7 @@ void BluetoothEventRouter::OnStartDiscoverySession(
     const std::string& extension_id,
     const base::Closure& callback,
     std::unique_ptr<device::BluetoothDiscoverySession> discovery_session) {
+  BLUETOOTH_LOG(EVENT) << "OnStartDiscoverySession";
   // Clean up any existing session instance for the extension.
   DiscoverySessionMap::iterator iter =
       discovery_session_map_.find(extension_id);
@@ -452,7 +468,7 @@ void BluetoothEventRouter::OnStartDiscoverySession(
 
 void BluetoothEventRouter::OnSetDiscoveryFilter(const std::string& extension_id,
                                                 const base::Closure& callback) {
-  DVLOG(1) << "Successfully set DiscoveryFilter.";
+  BLUETOOTH_LOG(DEBUG) << "Successfully set DiscoveryFilter.";
   callback.Run();
 }