Extends native logs with details about audio devices

Creates log sequences where we can track that audio input devices
are opened and closed correctly and what parameters are used.

Example (grep for AIDM):

AIDM::Open({session_id=45CE96DFC9576CDABE2524A89B6E5ADE}, {device=[type: DEVICE_AUDIO_CAPTURE, id: default, group_id: input, name: Default, parameters: [format: 4, channel_layout: 3, channels: 2, sample_rate: 44100, frames_per_buffer: 441, effects: 0, mic_positions: ]]})
AIDM::Opened({session_id=45CE96DFC9576CDABE2524A89B6E5ADE})
AIDM::Close({session_id=45CE96DFC9576CDABE2524A89B6E5ADE})
AIDM::Closed({session_id=45CE96DFC9576CDABE2524A89B6E5ADE})

No-Try: True
Bug: 1017219
Change-Id: Iad328af521f2d95d1a0d1893c23d1bc79928b22e
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1899872
Auto-Submit: Henrik Andreasson <henrika@chromium.org>
Reviewed-by: Guido Urdaneta <guidou@chromium.org>
Commit-Queue: Henrik Andreasson <henrika@chromium.org>
Cr-Commit-Position: refs/heads/master@{#720216}

content/browser/renderer_host/media/audio_input_device_manager.cc

@@ -11,8 +11,10 @@
 #include "base/callback.h"
 #include "base/command_line.h"
 #include "base/metrics/histogram_macros.h"
+#include "base/strings/stringprintf.h"
 #include "base/task/post_task.h"
 #include "build/build_config.h"
+#include "content/browser/renderer_host/media/media_stream_manager.h"
 #include "content/public/browser/browser_task_traits.h"
 #include "content/public/browser/browser_thread.h"
 #include "media/audio/audio_input_ipc.h"
@@ -21,6 +23,7 @@
 #include "media/base/channel_layout.h"
 #include "media/base/media_switches.h"
 #include "third_party/blink/public/common/mediastream/media_stream_request.h"
+#include "third_party/blink/public/mojom/mediastream/media_stream.mojom-shared.h"
 
 #if defined(OS_CHROMEOS)
 #include "chromeos/audio/cras_audio_handler.h"
@@ -37,6 +40,50 @@ void SetKeyboardMicStreamActiveOnUIThread(bool active) {
 }
 #endif
 
+void SendAudioLogMessage(const std::string& message) {
+  MediaStreamManager::SendMessageToNativeLog("AIDM::" + message);
+}
+
+const char* TypeToString(blink::mojom::MediaStreamType type) {
+  DCHECK(blink::IsAudioInputMediaType(type));
+  switch (type) {
+    case blink::mojom::MediaStreamType::DEVICE_AUDIO_CAPTURE:
+      return "DEVICE_AUDIO_CAPTURE";
+    case blink::mojom::MediaStreamType::GUM_TAB_AUDIO_CAPTURE:
+      return "GUM_TAB_AUDIO_CAPTURE";
+    case blink::mojom::MediaStreamType::GUM_DESKTOP_AUDIO_CAPTURE:
+      return "GUM_DESKTOP_AUDIO_CAPTURE";
+    case blink::mojom::MediaStreamType::DISPLAY_AUDIO_CAPTURE:
+      return "DISPLAY_AUDIO_CAPTURE";
+    default:
+      NOTREACHED();
+  }
+  return "INVALID";
+}
+
+std::string GetOpenLogString(const base::UnguessableToken& session_id,
+                             const blink::MediaStreamDevice& device) {
+  std::string str = base::StringPrintf("Open({session_id=%s}, ",
+                                       session_id.ToString().c_str());
+  base::StringAppendF(&str, "{device=[type: %s, ", TypeToString(device.type));
+  base::StringAppendF(&str, "id: %s, ", device.id.c_str());
+  if (device.group_id.has_value()) {
+    base::StringAppendF(&str, "group_id: %s, ",
+                        device.group_id.value().c_str());
+  }
+  if (device.matched_output_device_id.has_value()) {
+    base::StringAppendF(&str, "matched_output_device_id: %s, ",
+                        device.matched_output_device_id.value().c_str());
+  }
+  base::StringAppendF(&str, "name: %s", device.name.c_str());
+  if (blink::IsAudioInputMediaType(device.type)) {
+    base::StringAppendF(&str, ", parameters: [%s",
+                        device.input.AsHumanReadableString().c_str());
+  }
+  str += "]]})";
+  return str;
+}
+
 }  // namespace
 
 AudioInputDeviceManager::AudioInputDeviceManager(
@@ -80,6 +127,7 @@ base::UnguessableToken AudioInputDeviceManager::Open(
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
   // Generate a new id for this device.
   auto session_id = base::UnguessableToken::Create();
+  SendAudioLogMessage(GetOpenLogString(session_id, device));
 
   // base::Unretained(this) is safe, because AudioInputDeviceManager is
   // destroyed not earlier than on the IO message loop destruction.
@@ -113,6 +161,7 @@ base::UnguessableToken AudioInputDeviceManager::Open(
 
 void AudioInputDeviceManager::Close(const base::UnguessableToken& session_id) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  SendAudioLogMessage("Close({session_id=" + session_id.ToString() + "})");
   auto device = GetDevice(session_id);
   if (device == devices_.end())
     return;
@@ -193,6 +242,7 @@ void AudioInputDeviceManager::OpenedOnIOThread(
 
   UMA_HISTOGRAM_TIMES("Media.AudioInputDeviceManager.OpenOnDeviceThreadTime",
                       base::TimeTicks::Now() - start_time);
+  SendAudioLogMessage("Opened({session_id=" + session_id.ToString() + "})");
 
   blink::MediaStreamDevice media_stream_device(device.type, device.id,
                                                device.name);
@@ -213,6 +263,7 @@ void AudioInputDeviceManager::ClosedOnIOThread(
     blink::mojom::MediaStreamType stream_type,
     const base::UnguessableToken& session_id) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  SendAudioLogMessage("Closed({session_id=" + session_id.ToString() + "})");
   for (auto& listener : listeners_)
     listener.Closed(stream_type, session_id);
 }

content/browser/renderer_host/media/media_devices_manager.cc

@@ -63,13 +63,27 @@ struct {
 // Frame rates for sources with no support for capability enumeration.
 const uint16_t kFallbackVideoFrameRates[] = {30, 60};
 
+const char* DeviceTypeToString(blink::MediaDeviceType device_type) {
+  switch (device_type) {
+    case blink::MEDIA_DEVICE_TYPE_AUDIO_INPUT:
+      return "AUDIO_INPUT";
+    case blink::MEDIA_DEVICE_TYPE_VIDEO_INPUT:
+      return "VIDEO_INPUT";
+    case blink::MEDIA_DEVICE_TYPE_AUDIO_OUTPUT:
+      return "AUDIO_OUTPUT";
+    default:
+      NOTREACHED();
+  }
+  return "UNKNOWN";
+}
+
 // Private helper method to generate a string for the log message that lists the
 // human readable names of |devices|.
 std::string GetLogMessageString(
     blink::MediaDeviceType device_type,
     const blink::WebMediaDeviceInfoArray& device_infos) {
-  std::string output_string =
-      base::StringPrintf("Getting devices of type %d:\n", device_type);
+  std::string output_string = base::StringPrintf(
+      "Getting devices of type %s:\n", DeviceTypeToString(device_type));
   if (device_infos.empty())
     return output_string + "No devices found.";
   for (const auto& device_info : device_infos)

content/browser/renderer_host/media/media_stream_manager.cc

@@ -486,6 +486,7 @@ class MediaStreamManager::DeviceRequest {
 
 // static
 void MediaStreamManager::SendMessageToNativeLog(const std::string& message) {
+  DVLOG(1) << message;
   if (!BrowserThread::CurrentlyOn(BrowserThread::IO)) {
     base::PostTask(
         FROM_HERE, {BrowserThread::IO},