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, 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 {
   AudioEntry();
   ~AudioEntry();
 
   // The AudioInputController that manages the audio input stream.
   scoped_refptr<media::AudioInputController> controller;
 
   // The audio input stream ID in the render view.
@@ skipping 94 matching lines @@
                                      this,
                                      make_scoped_refptr(controller),
                                      message));
 }
 
 void AudioInputRendererHost::DoCompleteCreation(
     media::AudioInputController* controller) {
   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.";
     DeleteEntryOnError(entry, INVALID_PEER_HANDLE);
     return;
   }
 
   if (!entry->controller->SharedMemoryAndSyncSocketMode()) {
     NOTREACHED() << "Only shared-memory/sync-socket mode is supported.";
     DeleteEntryOnError(entry, INVALID_LATENCY_MODE);
@@ skipping 21 matching lines @@
 #endif
 
   // If we failed to prepare the sync socket for the renderer then we fail
   // the construction of audio input stream.
   if (!writer->PrepareForeignSocketHandle(PeerHandle(),
                                           &foreign_socket_handle)) {
     DeleteEntryOnError(entry, SYNC_SOCKET_ERROR);
     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(),
       entry->shared_memory_segment_count));
 }
 
 void AudioInputRendererHost::DoSendRecordingMessage(
     media::AudioInputController* controller) {
   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);
 }
 
 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) {
   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_name=" << device_name;
   }
 
   // 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;
 
@@ skipping 43 matching lines @@
                                                       user_input_monitor_);
   }
 
   if (!entry->controller.get()) {
     SendErrorMessage(stream_id, STREAM_CREATE_ERROR);
     return;
   }
 
   // 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) {
     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 => stream is now closed", 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