chromeos/dbus: Add verbose log to media-related clients and service provider.

This CL adds some VLOG to BluetoothMediaClient,
BluetoothMediaTransportClient, BluetoothMediaEndpointServiceProvider
and BluetoothAudioSinkChromeOS.

BUG=429016
TEST=None

Review URL: https://codereview.chromium.org/963983002

Cr-Commit-Position: refs/heads/master@{#318598}

4 files changed, 104 insertions, 33 deletions

diff --git a/chromeos/dbus/bluetooth_media_client.cc b/chromeos/dbus/bluetooth_media_client.cc
index 23fc2ed..0bdca3f 100644
--- a/chromeos/dbus/bluetooth_media_client.cc
+++ b/chromeos/dbus/bluetooth_media_client.cc
@@ -103,6 +103,8 @@ class BluetoothMediaClientImpl
                         const EndpointProperties& properties,
                         const base::Closure& callback,
                         const ErrorCallback& error_callback) override {
+    VLOG(1) << "RegisterEndpoint - endpoint: " << endpoint_path.value();
+
     dbus::MethodCall method_call(kBluetoothMediaInterface, kRegisterEndpoint);
 
     dbus::MessageWriter writer(&method_call);
@@ -155,6 +157,8 @@ class BluetoothMediaClientImpl
                           const dbus::ObjectPath& endpoint_path,
                           const base::Closure& callback,
                           const ErrorCallback& error_callback) override {
+    VLOG(1) << "UnregisterEndpoint - endpoint: " << endpoint_path.value();
+
     dbus::MethodCall method_call(kBluetoothMediaInterface, kUnregisterEndpoint);
 
     // Send the path to the endpoint.
diff --git a/chromeos/dbus/bluetooth_media_endpoint_service_provider.cc b/chromeos/dbus/bluetooth_media_endpoint_service_provider.cc
index 82b9742..49e9bad 100644
--- a/chromeos/dbus/bluetooth_media_endpoint_service_provider.cc
+++ b/chromeos/dbus/bluetooth_media_endpoint_service_provider.cc
@@ -106,13 +106,15 @@ class CHROMEOS_EXPORT BluetoothMediaEndpointServiceProviderImpl
   void OnExported(const std::string& interface_name,
                   const std::string& method_name,
                   bool success) {
-    LOG_IF(WARNING, !success) << "Failed to export "
-                              << interface_name << "." << method_name;
+    LOG_IF(ERROR, !success) << "Failed to export " << interface_name << "."
+                            << method_name;
   }
 
   // Called by dbus:: when the remote device connects to the Media Endpoint.
   void SetConfiguration(dbus::MethodCall* method_call,
                         dbus::ExportedObject::ResponseSender response_sender) {
+    VLOG(1) << "SetConfiuration";
+
     DCHECK(OnOriginThread());
     DCHECK(delegate_);
 
@@ -121,8 +123,8 @@ class CHROMEOS_EXPORT BluetoothMediaEndpointServiceProviderImpl
     dbus::MessageReader property_reader(method_call);
     if (!reader.PopObjectPath(&transport_path) ||
         !reader.PopArray(&property_reader)) {
-      LOG(WARNING) << "SetConfiguration called with incorrect parameters: "
-                   << method_call->ToString();
+      LOG(ERROR) << "SetConfiguration called with incorrect parameters: "
+                 << method_call->ToString();
       return;
     }
 
@@ -134,8 +136,8 @@ class CHROMEOS_EXPORT BluetoothMediaEndpointServiceProviderImpl
       std::string key;
       if (!property_reader.PopDictEntry(&dict_entry_reader) ||
           !dict_entry_reader.PopString(&key)) {
-        LOG(WARNING) << "SetConfiguration called with incorrect parameters: "
-                     << method_call->ToString();
+        LOG(ERROR) << "SetConfiguration called with incorrect parameters: "
+                   << method_call->ToString();
       } else if (key == BluetoothMediaTransportClient::kDeviceProperty) {
         dict_entry_reader.PopVariantOfObjectPath(&properties.device);
       } else if (key == BluetoothMediaTransportClient::kUUIDProperty) {
@@ -164,8 +166,8 @@ class CHROMEOS_EXPORT BluetoothMediaEndpointServiceProviderImpl
         properties.state != kInvalidState) {
       delegate_->SetConfiguration(transport_path, properties);
     } else {
-      LOG(WARNING) << "SetConfiguration called with incorrect parameters: "
-                   << method_call->ToString();
+      LOG(ERROR) << "SetConfiguration called with incorrect parameters: "
+                 << method_call->ToString();
     }
 
     response_sender.Run(dbus::Response::FromMethodCall(method_call));
@@ -176,6 +178,8 @@ class CHROMEOS_EXPORT BluetoothMediaEndpointServiceProviderImpl
   void SelectConfiguration(
       dbus::MethodCall* method_call,
       dbus::ExportedObject::ResponseSender response_sender) {
+    VLOG(1) << "SelectConfiguration";
+
     DCHECK(OnOriginThread());
     DCHECK(delegate_);
 
@@ -183,8 +187,8 @@ class CHROMEOS_EXPORT BluetoothMediaEndpointServiceProviderImpl
     const uint8_t* capabilities = nullptr;
     size_t length = 0;
     if (!reader.PopArrayOfBytes(&capabilities, &length)) {
-      LOG(WARNING) << "SelectConfiguration called with incorrect parameters: "
-                   << method_call->ToString();
+      LOG(ERROR) << "SelectConfiguration called with incorrect parameters: "
+                 << method_call->ToString();
       return;
     }
 
@@ -205,14 +209,16 @@ class CHROMEOS_EXPORT BluetoothMediaEndpointServiceProviderImpl
   void ClearConfiguration(
       dbus::MethodCall* method_call,
       dbus::ExportedObject::ResponseSender response_sender) {
+    VLOG(1) << "ClearConfiguration";
+
     DCHECK(OnOriginThread());
     DCHECK(delegate_);
 
     dbus::MessageReader reader(method_call);
     dbus::ObjectPath transport_path;
     if (!reader.PopObjectPath(&transport_path)) {
-      LOG(WARNING) << "ClearConfiguration called with incorrect parameters: "
-                   << method_call->ToString();
+      LOG(ERROR) << "ClearConfiguration called with incorrect parameters: "
+                 << method_call->ToString();
       return;
     }
 
@@ -225,6 +231,8 @@ class CHROMEOS_EXPORT BluetoothMediaEndpointServiceProviderImpl
   // Endpoint.
   void Release(dbus::MethodCall* method_call,
                dbus::ExportedObject::ResponseSender response_sender) {
+    VLOG(1) << "Release";
+
     DCHECK(OnOriginThread());
     DCHECK(delegate_);
 
@@ -238,6 +246,8 @@ class CHROMEOS_EXPORT BluetoothMediaEndpointServiceProviderImpl
   void OnConfiguration(dbus::MethodCall* method_call,
                        dbus::ExportedObject::ResponseSender response_sender,
                        const std::vector<uint8_t>& configuration) {
+    VLOG(1) << "OnConfiguration";
+
     DCHECK(OnOriginThread());
 
     // Generates the response to the method call.
@@ -245,7 +255,7 @@ class CHROMEOS_EXPORT BluetoothMediaEndpointServiceProviderImpl
         dbus::Response::FromMethodCall(method_call));
     dbus::MessageWriter writer(response.get());
     if (configuration.empty()) {
-      LOG(WARNING) << "OnConfiguration called with empty configuration.";
+      LOG(ERROR) << "OnConfiguration called with empty configuration.";
       writer.AppendArrayOfBytes(nullptr, 0);
     } else {
       writer.AppendArrayOfBytes(&configuration[0], configuration.size());
diff --git a/chromeos/dbus/bluetooth_media_transport_client.cc b/chromeos/dbus/bluetooth_media_transport_client.cc
index 7672ea3..2be8a56 100644
--- a/chromeos/dbus/bluetooth_media_transport_client.cc
+++ b/chromeos/dbus/bluetooth_media_transport_client.cc
@@ -129,6 +129,8 @@ class BluetoothMediaTransportClientImpl
   void Acquire(const dbus::ObjectPath& object_path,
                const AcquireCallback& callback,
                const ErrorCallback& error_callback) override {
+    VLOG(1) << "Acquire - transport: " << object_path.value();
+
     DCHECK(object_manager_);
 
     dbus::MethodCall method_call(kBluetoothMediaTransportInterface, kAcquire);
@@ -150,6 +152,8 @@ class BluetoothMediaTransportClientImpl
   void TryAcquire(const dbus::ObjectPath& object_path,
                   const AcquireCallback& callback,
                   const ErrorCallback& error_callback) override {
+    VLOG(1) << "TryAcquire - transport: " << object_path.value();
+
     DCHECK(object_manager_);
 
     dbus::MethodCall method_call(kBluetoothMediaTransportInterface,
@@ -172,6 +176,8 @@ class BluetoothMediaTransportClientImpl
   void Release(const dbus::ObjectPath& object_path,
                const base::Closure& callback,
                const ErrorCallback& error_callback) override {
+    VLOG(1) << "Release - transport: " << object_path.value();
+
     DCHECK(object_manager_);
 
     dbus::MethodCall method_call(kBluetoothMediaTransportInterface, kRelease);
diff --git a/device/bluetooth/bluetooth_audio_sink_chromeos.cc b/device/bluetooth/bluetooth_audio_sink_chromeos.cc
index 98124e8..fb1ddf7 100644
--- a/device/bluetooth/bluetooth_audio_sink_chromeos.cc
+++ b/device/bluetooth/bluetooth_audio_sink_chromeos.cc
@@ -6,6 +6,7 @@
 
 #include <algorithm>
 #include <sstream>
+#include <string>
 #include <vector>
 
 #include "base/debug/stack_trace.h"
@@ -30,10 +31,43 @@ ObjectPath GenerateEndpointPath() {
   return ObjectPath(path.str());
 }
 
+std::string StateToString(const BluetoothAudioSink::State& state) {
+  switch (state) {
+    case BluetoothAudioSink::STATE_INVALID:
+      return "invalid";
+    case BluetoothAudioSink::STATE_DISCONNECTED:
+      return "disconnected";
+    case BluetoothAudioSink::STATE_IDLE:
+      return "idle";
+    case BluetoothAudioSink::STATE_PENDING:
+      return "pending";
+    case BluetoothAudioSink::STATE_ACTIVE:
+      return "active";
+    default:
+      return "unknown";
+  }
+}
+
+std::string ErrorCodeToString(const BluetoothAudioSink::ErrorCode& error_code) {
+  switch (error_code) {
+    case BluetoothAudioSink::ERROR_UNSUPPORTED_PLATFORM:
+      return "unsupported platform";
+    case BluetoothAudioSink::ERROR_INVALID_ADAPTER:
+      return "invalid adapter";
+    case BluetoothAudioSink::ERROR_NOT_REGISTERED:
+      return "not registered";
+    case BluetoothAudioSink::ERROR_NOT_UNREGISTERED:
+      return "not unregistered";
+    default:
+      return "unknown";
+  }
+}
+
 // A dummy error callback for calling Unregister() in destructor.
 void UnregisterErrorCallback(
     device::BluetoothAudioSink::ErrorCode error_code) {
-  VLOG(1) << "Bluetooth audio sink: Error code: " << error_code;
+  VLOG(1) << "UnregisterErrorCallback - " << ErrorCodeToString(error_code)
+          << "(" << error_code << ")";
 }
 
 }  // namespace
@@ -48,6 +82,8 @@ BluetoothAudioSinkChromeOS::BluetoothAudioSinkChromeOS(
       write_mtu_(nullptr),
       adapter_(adapter),
       weak_ptr_factory_(this) {
+  VLOG(1) << "BluetoothAudioSinkChromeOS created";
+
   DCHECK(adapter_.get());
   DCHECK(adapter_->IsPresent());
 
@@ -67,6 +103,8 @@ BluetoothAudioSinkChromeOS::BluetoothAudioSinkChromeOS(
 }
 
 BluetoothAudioSinkChromeOS::~BluetoothAudioSinkChromeOS() {
+  VLOG(1) << "BluetoothAudioSinkChromeOS destroyed";
+
   DCHECK(adapter_.get());
 
   if (state_ != BluetoothAudioSink::STATE_INVALID && media_endpoint_.get()) {
@@ -90,6 +128,8 @@ BluetoothAudioSinkChromeOS::~BluetoothAudioSinkChromeOS() {
 void BluetoothAudioSinkChromeOS::Unregister(
     const base::Closure& callback,
     const device::BluetoothAudioSink::ErrorCallback& error_callback) {
+  VLOG(1) << "Unregister";
+
   if (!DBusThreadManager::IsInitialized())
     error_callback.Run(BluetoothAudioSink::ERROR_NOT_UNREGISTERED);
 
@@ -128,8 +168,7 @@ uint16_t BluetoothAudioSinkChromeOS::GetVolume() const {
 
 void BluetoothAudioSinkChromeOS::AdapterPresentChanged(
     device::BluetoothAdapter* adapter, bool present) {
-  VLOG(1) << "Bluetooth audio sink: Bluetooth adapter present changed: "
-          << present;
+  VLOG(1) << "AdapterPresentChanged: " << present;
 
   if (adapter->IsPresent()) {
     StateChanged(BluetoothAudioSink::STATE_DISCONNECTED);
@@ -141,8 +180,7 @@ void BluetoothAudioSinkChromeOS::AdapterPresentChanged(
 
 void BluetoothAudioSinkChromeOS::AdapterPoweredChanged(
     device::BluetoothAdapter* adapter, bool powered) {
-  VLOG(1) << "Bluetooth audio sink: Bluetooth adapter powered changed: "
-          << powered;
+  VLOG(1) << "AdapterPoweredChanged: " << powered;
 
   // Regardless of the new powered state, |state_| goes to STATE_DISCONNECTED.
   // If false, the transport is closed, but the endpoint is still valid for use.
@@ -154,6 +192,7 @@ void BluetoothAudioSinkChromeOS::AdapterPoweredChanged(
 
 void BluetoothAudioSinkChromeOS::MediaRemoved(const ObjectPath& object_path) {
   if (object_path == media_path_) {
+    VLOG(1) << "MediaRemoved: " << object_path.value();
     StateChanged(BluetoothAudioSink::STATE_INVALID);
   }
 }
@@ -164,6 +203,7 @@ void BluetoothAudioSinkChromeOS::MediaTransportRemoved(
   // transport object should be removed accordingly, and the state should be
   // changed to STATE_DISCONNECTED.
   if (object_path == transport_path_) {
+    VLOG(1) << "MediaTransportRemoved: " << object_path.value();
     StateChanged(BluetoothAudioSink::STATE_DISCONNECTED);
   }
 }
@@ -174,6 +214,8 @@ void BluetoothAudioSinkChromeOS::MediaTransportPropertyChanged(
   if (object_path != transport_path_)
     return;
 
+  VLOG(1) << "MediaTransportPropertyChanged: " << property_name;
+
   // Retrieves the property set of the transport object with |object_path|.
   chromeos::BluetoothMediaTransportClient::Properties* properties =
       DBusThreadManager::Get()
@@ -194,21 +236,18 @@ void BluetoothAudioSinkChromeOS::MediaTransportPropertyChanged(
     }
   } else if (property_name == properties->volume.name()) {
     VolumeChanged(properties->volume.value());
-  } else {
-    VLOG(1) << "Bluetooth audio sink: transport property " << property_name
-            << " changed";
   }
 }
 
 void BluetoothAudioSinkChromeOS::SetConfiguration(
     const ObjectPath& transport_path,
     const TransportProperties& properties) {
-  VLOG(1) << "Bluetooth audio sink: SetConfiguration called";
+  VLOG(1) << "SetConfiguration";
   transport_path_ = transport_path;
 
   // The initial state for a connection should be "idle".
   if (properties.state != BluetoothMediaTransportClient::kStateIdle) {
-    VLOG(1) << "Bluetooth Audio Sink: unexpected state " << properties.state;
+    VLOG(1) << "SetConfiugration - unexpected state :" << properties.state;
     return;
   }
 
@@ -223,7 +262,7 @@ void BluetoothAudioSinkChromeOS::SetConfiguration(
 void BluetoothAudioSinkChromeOS::SelectConfiguration(
     const std::vector<uint8_t>& capabilities,
     const SelectConfigurationCallback& callback) {
-  VLOG(1) << "Bluetooth audio sink: SelectConfiguration called";
+  VLOG(1) << "SelectConfiguration";
   callback.Run(options_.capabilities);
 }
 
@@ -231,12 +270,12 @@ void BluetoothAudioSinkChromeOS::ClearConfiguration(
     const ObjectPath& transport_path) {
   if (transport_path != transport_path_)
     return;
-  VLOG(1) << "Bluetooth audio sink: ClearConfiguration called";
+  VLOG(1) << "ClearConfiguration";
   StateChanged(BluetoothAudioSink::STATE_DISCONNECTED);
 }
 
 void BluetoothAudioSinkChromeOS::Released() {
-  VLOG(1) << "Bluetooth audio sink: Released called";
+  VLOG(1) << "Released";
   StateChanged(BluetoothAudioSink::STATE_INVALID);
 }
 
@@ -244,6 +283,8 @@ void BluetoothAudioSinkChromeOS::Register(
     const BluetoothAudioSink::Options& options,
     const base::Closure& callback,
     const BluetoothAudioSink::ErrorCallback& error_callback) {
+  VLOG(1) << "Register";
+
   DCHECK(adapter_.get());
   DCHECK_EQ(state_, BluetoothAudioSink::STATE_DISCONNECTED);
 
@@ -291,7 +332,8 @@ void BluetoothAudioSinkChromeOS::StateChanged(
   if (state == state_)
     return;
 
-  VLOG(1) << "Bluetooth audio sink state changed: " << state;
+  VLOG(1) << "StateChnaged: " << StateToString(state);
+
   switch (state) {
     case BluetoothAudioSink::STATE_INVALID:
       ResetMedia();
@@ -326,9 +368,9 @@ void BluetoothAudioSinkChromeOS::VolumeChanged(uint16_t volume) {
   if (volume == volume_)
     return;
 
-  VLOG(1) << "Bluetooth audio sink volume changed: " << volume;
-  volume_ = std::min(volume, BluetoothAudioSink::kInvalidVolume);
+  VLOG(1) << "VolumeChanged: " << volume;
 
+  volume_ = std::min(volume, BluetoothAudioSink::kInvalidVolume);
   FOR_EACH_OBSERVER(BluetoothAudioSink::Observer, observers_,
                     BluetoothAudioSinkVolumeChanged(this, volume_));
 }
@@ -336,7 +378,7 @@ void BluetoothAudioSinkChromeOS::VolumeChanged(uint16_t volume) {
 void BluetoothAudioSinkChromeOS::OnRegisterSucceeded(
     const base::Closure& callback) {
   DCHECK(media_endpoint_.get());
-  VLOG(1) << "Bluetooth audio sink registerd";
+  VLOG(1) << "OnRegisterSucceeded";
 
   StateChanged(BluetoothAudioSink::STATE_DISCONNECTED);
   callback.Run();
@@ -346,7 +388,8 @@ void BluetoothAudioSinkChromeOS::OnRegisterFailed(
     const BluetoothAudioSink::ErrorCallback& error_callback,
     const std::string& error_name,
     const std::string& error_message) {
-  VLOG(1) << "Bluetooth audio sink: " << error_name << ": " <<  error_message;
+  VLOG(1) << "OnRegisterFailed - error name: " << error_name
+          << ", error message: " << error_message;
 
   ResetEndpoint();
   error_callback.Run(BluetoothAudioSink::ERROR_NOT_REGISTERED);
@@ -354,7 +397,7 @@ void BluetoothAudioSinkChromeOS::OnRegisterFailed(
 
 void BluetoothAudioSinkChromeOS::OnUnregisterSucceeded(
     const base::Closure& callback) {
-  VLOG(1) << "Bluetooth audio sink unregisterd";
+  VLOG(1) << "Unregisterd";
 
   // Once the state becomes STATE_INVALID, media, media transport and media
   // endpoint will be reset.
@@ -366,7 +409,9 @@ void BluetoothAudioSinkChromeOS::OnUnregisterFailed(
     const device::BluetoothAudioSink::ErrorCallback& error_callback,
     const std::string& error_name,
     const std::string& error_message) {
-  VLOG(1) << "Bluetooth audio sink: " << error_name << ": " <<  error_message;
+  VLOG(1) << "OnUnregisterFailed - error name: " << error_name
+          << ", error message: " << error_message;
+
   error_callback.Run(BluetoothAudioSink::ERROR_NOT_UNREGISTERED);
 }
 
@@ -379,10 +424,14 @@ void BluetoothAudioSinkChromeOS::ReadFromFD() {
 }
 
 void BluetoothAudioSinkChromeOS::ResetMedia() {
+  VLOG(1) << "ResetMedia";
+
   media_path_ = dbus::ObjectPath("");
 }
 
 void BluetoothAudioSinkChromeOS::ResetTransport() {
+  VLOG(1) << "ResetTransport";
+
   if (transport_path_.value() == "")
     return;
   transport_path_ = dbus::ObjectPath("");
@@ -393,6 +442,8 @@ void BluetoothAudioSinkChromeOS::ResetTransport() {
 }
 
 void BluetoothAudioSinkChromeOS::ResetEndpoint() {
+  VLOG(1) << "ResetEndpoint";
+
   endpoint_path_ = ObjectPath("");
   media_endpoint_ = nullptr;
 }