Added initial set of logging for AudioOutputController.

BUG=chromium:714119
CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.android:android_optional_gpu_tests_rel;master.tryserver.chromium.linux:linux_optional_gpu_tests_rel;master.tryserver.chromium.mac:mac_optional_gpu_tests_rel;master.tryserver.chromium.win:win_optional_gpu_tests_rel

Review-Url: https://codereview.chromium.org/2900043002
Cr-Commit-Position: refs/heads/master@{#476257}

content/browser/renderer_host/media/audio_output_delegate_impl.cc

@@ -12,6 +12,7 @@
 #include "content/browser/media/capture/audio_mirroring_manager.h"
 #include "content/browser/media/media_internals.h"
 #include "content/browser/renderer_host/media/audio_sync_reader.h"
+#include "content/browser/renderer_host/media/media_stream_manager.h"
 #include "content/public/browser/browser_thread.h"
 #include "content/public/browser/media_observer.h"
 #include "media/audio/audio_output_controller.h"
@@ -25,21 +26,24 @@ namespace content {
 class AudioOutputDelegateImpl::ControllerEventHandler
     : public media::AudioOutputController::EventHandler {
  public:
-  explicit ControllerEventHandler(
-      base::WeakPtr<AudioOutputDelegateImpl> delegate);
+  ControllerEventHandler(base::WeakPtr<AudioOutputDelegateImpl> delegate,
+                         int stream_id);
 
  private:
   void OnControllerCreated() override;
   void OnControllerPlaying() override;
   void OnControllerPaused() override;
   void OnControllerError() override;
+  void OnLog(const std::string& message) override;
 
   base::WeakPtr<AudioOutputDelegateImpl> delegate_;
+  const int stream_id_;  // Retained separately for logging.
 };
 
 AudioOutputDelegateImpl::ControllerEventHandler::ControllerEventHandler(
-    base::WeakPtr<AudioOutputDelegateImpl> delegate)
-    : delegate_(std::move(delegate)) {}
+    base::WeakPtr<AudioOutputDelegateImpl> delegate,
+    int stream_id)
+    : delegate_(std::move(delegate)), stream_id_(stream_id) {}
 
 void AudioOutputDelegateImpl::ControllerEventHandler::OnControllerCreated() {
   BrowserThread::PostTask(
@@ -68,6 +72,15 @@ void AudioOutputDelegateImpl::ControllerEventHandler::OnControllerError() {
       base::BindOnce(&AudioOutputDelegateImpl::OnError, delegate_));
 }
 
+void AudioOutputDelegateImpl::ControllerEventHandler::OnLog(
+    const std::string& message) {
+  std::ostringstream oss;
+  oss << "[stream_id=" << stream_id_ << "] " << message;
+  const std::string out_message = oss.str();
+  content::MediaStreamManager::SendMessageToNativeLog(out_message);
+  DVLOG(1) << out_message;
+}
+
 std::unique_ptr<media::AudioOutputDelegate> AudioOutputDelegateImpl::Create(
     EventHandler* handler,
     media::AudioManager* audio_manager,
@@ -118,8 +131,8 @@ AudioOutputDelegateImpl::AudioOutputDelegateImpl(
   // Since the event handler never directly calls functions on |this| but rather
   // posts them to the IO thread, passing a pointer from the constructor is
   // safe.
-  controller_event_handler_ =
-      base::MakeUnique<ControllerEventHandler>(weak_factory_.GetWeakPtr());
+  controller_event_handler_ = base::MakeUnique<ControllerEventHandler>(
+      weak_factory_.GetWeakPtr(), stream_id_);
   audio_log_->OnCreated(stream_id, params, output_device_id);
   controller_ = media::AudioOutputController::Create(
       audio_manager, controller_event_handler_.get(), params, output_device_id,

media/audio/audio_output_controller.cc

@@ -12,6 +12,7 @@
 #include "base/bind.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/numerics/safe_conversions.h"
+#include "base/strings/stringprintf.h"
 #include "base/task_runner_util.h"
 #include "base/threading/platform_thread.h"
 #include "base/time/time.h"
@@ -107,6 +108,8 @@ void AudioOutputController::DoCreate(bool is_for_device_change) {
   DCHECK(message_loop_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.CreateTime");
   TRACE_EVENT0("audio", "AudioOutputController::DoCreate");
+  handler_->OnLog(base::StringPrintf("AOC::DoCreate (for device change: %s)",
+                                     is_for_device_change ? "yes" : "no"));
 
   // Close() can be called before DoCreate() is executed.
   if (state_ == kClosed)
@@ -151,6 +154,7 @@ void AudioOutputController::DoPlay() {
   DCHECK(message_loop_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.PlayTime");
   TRACE_EVENT0("audio", "AudioOutputController::DoPlay");
+  handler_->OnLog("AOC::DoPlay");
 
   // We can start from created or paused state.
   if (state_ != kCreated && state_ != kPaused)
@@ -201,6 +205,7 @@ void AudioOutputController::DoPause() {
   DCHECK(message_loop_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.PauseTime");
   TRACE_EVENT0("audio", "AudioOutputController::DoPause");
+  handler_->OnLog("AOC::DoPause");
 
   StopStream();
 
@@ -219,6 +224,7 @@ void AudioOutputController::DoClose() {
   DCHECK(message_loop_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.CloseTime");
   TRACE_EVENT0("audio", "AudioOutputController::DoClose");
+  handler_->OnLog("AOC::DoClose");
 
   if (state_ != kClosed) {
     DoStopCloseAndClearStream();
@@ -353,6 +359,27 @@ void AudioOutputController::OnDeviceChange() {
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.DeviceChangeTime");
   TRACE_EVENT0("audio", "AudioOutputController::OnDeviceChange");
 
+  auto state_to_string = [](State state) {
+    switch (state) {
+      case AudioOutputController::kEmpty:
+        return "empty";
+      case AudioOutputController::kCreated:
+        return "created";
+      case AudioOutputController::kPlaying:
+        return "playing";
+      case AudioOutputController::kPaused:
+        return "paused";
+      case AudioOutputController::kClosed:
+        return "closed";
+      case AudioOutputController::kError:
+        return "error";
+    };
+    return "unknown";
+  };
+
+  handler_->OnLog(base::StringPrintf("AOC::OnDeviceChange while in state: %s",
+                                     state_to_string(state_)));
+
   // TODO(dalecurtis): Notify the renderer side that a device change has
   // occurred.  Currently querying the hardware information here will lead to
   // crashes on OSX.  See http://crbug.com/158170.

media/audio/audio_output_controller.h

@@ -75,6 +75,7 @@ class MEDIA_EXPORT AudioOutputController
     virtual void OnControllerPlaying() = 0;
     virtual void OnControllerPaused() = 0;
     virtual void OnControllerError() = 0;
+    virtual void OnLog(const std::string& message) = 0;
 
    protected:
     virtual ~EventHandler() {}

media/audio/audio_output_controller_unittest.cc

@@ -53,6 +53,7 @@ class MockAudioOutputControllerEventHandler
   MOCK_METHOD0(OnControllerPlaying, void());
   MOCK_METHOD0(OnControllerPaused, void());
   MOCK_METHOD0(OnControllerError, void());
+  MOCK_METHOD1(OnLog, void(const std::string&));
 
  private:
   DISALLOW_COPY_AND_ASSIGN(MockAudioOutputControllerEventHandler);