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

BUG=405449
TEST=Manual testing using different WebRTC clients

Review URL: https://codereview.chromium.org/495983002

Cr-Commit-Position: refs/heads/master@{#292622}

content/browser/renderer_host/media/audio_input_renderer_host.cc

@@ -19,6 +19,20 @@
 #include "media/audio/audio_manager_base.h"
 #include "media/base/audio_bus.h"
 
+namespace {
+
+void LogMessage(int stream_id, const std::string& msg, bool add_prefix) {
+  std::ostringstream oss;
+  oss << "[stream_id=" << stream_id << "] ";
+  if (add_prefix)
+    oss << "AIRH::";
+  oss << msg;
+  content::MediaStreamManager::SendMessageToNativeLog(oss.str());
+  DVLOG(1) << oss.str();
+}
+
+}
+
 namespace content {
 
 struct AudioInputRendererHost::AudioEntry {
@@ -133,8 +147,10 @@ void AudioInputRendererHost::DoCompleteCreation(
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   AudioEntry* entry = LookupByController(controller);
-  if (!entry)
+  if (!entry) {
+    NOTREACHED() << "AudioInputController is invalid.";
     return;
+  }
 
   if (!PeerHandle()) {
     NOTREACHED() << "Renderer process handle is invalid.";
@@ -176,6 +192,10 @@ void AudioInputRendererHost::DoCompleteCreation(
     return;
   }
 
+  LogMessage(entry->stream_id,
+             "DoCompleteCreation => IPC channel and stream are now open",
+             true);
+
   Send(new AudioInputMsg_NotifyStreamCreated(entry->stream_id,
       foreign_memory_handle, foreign_socket_handle,
       entry->shared_memory.requested_size(),
@@ -187,29 +207,40 @@ void AudioInputRendererHost::DoSendRecordingMessage(
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
   // TODO(henrika): See crbug.com/115262 for details on why this method
   // should be implemented.
+  AudioEntry* entry = LookupByController(controller);
+  if (!entry) {
+    NOTREACHED() << "AudioInputController is invalid.";
+    return;
+  }
+  LogMessage(entry->stream_id,
+             "DoSendRecordingMessage => stream is now started",
+             true);
 }
 
 void AudioInputRendererHost::DoHandleError(
     media::AudioInputController* controller,
     media::AudioInputController::ErrorCode error_code) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
-  // Log all errors even it is ignored later.
-  MediaStreamManager::SendMessageToNativeLog(
-      base::StringPrintf("AudioInputController error: %d", error_code));
+  AudioEntry* entry = LookupByController(controller);
+  if (!entry) {
+    NOTREACHED() << "AudioInputController is invalid.";
+    return;
+  }
 
   // This is a fix for crbug.com/357501. The error can be triggered when closing
   // the lid on Macs, which causes more problems than it fixes.
   // Also, in crbug.com/357569, the goal is to remove usage of the error since
   // it was added to solve a crash on Windows that no longer can be reproduced.
   if (error_code == media::AudioInputController::NO_DATA_ERROR) {
-    DVLOG(1) << "AudioInputRendererHost@" << this << "::DoHandleError: "
-             << "NO_DATA_ERROR ignored.";
+    // TODO(henrika): it might be possible to do something other than just
+    // logging when we detect many NO_DATA_ERROR calls for a stream.
+    LogMessage(entry->stream_id, "AIC => NO_DATA_ERROR", false);
     return;
   }
 
-  AudioEntry* entry = LookupByController(controller);
-  if (!entry)
-    return;
+  std::ostringstream oss;
+  oss << "AIC reports error_code=" << error_code;
+  LogMessage(entry->stream_id, oss.str(), false);
 
   audio_log_->OnError(entry->stream_id);
   DeleteEntryOnError(entry, AUDIO_INPUT_CONTROLLER_ERROR);
@@ -219,15 +250,13 @@ void AudioInputRendererHost::DoLog(media::AudioInputController* controller,
                                    const std::string& message) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
   AudioEntry* entry = LookupByController(controller);
-  if (!entry)
+  if (!entry) {
+    NOTREACHED() << "AudioInputController is invalid.";
     return;
+  }
 
   // Add stream ID and current audio level reported by AIC to native log.
-  std::string log_string =
-      base::StringPrintf("[stream_id=%d] ", entry->stream_id);
-  log_string += message;
-  MediaStreamManager::SendMessageToNativeLog(log_string);
-  DVLOG(1) << log_string;
+  LogMessage(entry->stream_id, message, false);
 }
 
 bool AudioInputRendererHost::OnMessageReceived(const IPC::Message& message) {
@@ -250,10 +279,10 @@ void AudioInputRendererHost::OnCreateStream(
     const AudioInputHostMsg_CreateStream_Config& config) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
-  DVLOG(1) << "AudioInputRendererHost@" << this
-           << "::OnCreateStream(stream_id=" << stream_id
-           << ", render_view_id=" << render_view_id
-           << ", session_id=" << session_id << ")";
+  std::ostringstream oss;
+  oss << "[stream_id=" << stream_id << "] "
+      << "AIRH::OnCreateStream(render_view_id=" << render_view_id
+      << ", session_id=" << session_id << ")";
   DCHECK_GT(render_view_id, 0);
 
   // media::AudioParameters is validated in the deserializer.
@@ -287,6 +316,7 @@ void AudioInputRendererHost::OnCreateStream(
 
     device_id = info->device.id;
     device_name = info->device.name;
+    oss << ": device_name=" << device_name;
   }
 
   // Create a new AudioEntry structure.
@@ -350,21 +380,24 @@ void AudioInputRendererHost::OnCreateStream(
 
   // Set the initial AGC state for the audio input stream. Note that, the AGC
   // is only supported in AUDIO_PCM_LOW_LATENCY mode.
-  if (config.params.format() == media::AudioParameters::AUDIO_PCM_LOW_LATENCY)
+  if (config.params.format() == media::AudioParameters::AUDIO_PCM_LOW_LATENCY) {
     entry->controller->SetAutomaticGainControl(config.automatic_gain_control);
+    oss << ", AGC=" << config.automatic_gain_control;
+  }
+
+  MediaStreamManager::SendMessageToNativeLog(oss.str());
+  DVLOG(1) << oss.str();
 
   // Since the controller was created successfully, create an entry and add it
   // to the map.
   entry->stream_id = stream_id;
   audio_entries_.insert(std::make_pair(stream_id, entry.release()));
-
-  MediaStreamManager::SendMessageToNativeLog(
-      "Audio input stream created successfully. Device name: " + device_name);
   audio_log_->OnCreated(stream_id, audio_params, device_id);
 }
 
 void AudioInputRendererHost::OnRecordStream(int stream_id) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  LogMessage(stream_id, "OnRecordStream", true);
 
   AudioEntry* entry = LookupById(stream_id);
   if (!entry) {
@@ -378,6 +411,7 @@ void AudioInputRendererHost::OnRecordStream(int stream_id) {
 
 void AudioInputRendererHost::OnCloseStream(int stream_id) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  LogMessage(stream_id, "OnCloseStream", true);
 
   AudioEntry* entry = LookupById(stream_id);
 
@@ -400,8 +434,10 @@ void AudioInputRendererHost::OnSetVolume(int stream_id, double volume) {
 
 void AudioInputRendererHost::SendErrorMessage(
     int stream_id, ErrorCode error_code) {
-  MediaStreamManager::SendMessageToNativeLog(
-      base::StringPrintf("AudioInputRendererHost error: %d", error_code));
+  std::string err_msg =
+      base::StringPrintf("SendErrorMessage(error_code=%d)", error_code);
+  LogMessage(stream_id, err_msg, true);
+
   Send(new AudioInputMsg_NotifyStreamStateChanged(
       stream_id, media::AudioInputIPCDelegate::kError));
 }
@@ -419,6 +455,7 @@ void AudioInputRendererHost::CloseAndDeleteStream(AudioEntry* entry) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   if (!entry->pending_close) {
+    LogMessage(entry->stream_id, "CloseAndDeleteStream", true);
     entry->controller->Close(base::Bind(&AudioInputRendererHost::DeleteEntry,
                                         this, entry));
     entry->pending_close = true;
@@ -428,6 +465,7 @@ void AudioInputRendererHost::CloseAndDeleteStream(AudioEntry* entry) {
 
 void AudioInputRendererHost::DeleteEntry(AudioEntry* entry) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  LogMessage(entry->stream_id, "DeleteEntry => stream is now closed", true);
 
   // Delete the entry when this method goes out of scope.
   scoped_ptr<AudioEntry> entry_deleter(entry);

content/browser/renderer_host/media/audio_input_sync_writer.cc

@@ -60,18 +60,20 @@ void AudioInputSyncWriter::Write(const media::AudioBus* data,
   if (last_write_time_.is_null()) {
     // This is the first time Write is called.
     base::TimeDelta interval = base::Time::Now() - creation_time_;
-    oss << "Audio input data received for the first time: delay = "
-        << interval.InMilliseconds() << "ms.";
+    oss << "AISW::Write => audio input data received for the first time: delay "
+           "= " << interval.InMilliseconds() << "ms";
 
   } else {
     base::TimeDelta interval = base::Time::Now() - last_write_time_;
     if (interval > kLogDelayThreadhold) {
-      oss << "Audio input data delay unexpectedly long: delay = "
-          << interval.InMilliseconds() << "ms.";
+      oss << "AISW::Write => audio input data delay unexpectedly long: delay = "
+          << interval.InMilliseconds() << "ms";
     }
   }
-  if (!oss.str().empty())
+  if (!oss.str().empty()) {
     MediaStreamManager::SendMessageToNativeLog(oss.str());
+    DVLOG(1) << oss.str();
+  }
 
   last_write_time_ = base::Time::Now();
 #endif

content/renderer/media/audio_input_message_filter.cc

@@ -12,12 +12,21 @@
 #include "ipc/ipc_logging.h"
 #include "ipc/ipc_sender.h"
 
-namespace content {
-
 namespace {
+
 const int kStreamIDNotSet = -1;
+
+void LogMessage(int stream_id, const std::string& msg) {
+  std::ostringstream oss;
+  oss << "[stream_id=" << stream_id << "] AIMF::" << msg;
+  content::WebRtcLogMessage(oss.str());
+  DVLOG(1) << oss.str();
 }
 
+}
+
+namespace content {
+
 class AudioInputMessageFilter::AudioInputIPCImpl
     : public NON_EXPORTED_BASE(media::AudioInputIPC) {
  public:
@@ -125,10 +134,7 @@ void AudioInputMessageFilter::OnStreamCreated(
     uint32 length,
     uint32 total_segments) {
   DCHECK(io_message_loop_->BelongsToCurrentThread());
-
-  WebRtcLogMessage(base::StringPrintf(
-      "AIMF::OnStreamCreated. stream_id=%d",
-      stream_id));
+  LogMessage(stream_id, "OnStreamCreated");
 
 #if !defined(OS_WIN)
   base::SyncSocket::Handle socket_handle = socket_descriptor.fd;
@@ -193,6 +199,9 @@ void AudioInputMessageFilter::AudioInputIPCImpl::CreateStream(
   DCHECK(delegate);
 
   stream_id_ = filter_->delegates_.Add(delegate);
+  // TODO(henrika): remove all LogMessage calls when we have sorted out the
+  // existing "no input audio" issues.
+  LogMessage(stream_id_, "CreateStream");
 
   AudioInputHostMsg_CreateStream_Config config;
   config.params = params;
@@ -204,6 +213,7 @@ void AudioInputMessageFilter::AudioInputIPCImpl::CreateStream(
 
 void AudioInputMessageFilter::AudioInputIPCImpl::RecordStream() {
   DCHECK_NE(stream_id_, kStreamIDNotSet);
+  LogMessage(stream_id_, "RecordStream");
   filter_->Send(new AudioInputHostMsg_RecordStream(stream_id_));
 }
 
@@ -215,6 +225,7 @@ void AudioInputMessageFilter::AudioInputIPCImpl::SetVolume(double volume) {
 void AudioInputMessageFilter::AudioInputIPCImpl::CloseStream() {
   DCHECK(filter_->io_message_loop_->BelongsToCurrentThread());
   DCHECK_NE(stream_id_, kStreamIDNotSet);
+  LogMessage(stream_id_, "CloseStream");
   filter_->Send(new AudioInputHostMsg_CloseStream(stream_id_));
   filter_->delegates_.Remove(stream_id_);
   stream_id_ = kStreamIDNotSet;

media/audio/audio_input_controller.cc

@@ -120,9 +120,13 @@ scoped_refptr<AudioInputController> AudioInputController::Create(
 
   // 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,
+                     base::Unretained(audio_manager),
+                     params,
+                     device_id))) {
     controller = NULL;
   }
 
@@ -151,9 +155,13 @@ scoped_refptr<AudioInputController> AudioInputController::CreateLowLatency(
 
   // 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::DoCreateForLowLatency, controller,
-                     base::Unretained(audio_manager), params, device_id))) {
+  if (!controller->task_runner_->PostTask(
+          FROM_HERE,
+          base::Bind(&AudioInputController::DoCreateForLowLatency,
+                     controller,
+                     base::Unretained(audio_manager),
+                     params,
+                     device_id))) {
     controller = NULL;
   }
 
@@ -220,12 +228,15 @@ void AudioInputController::DoCreate(AudioManager* audio_manager,
                                     const std::string& device_id) {
   DCHECK(task_runner_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioInputController.CreateTime");
+  if (handler_)
+    handler_->OnLog(this, "AIC::DoCreate");
 
 #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.
+  last_audio_level_log_time_ = base::TimeTicks::Now();
   audio_level_.reset(new media::AudioPowerMonitor(
       params.sample_rate(),
       TimeDelta::FromMilliseconds(kPowerMeasurementTimeConstantMilliseconds)));
@@ -315,6 +326,9 @@ void AudioInputController::DoRecord() {
     state_ = RECORDING;
   }
 
+  if (handler_)
+    handler_->OnLog(this, "AIC::DoRecord");
+
   if (no_data_timer_) {
     // Start the data timer. Once |kTimerResetIntervalSeconds| have passed,
     // a callback to FirstCheckForNoData() is made.
@@ -333,6 +347,9 @@ void AudioInputController::DoClose() {
   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();
 
@@ -400,6 +417,11 @@ void AudioInputController::FirstCheckForNoData() {
   LogCaptureStartupResult(GetDataIsActive() ?
                           CAPTURE_STARTUP_OK :
                           CAPTURE_STARTUP_NO_DATA_CALLBACK);
+  if (handler_) {
+    handler_->OnLog(this, GetDataIsActive() ?
+                    "AIC::FirstCheckForNoData => data is active" :
+                    "AIC::FirstCheckForNoData => data is NOT active");
+  }
   DoCheckForNoData();
 }
 

media/audio/audio_input_controller.h

@@ -272,7 +272,8 @@ class MEDIA_EXPORT AudioInputController
   virtual ~AudioInputController();
 
   // Methods called on the audio thread (owned by the AudioManager).
-  void DoCreate(AudioManager* audio_manager, const AudioParameters& params,
+  void DoCreate(AudioManager* audio_manager,
+                const AudioParameters& params,
                 const std::string& device_id);
   void DoCreateForLowLatency(AudioManager* audio_manager,
                              const AudioParameters& params,