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

content/browser/renderer_host/media/audio_input_renderer_host.cc

Index: content/browser/renderer_host/media/audio_input_renderer_host.cc
diff --git a/content/browser/renderer_host/media/audio_input_renderer_host.cc b/content/browser/renderer_host/media/audio_input_renderer_host.cc
index 87eed7eb3998716c185dec509fd3198c0676288b..540185dcca0b9331dbc790b57a1f9d6309088d18 100644
--- a/content/browser/renderer_host/media/audio_input_renderer_host.cc
+++ b/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;

[Henrik Grunell, 2014/08/29 13:32:21]

I'm not sure how this is supposed to be formatted. Seems like it will be
"[stream_id=1] AIRH::This is a log message."
Isn't the :: strange in this case? Maybe prefix "AIRH: "?

[henrika (OOO until Aug 14), 2014/08/29 14:05:14]

Good comment. Almost all messages starts with funcname, hence :: makes sense.
But there are some that does not. Will fix in separate CL.

+  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);