Added initial set of logging for AudioOutputController.

media/audio/audio_output_controller.cc

Index: media/audio/audio_output_controller.cc
diff --git a/media/audio/audio_output_controller.cc b/media/audio/audio_output_controller.cc
index 6c9daa0c00fac39375f51ecc5465becdb7cdb15a..fdca8112f14caba8fe3da63ef0d365914576dfd8 100644
--- a/media/audio/audio_output_controller.cc
+++ b/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)",

[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)
@@ -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.