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

content/browser/renderer_host/media/audio_input_renderer_host.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 "content/browser/renderer_host/media/audio_input_renderer_host.h"
 
 #include "base/bind.h"
 #include "base/memory/shared_memory.h"
 #include "base/metrics/histogram.h"
 #include "base/numerics/safe_math.h"
 #include "base/process/process.h"
 #include "base/strings/stringprintf.h"
 #include "content/browser/media/capture/web_contents_audio_input_stream.h"
 #include "content/browser/media/capture/web_contents_capture_util.h"
 #include "content/browser/media/media_internals.h"
 #include "content/browser/renderer_host/media/audio_input_device_manager.h"
 #include "content/browser/renderer_host/media/audio_input_sync_writer.h"
 #include "content/browser/renderer_host/media/media_stream_manager.h"
 #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 {
   AudioEntry();
   ~AudioEntry();
 
   // The AudioInputController that manages the audio input stream.
   scoped_refptr<media::AudioInputController> controller;
 
   // The audio input stream ID in the render view.
   int stream_id;
 
   // Shared memory for transmission of the audio data. It has
   // |shared_memory_segment_count| equal lengthed segments.
   base::SharedMemory shared_memory;
   int shared_memory_segment_count;
 
   // The synchronous writer to be used by the controller. We have the
   // ownership of the writer.
   scoped_ptr<media::AudioInputController::SyncWriter> writer;
 
   // 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() {}
 
 AudioInputRendererHost::AudioInputRendererHost(
     media::AudioManager* audio_manager,
     MediaStreamManager* media_stream_manager,
     AudioMirroringManager* audio_mirroring_manager,
     media::UserInputMonitor* user_input_monitor)
     : BrowserMessageFilter(AudioMsgStart),
@@ skipping 125 matching lines @@
     media::AudioInputController* controller) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
   // TODO(henrika): See crbug.com/115262 for details on why this method
   // should be implemented.
 }
 
 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);
 }
 
 void AudioInputRendererHost::DoLog(media::AudioInputController* controller,
                                    const std::string& message) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
   AudioEntry* entry = LookupByController(controller);
   if (!entry)
     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) {
   bool handled = true;
   IPC_BEGIN_MESSAGE_MAP(AudioInputRendererHost, message)
     IPC_MESSAGE_HANDLER(AudioInputHostMsg_CreateStream, OnCreateStream)
     IPC_MESSAGE_HANDLER(AudioInputHostMsg_RecordStream, OnRecordStream)
     IPC_MESSAGE_HANDLER(AudioInputHostMsg_CloseStream, OnCloseStream)
     IPC_MESSAGE_HANDLER(AudioInputHostMsg_SetVolume, OnSetVolume)
     IPC_MESSAGE_UNHANDLED(handled = false)
   IPC_END_MESSAGE_MAP()
 
   return handled;
 }
 
 void AudioInputRendererHost::OnCreateStream(
     int stream_id,
     int render_view_id,
     int session_id,
     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.
   if (LookupById(stream_id) != NULL) {
     SendErrorMessage(stream_id, STREAM_ALREADY_EXISTS);
     return;
   }
 
   media::AudioParameters audio_params(config.params);
   if (media_stream_manager_->audio_input_device_manager()->
@@ skipping 13 matching lines @@
         audio_input_device_manager()->GetOpenedDeviceInfoById(session_id);
     if (!info) {
       SendErrorMessage(stream_id, PERMISSION_DENIED);
       DLOG(WARNING) << "No permission has been granted to input stream with "
                     << "session_id=" << session_id;
       return;
     }
 
     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());
 
   const uint32 segment_size =
       (sizeof(media::AudioInputBufferParameters) +
        media::AudioBus::CalculateMemorySize(audio_params));
   entry->shared_memory_segment_count = config.shared_memory_count;
 
   // Create the shared memory and share it with the renderer process
@@ skipping 49 matching lines @@
 
   // 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)
     entry->controller->SetAutomaticGainControl(config.automatic_gain_control);
 
   // 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);

[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) {
     SendErrorMessage(stream_id, INVALID_AUDIO_ENTRY);
     return;
   }
 
   entry->controller->Record();
   audio_log_->OnStarted(stream_id);
 }
 
 void AudioInputRendererHost::OnCloseStream(int stream_id) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  LogMessage(stream_id, "OnCloseStream", true);
 
   AudioEntry* entry = LookupById(stream_id);
 
   if (entry)
     CloseAndDeleteStream(entry);
 }
 
 void AudioInputRendererHost::OnSetVolume(int stream_id, double volume) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   AudioEntry* entry = LookupById(stream_id);
   if (!entry) {
     SendErrorMessage(stream_id, INVALID_AUDIO_ENTRY);
     return;
   }
 
   entry->controller->SetVolume(volume);
   audio_log_->OnSetVolume(stream_id, 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));
 }
 
 void AudioInputRendererHost::DeleteEntries() {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   for (AudioEntryMap::iterator i = audio_entries_.begin();
        i != audio_entries_.end(); ++i) {
     CloseAndDeleteStream(i->second);
   }
 }
 
 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;
     audio_log_->OnClosed(entry->stream_id);
   }
 }
 
 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);
 
   // Erase the entry from the map.
   audio_entries_.erase(entry->stream_id);
 }
 
 void AudioInputRendererHost::DeleteEntryOnError(AudioEntry* entry,
     ErrorCode error_code) {
@@ skipping 23 matching lines @@
   // TODO(hclam): Implement a faster look up method.
   for (AudioEntryMap::iterator i = audio_entries_.begin();
        i != audio_entries_.end(); ++i) {
     if (controller == i->second->controller.get())
       return i->second;
   }
   return NULL;
 }
 
 }  // namespace content