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 2dcc56d0918090e456ba0227cae5774e33bd947d..045ee8175d6d518e1aedc8ceab808ea78a95cfac 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,17 @@
 #include "media/audio/audio_manager_base.h"
 #include "media/base/audio_bus.h"
 
+namespace {
+void LogMessage(int stream_id, std::string msg, bool add_prefix) {
+  std::string log_string =
+      add_prefix ? base::StringPrintf("[stream_id=%d] AIRH::", stream_id)
+                 : base::StringPrintf("[stream_id=%d] ", stream_id);
+  log_string += msg;
+  content::MediaStreamManager::SendMessageToNativeLog(log_string);
+  DVLOG(1) << log_string;
+}
+}
+
 namespace content {
 
 struct AudioInputRendererHost::AudioEntry {
@@ -42,12 +53,16 @@ struct AudioInputRendererHost::AudioEntry {
 
   // Set to true after we called Close() for the controller.
   bool pending_close;
+
+  // Counts number of NO_DATA_ERROR calls for this stream.
+  int num_no_data_errors;
 };
 
 AudioInputRendererHost::AudioEntry::AudioEntry()
     : stream_id(0),
       shared_memory_segment_count(0),
-      pending_close(false) {
+      pending_close(false),
+      num_no_data_errors(0) {
 }
 
 AudioInputRendererHost::AudioEntry::~AudioEntry() {}
@@ -193,23 +208,28 @@ 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)
+    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.
+    entry->num_no_data_errors++;
+    if (entry->num_no_data_errors > 5)
+      LogMessage(entry->stream_id, "AIC => stream looks dead", false);
+    else
+      LogMessage(entry->stream_id, "AIC => NO_DATA_ERROR", false);
     return;
   }
 
-  AudioEntry* entry = LookupByController(controller);
-  if (!entry)
-    return;
+  std::string err_msg =

[no longer working on chromium, 2014/08/26 08:38:08]

nit const std::string

[henrika (OOO until Aug 14), 2014/08/26 10:30:10]

Done.

+      base::StringPrintf("AIC reports error_code=%d", error_code);
+  LogMessage(entry->stream_id, err_msg, false);
 
   audio_log_->OnError(entry->stream_id);
   DeleteEntryOnError(entry, AUDIO_INPUT_CONTROLLER_ERROR);
@@ -223,11 +243,7 @@ void AudioInputRendererHost::DoLog(media::AudioInputController* controller,
     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 +266,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,7 +303,10 @@ void AudioInputRendererHost::OnCreateStream(
 
     device_id = info->device.id;
     device_name = info->device.name;
+    oss << ": device_id=" << device_id << ", device_name=" << device_name;

[no longer working on chromium, 2014/08/26 08:38:08]

 privacy concern.

[henrika (OOO until Aug 14), 2014/08/26 10:30:10]

Removed device_id.

   }
+  MediaStreamManager::SendMessageToNativeLog(oss.str());
+  DVLOG(1) << oss.str();
 
   // Create a new AudioEntry structure.
   scoped_ptr<AudioEntry> entry(new AudioEntry());
@@ -357,14 +376,12 @@ void AudioInputRendererHost::OnCreateStream(
   // 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);

[no longer working on chromium, 2014/08/26 08:38:08]

If we don't have any problem with the existing logging, I suggest not remove it.
Other people might have been using this "Audio input stream created
successfully" logging to determine if the stream is created successfully,
removing it will confuse other people since different version of chrome will
give different loggings.

[henrika (OOO until Aug 14), 2014/08/26 10:30:10]

I think we need an improved way of reading the error log where the new way
allows for filtering. The new log will still contain this info, just in a new
format. Hope that is OK.

[no longer working on chromium, 2014/08/26 10:54:50]

To be clear, the new log will still contain the string as:
Audio input stream created successfully. Device name: xxxxx

If so, then it is fine. otherwise I will highly suggest keeping the existing
log, so that we won't surprise the ML team.

   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 +395,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 +418,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 +439,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 +449,7 @@ void AudioInputRendererHost::CloseAndDeleteStream(AudioEntry* entry) {
 
 void AudioInputRendererHost::DeleteEntry(AudioEntry* entry) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  LogMessage(entry->stream_id, "DeleteEntry", true);
 
   // Delete the entry when this method goes out of scope.
   scoped_ptr<AudioEntry> entry_deleter(entry);