Discovery: Add Trace Logging

Adds trace logging to the DNS-SD layer so that multiple calls with error
codes can all be traced if multiple failures occur.

Bug: b/155337599
Change-Id: Ic5ba146cf467895092ee6655213097bb0cf2fef2
Reviewed-on: https://chromium-review.googlesource.com/c/openscreen/+/2182319
Commit-Queue: Ryan Keane <rwkeane@google.com>
Reviewed-by: Jordan Bayles <jophba@chromium.org>

4 files changed, 32 insertions, 15 deletions

diff --git a/discovery/dnssd/impl/publisher_impl.cc b/discovery/dnssd/impl/publisher_impl.cc
index ebefb70b..4dac0aa6 100644
--- a/discovery/dnssd/impl/publisher_impl.cc
+++ b/discovery/dnssd/impl/publisher_impl.cc
@@ -16,6 +16,7 @@
 #include "discovery/mdns/public/mdns_constants.h"
 #include "platform/api/task_runner.h"
 #include "platform/base/error.h"
+#include "util/trace_logging.h"
 
 namespace openscreen {
 namespace discovery {
@@ -195,25 +196,29 @@ Error PublisherImpl::UpdatePublishedRegistration(
   }
 
   // Apply changes called out in |changed_records|.
-  // TODO(crbug.com/openscreen/114): Trace each below call so multiple errors
-  // can be seen.
   Error total_result = Error::None();
   for (const auto& pair : changed_records) {
     OSP_DCHECK(pair.second.first != absl::nullopt ||
                pair.second.second != absl::nullopt);
     if (pair.second.first == absl::nullopt) {
+      TRACE_SCOPED(TraceCategory::kDiscovery, "mdns.RegisterRecord");
       auto error = mdns_publisher_->RegisterRecord(pair.second.second.value());
+      TRACE_SET_RESULT(error);
       if (!error.ok()) {
         total_result = error;
       }
     } else if (pair.second.second == absl::nullopt) {
+      TRACE_SCOPED(TraceCategory::kDiscovery, "mdns.UnregisterRecord");
       auto error = mdns_publisher_->UnregisterRecord(pair.second.first.value());
+      TRACE_SET_RESULT(error);
       if (!error.ok()) {
         total_result = error;
       }
     } else if (pair.second.first.value() != pair.second.second.value()) {
+      TRACE_SCOPED(TraceCategory::kDiscovery, "mdns.UpdateRegisteredRecord");
       auto error = mdns_publisher_->UpdateRegisteredRecord(
           pair.second.first.value(), pair.second.second.value());
+      TRACE_SET_RESULT(error);
       if (!error.ok()) {
         total_result = error;
       }
@@ -233,15 +238,14 @@ ErrorOr<int> PublisherImpl::DeregisterAll(const std::string& service) {
   OSP_DVLOG << "Deregistering all instances";
 
   int removed_count = 0;
-
-  // TODO(crbug.com/openscreen/114): Trace each below call so multiple errors
-  // can be seen.
   Error error = Error::None();
   for (auto it = published_instances_.begin();
        it != published_instances_.end();) {
     if (it->second.service_id() == service) {
       for (const auto& mdns_record : GetDnsRecords(it->second)) {
+        TRACE_SCOPED(TraceCategory::kDiscovery, "mdns.UnregisterRecord");
         auto publisher_error = mdns_publisher_->UnregisterRecord(mdns_record);
+        TRACE_SET_RESULT(error);
         if (!publisher_error.ok()) {
           error = publisher_error;
         }
@@ -264,6 +268,7 @@ ErrorOr<int> PublisherImpl::DeregisterAll(const std::string& service) {
 
 void PublisherImpl::OnDomainFound(const DomainName& requested_name,
                                   const DomainName& confirmed_name) {
+  TRACE_DEFAULT_SCOPED(TraceCategory::kDiscovery);
   OSP_DCHECK(task_runner_->IsRunningOnTaskRunner());
 
   OSP_DVLOG << "Domain successfully claimed: '" << confirmed_name.ToString()
@@ -293,6 +298,7 @@ void PublisherImpl::OnDomainFound(const DomainName& requested_name,
   }
 
   for (const auto& mdns_record : GetDnsRecords(endpoint)) {
+    TRACE_SCOPED(TraceCategory::kDiscovery, "mdns.RegisterRecord");
     Error result = mdns_publisher_->RegisterRecord(mdns_record);
     if (!result.ok()) {
       reporting_client_->OnRecoverableError(
diff --git a/discovery/dnssd/impl/service_dispatcher.cc b/discovery/dnssd/impl/service_dispatcher.cc
index 6b8d807e..794511a8 100644
--- a/discovery/dnssd/impl/service_dispatcher.cc
+++ b/discovery/dnssd/impl/service_dispatcher.cc
@@ -11,6 +11,7 @@
 #include "discovery/dnssd/public/dns_sd_instance.h"
 #include "discovery/mdns/public/mdns_service.h"
 #include "platform/api/task_runner.h"
+#include "util/trace_logging.h"
 
 namespace openscreen {
 namespace discovery {
@@ -19,8 +20,6 @@ namespace {
 void ForAllQueriers(
     std::vector<std::unique_ptr<ServiceInstance>>* service_instances,
     std::function<void(DnsSdQuerier*)> action) {
-  // TODO(crbug.com/openscreen/114): Trace each below call so multiple errors
-  // can be seen.
   for (auto& service_instance : *service_instances) {
     auto* querier = service_instance->GetQuerier();
     OSP_CHECK(querier);
@@ -31,15 +30,16 @@ void ForAllQueriers(
 
 Error ForAllPublishers(
     std::vector<std::unique_ptr<ServiceInstance>>* service_instances,
-    std::function<Error(DnsSdPublisher*)> action) {
-  // TODO(crbug.com/openscreen/114): Trace each below call so multiple errors
-  // can be seen.
+    std::function<Error(DnsSdPublisher*)> action,
+    const char* operation) {
   Error result = Error::None();
   for (auto& service_instance : *service_instances) {
     auto* publisher = service_instance->GetPublisher();
     OSP_CHECK(publisher);
 
+    TRACE_SCOPED(TraceCategory::kDiscovery, operation);
     Error inner_result = action(publisher);
+    TRACE_SET_RESULT(inner_result);
     if (!inner_result.ok()) {
       result = std::move(inner_result);
     }
@@ -81,6 +81,7 @@ ServiceDispatcher::~ServiceDispatcher() {
 
 // DnsSdQuerier overrides.
 void ServiceDispatcher::StartQuery(const std::string& service, Callback* cb) {
+  TRACE_DEFAULT_SCOPED(TraceCategory::kDiscovery);
   auto start_query = [&service, cb](DnsSdQuerier* querier) {
     querier->StartQuery(service, cb);
   };
@@ -88,6 +89,7 @@ void ServiceDispatcher::StartQuery(const std::string& service, Callback* cb) {
 }
 
 void ServiceDispatcher::StopQuery(const std::string& service, Callback* cb) {
+  TRACE_DEFAULT_SCOPED(TraceCategory::kDiscovery);
   auto stop_query = [&service, cb](DnsSdQuerier* querier) {
     querier->StopQuery(service, cb);
   };
@@ -95,6 +97,7 @@ void ServiceDispatcher::StopQuery(const std::string& service, Callback* cb) {
 }
 
 void ServiceDispatcher::ReinitializeQueries(const std::string& service) {
+  TRACE_DEFAULT_SCOPED(TraceCategory::kDiscovery);
   auto reinitialize_queries = [&service](DnsSdQuerier* querier) {
     querier->ReinitializeQueries(service);
   };
@@ -104,30 +107,35 @@ void ServiceDispatcher::ReinitializeQueries(const std::string& service) {
 // DnsSdPublisher overrides.
 Error ServiceDispatcher::Register(const DnsSdInstance& instance,
                                   Client* client) {
+  TRACE_DEFAULT_SCOPED(TraceCategory::kDiscovery);
   auto register_instance = [&instance, client](DnsSdPublisher* publisher) {
     return publisher->Register(instance, client);
   };
-  return ForAllPublishers(&service_instances_, std::move(register_instance));
+  return ForAllPublishers(&service_instances_, std::move(register_instance),
+                          "DNS-SD.Register");
 }
 
 Error ServiceDispatcher::UpdateRegistration(const DnsSdInstance& instance) {
+  TRACE_DEFAULT_SCOPED(TraceCategory::kDiscovery);
   auto update_registration = [&instance](DnsSdPublisher* publisher) {
     return publisher->UpdateRegistration(instance);
   };
-  return ForAllPublishers(&service_instances_, std::move(update_registration));
+  return ForAllPublishers(&service_instances_, std::move(update_registration),
+                          "DNS-SD.UpdateRegistration");
 }
 
 ErrorOr<int> ServiceDispatcher::DeregisterAll(const std::string& service) {
-  // TODO(crbug.com/openscreen/114): Trace each below call so multiple errors
-  // can be seen.
+  TRACE_DEFAULT_SCOPED(TraceCategory::kDiscovery);
   int total = 0;
   Error failure = Error::None();
   for (auto& service_instance : service_instances_) {
     auto* publisher = service_instance->GetPublisher();
     OSP_CHECK(publisher);
 
+    TRACE_SCOPED(TraceCategory::kDiscovery, "DNS-SD.DeregisterAll");
     auto result = publisher->DeregisterAll(service);
     if (result.is_error()) {
+      TRACE_SET_RESULT(result.error());
       failure = std::move(result.error());
     } else {
       total += result.value();
diff --git a/platform/base/trace_logging_types.h b/platform/base/trace_logging_types.h
index 0ee9dfb1..64149a7e 100644
--- a/platform/base/trace_logging_types.h
+++ b/platform/base/trace_logging_types.h
@@ -59,7 +59,8 @@ struct TraceCategory {
     kQuic = 0x01 << 1,
     kSsl = 0x01 << 2,
     kPresentation = 0x01 << 3,
-    kStandaloneReceiver = 0x01 << 4
+    kStandaloneReceiver = 0x01 << 4,
+    kDiscovery = 0x01 << 5
   };
 };
 
diff --git a/util/trace_logging.h b/util/trace_logging.h
index 84732be2..0384ab70 100644
--- a/util/trace_logging.h
+++ b/util/trace_logging.h
@@ -82,6 +82,8 @@ inline void DoNothingForTracing(Args... args) {}
 #define TRACE_ROOT_ID openscreen::kEmptyTraceId
 #define TRACE_SCOPED(category, name, ...) \
   openscreen::internal::DoNothingForTracing(category, name, ##__VA_ARGS__)
+#define TRACE_DEFAULT_SCOPED(category, ...) \
+  TRACE_SCOPED(category, __PRETTY_FUNCTION__, ##__VA_ARGS__)
 #define TRACE_ASYNC_START(category, name, ...) \
   openscreen::internal::DoNothingForTracing(category, name, ##__VA_ARGS__)
 #define TRACE_ASYNC_END(category, id, result) \