Bluetooth: macOS: Adding logs

device/bluetooth/bluetooth_remote_gatt_characteristic_mac.mm

Index: device/bluetooth/bluetooth_remote_gatt_characteristic_mac.mm
diff --git a/device/bluetooth/bluetooth_remote_gatt_characteristic_mac.mm b/device/bluetooth/bluetooth_remote_gatt_characteristic_mac.mm
index 2e2da4e618c0214d4907811847147a72b587390d..ead4ae8a33b6b0d0ae36ec0febce624574d61a07 100644
--- a/device/bluetooth/bluetooth_remote_gatt_characteristic_mac.mm
+++ b/device/bluetooth/bluetooth_remote_gatt_characteristic_mac.mm
@@ -152,6 +152,7 @@ void BluetoothRemoteGattCharacteristicMac::ReadRemoteCharacteristic(
     const ValueCallback& callback,
     const ErrorCallback& error_callback) {
   if (!IsReadable()) {
+    VLOG(1) << ToString() << ": Characteristic not readable.";
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::Bind(error_callback,
@@ -159,12 +160,14 @@ void BluetoothRemoteGattCharacteristicMac::ReadRemoteCharacteristic(
     return;
   }
   if (characteristic_value_read_or_write_in_progress_) {
+    VLOG(1) << ToString() << ": Characteristic read already in progress.";
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::Bind(error_callback,
                    BluetoothRemoteGattService::GATT_ERROR_IN_PROGRESS));
     return;
   }
+  VLOG(1) << ToString() << ": Read characteristic.";
   characteristic_value_read_or_write_in_progress_ = true;
   read_characteristic_value_callbacks_ =
       std::make_pair(callback, error_callback);
@@ -176,6 +179,7 @@ void BluetoothRemoteGattCharacteristicMac::WriteRemoteCharacteristic(
     const base::Closure& callback,
     const ErrorCallback& error_callback) {
   if (!IsWritable()) {
+    VLOG(1) << ToString() << ": Characteristic not writable.";
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::Bind(error_callback,
@@ -183,12 +187,14 @@ void BluetoothRemoteGattCharacteristicMac::WriteRemoteCharacteristic(
     return;
   }
   if (characteristic_value_read_or_write_in_progress_) {
+    VLOG(1) << ToString() << ": Characteristic write already in progress.";
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::Bind(error_callback,
                    BluetoothRemoteGattService::GATT_ERROR_IN_PROGRESS));
     return;
   }
+  VLOG(1) << ToString() << ": Write characteristic.";
   characteristic_value_read_or_write_in_progress_ = true;
   write_characteristic_value_callbacks_ =
       std::make_pair(callback, error_callback);
@@ -210,6 +216,7 @@ void BluetoothRemoteGattCharacteristicMac::SubscribeToNotifications(
     BluetoothRemoteGattDescriptor* ccc_descriptor,
     const base::Closure& callback,
     const ErrorCallback& error_callback) {
+  VLOG(1) << ToString() << ": Subscribe to characteristic.";
   DCHECK(subscribe_to_notification_callbacks_.first.is_null());
   DCHECK(subscribe_to_notification_callbacks_.second.is_null());
   DCHECK(unsubscribe_from_notification_callbacks_.first.is_null());
@@ -224,6 +231,7 @@ void BluetoothRemoteGattCharacteristicMac::UnsubscribeFromNotifications(
     BluetoothRemoteGattDescriptor* ccc_descriptor,
     const base::Closure& callback,
     const ErrorCallback& error_callback) {
+  VLOG(1) << ToString() << ": Unsubscribe to characteristic.";

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

Unsubscribe from characteristic.

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

Done.

   DCHECK(subscribe_to_notification_callbacks_.first.is_null());
   DCHECK(subscribe_to_notification_callbacks_.second.is_null());
   DCHECK(unsubscribe_from_notification_callbacks_.first.is_null());
@@ -235,6 +243,7 @@ void BluetoothRemoteGattCharacteristicMac::UnsubscribeFromNotifications(
 }
 
 void BluetoothRemoteGattCharacteristicMac::DiscoverDescriptors() {
+  VLOG(1) << ToString() << ": Discover descriptors.";
   is_discovery_complete_ = false;
   [GetCBPeripheral()
       discoverDescriptorsForCharacteristic:cb_characteristic_.get()];
@@ -245,11 +254,13 @@ void BluetoothRemoteGattCharacteristicMac::DidUpdateValue(NSError* error) {
   // This method is called when the characteristic is read and when a
   // notification is received.
   if (characteristic_value_read_or_write_in_progress_) {
+    VLOG(1) << ToString() << ": Update value.";

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

I would get rid of this one and log each case separately. See below

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

Done.

     std::pair<ValueCallback, ErrorCallback> callbacks;
     callbacks.swap(read_characteristic_value_callbacks_);
     characteristic_value_read_or_write_in_progress_ = false;
     if (error) {
-      VLOG(1) << "Bluetooth error while reading for characteristic, domain: "
+      VLOG(1) << ToString()
+              << ": Bluetooth error while reading for characteristic, domain: "
               << base::SysNSStringToUTF8(error.domain)
               << ", error code: " << error.code;
       BluetoothGattService::GattErrorCode error_code =
@@ -266,12 +277,15 @@ void BluetoothRemoteGattCharacteristicMac::DidUpdateValue(NSError* error) {
   } else {
     // In case of buggy device, nothing should be done if receiving extra
     // read confirmation.
-    VLOG(1) << "Characteristic value updated while having no pending read nor "
-               "notification.";
+    VLOG(1)
+        << ToString()
+        << ": Characteristic value updated while having no pending read nor "
+           "notification.";
   }
 }
 
 void BluetoothRemoteGattCharacteristicMac::UpdateValue() {
+  VLOG(1) << ToString() << ": Update value.";

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

This seems a bit unnecessary. We are already logging function that call this.

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

Done.

   NSData* nsdata_value = cb_characteristic_.get().value;
   const uint8_t* buffer = static_cast<const uint8_t*>(nsdata_value.bytes);
   value_.assign(buffer, buffer + nsdata_value.length);
@@ -282,14 +296,17 @@ void BluetoothRemoteGattCharacteristicMac::DidWriteValue(NSError* error) {
   if (!characteristic_value_read_or_write_in_progress_) {
     // In case of buggy device, nothing should be done if receiving extra
     // write confirmation.
-    VLOG(1) << "Write notification while no write operation pending.";
+    VLOG(1) << ToString()
+            << ": Write notification while no write operation pending.";
     return;
   }
+  VLOG(1) << ToString() << ": Write value.";

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

Move this all the way down and change it to: "Write value succeeded."

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

Done.

   std::pair<base::Closure, ErrorCallback> callbacks;
   callbacks.swap(write_characteristic_value_callbacks_);
   characteristic_value_read_or_write_in_progress_ = false;
   if (error) {
-    VLOG(1) << "Bluetooth error while writing for characteristic, domain: "
+    VLOG(1) << ToString()
+            << ": Bluetooth error while writing for characteristic, domain: "
             << base::SysNSStringToUTF8(error.domain)
             << ", error code: " << error.code;
     BluetoothGattService::GattErrorCode error_code =
@@ -310,12 +327,13 @@ void BluetoothRemoteGattCharacteristicMac::DidUpdateNotificationState(
     DCHECK(![GetCBCharacteristic() isNotifying] || error);
     reentrant_safe_callbacks.swap(unsubscribe_from_notification_callbacks_);
   } else {
-    VLOG(1) << "No pending notification update for characteristic "
-            << GetUUID().value();
+    VLOG(1) << ToString()
+            << ": No pending notification update for characteristic.";
     return;
   }
   if (error) {
-    VLOG(1) << "Bluetooth error while modifying notification state for "
+    VLOG(1) << ToString()
+            << ": Bluetooth error while modifying notification state for "
                "characteristic, domain: "
             << base::SysNSStringToUTF8(error.domain)
             << ", error code: " << error.code << ", localized description: "
@@ -330,6 +348,7 @@ void BluetoothRemoteGattCharacteristicMac::DidUpdateNotificationState(
 
 void BluetoothRemoteGattCharacteristicMac::DidDiscoverDescriptors() {
   DCHECK(!is_discovery_complete_);
+  VLOG(1) << ToString() << "Did discover descriptors.";
   std::unordered_set<std::string> descriptor_identifier_to_remove;
   for (const auto& iter : gatt_descriptor_macs_) {
     descriptor_identifier_to_remove.insert(iter.first);
@@ -339,6 +358,7 @@ void BluetoothRemoteGattCharacteristicMac::DidDiscoverDescriptors() {
     BluetoothRemoteGattDescriptorMac* gatt_descriptor_mac =
         GetBluetoothRemoteGattDescriptorMac(cb_descriptor);
     if (gatt_descriptor_mac) {
+      VLOG(1) << gatt_descriptor_mac->ToString() << ": Known descriptor.";
       const std::string& identifier = gatt_descriptor_mac->GetIdentifier();
       descriptor_identifier_to_remove.erase(identifier);
       continue;
@@ -350,11 +370,13 @@ void BluetoothRemoteGattCharacteristicMac::DidDiscoverDescriptors() {
         {identifier, base::WrapUnique(gatt_descriptor_mac)});
     DCHECK(result_iter.second);
     GetMacAdapter()->NotifyGattDescriptorAdded(gatt_descriptor_mac);
+    VLOG(1) << gatt_descriptor_mac->ToString() << ": New descriptor.";
   }
 
   for (const std::string& identifier : descriptor_identifier_to_remove) {
     auto pair_to_remove = gatt_descriptor_macs_.find(identifier);
     std::unique_ptr<BluetoothRemoteGattDescriptorMac> descriptor_to_remove;
+    VLOG(1) << descriptor_to_remove->ToString() << ": Removed descriptor.";
     pair_to_remove->second.swap(descriptor_to_remove);
     gatt_descriptor_macs_.erase(pair_to_remove);
     GetMacAdapter()->NotifyGattDescriptorRemoved(descriptor_to_remove.get());
@@ -420,4 +442,9 @@ BluetoothRemoteGattCharacteristicMac::GetBluetoothRemoteGattDescriptorMac(
     return found->second.get();
   }
 }
+
+std::string BluetoothRemoteGattCharacteristicMac::ToString() const {
+  return std::string("<BluetoothRemoteGattCharacteristicMac ") +
+         GetIdentifier() + ", service " + gatt_service_->GetIdentifier() + ">";

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

A UUID is more useful than the identifier.

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

The identifier contains the uuid and the memory address. I chose that to make
sure we don't have confusion between 2 characteristics.
But I can change it to UUID if you prefer.

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

I think GetIdentifier is OK as jlebel states - no matter what the format is
internally it will be uniquely identifiable. It's nice that it includes the UUID
for now. Best solution would be to explicitly print UUID and the pointer here to
make the code very clear in it's intent.

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

Done.

+}
 }  // namespace device.