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..a1b41463b20660c2c8e8438b6a60c02675dd360d 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"
@@ -44,6 +45,11 @@ void IgnoreAdapterResultAndThen(
   callback.Run();
 }
 
+std::string GetListenerId(const extensions::EventListenerInfo& details) {
+  return !details.extension_id.empty() ? details.extension_id
+                                       : details.listener_url.host();

[Devlin, 2017/04/12 19:21:44]

Haven't we had issues with using the host as an id before?  Does this handle
e.g. multiple tabs with the same host?

[stevenjb, 2017/04/12 20:35:41]

The code (and TODO) you are thinking of (I assume) are at the top of
event_listener_map.cc, We already call url::Origin(listener_url).GetURL(). This
just extracts the relevant part as a string (we also do this in
bluetooth_private_api.cc).

I want to replace 'extension_id' and 'url' with 'listener_id' in
EventListenerInfo so this isn't needed, but that is more involved and we should
do that separately.

+}
+
 }  // namespace
 
 namespace bluetooth = api::bluetooth;
@@ -52,19 +58,19 @@ namespace bt_private = api::bluetooth_private;
 BluetoothEventRouter::BluetoothEventRouter(content::BrowserContext* context)
     : browser_context_(context),
       adapter_(nullptr),
-      num_event_listeners_(0),
       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;
@@ -113,23 +119,26 @@ 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;
   }
 
+  BLUETOOTH_LOG(USER) << "StartDiscoverySession: " << extension_id;
+
   // Check whether user pre set discovery filter by calling SetDiscoveryFilter
   // before. If the user has set a discovery filter then start a filtered
   // discovery session, otherwise start a regular session
@@ -162,10 +171,11 @@ void BluetoothEventRouter::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;
   }
+  BLUETOOTH_LOG(USER) << "StopDiscoverySession: " << extension_id;
   device::BluetoothDiscoverySession* session = iter->second;
   session->Stop(callback, error_callback);
 }
@@ -176,7 +186,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 +195,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;
@@ -216,9 +226,9 @@ void BluetoothEventRouter::OnAdapterInitialized(
 }
 
 void BluetoothEventRouter::MaybeReleaseAdapter() {
-  if (adapter_.get() && num_event_listeners_ == 0 &&
+  if (adapter_.get() && event_listener_count_.empty() &&
       pairing_delegate_map_.empty()) {
-    VLOG(1) << "Releasing Adapter.";
+    BLUETOOTH_LOG(EVENT) << "Releasing Adapter.";
     adapter_->RemoveObserver(this);
     adapter_ = nullptr;
   }
@@ -244,8 +254,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 +283,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 +295,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 +307,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 +316,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 +338,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 +351,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 +364,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;
   }
 
@@ -358,16 +373,30 @@ void BluetoothEventRouter::DeviceRemoved(device::BluetoothAdapter* adapter,
                       bluetooth::OnDeviceRemoved::kEventName, device);
 }
 
-void BluetoothEventRouter::OnListenerAdded() {
-  num_event_listeners_++;
+void BluetoothEventRouter::OnListenerAdded(const EventListenerInfo& details) {
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
+  std::string id = GetListenerId(details);
+  int count = ++event_listener_count_[id];
+  BLUETOOTH_LOG(EVENT) << "Event Listener Added: " << id << " Count: " << count;
   if (!adapter_.get())
     GetAdapter(base::Bind(&IgnoreAdapterResult));
 }
 
-void BluetoothEventRouter::OnListenerRemoved() {
-  if (num_event_listeners_ > 0)
-    num_event_listeners_--;
+void BluetoothEventRouter::OnListenerRemoved(const EventListenerInfo& details) {
+  DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
+  std::string id = GetListenerId(details);
+  auto iter = event_listener_count_.find(id);
+  if (iter == event_listener_count_.end())
+    return;  // Edge case if adapter wasn't ready when listener was added.

[Devlin, 2017/04/12 19:21:44]

If this can happen, doesn't that mean we could also be off-by-one somewhere?

[stevenjb, 2017/04/12 20:35:41]

We can theoretically (by code inspection) remove more than add but not vice
versa. I don't think it can happen in practice. Updated comment.

[Devlin, 2017/04/12 22:23:20]

So, my interpretation of your comment here is that the following is possible:

1. Listener added
2. Adapter initialized
3. Listener removed -> no listener entry

But, doesn't that mean we could also have:
1. Listener added
2. Adapter initialized
3. Listener 2 added
4. Listener removed -> we'll remove the entry in the map, despite the fact that
there's still an active listener.

Am I missing something?

[stevenjb, 2017/04/12 22:33:01]

1. Listener is *not* added because adapter is not intialized:
https://cs.chromium.org/chromium/src/extensions/browser/api/bluetooth/bluetoo...

[Devlin, 2017/04/12 23:01:26]

I should have been more clear.

1. Listener added through addListener(), notifies EventRouter, notifies
BluetoothAPI, checks adapter - adapter unitialized.

Net State:
1 listener in EventRouter
0 listeners in BluetoothEventRouter

2. Adapter initialized

Net State:
1 listener in EventRouter
0 listeners in BluetoothEventRouter

3. Listener 2 added through addListener(), notifies EventRouter, notifies
BluetoothAPI, adapter is initialized, so notifies BluetoothEventRouter.

Net State:
2 listeners in EventRouter
1 listener in BluetoothEventRouter

4. Listener removed through removeListener(), notifies EventRouter, notifies
BluetoothAPI, adapter is initialized, so notifies BluetoothEventRouter.  We'll
remove the entry in the map, despite the fact that there's still an active
listener in EventRouter.

Net State:
1 listener in EventRouter
0 listeners in BluetoothEventRouter

[stevenjb, 2017/04/12 23:12:28]

HUH????

"added through addListener()" - what addListener where?

Basically:

In this code:
https://cs.chromium.org/chromium/src/extensions/browser/api/bluetooth/bluetoo...

We may not call addListener for "Reasons" that I think never happen but, in
theory, could.

Therefore we could, in theory, call this method (OnListenerRemoved) without a
corresponding call to OnListenerAdded().

The opposite may or may not be true but I don't care about that - it won't cause
a crash, just another dangling ref counter and this code is so full of potential
for that I barely know where to begin.

I can put a CHECK here instead.

What would you like me to do, other than rewrite all of this code which I simply
do not have time for?

[Devlin, 2017/04/13 00:13:39]

addListener() == the JS addListener function, which is forwarded to the event
router.

Making this CHECK would solve my concerns. :)

[stevenjb, 2017/04/13 00:25:30]

Done.

+  int count = --(iter->second);
+  BLUETOOTH_LOG(EVENT) << "Event Listener Removed: " << id
+                       << " Count: " << count;
+  if (count <= 0) {

[Devlin, 2017/04/12 19:21:44]

< 0?  How?

[stevenjb, 2017/04/12 20:35:40]

Habit, changed to == 0.

+    event_listener_count_.erase(iter);
+    // When all listeners for a listener id have been removed, remove any
+    // pairing delegate or discovery session and filters.
+    CleanUpForExtension(id);
+  }
   MaybeReleaseAdapter();
 }
 
@@ -402,6 +431,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,14 +452,16 @@ void BluetoothEventRouter::CleanUpForExtension(
 }
 
 void BluetoothEventRouter::CleanUpAllExtensions() {
+  BLUETOOTH_LOG(DEBUG) << "CleanUpAllExtensions";
+
   for (auto& it : pre_set_filter_map_)
     delete it.second;
-
   pre_set_filter_map_.clear();
 
-  for (auto& it : discovery_session_map_)
+  for (auto& it : discovery_session_map_) {
+    BLUETOOTH_LOG(DEBUG) << "Clean up Discovery Session: " << it.first;
     delete it.second;
-
+  }
   discovery_session_map_.clear();
 
   PairingDelegateMap::iterator pairing_iter = pairing_delegate_map_.begin();
@@ -441,6 +473,7 @@ void BluetoothEventRouter::OnStartDiscoverySession(
     const std::string& extension_id,
     const base::Closure& callback,
     std::unique_ptr<device::BluetoothDiscoverySession> discovery_session) {
+  BLUETOOTH_LOG(EVENT) << "OnStartDiscoverySession: " << extension_id;
   // Clean up any existing session instance for the extension.
   DiscoverySessionMap::iterator iter =
       discovery_session_map_.find(extension_id);
@@ -452,7 +485,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();
 }
 
@@ -463,6 +496,7 @@ void BluetoothEventRouter::Observe(
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
   DCHECK_EQ(extensions::NOTIFICATION_EXTENSION_HOST_DESTROYED, type);
   ExtensionHost* host = content::Details<ExtensionHost>(details).ptr();
+  BLUETOOTH_LOG(DEBUG) << "Host Destroyed: " << host->extension_id();
   CleanUpForExtension(host->extension_id());
 }