Improves logs for rendering of remote WebRTC media streams

Adds more details related to audio output device authorization
(required e.g. when a device is switched, or SetSinkId is called).

Example of new log output: https://paste.googleplex.com/4803560074117120
Added tag(s): RFAOSF

See https://chromium-review.googlesource.com/c/chromium/src/+/2093443
for related work.

Bug: 1017219, b/152054751
Change-Id: I568a3d02f41599dc3e564682761e602592048f2b
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2340908Reviewed-by: Guido Urdaneta <guidou@chromium.org>
Commit-Queue: Henrik Andreasson <henrika@chromium.org>
Cr-Commit-Position: refs/heads/master@{#795480}

content/browser/renderer_host/media/render_frame_audio_output_stream_factory.cc

@@ -4,6 +4,7 @@
 
 #include "content/browser/renderer_host/media/render_frame_audio_output_stream_factory.h"
 
+#include <inttypes.h>
 #include <cstdint>
 #include <string>
 #include <utility>
@@ -16,6 +17,7 @@
 #include "base/location.h"
 #include "base/memory/weak_ptr.h"
 #include "base/optional.h"
+#include "base/strings/stringprintf.h"
 #include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
 #include "base/unguessable_token.h"
@@ -33,6 +35,25 @@
 
 namespace content {
 
+namespace {
+
+const char* OutputDeviceStatusToString(media::OutputDeviceStatus status) {
+  switch (status) {
+    case media::OUTPUT_DEVICE_STATUS_OK:
+      return "OK";
+    case media::OUTPUT_DEVICE_STATUS_ERROR_NOT_FOUND:
+      return "ERROR_NOT_FOUND";
+    case media::OUTPUT_DEVICE_STATUS_ERROR_NOT_AUTHORIZED:
+      return "ERROR_NOT_AUTHORIZED";
+    case media::OUTPUT_DEVICE_STATUS_ERROR_TIMED_OUT:
+      return "ERROR_TIMED_OUT";
+    case media::OUTPUT_DEVICE_STATUS_ERROR_INTERNAL:
+      return "ERROR_INTERNAL";
+  }
+}
+
+}  // namespace
+
 class RenderFrameAudioOutputStreamFactory::Core final
     : public blink::mojom::RendererAudioOutputStreamFactory {
  public:
@@ -135,6 +156,9 @@ class RenderFrameAudioOutputStreamFactory::Core final
 
   void DeleteProvider(media::mojom::AudioOutputStreamProvider* stream_provider);
 
+  // Helper method for storing native logs.
+  void SendLogMessage(const std::string& message) const;
+
   const int process_id_;
   const int frame_id_;
   AudioOutputAuthorizationHandler authorization_handler_;
@@ -202,6 +226,7 @@ RenderFrameAudioOutputStreamFactory::Core::Core(
       frame_id_(frame->GetRoutingID()),
       authorization_handler_(audio_system, media_stream_manager, process_id_) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
+  SendLogMessage(base::StringPrintf("%s()", __func__));
 
   ForwardingAudioStreamFactory::Core* tmp_factory =
       ForwardingAudioStreamFactory::CoreForFrame(frame);
@@ -248,6 +273,8 @@ void RenderFrameAudioOutputStreamFactory::Core::RequestDeviceAuthorization(
       "RenderFrameAudioOutputStreamFactory::RequestDeviceAuthorization",
       "device id", device_id, "session_id",
       session_id.value_or(base::UnguessableToken()).ToString());
+  SendLogMessage(
+      base::StringPrintf("%s({device_id=%s})", __func__, device_id.c_str()));
 
   const base::TimeTicks auth_start_time = base::TimeTicks::Now();
 
@@ -274,6 +301,13 @@ void RenderFrameAudioOutputStreamFactory::Core::AuthorizationCompleted(
   TRACE_EVENT2("audio",
                "RenderFrameAudioOutputStreamFactory::AuthorizationCompleted",
                "raw device id", raw_device_id, "status", status);
+  SendLogMessage(base::StringPrintf(
+      "%s({status=%s}, {params=%s}, {device_id=%s})", __func__,
+      OutputDeviceStatusToString(status),
+      params.AsHumanReadableString().c_str(), raw_device_id.c_str()));
+  SendLogMessage(base::StringPrintf(
+      "%s => (authorization time=%" PRId64 " ms)", __func__,
+      (base::TimeTicks::Now() - auth_start_time).InMilliseconds()));
 
   AudioOutputAuthorizationHandler::UMALogDeviceAuthorizationTime(
       auth_start_time);
@@ -285,6 +319,9 @@ void RenderFrameAudioOutputStreamFactory::Core::AuthorizationCompleted(
   if (status == media::OUTPUT_DEVICE_STATUS_OK) {
     stream_providers_.insert(std::make_unique<ProviderImpl>(
         std::move(receiver), this, std::move(raw_device_id)));
+  } else {
+    SendLogMessage(base::StringPrintf("%s => (ERROR: %s)", __func__,
+                                      OutputDeviceStatusToString(status)));
   }
 }
 
@@ -295,4 +332,12 @@ void RenderFrameAudioOutputStreamFactory::Core::DeleteProvider(
   DCHECK_EQ(1u, deleted);
 }
 
+void RenderFrameAudioOutputStreamFactory::Core::SendLogMessage(
+    const std::string& message) const {
+  MediaStreamManager::SendMessageToNativeLog(
+      "RFAOSF::" + message +
+      base::StringPrintf(" [process_id=%d, frame_id=%d]", process_id_,
+                         frame_id_));
+}
+
 }  // namespace content

third_party/blink/renderer/modules/mediastream/media_stream_renderer_factory.cc

@@ -42,7 +42,7 @@ base::UnguessableToken GetSessionIdForWebRtcAudioRenderer() {
 }
 
 void SendLogMessage(const WTF::String& message) {
-  WebRtcLogMessage("MSRFI::" + message.Utf8());
+  WebRtcLogMessage("MSRF::" + message.Utf8());
 }
 
 }  // namespace

third_party/blink/renderer/modules/mediastream/webmediaplayer_ms.cc

@@ -351,9 +351,10 @@ WebMediaPlayerMS::WebMediaPlayerMS(
   DCHECK(delegate_);
   weak_this_ = weak_factory_.GetWeakPtr();
   delegate_id_ = delegate_->AddObserver(this);
-  SendLogMessage(String::Format("%s({delegate_id=%d}, {is_audio_element=%s})",
-                                __func__, delegate_id_,
-                                client->IsAudioElement() ? "true" : "false"));
+  SendLogMessage(String::Format(
+      "%s({delegate_id=%d}, {is_audio_element=%s}, {sink_id=%s})", __func__,
+      delegate_id_, client->IsAudioElement() ? "true" : "false",
+      sink_id.Utf8().c_str()));
 
   // TODO(tmathmeyer) WebMediaPlayerImpl gets the URL from the WebLocalFrame.
   // doing that here causes a nullptr deref.
@@ -362,6 +363,8 @@ WebMediaPlayerMS::WebMediaPlayerMS(
 
 WebMediaPlayerMS::~WebMediaPlayerMS() {
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
+  SendLogMessage(
+      String::Format("%s() [delegate_id=%d]", __func__, delegate_id_));
 
   if (!web_stream_.IsNull())
     web_stream_.RemoveObserver(this);

third_party/blink/renderer/modules/webrtc/webrtc_audio_device_impl.cc

@@ -360,6 +360,8 @@ bool WebRtcAudioDeviceImpl::SetAudioRenderer(
     blink::WebRtcAudioRenderer* renderer) {
   DCHECK_CALLED_ON_VALID_THREAD(main_thread_checker_);
   DCHECK(renderer);
+  SendLogMessage(base::StringPrintf("%s() [id=%s]", __func__,
+                                    GetAudioProcessingId().ToString().c_str()));
 
   // Here we acquire |lock_| in order to protect the internal state.
   {

third_party/blink/renderer/modules/webrtc/webrtc_audio_renderer.cc

@@ -529,6 +529,7 @@ void WebRtcAudioRenderer::Stop() {
 void WebRtcAudioRenderer::SetVolume(float volume) {
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
   DCHECK(volume >= 0.0f && volume <= 1.0f);
+  SendLogMessage(String::Format("%s({volume=%.2f})", __func__, volume));
 
   playing_state_.set_volume(volume);
   OnPlayStateChanged(media_stream_descriptor_, &playing_state_);
@@ -772,6 +773,8 @@ bool WebRtcAudioRenderer::AddPlayingState(webrtc::AudioSourceInterface* source,
     return false;
 
   array.push_back(state);
+  SendLogMessage(String::Format("%s => (number of playing audio sources=%d)",
+                                __func__, static_cast<int>(array.size())));
 
   return true;
 }
@@ -849,6 +852,7 @@ void WebRtcAudioRenderer::OnPlayStateRemoved(PlayingState* state) {
 
 void WebRtcAudioRenderer::PrepareSink() {
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
+  SendLogMessage(String::Format("%s()", __func__));
   media::AudioParameters new_sink_params;
   {
     base::AutoLock lock(lock_);