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

[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 {
   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;

[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);
 }
 
 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);

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

would we want to call SendMessageToNativeLog() in this case or below when/if
GetOpenedDeviceInfoById fails?

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

Yes, and we do since it is included in SendErrorMessage ;-)

     return;
   }
 
   media::AudioParameters audio_params(config.params);
   if (media_stream_manager_->audio_input_device_manager()->
       ShouldUseFakeDevice()) {
     audio_params.Reset(
         media::AudioParameters::AUDIO_FAKE,
         config.params.channel_layout(), config.params.channels(), 0,
         config.params.sample_rate(), config.params.bits_per_sample(),
         config.params.frames_per_buffer());
   }
 
   // Check if we have the permission to open the device and which device to use.
   std::string device_name;
   std::string device_id = media::AudioManagerBase::kDefaultDeviceId;
   if (audio_params.format() != media::AudioParameters::AUDIO_FAKE) {
     const StreamDeviceInfo* info = media_stream_manager_->
         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_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());
 
   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);
   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 =

[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));
 }
 
 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