Added initial set of logging for AudioOutputController.

media/audio/audio_output_controller.cc

 // Copyright (c) 2012 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 "media/audio/audio_output_controller.h"
 
 #include <stdint.h>
 
 #include <algorithm>
 #include <limits>
 
 #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"
 #include "base/trace_event/trace_event.h"
 #include "media/base/audio_timestamp_helper.h"
 
 using base::TimeDelta;
 
 namespace media {
 
@@ skipping 75 matching lines @@
   CHECK_EQ(AudioManager::Get(), audio_manager_);
   message_loop_->PostTask(
       FROM_HERE,
       base::BindOnce(&AudioOutputController::DoSetVolume, this, volume));
 }
 
 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)",

[Max Morin, 2017/05/29 08:12:53]

I think we should consider having a common logging prefix for all audio things.
This makes it easier to grep it in logs and also makes it more forward
compatible (e.g. we don't have to worry about the prefix if we move the log
message to another class).

[ossu-chromium, 2017/05/29 14:19:43]

It should be possible to grep for these lines from AudioInputController and
AudioOutputController by grepping for A[IO]C for now. We can bike-shed a bit
what exactly the common prefix should be and which files it should be applied
to, and I can fix that in a separate CL, if that's alright?

[Max Morin, 2017/05/29 14:25:44]

Sounds good.

+                                     is_for_device_change ? "yes" : "no"));
 
   // Close() can be called before DoCreate() is executed.
   if (state_ == kClosed)
     return;
 
   DoStopCloseAndClearStream();  // Calls RemoveOutputDeviceChangeListener().
   DCHECK_EQ(kEmpty, state_);
 
   stream_ = diverting_to_stream_ ?
       diverting_to_stream_ :
@@ skipping 24 matching lines @@
 
   // And then report we have been created if we haven't done so already.
   if (!is_for_device_change)
     handler_->OnControllerCreated();
 }
 
 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)
     return;
 
   // Ask for first packet.
   sync_reader_->RequestMoreData(base::TimeDelta(), base::TimeTicks(), 0);
 
   state_ = kPlaying;
 
@@ skipping 30 matching lines @@
     power_monitor_.Reset();
 
     state_ = kPaused;
   }
 }
 
 void AudioOutputController::DoPause() {
   DCHECK(message_loop_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.PauseTime");
   TRACE_EVENT0("audio", "AudioOutputController::DoPause");
+  handler_->OnLog("AOC::DoPause");
 
   StopStream();
 
   if (state_ != kPaused)
     return;
 
   // Let the renderer know we've stopped.  Necessary to let PPAPI clients know
   // audio has been shutdown.  TODO(dalecurtis): This stinks.  PPAPI should have
   // a better way to know when it should exit PPB_Audio_Shared::Run().
   sync_reader_->RequestMoreData(base::TimeDelta::Max(), base::TimeTicks(), 0);
 
   handler_->OnControllerPaused();
 }
 
 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();
     sync_reader_->Close();
     state_ = kClosed;
   }
 }
 
 void AudioOutputController::DoSetVolume(double volume) {
   DCHECK(message_loop_->BelongsToCurrentThread());
@@ skipping 114 matching lines @@
   }
 
   state_ = kEmpty;
 }
 
 void AudioOutputController::OnDeviceChange() {
   DCHECK(message_loop_->BelongsToCurrentThread());
   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.
 
   // Recreate the stream (DoCreate() will first shut down an existing stream).
   // Exit if we ran into an error.
   const State original_state = state_;
   DoCreate(true);
   if (!stream_ || state_ == kError)
     return;
@@ skipping 97 matching lines @@
   DCHECK(message_loop_->BelongsToCurrentThread());
 
   // If we should be playing and we haven't, that's a wedge.
   if (state_ == kPlaying) {
     UMA_HISTOGRAM_BOOLEAN("Media.AudioOutputControllerPlaybackStartupSuccess",
                           base::AtomicRefCountIsOne(&on_more_io_data_called_));
   }
 }
 
 }  // namespace media