[Media Router] Add AppAvailability Logs

This CL adds a mojo::Remote<mojom::Logger> in CastAppDiscoveryService to
log unavailable (app_id, sink_id) pairs and socket not found errors.

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

chrome/browser/media/router/mojo/media_router_desktop_unittest.cc

@@ -72,9 +72,11 @@ class MediaRouterDesktopTest : public MediaRouterMojoTest {
     feature_list_.InitAndDisableFeature(kDialMediaRouteProvider);
     cast_media_sink_service = std::make_unique<MockCastMediaSinkService>();
     cast_media_sink_service_ = cast_media_sink_service.get();
-    media_sink_service_ = std::unique_ptr<DualMediaSinkService>(
-        new DualMediaSinkService(std::move(cast_media_sink_service),
-                                 std::make_unique<MockDialMediaSinkService>()));
+    media_sink_service_ =
+        std::unique_ptr<DualMediaSinkService>(new DualMediaSinkService(
+            std::move(cast_media_sink_service),
+            std::make_unique<MockDialMediaSinkService>(),
+            std::make_unique<MockCastAppDiscoveryService>()));
     return std::unique_ptr<MediaRouterDesktop>(
         new MediaRouterDesktop(profile(), media_sink_service_.get()));
   }

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

@@ -5,6 +5,7 @@
 #include "chrome/browser/media/router/providers/cast/cast_app_discovery_service.h"
 
 #include "base/bind.h"
+#include "base/strings/strcat.h"
 #include "base/time/tick_clock.h"
 #include "chrome/browser/media/router/providers/cast/cast_media_route_provider_metrics.h"
 #include "components/cast_channel/cast_message_handler.h"
@@ -15,6 +16,8 @@ namespace media_router {
 
 namespace {
 
+constexpr char kLoggerComponent[] = "CastAppDiscoveryService";
+
 // The minimum time that must elapse before an app availability result can be
 // force refreshed.
 static constexpr base::TimeDelta kRefreshThreshold =
@@ -79,7 +82,15 @@ CastAppDiscoveryServiceImpl::StartObservingMediaSinks(
         cast_channel::CastSocket* socket =
             socket_service_->GetSocket(channel_id);
         if (!socket) {
-          DVLOG(1) << "Socket not found for id " << channel_id;
+          if (logger_.is_bound()) {
+            logger_->LogError(
+                mojom::LogCategory::kDiscovery, kLoggerComponent,
+                base::StringPrintf(
+                    "Socket not found for channel id: %d when starting "
+                    "discovery for source.",
+                    channel_id),
+                sink.first, source.source_id(), "");
+          }
           continue;
         }
 
@@ -98,18 +109,36 @@ void CastAppDiscoveryServiceImpl::Refresh() {
   // being iterated.
   for (const auto& sink : sinks) {
     for (const auto& app_id : app_ids) {
-        int channel_id = sink.second.cast_data().cast_channel_id;
-        cast_channel::CastSocket* socket =
-            socket_service_->GetSocket(channel_id);
-        if (!socket) {
-          DVLOG(1) << "Socket not found for id " << channel_id;
-          continue;
+      int channel_id = sink.second.cast_data().cast_channel_id;
+      cast_channel::CastSocket* socket = socket_service_->GetSocket(channel_id);
+      if (!socket) {
+        if (logger_.is_bound()) {
+          logger_->LogError(
+              mojom::LogCategory::kDiscovery, kLoggerComponent,
+              base::StringPrintf(
+                  "Socket not found for channel id: %d when refreshing "
+                  "the discovery state.",
+                  channel_id),
+              sink.first, "", "");
         }
-        RequestAppAvailability(socket, app_id, sink.first);
+        continue;
       }
+      RequestAppAvailability(socket, app_id, sink.first);
+    }
   }
 }
 
+void CastAppDiscoveryServiceImpl::BindLogger(
+    mojo::PendingRemote<mojom::Logger> pending_remote) {
+  DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
+  logger_.Bind(std::move(pending_remote));
+}
+
+scoped_refptr<base::SequencedTaskRunner>
+CastAppDiscoveryServiceImpl::task_runner() {
+  return socket_service_->task_runner();
+}
+
 void CastAppDiscoveryServiceImpl::MaybeRemoveSinkQueryEntry(
     const CastMediaSource& source) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
@@ -174,8 +203,13 @@ void CastAppDiscoveryServiceImpl::UpdateAppAvailability(
   if (!media_sink_service_->GetSinkById(sink_id))
     return;
 
-  DVLOG(1) << "App " << app_id << " on sink " << sink_id << " is "
-           << ToString(availability);
+  if (availability != cast_channel::GetAppAvailabilityResult::kAvailable &&
+      logger_.is_bound()) {
+    logger_->LogInfo(
+        mojom::LogCategory::kDiscovery, kLoggerComponent,
+        base::StrCat({"App ", app_id, " on sink is ", ToString(availability)}),
+        sink_id, "", "");
+  }
 
   UpdateSinkQueries(availability_tracker_.UpdateAppAvailability(
       sink_id, app_id, {availability, clock_->NowTicks()}));

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

@@ -20,8 +20,10 @@
 #include "chrome/common/media_router/discovery/media_sink_service_base.h"
 #include "chrome/common/media_router/media_sink.h"
 #include "chrome/common/media_router/media_source.h"
+#include "chrome/common/media_router/mojom/logger.mojom.h"
 #include "chrome/common/media_router/providers/cast/cast_media_source.h"
 #include "components/cast_channel/cast_message_util.h"
+#include "mojo/public/cpp/bindings/remote.h"
 
 namespace base {
 class TickClock;
@@ -58,6 +60,14 @@ class CastAppDiscoveryService {
   // this method when the user initiates a user gesture (such as opening the
   // Media Router dialog).
   virtual void Refresh() = 0;
+
+  // Binds |pending_remote| to the Mojo Remote owned by |impl_|.
+  virtual void BindLogger(
+      mojo::PendingRemote<mojom::Logger> pending_remote) = 0;
+
+  // Returns the SequencedTaskRunner that should be used to invoke methods on
+  // this instance. Can be invoked on any thread.
+  virtual scoped_refptr<base::SequencedTaskRunner> task_runner() = 0;
 };
 
 // Keeps track of sink queries and listens to CastMediaSinkServiceImpl for sink
@@ -82,6 +92,10 @@ class CastAppDiscoveryServiceImpl : public CastAppDiscoveryService,
   // pairs whose status is kUnavailable or kUnknown.
   void Refresh() override;
 
+  void BindLogger(mojo::PendingRemote<mojom::Logger> pending_remote) override;
+
+  scoped_refptr<base::SequencedTaskRunner> task_runner() override;
+
  private:
   friend class CastAppDiscoveryServiceImplTest;
 
@@ -136,6 +150,10 @@ class CastAppDiscoveryServiceImpl : public CastAppDiscoveryService,
   CastAppAvailabilityTracker availability_tracker_;
 
   const base::TickClock* const clock_;
+  // Mojo Remote to the logger owned by the Media Router. The Remote is not
+  // bound until |BindLogger()| is called. Always check if |logger_.is_bound()|
+  // is true before using.
+  mojo::Remote<mojom::Logger> logger_;
 
   SEQUENCE_CHECKER(sequence_checker_);
   base::WeakPtrFactory<CastAppDiscoveryServiceImpl> weak_ptr_factory_{this};

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

@@ -89,9 +89,11 @@ DualMediaSinkService::DualMediaSinkService() {
 
 DualMediaSinkService::DualMediaSinkService(
     std::unique_ptr<CastMediaSinkService> cast_media_sink_service,
-    std::unique_ptr<DialMediaSinkService> dial_media_sink_service)
+    std::unique_ptr<DialMediaSinkService> dial_media_sink_service,
+    std::unique_ptr<CastAppDiscoveryService> cast_app_discovery_service)
     : dial_media_sink_service_(std::move(dial_media_sink_service)),
-      cast_media_sink_service_(std::move(cast_media_sink_service)) {}
+      cast_media_sink_service_(std::move(cast_media_sink_service)),
+      cast_app_discovery_service_(std::move(cast_app_discovery_service)) {}
 
 DualMediaSinkService::~DualMediaSinkService() = default;
 
@@ -116,6 +118,15 @@ void DualMediaSinkService::BindLogger(LoggerImpl* logger_impl) {
   mojo::PendingRemote<mojom::Logger> dial_pending_remote;
   logger_impl->Bind(dial_pending_remote.InitWithNewPipeAndPassReceiver());
   dial_media_sink_service_->BindLogger(std::move(dial_pending_remote));
+
+  mojo::PendingRemote<mojom::Logger> cast_discovery_pending_remote;
+  logger_impl->Bind(
+      cast_discovery_pending_remote.InitWithNewPipeAndPassReceiver());
+  cast_app_discovery_service_->task_runner()->PostTask(
+      FROM_HERE,
+      base::BindOnce(&CastAppDiscoveryService::BindLogger,
+                     base::Unretained(cast_app_discovery_service_.get()),
+                     std::move(cast_discovery_pending_remote)));
 }
 
 }  // namespace media_router

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

@@ -77,7 +77,8 @@ class DualMediaSinkService {
   // |dial_media_sink_service_|.
   // The binding should be done once and the method is a no-op after the first
   // call.
-  void BindLogger(LoggerImpl* logger_impl);
+  // Marked virtual for testing.
+  virtual void BindLogger(LoggerImpl* logger_impl);
 
   virtual void OnUserGesture();
 
@@ -89,7 +90,8 @@ class DualMediaSinkService {
   // Used by tests.
   DualMediaSinkService(
       std::unique_ptr<CastMediaSinkService> cast_media_sink_service,
-      std::unique_ptr<DialMediaSinkService> dial_media_sink_service);
+      std::unique_ptr<DialMediaSinkService> dial_media_sink_service,
+      std::unique_ptr<CastAppDiscoveryService> cast_app_discovery_service);
   virtual ~DualMediaSinkService();
 
  private:

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

@@ -16,11 +16,15 @@ class DualMediaSinkServiceTest : public testing::Test {
   DualMediaSinkServiceTest() {
     auto cast_media_sink_service = std::make_unique<MockCastMediaSinkService>();
     auto dial_media_sink_service = std::make_unique<MockDialMediaSinkService>();
+    auto cast_app_discovery_service =
+        std::make_unique<MockCastAppDiscoveryService>();
     cast_media_sink_service_ = cast_media_sink_service.get();
     dial_media_sink_service_ = dial_media_sink_service.get();
+    cast_app_discovery_service_ = cast_app_discovery_service.get();
     dual_media_sink_service_ = std::unique_ptr<DualMediaSinkService>(
         new DualMediaSinkService(std::move(cast_media_sink_service),
-                                 std::move(dial_media_sink_service)));
+                                 std::move(dial_media_sink_service),
+                                 std::move(cast_app_discovery_service)));
   }
 
   ~DualMediaSinkServiceTest() override = default;
@@ -42,6 +46,7 @@ class DualMediaSinkServiceTest : public testing::Test {
  private:
   MockCastMediaSinkService* cast_media_sink_service_;
   MockDialMediaSinkService* dial_media_sink_service_;
+  MockCastAppDiscoveryService* cast_app_discovery_service_;
   std::unique_ptr<DualMediaSinkService> dual_media_sink_service_;
 };
 

chrome/browser/media/router/test/noop_dual_media_sink_service.cc

@@ -6,12 +6,14 @@
 
 #include "chrome/browser/media/router/discovery/dial/dial_media_sink_service.h"
 #include "chrome/browser/media/router/discovery/mdns/cast_media_sink_service.h"
+#include "chrome/browser/media/router/providers/cast/cast_app_discovery_service.h"
 
 namespace media_router {
 
 NoopDualMediaSinkService::NoopDualMediaSinkService()
     : DualMediaSinkService(std::unique_ptr<CastMediaSinkService>(nullptr),
-                           std::unique_ptr<DialMediaSinkService>(nullptr)) {}
+                           std::unique_ptr<DialMediaSinkService>(nullptr),
+                           std::unique_ptr<CastAppDiscoveryService>(nullptr)) {}
 NoopDualMediaSinkService::~NoopDualMediaSinkService() = default;
 
 }  // namespace media_router

chrome/browser/media/router/test/test_helper.cc

@@ -12,6 +12,8 @@
 
 #if !defined(OS_ANDROID)
 #include "base/json/json_reader.h"
+#include "content/public/browser/browser_task_traits.h"
+#include "content/public/browser/browser_thread.h"
 #include "services/network/public/cpp/simple_url_loader.h"
 #include "url/gurl.h"
 #endif
@@ -38,7 +40,7 @@ MockPresentationConnectionProxy::MockPresentationConnectionProxy() {}
 MockPresentationConnectionProxy::~MockPresentationConnectionProxy() {}
 
 #if !defined(OS_ANDROID)
-MockDialMediaSinkService::MockDialMediaSinkService() : DialMediaSinkService() {}
+MockDialMediaSinkService::MockDialMediaSinkService() = default;
 MockDialMediaSinkService::~MockDialMediaSinkService() = default;
 
 MockCastMediaSinkService::MockCastMediaSinkService() : CastMediaSinkService() {}
@@ -54,6 +56,10 @@ MockCastAppDiscoveryService::StartObservingMediaSinks(
   DoStartObservingMediaSinks(source);
   return callbacks_.Add(callback);
 }
+scoped_refptr<base::SequencedTaskRunner>
+MockCastAppDiscoveryService::task_runner() {
+  return base::CreateSingleThreadTaskRunner({content::BrowserThread::IO});
+}
 
 MockDialAppDiscoveryService::MockDialAppDiscoveryService() = default;
 

chrome/browser/media/router/test/test_helper.h

@@ -28,6 +28,7 @@
 #include "chrome/browser/media/router/providers/dial/dial_activity_manager.h"
 #include "chrome/browser/media/router/providers/dial/dial_internal_message_util.h"
 #include "chrome/common/media_router/discovery/media_sink_internal.h"
+#include "chrome/common/media_router/mojom/logger.mojom.h"
 #include "net/base/ip_endpoint.h"
 #include "services/network/test/test_url_loader_factory.h"
 #endif  // !defined(OS_ANDROID)
@@ -117,8 +118,10 @@ class MockCastAppDiscoveryService : public CastAppDiscoveryService {
   Subscription StartObservingMediaSinks(
       const CastMediaSource& source,
       const SinkQueryCallback& callback) override;
+  scoped_refptr<base::SequencedTaskRunner> task_runner() override;
   MOCK_METHOD1(DoStartObservingMediaSinks, void(const CastMediaSource&));
   MOCK_METHOD0(Refresh, void());
+  MOCK_METHOD1(BindLogger, void(mojo::PendingRemote<mojom::Logger>));
 
   SinkQueryCallbackList& callbacks() { return callbacks_; }