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..fc27fe6a9262436d6b22d87a6140a2be8406583e 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) {

[tommi (sloooow) - chröme, 2014/08/26 11:42:30]

const &

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

Done.

+  std::string log_string =

[tommi (sloooow) - chröme, 2014/08/26 11:42:30]

instead of constructing strings and using StringPrintf, you could use a string
stream. That delays the construction of the string until it's actually needed.

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

[tommi (sloooow) - chröme, 2014/08/26 11:42:30]

Since this is a DVLOG, this whole function should only exist in debug builds.

[henrika (OOO until Aug 14), 2014/08/26 13:56:51]

Not sure if I understand. I want the add native WebRTC logging always but also
add a DVLOG for local debugging.

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

Discussed off-line. Seems like we are in phase on this one.

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

[tommi (sloooow) - chröme, 2014/08/26 11:42:30]

should this be considered an error case or is it expected?  If expected, can you
add a comment for when this happens?

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

Good comment. Old style that I've reused here. "Should not happen" but can
happen if the caller (AudioInputController) can't be found in the map which
contains all AICs this AIRH has created. Hence, call comes from a "bad AIC".

Same style can be found on ~8 different places.

Audio Output Renderer Host does:

AudioEntry* const entry = LookupById(stream_id);
  if (!entry)
    return;

Actually, it is not clear to me why this safety was added or if it is even
needed.  Let me give it a try.

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

[tommi (sloooow) - chröme, 2014/08/26 11:42:30]

is num_no_data_errors only used in debug builds?  If so, you could add a method
to AudioEntry that's empty in release builds but in debug builds does a few
different things:
- DCHECKs that the member variable is being touched on the correct thread.
- increments the member variable
- if > 5, log one thing, else log the other thing.

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

Thx, given where we are I decided to remove it. It was a "nice-to-have" thing
that improved reading of the logs but does not add any new information.

+    if (entry->num_no_data_errors > 5)
+      LogMessage(entry->stream_id, "AIC => stream looks dead", false);

[tommi (sloooow) - chröme, 2014/08/26 11:42:30]

what about logging num_no_data_errors?

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

see above

+    else
+      LogMessage(entry->stream_id, "AIC => NO_DATA_ERROR", false);
     return;
   }
 
-  AudioEntry* entry = LookupByController(controller);
-  if (!entry)
-    return;
+  const std::string err_msg =
+      base::StringPrintf("AIC reports error_code=%d", error_code);

[tommi (sloooow) - chröme, 2014/08/26 11:42:30]

this should be debug only

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

A similar log is used today in Release. Would like to keep since we do see it a
lot.

+  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_name=" << device_name;
   }
+  MediaStreamManager::SendMessageToNativeLog(oss.str());
+  DVLOG(1) << oss.str();

[tommi (sloooow) - chröme, 2014/08/26 11:42:30]

nit: don't think you need the |.str()| part

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

Done.

[henrika (OOO until Aug 14), 2014/08/27 14:26:00]

Actually we do. No log is printed otherwise.

 
   // 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);
   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 =

[tommi (sloooow) - chröme, 2014/08/26 11:42:30]

debug only

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

As discussed off-line. Plan was to keep as is since we need it for release as
well.

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