Bluetooth: macOS: Adding logs

device/bluetooth/bluetooth_remote_gatt_characteristic_mac.mm

 // Copyright 2016 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_remote_gatt_characteristic_mac.h"
 
 #include "base/bind.h"
 #include "base/memory/ptr_util.h"
 #include "base/strings/sys_string_conversions.h"
 #include "base/threading/thread_task_runner_handle.h"
@@ skipping 134 matching lines @@
     return nullptr;
   }
   return static_cast<BluetoothRemoteGattDescriptor*>(
       searched_pair->second.get());
 }
 
 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,
                    BluetoothRemoteGattService::GATT_ERROR_NOT_SUPPORTED));
     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);
   [GetCBPeripheral() readValueForCharacteristic:cb_characteristic_];
 }
 
 void BluetoothRemoteGattCharacteristicMac::WriteRemoteCharacteristic(
     const std::vector<uint8_t>& value,
     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,
                    BluetoothRemoteGattService::GATT_ERROR_NOT_PERMITTED));
     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);
   base::scoped_nsobject<NSData> nsdata_value(
       [[NSData alloc] initWithBytes:value.data() length:value.size()]);
   CBCharacteristicWriteType write_type = GetCBWriteType();
   [GetCBPeripheral() writeValue:nsdata_value
               forCharacteristic:cb_characteristic_
                            type:write_type];
   if (write_type == CBCharacteristicWriteWithoutResponse) {
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::Bind(&BluetoothRemoteGattCharacteristicMac::DidWriteValue,
                    base::Unretained(this), nil));
   }
 }
 
 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());
   DCHECK(unsubscribe_from_notification_callbacks_.second.is_null());
   subscribe_to_notification_callbacks_ =
       std::make_pair(callback, error_callback);
   [GetCBPeripheral() setNotifyValue:YES
                   forCharacteristic:cb_characteristic_.get()];
 }
 
 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());
   DCHECK(unsubscribe_from_notification_callbacks_.second.is_null());
   unsubscribe_from_notification_callbacks_ =
       std::make_pair(callback, error_callback);
   [GetCBPeripheral() setNotifyValue:NO
                   forCharacteristic:cb_characteristic_.get()];
 }
 
 void BluetoothRemoteGattCharacteristicMac::DiscoverDescriptors() {
+  VLOG(1) << ToString() << ": Discover descriptors.";
   is_discovery_complete_ = false;
   [GetCBPeripheral()
       discoverDescriptorsForCharacteristic:cb_characteristic_.get()];
 }
 
 void BluetoothRemoteGattCharacteristicMac::DidUpdateValue(NSError* error) {
   CHECK_EQ(GetCBPeripheral().state, CBPeripheralStateConnected);
   // 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 =
           BluetoothDeviceMac::GetGattErrorCodeFromNSError(error);
       callbacks.second.Run(error_code);
       return;
     }
     UpdateValue();

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

Read request arrived.

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

Done.

     callbacks.first.Run(value_);
   } else if (IsNotifying()) {
     UpdateValue();

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

Notification arrived.

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

Done.

     gatt_service_->GetMacAdapter()->NotifyGattCharacteristicValueChanged(
         this, value_);
   } 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);
 }
 
 void BluetoothRemoteGattCharacteristicMac::DidWriteValue(NSError* error) {
   CHECK_EQ(GetCBPeripheral().state, CBPeripheralStateConnected);
   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 =
         BluetoothDeviceMac::GetGattErrorCodeFromNSError(error);
     callbacks.second.Run(error_code);
     return;
   }
   callbacks.first.Run();
 }
 
 void BluetoothRemoteGattCharacteristicMac::DidUpdateNotificationState(
     NSError* error) {
   PendingNotifyCallbacks reentrant_safe_callbacks;
   if (!subscribe_to_notification_callbacks_.first.is_null()) {
     DCHECK([GetCBCharacteristic() isNotifying] || error);
     reentrant_safe_callbacks.swap(subscribe_to_notification_callbacks_);
   } else if (!unsubscribe_from_notification_callbacks_.first.is_null()) {
     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: "
             << base::SysNSStringToUTF8(error.localizedDescription);
     BluetoothGattService::GattErrorCode error_code =
         BluetoothDeviceMac::GetGattErrorCodeFromNSError(error);
     reentrant_safe_callbacks.second.Run(error_code);
     return;
   }
   reentrant_safe_callbacks.first.Run();
 }
 
 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);
   }
 
   for (CBDescriptor* cb_descriptor in cb_characteristic_.get().descriptors) {
     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;
     }
     gatt_descriptor_mac =
         new BluetoothRemoteGattDescriptorMac(this, cb_descriptor);
     const std::string& identifier = gatt_descriptor_mac->GetIdentifier();
     auto result_iter = gatt_descriptor_macs_.insert(
         {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());
   }
   is_discovery_complete_ = true;
 }
 
 bool BluetoothRemoteGattCharacteristicMac::IsReadable() const {
   return GetProperties() & BluetoothGattCharacteristic::PROPERTY_READ;
 }
@@ skipping 45 matching lines @@
                           std::unique_ptr<BluetoothRemoteGattDescriptorMac>>&
               pair) {
         return pair.second->GetCBDescriptor() == cb_descriptor;
       });
   if (found == gatt_descriptor_macs_.end()) {
     return nullptr;
   } else {
     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.