Bluetooth: macOS: Adding logs

device/bluetooth/bluetooth_low_energy_device_mac.mm

 // Copyright 2015 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "device/bluetooth/bluetooth_low_energy_device_mac.h"
 
 #import <CoreFoundation/CoreFoundation.h>
 #include <stddef.h>
 
 #include "base/mac/mac_util.h"
@@ skipping 158 matching lines @@
 
 void BluetoothLowEnergyDeviceMac::ConnectToServiceInsecurely(
     const device::BluetoothUUID& uuid,
     const ConnectToServiceCallback& callback,
     const ConnectToServiceErrorCallback& error_callback) {
   NOTIMPLEMENTED();
 }
 
 void BluetoothLowEnergyDeviceMac::CreateGattConnectionImpl() {
   if (!IsGattConnected()) {
+    VLOG(1) << ToString() << ": CreateGattConnection.";
     GetMacAdapter()->CreateGattConnection(this);
   }
 }
 
 void BluetoothLowEnergyDeviceMac::DisconnectGatt() {
+  VLOG(1) << ToString() << ": Disconnect.";
   GetMacAdapter()->DisconnectGatt(this);
 }
 
 void BluetoothLowEnergyDeviceMac::DidDiscoverPrimaryServices(NSError* error) {
   --discovery_pending_count_;
   if (discovery_pending_count_ < 0) {
     // This should never happens, just in case it happens with a device,
     // discovery_pending_count_ is set back to 0.
-    VLOG(1) << GetName()->c_str()
+    VLOG(1) << ToString()
             << ": BluetoothLowEnergyDeviceMac::discovery_pending_count_ "
             << discovery_pending_count_;
     discovery_pending_count_ = 0;
     return;
   }
   if (error) {
     // TODO(http://crbug.com/609320): Need to pass the error.
     // TODO(http://crbug.com/609844): Decide what to do if discover failed
     // a device services.
-    VLOG(1) << "Can't discover primary services: "
+    VLOG(1) << ToString() << ": Can't discover primary services: "
             << error.localizedDescription.UTF8String << " (" << error.domain
-            << ": " << error.code << ")";
+            << ": " << error.code << ").";
     return;
   }
-  VLOG(1) << "DidDiscoverPrimaryServices, pending count: "
-          << discovery_pending_count_;
 
   if (!IsGattConnected()) {
     // Don't create services if the device disconnected.
+    VLOG(1) << ToString()
+            << ": DidDiscoverPrimaryServices, gatt not connected.";
     return;
   }
+  VLOG(1) << ToString() << ": DidDiscoverPrimaryServices, pending count: "
+          << discovery_pending_count_;
 
   for (CBService* cb_service in GetPeripheral().services) {
     BluetoothRemoteGattServiceMac* gatt_service =
         GetBluetoothRemoteGattService(cb_service);
-    if (!gatt_service) {
-      gatt_service = new BluetoothRemoteGattServiceMac(this, cb_service,
-                                                       true /* is_primary */);
-      auto result_iter = gatt_services_.insert(std::make_pair(
-          gatt_service->GetIdentifier(), base::WrapUnique(gatt_service)));
-      DCHECK(result_iter.second);
-      adapter_->NotifyGattServiceAdded(gatt_service);
+    if (gatt_service) {
+      VLOG(1) << gatt_service->ToString() << ": Known service.";
+      continue;
     }
+    gatt_service = new BluetoothRemoteGattServiceMac(this, cb_service,
+                                                     true /* is_primary */);
+    auto result_iter = gatt_services_.insert(std::make_pair(
+        gatt_service->GetIdentifier(), base::WrapUnique(gatt_service)));
+    DCHECK(result_iter.second);
+    VLOG(1) << gatt_service->ToString() << ": New service.";
+    adapter_->NotifyGattServiceAdded(gatt_service);

[ortuno, 2017/03/14 00:34:33]

I like this change but I would keep it out of this CL since it's pretty
unrelated.

[jlebel, 2017/03/15 01:08:40]

Done.

   }
   if (discovery_pending_count_ == 0) {
     for (auto it = gatt_services_.begin(); it != gatt_services_.end(); ++it) {
       device::BluetoothRemoteGattService* gatt_service = it->second.get();
       device::BluetoothRemoteGattServiceMac* gatt_service_mac =
           static_cast<BluetoothRemoteGattServiceMac*>(gatt_service);
       gatt_service_mac->DiscoverCharacteristics();
     }
     SendNotificationIfDiscoveryComplete();
   }
 }
 
 void BluetoothLowEnergyDeviceMac::DidDiscoverCharacteristics(
     CBService* cb_service,
     NSError* error) {
   if (error) {
     // TODO(http://crbug.com/609320): Need to pass the error.
     // TODO(http://crbug.com/609844): Decide what to do if discover failed
-    VLOG(1) << "Can't discover characteristics: "
+    VLOG(1) << ToString() << ": Can't discover characteristics: "
             << error.localizedDescription.UTF8String << " (" << error.domain
-            << ": " << error.code << ")";
+            << ": " << error.code << ").";
     return;
   }
-  VLOG(1) << "DidDiscoverCharacteristics.";
 
   if (!IsGattConnected()) {
+    VLOG(1) << ToString() << ": DidDiscoverCharacteristics, gatt disconnected.";
     // Don't create characteristics if the device disconnected.
     return;
   }
 
   BluetoothRemoteGattServiceMac* gatt_service =
       GetBluetoothRemoteGattService(cb_service);
   DCHECK(gatt_service);
   gatt_service->DidDiscoverCharacteristics();
   SendNotificationIfDiscoveryComplete();
 }
 
 void BluetoothLowEnergyDeviceMac::DidModifyServices(
     NSArray* invalidatedServices) {
-  VLOG(1) << "DidModifyServices: ";
+  VLOG(1) << ToString() << ": DidModifyServices: "
+          << " invalidated services "
+          << base::SysNSStringToUTF8([invalidatedServices description]);
   for (CBService* cb_service in invalidatedServices) {
     BluetoothRemoteGattServiceMac* gatt_service =
         GetBluetoothRemoteGattService(cb_service);
     DCHECK(gatt_service);
     VLOG(1) << gatt_service->GetUUID().canonical_value();
     std::unique_ptr<BluetoothRemoteGattService> scoped_service =
         std::move(gatt_services_[gatt_service->GetIdentifier()]);
     gatt_services_.erase(gatt_service->GetIdentifier());
     adapter_->NotifyGattServiceRemoved(scoped_service.get());
   }
   device_uuids_.ClearServiceUUIDs();
   SetGattServicesDiscoveryComplete(false);
   adapter_->NotifyDeviceChanged(this);
   DiscoverPrimaryServices();
 }
 
 void BluetoothLowEnergyDeviceMac::DidUpdateValue(
     CBCharacteristic* characteristic,
     NSError* error) {
-  VLOG(1) << "DidUpdateValue.";
   BluetoothRemoteGattServiceMac* gatt_service =
       GetBluetoothRemoteGattService(characteristic.service);
   DCHECK(gatt_service);
   gatt_service->DidUpdateValue(characteristic, error);
 }
 
 void BluetoothLowEnergyDeviceMac::DidWriteValue(
     CBCharacteristic* characteristic,
     NSError* error) {
-  VLOG(1) << "DidWriteValue.";
   BluetoothRemoteGattServiceMac* gatt_service =
       GetBluetoothRemoteGattService(characteristic.service);
   DCHECK(gatt_service);
   gatt_service->DidWriteValue(characteristic, error);
 }
 
 void BluetoothLowEnergyDeviceMac::DidUpdateNotificationState(
     CBCharacteristic* characteristic,
     NSError* error) {
-  VLOG(1) << "DidUpdateNotificationState";
   BluetoothRemoteGattServiceMac* gatt_service =
       GetBluetoothRemoteGattService(characteristic.service);
   DCHECK(gatt_service);
   gatt_service->DidUpdateNotificationState(characteristic, error);
 }
 
 void BluetoothLowEnergyDeviceMac::DidDiscoverDescriptors(
     CBCharacteristic* cb_characteristic,
     NSError* error) {
   if (error) {
     // TODO(http://crbug.com/609320): Need to pass the error.
     // TODO(http://crbug.com/609844): Decide what to do if discover failed
-    VLOG(1) << "Can't discover descriptors: "
+    VLOG(1) << ToString() << ": Can't discover descriptors: "
             << error.localizedDescription.UTF8String << " (" << error.domain
-            << ": " << error.code << ")";
+            << ": " << error.code << ").";
     return;
   }
-  VLOG(1) << "DidDiscoverDescriptors.";
   if (!IsGattConnected()) {
+    VLOG(1) << ToString() << ": DidDiscoverDescriptors, disconnected.";
     // Don't discover descriptors if the device disconnected.
     return;
   }
   BluetoothRemoteGattServiceMac* gatt_service =
       GetBluetoothRemoteGattService(cb_characteristic.service);
   DCHECK(gatt_service);
   gatt_service->DidDiscoverDescriptors(cb_characteristic);
   SendNotificationIfDiscoveryComplete();
 }
 
@@ skipping 11 matching lines @@
     CBPeripheral* peripheral) {
   const size_t kCanonicalAddressNumberOfBytes = 6;
   char raw[kCanonicalAddressNumberOfBytes];
   crypto::SHA256HashString(GetPeripheralIdentifier(peripheral), raw,
                            sizeof(raw));
   std::string hash = base::HexEncode(raw, sizeof(raw));
   return BluetoothDevice::CanonicalizeAddress(hash);
 }
 
 void BluetoothLowEnergyDeviceMac::DiscoverPrimaryServices() {
-  VLOG(1) << "DidDiscoverDescriptors pending count" << discovery_pending_count_;
+  VLOG(1) << ToString() << ": DidDiscoverDescriptors, pending count "

[ortuno, 2017/03/14 00:34:33]

This log seems incorrect. Why do we say DidDiscoverDescriptors?

[jlebel, 2017/03/15 01:08:40]

Done.

+          << discovery_pending_count_;
   ++discovery_pending_count_;
   [GetPeripheral() discoverServices:nil];
 }
 
 void BluetoothLowEnergyDeviceMac::SendNotificationIfDiscoveryComplete() {
   // Notify when all services have been discovered.
   bool discovery_complete =
       discovery_pending_count_ == 0 &&
       std::find_if_not(
           gatt_services_.begin(),
           gatt_services_.end(), [](GattServiceMap::value_type & pair) {
             BluetoothRemoteGattService* gatt_service = pair.second.get();
             return static_cast<BluetoothRemoteGattServiceMac*>(gatt_service)
                 ->IsDiscoveryComplete();
           }) == gatt_services_.end();
   if (discovery_complete) {
+    VLOG(1) << ToString() << ": Discovery complete.";
     device_uuids_.ReplaceServiceUUIDs(gatt_services_);
     SetGattServicesDiscoveryComplete(true);
     adapter_->NotifyGattServicesDiscovered(this);
     adapter_->NotifyDeviceChanged(this);
   }
 }
 
 device::BluetoothAdapterMac* BluetoothLowEnergyDeviceMac::GetMacAdapter() {
   return static_cast<BluetoothAdapterMac*>(this->adapter_);
 }
@@ skipping 16 matching lines @@
 }
 
 void BluetoothLowEnergyDeviceMac::DidDisconnectPeripheral(NSError* error) {
   SetGattServicesDiscoveryComplete(false);
   // Removing all services at once to ensure that calling GetGattService on
   // removed service in GattServiceRemoved returns null.
   GattServiceMap gatt_services_swapped;
   gatt_services_swapped.swap(gatt_services_);
   gatt_services_swapped.clear();
   device_uuids_.ClearServiceUUIDs();
+  VLOG(1) << ToString() << ": Did disconnect.";

[ortuno, 2017/03/14 00:34:33]

We are double logging here, bluetooth adapter already logs this. We should
decide where we want to actually do the logging. Should it be at the
bluetooth_adapter layer or at the bluetooth_device layer. Then move all the logs
to the layer we decide. Which layer do you think we should have the logging on?

[jlebel, 2017/03/15 01:08:40]

I think this should be done on the device layer. That's what I've done for the
rest:
I've added logs when the action is really done, not when passing the event from
one layer to the other.
I also had the issue with BluetoothDevice::DidFailToConnectGatt()

[scheib, 2017/03/21 21:43:30]

Unsure if ortuno will agree here or not. I think we can follow up later if
needed. I'm also OK erring on the side of double logging.

   // There are two cases in which this function will be called:
   //   1. When the connection to the device breaks (either because
   //      we closed it or the device closed it).
   //   2. When we cancel a pending connection request.
   if (create_gatt_connection_error_callbacks_.empty()) {
     // If there are no pending callbacks then the connection broke (#1).
     DidDisconnectGatt(true /* notifyDeviceChanged */);
     return;
   }
   // Else we canceled the connection request (#2).
   // TODO(http://crbug.com/585897): Need to pass the error.
   DidFailToConnectGatt(BluetoothDevice::ConnectErrorCode::ERROR_FAILED);
 }
+
+std::string BluetoothLowEnergyDeviceMac::ToString() const {
+  base::Optional<std::string> name = GetName();
+  const char* name_cstr = name ? name->c_str() : "";

[ortuno, 2017/03/14 02:12:00]

You can use GetNameForDisplay() to always get a name back.

[jlebel, 2017/03/15 01:08:40]

I can't run the unit tests with GetNameForDisplay(). DCHECK at
resource_bundle.cc:246 fails.
https://cs.chromium.org/chromium/src/ui/base/resource/resource_bundle.cc?q=re...

Called by:
https://cs.chromium.org/chromium/src/device/bluetooth/bluetooth_device.cc?q=b...

[scheib, 2017/03/21 21:43:30]

:( yeah, we need to fix that some day. Leave a TODO here with that issue number
please so we can improve this later.

[jlebel, 2017/03/21 23:57:59]

Done.

+  return std::string("<BluetoothLowEnergyDeviceMac ") + GetIdentifier() +

[ortuno, 2017/03/14 02:12:00]

Could you use a StringPiece here?

[jlebel, 2017/03/15 01:08:40]

I'm not sure to understand how to use StringPiece and what is the benefit of it.

[scheib, 2017/03/21 21:43:30]

See string_piece.h top of header file comment. A better description in google3
where it came from originally. It can save conversions between string types.
It's not a priority here I think since VLOGs will be enabled rarely.

+         ", \"" + name_cstr + "\", " + std::to_string(gatt_services_.size()) +
+         " services>";
+}