Bluetooth: macOS: Adding logs

device/bluetooth/bluetooth_low_energy_device_mac.mm

Index: device/bluetooth/bluetooth_low_energy_device_mac.mm
diff --git a/device/bluetooth/bluetooth_low_energy_device_mac.mm b/device/bluetooth/bluetooth_low_energy_device_mac.mm
index 6fa8927657b9b53b79404a03d6a621a03db24542..44395c62616b78ef07af3b6eb66137a98e39331f 100644
--- a/device/bluetooth/bluetooth_low_energy_device_mac.mm
+++ b/device/bluetooth/bluetooth_low_energy_device_mac.mm
@@ -176,11 +176,13 @@ void BluetoothLowEnergyDeviceMac::ConnectToServiceInsecurely(
 
 void BluetoothLowEnergyDeviceMac::CreateGattConnectionImpl() {
   if (!IsGattConnected()) {
+    VLOG(1) << ToString() << ": CreateGattConnection.";
     GetMacAdapter()->CreateGattConnection(this);
   }
 }
 
 void BluetoothLowEnergyDeviceMac::DisconnectGatt() {
+  VLOG(1) << ToString() << ": Disconnect.";
   GetMacAdapter()->DisconnectGatt(this);
 }
 
@@ -189,7 +191,7 @@ void BluetoothLowEnergyDeviceMac::DidDiscoverPrimaryServices(NSError* error) {
   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;
@@ -199,30 +201,35 @@ void BluetoothLowEnergyDeviceMac::DidDiscoverPrimaryServices(NSError* 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) {
@@ -241,14 +248,14 @@ void BluetoothLowEnergyDeviceMac::DidDiscoverCharacteristics(
   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;
   }
@@ -262,7 +269,9 @@ void BluetoothLowEnergyDeviceMac::DidDiscoverCharacteristics(
 
 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);
@@ -282,7 +291,6 @@ void BluetoothLowEnergyDeviceMac::DidModifyServices(
 void BluetoothLowEnergyDeviceMac::DidUpdateValue(
     CBCharacteristic* characteristic,
     NSError* error) {
-  VLOG(1) << "DidUpdateValue.";
   BluetoothRemoteGattServiceMac* gatt_service =
       GetBluetoothRemoteGattService(characteristic.service);
   DCHECK(gatt_service);
@@ -292,7 +300,6 @@ void BluetoothLowEnergyDeviceMac::DidUpdateValue(
 void BluetoothLowEnergyDeviceMac::DidWriteValue(
     CBCharacteristic* characteristic,
     NSError* error) {
-  VLOG(1) << "DidWriteValue.";
   BluetoothRemoteGattServiceMac* gatt_service =
       GetBluetoothRemoteGattService(characteristic.service);
   DCHECK(gatt_service);
@@ -302,7 +309,6 @@ void BluetoothLowEnergyDeviceMac::DidWriteValue(
 void BluetoothLowEnergyDeviceMac::DidUpdateNotificationState(
     CBCharacteristic* characteristic,
     NSError* error) {
-  VLOG(1) << "DidUpdateNotificationState";
   BluetoothRemoteGattServiceMac* gatt_service =
       GetBluetoothRemoteGattService(characteristic.service);
   DCHECK(gatt_service);
@@ -315,13 +321,13 @@ void BluetoothLowEnergyDeviceMac::DidDiscoverDescriptors(
   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;
   }
@@ -353,7 +359,8 @@ std::string BluetoothLowEnergyDeviceMac::GetPeripheralHashAddress(
 }
 
 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];
 }
@@ -370,6 +377,7 @@ void BluetoothLowEnergyDeviceMac::SendNotificationIfDiscoveryComplete() {
                 ->IsDiscoveryComplete();
           }) == gatt_services_.end();
   if (discovery_complete) {
+    VLOG(1) << ToString() << ": Discovery complete.";
     device_uuids_.ReplaceServiceUUIDs(gatt_services_);
     SetGattServicesDiscoveryComplete(true);
     adapter_->NotifyGattServicesDiscovered(this);
@@ -406,6 +414,7 @@ void BluetoothLowEnergyDeviceMac::DidDisconnectPeripheral(NSError* error) {
   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).
@@ -419,3 +428,11 @@ void BluetoothLowEnergyDeviceMac::DidDisconnectPeripheral(NSError* error) {
   // 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>";
+}