[Media Router]Add native logs in MirroringActivity

This CL uses the native logger to log WebRTC messages between the
mirroring service and mirroring receiver.
AES related data will be scrubbed before sent to the logger.

Bug: b/170651376, 1117673
Change-Id: I4e72edc715d8f56b6ac7f3c3353dae1d119e8d10
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2533118
Commit-Queue: Muyao Xu <muyaoxu@google.com>
Reviewed-by: Takumi Fujimoto <takumif@chromium.org>
Cr-Commit-Position: refs/heads/master@{#828439}

chrome/browser/media/router/providers/cast/mirroring_activity.cc

@@ -16,6 +16,7 @@
 #include "base/metrics/user_metrics.h"
 #include "base/metrics/user_metrics_action.h"
 #include "base/optional.h"
+#include "base/strings/strcat.h"
 #include "base/values.h"
 #include "chrome/browser/media/router/data_decoder_util.h"
 #include "chrome/browser/media/router/providers/cast/cast_activity_manager.h"
@@ -62,6 +63,8 @@ constexpr char kHistogramStartFailureNative[] =
 constexpr char kHistogramStartSuccess[] =
     "MediaRouter.CastStreaming.Start.Success";
 
+constexpr char kLoggerComponent[] = "MirroringService";
+
 using MirroringType = MirroringActivity::MirroringType;
 
 const std::string GetMirroringNamespace(const base::Value& message) {
@@ -196,6 +199,7 @@ void MirroringActivity::CreateMojoBindings(mojom::MediaRouter* media_router) {
           host_.BindNewPipeAndPassReceiver());
       break;
   }
+  media_router->GetLogger(logger_.BindNewPipeAndPassReceiver());
 
   DCHECK(!channel_to_service_receiver_);
   channel_to_service_receiver_ =
@@ -265,6 +269,16 @@ void MirroringActivity::OnAppMessage(
   DCHECK(message.has_payload_utf8());
   DCHECK_EQ(message.protocol_version(),
             cast::channel::CastMessage_ProtocolVersion_CASTV2_1_0);
+  if (message.namespace_() == mirroring::mojom::kWebRtcNamespace) {
+    CastSession* session = GetSession();
+    logger_->LogInfo(media_router::mojom::LogCategory::kMirroring,
+                     kLoggerComponent,
+                     base::StrCat({"Relaying app message from receiver:",
+                                   message.payload_utf8()}),
+                     route().media_sink_id(), route().media_source().id(),
+                     session ? session->session_id() : "");
+  }
+
   mirroring::mojom::CastMessagePtr ptr = mirroring::mojom::CastMessage::New();
   ptr->message_namespace = message.namespace_();
   ptr->json_format_data = message.payload_utf8();
@@ -281,6 +295,15 @@ void MirroringActivity::OnInternalMessage(
   mirroring::mojom::CastMessagePtr ptr = mirroring::mojom::CastMessage::New();
   ptr->message_namespace = message.message_namespace;
   CHECK(base::JSONWriter::Write(message.message, &ptr->json_format_data));
+  if (message.message_namespace == mirroring::mojom::kWebRtcNamespace) {
+    CastSession* session = GetSession();
+    logger_->LogInfo(
+        media_router::mojom::LogCategory::kMirroring, kLoggerComponent,
+        base::StrCat({"Relaying internal WebRTC message from receiver: ",
+                      ptr->json_format_data}),
+        route().media_sink_id(), route().media_source().id(),
+        session ? session->session_id() : "");
+  }
   channel_to_service_->Send(std::move(ptr));
 }
 
@@ -291,17 +314,28 @@ void MirroringActivity::CreateMediaController(
 void MirroringActivity::HandleParseJsonResult(
     const std::string& route_id,
     data_decoder::DataDecoder::ValueOrError result) {
+  CastSession* session = GetSession();
+  DCHECK(session);
+
   if (!result.value) {
     // TODO(crbug.com/905002): Record UMA metric for parse result.
-    DLOG(ERROR) << "Failed to parse Cast client message for " << route_id
-                << ": " << *result.error;
+    logger_->LogError(
+        media_router::mojom::LogCategory::kMirroring, kLoggerComponent,
+        base::StrCat({"Failed to parse Cast client message:", *result.error}),
+        route().media_sink_id(), route().media_source().id(),
+        session->session_id());
     return;
   }
 
-  CastSession* session = GetSession();
-  DCHECK(session);
-
   const std::string message_namespace = GetMirroringNamespace(*result.value);
+  if (message_namespace == mirroring::mojom::kWebRtcNamespace) {
+    logger_->LogInfo(media_router::mojom::LogCategory::kMirroring,
+                     kLoggerComponent,
+                     base::StrCat({"WebRTC message received: ",
+                                   GetScrubbedLogMessage(*result.value)}),
+                     route().media_sink_id(), route().media_source().id(),
+                     session->session_id());
+  }
 
   cast::channel::CastMessage cast_message = cast_channel::CreateCastMessage(
       message_namespace, std::move(*result.value),
@@ -356,4 +390,26 @@ void MirroringActivity::StopMirroring() {
     std::move(on_stop_).Run();
 }
 
+std::string MirroringActivity::GetScrubbedLogMessage(
+    const base::Value& message) {
+  std::string message_str;
+  auto scrubbed_message = message.Clone();
+  auto* streams = scrubbed_message.FindPath("offer.supportedStreams");
+  if (!streams || !streams->is_list()) {
+    base::JSONWriter::Write(scrubbed_message, &message_str);
+    return message_str;
+  }
+
+  for (base::Value& item : streams->GetList()) {
+    if (item.FindStringKey("aesKey")) {
+      item.SetStringKey("aesKey", "AES_KEY");
+    }
+    if (item.FindStringKey("aesIvMask")) {
+      item.SetStringKey("aesIvMask", "AES_IV_MASK");
+    }
+  }
+  base::JSONWriter::Write(scrubbed_message, &message_str);
+  return message_str;
+}
+
 }  // namespace media_router

chrome/browser/media/router/providers/cast/mirroring_activity.h

@@ -75,11 +75,16 @@ class MirroringActivity : public CastActivity,
       mojo::PendingRemote<mojom::MediaStatusObserver> observer) override;
 
  private:
+  FRIEND_TEST_ALL_PREFIXES(MirroringActivityTest, GetScrubbedLogMessage);
+
   void HandleParseJsonResult(const std::string& route_id,
                              data_decoder::DataDecoder::ValueOrError result);
 
   void StopMirroring();
 
+  // Scrubs AES related data in messages with type "OFFER".
+  static std::string GetScrubbedLogMessage(const base::Value& message);
+
   mojo::Remote<mirroring::mojom::MirroringServiceHost> host_;
 
   // Sends Cast messages from the mirroring receiver to the mirroring service.
@@ -90,6 +95,12 @@ class MirroringActivity : public CastActivity,
   mojo::PendingReceiver<mirroring::mojom::CastMessageChannel>
       channel_to_service_receiver_;
 
+  // Remote to the logger owned by the Media Router. Used to log WebRTC messages
+  // sent between the mirroring service and mirroring receiver.
+  // |logger_| should be bound before the CastMessageChannel message pipe is
+  // created.
+  mojo::Remote<mojom::Logger> logger_;
+
   mojo::Receiver<mirroring::mojom::SessionObserver> observer_receiver_{this};
 
   // To handle Cast messages from the mirroring service to the mirroring

chrome/browser/media/router/providers/cast/mirroring_activity_unittest.cc

@@ -4,6 +4,8 @@
 
 #include "chrome/browser/media/router/providers/cast/mirroring_activity.h"
 
+#include "base/json/json_reader.h"
+#include "base/json/json_writer.h"
 #include "base/test/bind.h"
 #include "base/test/metrics/histogram_tester.h"
 #include "base/test/mock_callback.h"
@@ -329,4 +331,45 @@ TEST_F(MirroringActivityTest, OnInternalMessage) {
       base::test::ParseJson(kPayload)));
 }
 
+TEST_F(MirroringActivityTest, GetScrubbedLogMessage) {
+  static constexpr char message[] = R"(
+    {
+      "offer": {
+        "supportedStreams": [
+          {
+            "aesIvMask": "Mask_A",
+            "aesKey": "Key_A"
+          },
+          {
+            "aesIvMask": "Mask_B",
+            "aesKey": "Key_B"
+          }
+        ]
+      },
+      "type": "OFFER"
+    })";
+  static constexpr char scrubbed_message[] = R"(
+    {
+      "offer": {
+        "supportedStreams": [
+          {
+            "aesIvMask": "AES_IV_MASK",
+            "aesKey": "AES_KEY"
+          },
+          {
+            "aesIvMask": "AES_IV_MASK",
+            "aesKey": "AES_KEY"
+          }
+        ]
+      },
+      "type": "OFFER"
+    })";
+
+  base::Optional<base::Value> message_json = base::JSONReader::Read(message);
+  EXPECT_TRUE(message_json);
+  EXPECT_THAT(scrubbed_message,
+              base::test::IsJson(MirroringActivity::GetScrubbedLogMessage(
+                  message_json.value())));
+}
+
 }  // namespace media_router