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

media/audio/audio_input_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_input_controller.h"
 
 #include "base/bind.h"
 #include "base/strings/stringprintf.h"
 #include "base/threading/thread_restrictions.h"
 #include "base/time/time.h"
@@ skipping 55 matching lines @@
                             result,
                             CAPTURE_STARTUP_RESULT_MAX + 1);
 
 }
 
 namespace media {
 
 // static
 AudioInputController::Factory* AudioInputController::factory_ = NULL;
 
-AudioInputController::AudioInputController(EventHandler* handler,
+AudioInputController::AudioInputController(AudioManager* audio_manager,
+                                           EventHandler* handler,
                                            SyncWriter* sync_writer,
                                            UserInputMonitor* user_input_monitor)
     : creator_task_runner_(base::MessageLoopProxy::current()),
       handler_(handler),
+      audio_manager_(audio_manager),
       stream_(NULL),
       data_is_active_(false),
       state_(CLOSED),
       sync_writer_(sync_writer),
       max_volume_(0.0),
       user_input_monitor_(user_input_monitor),
 #if defined(AUDIO_POWER_MONITORING)
       silence_state_(SILENCE_STATE_NO_MEASUREMENT),
 #endif
       prev_key_down_count_(0) {
@@ skipping 13 matching lines @@
     UserInputMonitor* user_input_monitor) {
   DCHECK(audio_manager);
 
   if (!params.IsValid() || (params.channels() > kMaxInputChannels))
     return NULL;
 
   if (factory_) {
     return factory_->Create(
         audio_manager, event_handler, params, user_input_monitor);
   }
-  scoped_refptr<AudioInputController> controller(
-      new AudioInputController(event_handler, NULL, user_input_monitor));
+  scoped_refptr<AudioInputController> controller(new AudioInputController(
+      audio_manager, event_handler, NULL, user_input_monitor));
 
   controller->task_runner_ = audio_manager->GetTaskRunner();
 
   // Create and open a new audio input stream from the existing
   // audio-device thread.
-  if (!controller->task_runner_->PostTask(FROM_HERE,
-          base::Bind(&AudioInputController::DoCreate, controller,
-                     base::Unretained(audio_manager), params, device_id))) {
+  if (!controller->task_runner_->PostTask(
+          FROM_HERE,
+          base::Bind(&AudioInputController::DoCreate,
+                     controller,
+                     params,
+                     device_id))) {
     controller = NULL;
   }
 
   return controller;
 }
 
 // static
 scoped_refptr<AudioInputController> AudioInputController::CreateLowLatency(
     AudioManager* audio_manager,
     EventHandler* event_handler,
     const AudioParameters& params,
     const std::string& device_id,
     SyncWriter* sync_writer,
     UserInputMonitor* user_input_monitor) {
   DCHECK(audio_manager);
   DCHECK(sync_writer);
 
   if (!params.IsValid() || (params.channels() > kMaxInputChannels))
     return NULL;
 
   // Create the AudioInputController object and ensure that it runs on
   // the audio-manager thread.
-  scoped_refptr<AudioInputController> controller(
-      new AudioInputController(event_handler, sync_writer, user_input_monitor));
+  scoped_refptr<AudioInputController> controller(new AudioInputController(
+      audio_manager, event_handler, sync_writer, user_input_monitor));
   controller->task_runner_ = audio_manager->GetTaskRunner();
 
   // Create and open a new audio input stream from the existing
   // audio-device thread. Use the provided audio-input device.
-  if (!controller->task_runner_->PostTask(FROM_HERE,
-          base::Bind(&AudioInputController::DoCreate, controller,
-                     base::Unretained(audio_manager), params, device_id))) {
+  if (!controller->task_runner_->PostTask(
+          FROM_HERE,
+          base::Bind(&AudioInputController::DoCreate,
+                     controller,
+                     params,
+                     device_id))) {
     controller = NULL;
   }
 
   return controller;
 }
 
 // static
 scoped_refptr<AudioInputController> AudioInputController::CreateForStream(
     const scoped_refptr<base::SingleThreadTaskRunner>& task_runner,
     EventHandler* event_handler,
     AudioInputStream* stream,
     SyncWriter* sync_writer,
     UserInputMonitor* user_input_monitor) {
   DCHECK(sync_writer);
   DCHECK(stream);
 
   // Create the AudioInputController object and ensure that it runs on
   // the audio-manager thread.
-  scoped_refptr<AudioInputController> controller(
-      new AudioInputController(event_handler, sync_writer, user_input_monitor));
+  scoped_refptr<AudioInputController> controller(new AudioInputController(
+      NULL, event_handler, sync_writer, user_input_monitor));
   controller->task_runner_ = task_runner;
 
   // TODO(miu): See TODO at top of file.  Until that's resolved, we need to
   // disable the error auto-detection here (since the audio mirroring
   // implementation will reliably report error and close events).  Note, of
   // course, that we're assuming CreateForStream() has been called for the audio
   // mirroring use case only.
   if (!controller->task_runner_->PostTask(
           FROM_HERE,
           base::Bind(&AudioInputController::DoCreateForStream,
@@ skipping 21 matching lines @@
 void AudioInputController::SetVolume(double volume) {
   task_runner_->PostTask(FROM_HERE, base::Bind(
       &AudioInputController::DoSetVolume, this, volume));
 }
 
 void AudioInputController::SetAutomaticGainControl(bool enabled) {
   task_runner_->PostTask(FROM_HERE, base::Bind(
       &AudioInputController::DoSetAutomaticGainControl, this, enabled));
 }
 
-void AudioInputController::DoCreate(AudioManager* audio_manager,
-                                    const AudioParameters& params,
+void AudioInputController::DoCreate(const AudioParameters& params,
                                     const std::string& device_id) {
   DCHECK(task_runner_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioInputController.CreateTime");
+  if (handler_) {
+    std::string log_string =
+        base::StringPrintf("AIC::DoCreate(device_id=%s)", device_id.c_str());

[Henrik Grunell, 2014/08/22 16:14:42]

What device id is this? Unique in what way? Can it be used to identify someone?

[no longer working on chromium, 2014/08/25 08:20:05]

This is the uniqie id of the device, we can't log it due to privacy reason.

Also, AudioInputRendererHost line 366 has:
MediaStreamManager::SendMessageToNativeLog(
      "Audio input stream created successfully. Device name: " + device_name);

You probably don't need to log the device again

[henrika (OOO until Aug 14), 2014/08/25 12:47:44]

Removing. Thanks.

+    handler_->OnLog(this, log_string);
+  }
 
 #if defined(AUDIO_POWER_MONITORING)
   // Create the audio (power) level meter given the provided audio parameters.
   // An AudioBus is also needed to wrap the raw data buffer from the native
   // layer to match AudioPowerMonitor::Scan().
   // TODO(henrika): Remove use of extra AudioBus. See http://crbug.com/375155.
   audio_level_.reset(new media::AudioPowerMonitor(
       params.sample_rate(),
       TimeDelta::FromMilliseconds(kPowerMeasurementTimeConstantMilliseconds)));
   audio_params_ = params;
   silence_state_ = SILENCE_STATE_NO_MEASUREMENT;
 #endif
 
+  if (audio_manager_)
+    audio_manager_->AddStateChangeListener(this);
+
   // TODO(miu): See TODO at top of file.  Until that's resolved, assume all
   // platform audio input requires the |no_data_timer_| be used to auto-detect
   // errors.  In reality, probably only Windows needs to be treated as
   // unreliable here.
-  DoCreateForStream(audio_manager->MakeAudioInputStream(params, device_id));
+  DoCreateForStream(audio_manager_->MakeAudioInputStream(params, device_id));
 }
 
 void AudioInputController::DoCreateForStream(
     AudioInputStream* stream_to_control) {
   DCHECK(task_runner_->BelongsToCurrentThread());
 
   DCHECK(!stream_);
   stream_ = stream_to_control;
 
   if (!stream_) {
@@ skipping 42 matching lines @@
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioInputController.RecordTime");
 
   if (state_ != CREATED)
     return;
 
   {
     base::AutoLock auto_lock(lock_);
     state_ = RECORDING;
   }
 
+  if (handler_)
+    handler_->OnLog(this, "AIC::DoRecord");

[no longer working on chromium, 2014/08/25 08:20:05]

I don't really think you should log these, DoRecord and DoClose() are also used
by non webrtc clients, can it be corrupting our loggings?

[henrika (OOO until Aug 14), 2014/08/25 12:47:44]

Well, if it does that may very well be a reason why things go wrong and
something we want to catch. Again, I am trying to see the full picture since I
don't know what type of issue I am looking for ;-)

+
   if (no_data_timer_) {
     // Start the data timer. Once |kTimerResetIntervalSeconds| have passed,
     // a callback to FirstCheckForNoData() is made.
     no_data_timer_->Reset();
   }
 
   stream_->Start(this);
   if (handler_)
     handler_->OnRecording(this);
 }
 
 void AudioInputController::DoClose() {
   DCHECK(task_runner_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioInputController.CloseTime");
 
   if (state_ == CLOSED)
     return;
 
+  if (handler_)
+    handler_->OnLog(this, "AIC::DoClose");
+
   // Delete the timer on the same thread that created it.
   no_data_timer_.reset();
 
   DoStopCloseAndClearStream();
   SetDataIsActive(false);
 
+  if (audio_manager_)
+    audio_manager_->RemoveStateChangeListener(this);

[Henrik Grunell, 2014/08/22 16:14:43]

Should the raw |audio_manager_| pointer be set to NULL here?

[henrika (OOO until Aug 14), 2014/08/25 12:47:44]

It could but I can't really see the gain actually since we never NULL check it
anyhow.

+
   if (SharedMemoryAndSyncSocketMode())
     sync_writer_->Close();
 
   if (user_input_monitor_)
     user_input_monitor_->DisableKeyPressMonitoring();
 
 #if defined(AUDIO_POWER_MONITORING)
   // Send UMA stats if we have enabled power monitoring.
   if (audio_level_) {
     LogSilenceState(silence_state_);
@@ skipping 41 matching lines @@
     return;
 
   stream_->SetAutomaticGainControl(enabled);
 }
 
 void AudioInputController::FirstCheckForNoData() {
   DCHECK(task_runner_->BelongsToCurrentThread());
   LogCaptureStartupResult(GetDataIsActive() ?
                           CAPTURE_STARTUP_OK :
                           CAPTURE_STARTUP_NO_DATA_CALLBACK);
+  if (handler_) {
+    GetDataIsActive()
+        ? handler_->OnLog(this, "AIC::FirstCheckForNoData => data is active")

[no longer working on chromium, 2014/08/25 08:20:05]

this does not look like clang format, could you please run the script?

[henrika (OOO until Aug 14), 2014/08/25 12:47:44]

I did run git cl format and this is what it gives me. Not sure if I should
change it.

+        : handler_->OnLog(this,
+                          "AIC::FirstCheckForNoData => data is NOT active");
+  }
   DoCheckForNoData();
 }
 
 void AudioInputController::DoCheckForNoData() {
   DCHECK(task_runner_->BelongsToCurrentThread());
 
   if (!GetDataIsActive()) {
     // The data-is-active marker will be false only if it has been more than
     // one second since a data packet was recorded. This can happen if a
     // capture device has been removed or disabled.
@@ skipping 123 matching lines @@
       silence_state_ = SILENCE_STATE_AUDIO_AND_SILENCE;
     else
       DCHECK(silence_state_ == SILENCE_STATE_ONLY_AUDIO ||
              silence_state_ == SILENCE_STATE_AUDIO_AND_SILENCE);
   }
 
   handler_->OnLog(this, log_string);
 #endif
 }
 
+void AudioInputController::OnStateChange(const std::string state) {
+  DCHECK(task_runner_->BelongsToCurrentThread());
+  if (handler_)
+    handler_->OnLog(this, state);
+}
+
 void AudioInputController::OnError(AudioInputStream* stream) {
   // Handle error on the audio-manager thread.
   task_runner_->PostTask(FROM_HERE, base::Bind(
       &AudioInputController::DoReportError, this));
 }
 
 void AudioInputController::DoStopCloseAndClearStream() {
   DCHECK(task_runner_->BelongsToCurrentThread());
 
   // Allow calling unconditionally and bail if we don't have a stream to close.
@@ skipping 17 matching lines @@
 
 #if defined(AUDIO_POWER_MONITORING)
 void AudioInputController::LogSilenceState(SilenceState value) {
   UMA_HISTOGRAM_ENUMERATION("Media.AudioInputControllerSessionSilenceReport",
                             value,
                             SILENCE_STATE_MAX + 1);
 }
 #endif
 
 }  // namespace media