[chromecast][BLE] Add logging for some operations

Bug: internal b/112773799
Test: cast_bluetooth_unittests
Change-Id: I988345b574ddbc9ba8f7afc821aac90f56779985
Reviewed-on: https://chromium-review.googlesource.com/1182301Reviewed-by: Luke Halliwell <halliwell@chromium.org>
Commit-Queue: Bailey Forrest <bcf@chromium.org>
Cr-Commit-Position: refs/heads/master@{#584924}

chromecast/device/bluetooth/bluetooth_util.cc

@@ -39,6 +39,10 @@ std::string AddrToString(const bluetooth_v2_shlib::Addr& addr) {
                             addr[1], addr[0]);
 }
 
+std::string AddrLastByteString(const bluetooth_v2_shlib::Addr& addr) {
+  return base::StringPrintf("%02hhx", addr[0]);
+}
+
 bool ParseAddr(const std::string& str, bluetooth_v2_shlib::Addr* addr) {
   // sscanf will incorrectly succeed if all characters except the last one are
   // correct.

chromecast/device/bluetooth/bluetooth_util.h

@@ -21,6 +21,10 @@ extern const bluetooth_v2_shlib::Uuid kUuidBase;
 // (1a:2b:3c:4e:5f:60). Hex digits are lower case.
 std::string AddrToString(const bluetooth_v2_shlib::Addr& addr);
 
+// Get the last byte of |addr| as a hex string. This is used for logging since
+// full address is PII.
+std::string AddrLastByteString(const bluetooth_v2_shlib::Addr& addr);
+
 // Parse |str| as the canonical text representation of a 48 bit mac
 // address (1a:2b:3c:4e:5f:60). Hex digits may be either upper or lower case.
 //

chromecast/device/bluetooth/le/le_scan_manager_impl.cc

@@ -79,12 +79,15 @@ void LeScanManagerImpl::RemoveObserver(Observer* observer) {
 
 void LeScanManagerImpl::RequestScan(RequestScanCallback cb) {
   MAKE_SURE_IO_THREAD(RequestScan, BindToCurrentSequence(std::move(cb)));
+  LOG(INFO) << __func__;
+
   if (scan_handle_ids_.empty()) {
     if (!le_scanner_->StartScan()) {
       LOG(ERROR) << "Failed to enable scanning";
       std::move(cb).Run(nullptr);
       return;
     }
+    LOG(INFO) << "Enabling scan";
     observers_->Notify(FROM_HERE, &Observer::OnScanEnableChanged, true);
   }
 
@@ -163,6 +166,7 @@ void LeScanManagerImpl::NotifyScanHandleDestroyed(int32_t id) {
     if (!le_scanner_->StopScan()) {
       LOG(ERROR) << "Failed to disable scanning";
     } else {
+      LOG(INFO) << "Disabling scan";
       observers_->Notify(FROM_HERE, &Observer::OnScanEnableChanged, false);
     }
   }

chromecast/device/bluetooth/le/remote_device_impl.cc

@@ -79,6 +79,8 @@ void RemoteDeviceImpl::Connect(StatusCallback cb) {
 
 bool RemoteDeviceImpl::ConnectSync() {
   DCHECK(io_task_runner_->BelongsToCurrentThread());
+  LOG(INFO) << "Connect(" << util::AddrLastByteString(addr_) << ")";
+
   if (!gatt_client_manager_) {
     LOG(ERROR) << __func__ << " failed: Destroyed";
     return false;
@@ -108,6 +110,7 @@ void RemoteDeviceImpl::Disconnect(StatusCallback cb) {
 
 bool RemoteDeviceImpl::DisconnectSync() {
   DCHECK(io_task_runner_->BelongsToCurrentThread());
+  LOG(INFO) << "Disconnect(" << util::AddrLastByteString(addr_) << ")";
   if (!gatt_client_manager_) {
     LOG(ERROR) << __func__ << " failed: Destroyed";
     return false;
@@ -146,6 +149,8 @@ void RemoteDeviceImpl::ReadRemoteRssi(RssiCallback cb) {
 
 void RemoteDeviceImpl::RequestMtu(int mtu, StatusCallback cb) {
   MAKE_SURE_IO_THREAD(RequestMtu, mtu, BindToCurrentSequence(std::move(cb)));
+  LOG(INFO) << "RequestMtu(" << util::AddrLastByteString(addr_) << ", " << mtu
+            << ")";
   DCHECK(cb);
   if (!gatt_client_manager_) {
     LOG(ERROR) << __func__ << " failed: Destroyed";
@@ -164,6 +169,9 @@ void RemoteDeviceImpl::ConnectionParameterUpdate(int min_interval,
                                                  StatusCallback cb) {
   MAKE_SURE_IO_THREAD(ConnectionParameterUpdate, min_interval, max_interval,
                       latency, timeout, BindToCurrentSequence(std::move(cb)));
+  LOG(INFO) << "ConnectionParameterUpdate(" << util::AddrLastByteString(addr_)
+            << ", " << min_interval << ", " << max_interval << ", " << latency
+            << ", " << timeout << ")";
   if (!gatt_client_manager_) {
     LOG(ERROR) << __func__ << " failed: Destroyed";
     EXEC_CB_AND_RET(cb, false);
@@ -645,11 +653,7 @@ void RemoteDeviceImpl::ClearServices() {
 
 void RemoteDeviceImpl::OnCommandTimeout(const std::string& name) {
   DCHECK(io_task_runner_->BelongsToCurrentThread());
-  // Get the last byte because whole address is PII.
-  std::string addr_str = util::AddrToString(addr_);
-  addr_str = addr_str.substr(addr_str.size() - 2);
-
-  LOG(ERROR) << name << "(" << addr_str << ")"
+  LOG(ERROR) << name << "(" << util::AddrLastByteString(addr_) << ")"
              << " timed out. Disconnecting";
   Disconnect(base::DoNothing());
 }