Improve logging related to start/stop and failure of audio input streams in Chrome

media/audio/audio_manager_base.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_manager_base.h"
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/command_line.h"
 #include "base/strings/string_number_conversions.h"
+#include "base/strings/stringprintf.h"
 #include "build/build_config.h"
 #include "media/audio/audio_output_dispatcher_impl.h"
 #include "media/audio/audio_output_proxy.h"
 #include "media/audio/audio_output_resampler.h"
 #include "media/audio/fake_audio_input_stream.h"
 #include "media/audio/fake_audio_output_stream.h"
 #include "media/base/media_switches.h"
 
 namespace media {
 
@@ skipping 52 matching lines @@
 
 AudioManagerBase::AudioManagerBase(AudioLogFactory* audio_log_factory)
     : max_num_output_streams_(kDefaultMaxOutputStreams),
       max_num_input_streams_(kDefaultMaxInputStreams),
       num_output_streams_(0),
       num_input_streams_(0),
       // TODO(dalecurtis): Switch this to an ObserverListThreadSafe, so we don't
       // block the UI thread when swapping devices.
       output_listeners_(
           ObserverList<AudioDeviceListener>::NOTIFY_EXISTING_ONLY),
+      state_listeners_(ObserverList<StateChangeListener>::NOTIFY_EXISTING_ONLY),
       audio_thread_("AudioThread"),
       audio_log_factory_(audio_log_factory) {
 #if defined(OS_WIN)
   audio_thread_.init_com_with_mta(true);
 #elif defined(OS_MACOSX)
   // CoreAudio calls must occur on the main thread of the process, which in our
   // case is sadly the browser UI thread.  Failure to execute calls on the right
   // thread leads to crashes and odd behavior.  See http://crbug.com/158170.
   // TODO(dalecurtis): We should require the message loop to be passed in.
   if (base::MessageLoopForUI::IsCurrent()) {
@@ skipping 87 matching lines @@
 
 AudioInputStream* AudioManagerBase::MakeAudioInputStream(
     const AudioParameters& params,
     const std::string& device_id) {
   // TODO(miu): Fix ~20 call points across several unit test modules to call
   // this method on the audio thread, then uncomment the following:
   // DCHECK(task_runner_->BelongsToCurrentThread());
 
   if (!params.IsValid() || (params.channels() > kMaxInputChannels) ||
       device_id.empty()) {
-    DLOG(ERROR) << "Audio parameters are invalid for device " << device_id;
+    std::ostringstream oss;
+    oss << "MakeAudioInputStream => invalid parameters";
+    DLOG(ERROR) << oss;
+    NotifyAllStateChangeListeners(oss.str());

[DaleCurtis, 2014/08/26 20:09:29]

This seems wrong. Only the creating controller should get this information.

[henrika (OOO until Aug 14), 2014/08/27 13:54:38]

Done.

     return NULL;
   }
 
   if (num_input_streams_ >= max_num_input_streams_) {
-    DLOG(ERROR) << "Number of opened input audio streams "
-                << num_input_streams_
-                << " exceed the max allowed number " << max_num_input_streams_;
+    std::ostringstream oss;
+    oss << "MakeAudioInputStream => "

[DaleCurtis, 2014/08/26 20:09:29]

Ditto. All this is doing is spamming all listeners, of which there may be many.

[henrika (OOO until Aug 14), 2014/08/27 13:54:38]

Done.

+        << "number of opened input audio streams " << num_input_streams_
+        << " exceed the max allowed number " << max_num_input_streams_;
+    DLOG(ERROR) << oss;
+    NotifyAllStateChangeListeners(oss.str());
     return NULL;
   }
 
   AudioInputStream* stream;
+  std::ostringstream oss;
+  oss << "MakeAudioInputStream(";
   switch (params.format()) {
     case AudioParameters::AUDIO_PCM_LINEAR:
       stream = MakeLinearInputStream(params, device_id);
+      oss << "AUDIO_PCM_LINEAR)";
       break;
     case AudioParameters::AUDIO_PCM_LOW_LATENCY:
       stream = MakeLowLatencyInputStream(params, device_id);
+      oss << "AUDIO_PCM_LOW_LATENCY)";
       break;
     case AudioParameters::AUDIO_FAKE:
       stream = FakeAudioInputStream::MakeFakeStream(this, params);
+      oss << "AUDIO_FAKE)";
       break;
     default:
       stream = NULL;
       break;
   }
 
   if (stream) {
     ++num_input_streams_;
   }
+  oss << " => num_input_streams = " << num_input_streams_;
+  NotifyAllStateChangeListeners(oss.str());
 
   return stream;
 }
 
 AudioOutputStream* AudioManagerBase::MakeAudioOutputStreamProxy(
     const AudioParameters& params,
     const std::string& device_id) {
   DCHECK(task_runner_->BelongsToCurrentThread());
 
   // If the caller supplied an empty device id to select the default device,
@@ skipping 78 matching lines @@
   // For example, pass the ownership to AudioManager so it can delete the
   // streams.
   --num_output_streams_;
   delete stream;
 }
 
 void AudioManagerBase::ReleaseInputStream(AudioInputStream* stream) {
   DCHECK(stream);
   // TODO(xians) : Have a clearer destruction path for the AudioInputStream.
   --num_input_streams_;
+  std::string log_string = base::StringPrintf(

[DaleCurtis, 2014/08/26 20:09:29]

Further, none of this is actually a state change, it's merely an action log
which corresponds to a single controller.

[henrika (OOO until Aug 14), 2014/08/27 13:54:38]

Done.

+      "ReleaseInputStream => num_input_streams = %d", num_input_streams_);
+  NotifyAllStateChangeListeners(log_string);
   delete stream;
 }
 
 void AudioManagerBase::Shutdown() {
   // Only true when we're sharing the UI message loop with the browser.  The UI
   // loop is no longer running at this time and browser destruction is imminent.
   if (task_runner_->BelongsToCurrentThread()) {
     ShutdownOnAudioThread();
   } else {
     task_runner_->PostTask(FROM_HERE, base::Bind(
@@ skipping 23 matching lines @@
   DCHECK(task_runner_->BelongsToCurrentThread());
   output_listeners_.RemoveObserver(listener);
 }
 
 void AudioManagerBase::NotifyAllOutputDeviceChangeListeners() {
   DCHECK(task_runner_->BelongsToCurrentThread());
   DVLOG(1) << "Firing OnDeviceChange() notifications.";
   FOR_EACH_OBSERVER(AudioDeviceListener, output_listeners_, OnDeviceChange());
 }
 
+void AudioManagerBase::AddStateChangeListener(StateChangeListener* listener) {
+  DCHECK(task_runner_->BelongsToCurrentThread());
+  state_listeners_.AddObserver(listener);
+}
+
+void AudioManagerBase::RemoveStateChangeListener(
+    StateChangeListener* listener) {
+  DCHECK(task_runner_->BelongsToCurrentThread());
+  state_listeners_.RemoveObserver(listener);
+}
+
+void AudioManagerBase::NotifyAllStateChangeListeners(const std::string& msg) {
+  DCHECK(task_runner_->BelongsToCurrentThread());
+  std::string log_string("AMB::");
+  log_string += msg;
+  FOR_EACH_OBSERVER(
+      StateChangeListener, state_listeners_, OnStateChange(log_string));
+}
+
 AudioParameters AudioManagerBase::GetDefaultOutputStreamParameters() {
   return GetPreferredOutputStreamParameters(GetDefaultOutputDeviceID(),
       AudioParameters());
 }
 
 AudioParameters AudioManagerBase::GetOutputStreamParameters(
     const std::string& device_id) {
   return GetPreferredOutputStreamParameters(device_id,
       AudioParameters());
 }
@@ skipping 23 matching lines @@
 
   return 0;
 }
 
 scoped_ptr<AudioLog> AudioManagerBase::CreateAudioLog(
     AudioLogFactory::AudioComponent component) {
   return audio_log_factory_->CreateAudioLog(component);
 }
 
 }  // namespace media