Move most c-ares logs under a tracer

3 files changed, 74 insertions, 58 deletions

diff --git a/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc b/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc
index fc83fc4488..abacd0c960 100644
--- a/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc
+++ b/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc
@@ -170,7 +170,7 @@ AresDnsResolver::AresDnsResolver(const ResolverArgs& args)
 }
 
 AresDnsResolver::~AresDnsResolver() {
-  gpr_log(GPR_DEBUG, "destroying AresDnsResolver");
+  GRPC_CARES_TRACE_LOG("resolver:%p destroying AresDnsResolver", this);
   if (resolved_result_ != nullptr) {
     grpc_channel_args_destroy(resolved_result_);
   }
@@ -182,7 +182,8 @@ AresDnsResolver::~AresDnsResolver() {
 
 void AresDnsResolver::NextLocked(grpc_channel_args** target_result,
                                  grpc_closure* on_complete) {
-  gpr_log(GPR_DEBUG, "AresDnsResolver::NextLocked() is called.");
+  GRPC_CARES_TRACE_LOG("resolver:%p AresDnsResolver::NextLocked() is called.",
+                       this);
   GPR_ASSERT(next_completion_ == nullptr);
   next_completion_ = on_complete;
   target_result_ = target_result;
@@ -225,12 +226,14 @@ void AresDnsResolver::ShutdownLocked() {
 void AresDnsResolver::OnNextResolutionLocked(void* arg, grpc_error* error) {
   AresDnsResolver* r = static_cast<AresDnsResolver*>(arg);
   GRPC_CARES_TRACE_LOG(
-      "%p re-resolution timer fired. error: %s. shutdown_initiated_: %d", r,
-      grpc_error_string(error), r->shutdown_initiated_);
+      "resolver:%p re-resolution timer fired. error: %s. shutdown_initiated_: "
+      "%d",
+      r, grpc_error_string(error), r->shutdown_initiated_);
   r->have_next_resolution_timer_ = false;
   if (error == GRPC_ERROR_NONE && !r->shutdown_initiated_) {
     if (!r->resolving_) {
-      GRPC_CARES_TRACE_LOG("%p start resolving due to re-resolution timer", r);
+      GRPC_CARES_TRACE_LOG(
+          "resolver:%p start resolving due to re-resolution timer", r);
       r->StartResolvingLocked();
     }
   }
@@ -327,8 +330,8 @@ void AresDnsResolver::OnResolvedLocked(void* arg, grpc_error* error) {
       service_config_string = ChooseServiceConfig(r->service_config_json_);
       gpr_free(r->service_config_json_);
       if (service_config_string != nullptr) {
-        gpr_log(GPR_INFO, "selected service config choice: %s",
-                service_config_string);
+        GRPC_CARES_TRACE_LOG("resolver:%p selected service config choice: %s",
+                             r, service_config_string);
         args_to_remove[num_args_to_remove++] = GRPC_ARG_SERVICE_CONFIG;
         args_to_add[num_args_to_add++] = grpc_channel_arg_string_create(
             (char*)GRPC_ARG_SERVICE_CONFIG, service_config_string);
@@ -344,11 +347,11 @@ void AresDnsResolver::OnResolvedLocked(void* arg, grpc_error* error) {
     r->backoff_.Reset();
   } else if (!r->shutdown_initiated_) {
     const char* msg = grpc_error_string(error);
-    gpr_log(GPR_DEBUG, "dns resolution failed: %s", msg);
+    GRPC_CARES_TRACE_LOG("resolver:%p dns resolution failed: %s", r, msg);
     grpc_millis next_try = r->backoff_.NextAttemptTime();
     grpc_millis timeout = next_try - ExecCtx::Get()->Now();
-    gpr_log(GPR_INFO, "dns resolution failed (will retry): %s",
-            grpc_error_string(error));
+    GRPC_CARES_TRACE_LOG("resolver:%p dns resolution failed (will retry): %s",
+                         r, grpc_error_string(error));
     GPR_ASSERT(!r->have_next_resolution_timer_);
     r->have_next_resolution_timer_ = true;
     // TODO(roth): We currently deal with this ref manually.  Once the
@@ -357,9 +360,10 @@ void AresDnsResolver::OnResolvedLocked(void* arg, grpc_error* error) {
     RefCountedPtr<Resolver> self = r->Ref(DEBUG_LOCATION, "retry-timer");
     self.release();
     if (timeout > 0) {
-      gpr_log(GPR_DEBUG, "retrying in %" PRId64 " milliseconds", timeout);
+      GRPC_CARES_TRACE_LOG("resolver:%p retrying in %" PRId64 " milliseconds",
+                           r, timeout);
     } else {
-      gpr_log(GPR_DEBUG, "retrying immediately");
+      GRPC_CARES_TRACE_LOG("resolver:%p retrying immediately", r);
     }
     grpc_timer_init(&r->next_resolution_timer_, next_try,
                     &r->on_next_resolution_);
@@ -385,10 +389,10 @@ void AresDnsResolver::MaybeStartResolvingLocked() {
     if (ms_until_next_resolution > 0) {
       const grpc_millis last_resolution_ago =
           grpc_core::ExecCtx::Get()->Now() - last_resolution_timestamp_;
-      gpr_log(GPR_DEBUG,
-              "In cooldown from last resolution (from %" PRId64
-              " ms ago). Will resolve again in %" PRId64 " ms",
-              last_resolution_ago, ms_until_next_resolution);
+      GRPC_CARES_TRACE_LOG(
+          "resolver:%p In cooldown from last resolution (from %" PRId64
+          " ms ago). Will resolve again in %" PRId64 " ms",
+          this, last_resolution_ago, ms_until_next_resolution);
       have_next_resolution_timer_ = true;
       // TODO(roth): We currently deal with this ref manually.  Once the
       // new closure API is done, find a way to track this ref with the timer
@@ -405,7 +409,6 @@ void AresDnsResolver::MaybeStartResolvingLocked() {
 }
 
 void AresDnsResolver::StartResolvingLocked() {
-  gpr_log(GPR_DEBUG, "Start resolving.");
   // TODO(roth): We currently deal with this ref manually.  Once the
   // new closure API is done, find a way to track this ref with the timer
   // callback as part of the type system.
@@ -420,6 +423,8 @@ void AresDnsResolver::StartResolvingLocked() {
       request_service_config_ ? &service_config_json_ : nullptr,
       query_timeout_ms_, combiner());
   last_resolution_timestamp_ = grpc_core::ExecCtx::Get()->Now();
+  GRPC_CARES_TRACE_LOG("resolver:%p Started resolving. pending_request_:%p",
+                       this, pending_request_);
 }
 
 void AresDnsResolver::MaybeFinishNextLocked() {
@@ -427,7 +432,8 @@ void AresDnsResolver::MaybeFinishNextLocked() {
     *target_result_ = resolved_result_ == nullptr
                           ? nullptr
                           : grpc_channel_args_copy(resolved_result_);
-    gpr_log(GPR_DEBUG, "AresDnsResolver::MaybeFinishNextLocked()");
+    GRPC_CARES_TRACE_LOG("resolver:%p AresDnsResolver::MaybeFinishNextLocked()",
+                         this);
     GRPC_CLOSURE_SCHED(next_completion_, GRPC_ERROR_NONE);
     next_completion_ = nullptr;
     published_version_ = resolved_version_;
diff --git a/src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_ev_driver.cc b/src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_ev_driver.cc
index 8abc34c6ed..d99c2e3004 100644
--- a/src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_ev_driver.cc
+++ b/src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_ev_driver.cc
@@ -90,15 +90,18 @@ static void grpc_ares_notify_on_event_locked(grpc_ares_ev_driver* ev_driver);
 
 static grpc_ares_ev_driver* grpc_ares_ev_driver_ref(
     grpc_ares_ev_driver* ev_driver) {
-  gpr_log(GPR_DEBUG, "Ref ev_driver %" PRIuPTR, (uintptr_t)ev_driver);
+  GRPC_CARES_TRACE_LOG("request:%p Ref ev_driver %p", ev_driver->request,
+                       ev_driver);
   gpr_ref(&ev_driver->refs);
   return ev_driver;
 }
 
 static void grpc_ares_ev_driver_unref(grpc_ares_ev_driver* ev_driver) {
-  gpr_log(GPR_DEBUG, "Unref ev_driver %" PRIuPTR, (uintptr_t)ev_driver);
+  GRPC_CARES_TRACE_LOG("request:%p Unref ev_driver %p", ev_driver->request,
+                       ev_driver);
   if (gpr_unref(&ev_driver->refs)) {
-    gpr_log(GPR_DEBUG, "destroy ev_driver %" PRIuPTR, (uintptr_t)ev_driver);
+    GRPC_CARES_TRACE_LOG("request:%p destroy ev_driver %p", ev_driver->request,
+                         ev_driver);
     GPR_ASSERT(ev_driver->fds == nullptr);
     GRPC_COMBINER_UNREF(ev_driver->combiner, "free ares event driver");
     ares_destroy(ev_driver->channel);
@@ -108,7 +111,8 @@ static void grpc_ares_ev_driver_unref(grpc_ares_ev_driver* ev_driver) {
 }
 
 static void fd_node_destroy_locked(fd_node* fdn) {
-  gpr_log(GPR_DEBUG, "delete fd: %s", fdn->grpc_polled_fd->GetName());
+  GRPC_CARES_TRACE_LOG("request:%p delete fd: %s", fdn->ev_driver->request,
+                       fdn->grpc_polled_fd->GetName());
   GPR_ASSERT(!fdn->readable_registered);
   GPR_ASSERT(!fdn->writable_registered);
   GPR_ASSERT(fdn->already_shutdown);
@@ -136,7 +140,7 @@ grpc_error* grpc_ares_ev_driver_create_locked(grpc_ares_ev_driver** ev_driver,
   memset(&opts, 0, sizeof(opts));
   opts.flags |= ARES_FLAG_STAYOPEN;
   int status = ares_init_options(&(*ev_driver)->channel, &opts, ARES_OPT_FLAGS);
-  gpr_log(GPR_DEBUG, "grpc_ares_ev_driver_create_locked");
+  GRPC_CARES_TRACE_LOG("request:%p grpc_ares_ev_driver_create_locked", request);
   if (status != ARES_SUCCESS) {
     char* err_msg;
     gpr_asprintf(&err_msg, "Failed to init ares channel. C-ares error: %s",
@@ -203,8 +207,9 @@ static fd_node* pop_fd_node_locked(fd_node** head, ares_socket_t as) {
 static void on_timeout_locked(void* arg, grpc_error* error) {
   grpc_ares_ev_driver* driver = static_cast<grpc_ares_ev_driver*>(arg);
   GRPC_CARES_TRACE_LOG(
-      "ev_driver=%p on_timeout_locked. driver->shutting_down=%d. err=%s",
-      driver, driver->shutting_down, grpc_error_string(error));
+      "request:%p ev_driver=%p on_timeout_locked. driver->shutting_down=%d. "
+      "err=%s",
+      driver->request, driver, driver->shutting_down, grpc_error_string(error));
   if (!driver->shutting_down && error == GRPC_ERROR_NONE) {
     grpc_ares_ev_driver_shutdown_locked(driver);
   }
@@ -216,7 +221,8 @@ static void on_readable_locked(void* arg, grpc_error* error) {
   grpc_ares_ev_driver* ev_driver = fdn->ev_driver;
   const ares_socket_t as = fdn->grpc_polled_fd->GetWrappedAresSocketLocked();
   fdn->readable_registered = false;
-  gpr_log(GPR_DEBUG, "readable on %s", fdn->grpc_polled_fd->GetName());
+  GRPC_CARES_TRACE_LOG("request:%p readable on %s", fdn->ev_driver->request,
+                       fdn->grpc_polled_fd->GetName());
   if (error == GRPC_ERROR_NONE) {
     do {
       ares_process_fd(ev_driver->channel, as, ARES_SOCKET_BAD);
@@ -239,7 +245,8 @@ static void on_writable_locked(void* arg, grpc_error* error) {
   grpc_ares_ev_driver* ev_driver = fdn->ev_driver;
   const ares_socket_t as = fdn->grpc_polled_fd->GetWrappedAresSocketLocked();
   fdn->writable_registered = false;
-  gpr_log(GPR_DEBUG, "writable on %s", fdn->grpc_polled_fd->GetName());
+  GRPC_CARES_TRACE_LOG("request:%p writable on %s", ev_driver->request,
+                       fdn->grpc_polled_fd->GetName());
   if (error == GRPC_ERROR_NONE) {
     ares_process_fd(ev_driver->channel, ARES_SOCKET_BAD, as);
   } else {
@@ -278,7 +285,8 @@ static void grpc_ares_notify_on_event_locked(grpc_ares_ev_driver* ev_driver) {
           fdn->grpc_polled_fd =
               ev_driver->polled_fd_factory->NewGrpcPolledFdLocked(
                   socks[i], ev_driver->pollset_set, ev_driver->combiner);
-          gpr_log(GPR_DEBUG, "new fd: %s", fdn->grpc_polled_fd->GetName());
+          GRPC_CARES_TRACE_LOG("request:%p new fd: %s", ev_driver->request,
+                               fdn->grpc_polled_fd->GetName());
           fdn->ev_driver = ev_driver;
           fdn->readable_registered = false;
           fdn->writable_registered = false;
@@ -295,8 +303,9 @@ static void grpc_ares_notify_on_event_locked(grpc_ares_ev_driver* ev_driver) {
         if (ARES_GETSOCK_READABLE(socks_bitmask, i) &&
             !fdn->readable_registered) {
           grpc_ares_ev_driver_ref(ev_driver);
-          gpr_log(GPR_DEBUG, "notify read on: %s",
-                  fdn->grpc_polled_fd->GetName());
+          GRPC_CARES_TRACE_LOG("request:%p notify read on: %s",
+                               ev_driver->request,
+                               fdn->grpc_polled_fd->GetName());
           fdn->grpc_polled_fd->RegisterForOnReadableLocked(&fdn->read_closure);
           fdn->readable_registered = true;
         }
@@ -304,8 +313,9 @@ static void grpc_ares_notify_on_event_locked(grpc_ares_ev_driver* ev_driver) {
         // has not been registered with this socket.
         if (ARES_GETSOCK_WRITABLE(socks_bitmask, i) &&
             !fdn->writable_registered) {
-          gpr_log(GPR_DEBUG, "notify write on: %s",
-                  fdn->grpc_polled_fd->GetName());
+          GRPC_CARES_TRACE_LOG("request:%p notify write on: %s",
+                               ev_driver->request,
+                               fdn->grpc_polled_fd->GetName());
           grpc_ares_ev_driver_ref(ev_driver);
           fdn->grpc_polled_fd->RegisterForOnWriteableLocked(
               &fdn->write_closure);
@@ -332,7 +342,8 @@ static void grpc_ares_notify_on_event_locked(grpc_ares_ev_driver* ev_driver) {
   // If the ev driver has no working fd, all the tasks are done.
   if (new_list == nullptr) {
     ev_driver->working = false;
-    gpr_log(GPR_DEBUG, "ev driver stop working");
+    GRPC_CARES_TRACE_LOG("request:%p ev driver stop working",
+                         ev_driver->request);
   }
 }
 
@@ -345,9 +356,9 @@ void grpc_ares_ev_driver_start_locked(grpc_ares_ev_driver* ev_driver) {
             ? GRPC_MILLIS_INF_FUTURE
             : ev_driver->query_timeout_ms + grpc_core::ExecCtx::Get()->Now();
     GRPC_CARES_TRACE_LOG(
-        "ev_driver=%p grpc_ares_ev_driver_start_locked. timeout in %" PRId64
-        " ms",
-        ev_driver, timeout);
+        "request:%p ev_driver=%p grpc_ares_ev_driver_start_locked. timeout in "
+        "%" PRId64 " ms",
+        ev_driver->request, ev_driver, timeout);
     grpc_ares_ev_driver_ref(ev_driver);
     grpc_timer_init(&ev_driver->query_timeout, timeout,
                     &ev_driver->on_timeout_locked);
diff --git a/src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_wrapper.cc b/src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_wrapper.cc
index 6897756769..1a7e5d0626 100644
--- a/src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_wrapper.cc
+++ b/src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_wrapper.cc
@@ -96,11 +96,11 @@ static void log_address_sorting_list(const ServerAddressList& addresses,
   for (size_t i = 0; i < addresses.size(); i++) {
     char* addr_str;
     if (grpc_sockaddr_to_string(&addr_str, &addresses[i].address(), true)) {
-      gpr_log(GPR_DEBUG, "c-ares address sorting: %s[%" PRIuPTR "]=%s",
+      gpr_log(GPR_INFO, "c-ares address sorting: %s[%" PRIuPTR "]=%s",
               input_output_str, i, addr_str);
       gpr_free(addr_str);
     } else {
-      gpr_log(GPR_DEBUG,
+      gpr_log(GPR_INFO,
               "c-ares address sorting: %s[%" PRIuPTR "]=<unprintable>",
               input_output_str, i);
     }
@@ -209,10 +209,10 @@ static void on_hostbyname_done_locked(void* arg, int status, int timeouts,
           addresses.emplace_back(&addr, addr_len, args);
           char output[INET6_ADDRSTRLEN];
           ares_inet_ntop(AF_INET6, &addr.sin6_addr, output, INET6_ADDRSTRLEN);
-          gpr_log(GPR_DEBUG,
-                  "c-ares resolver gets a AF_INET6 result: \n"
-                  "  addr: %s\n  port: %d\n  sin6_scope_id: %d\n",
-                  output, ntohs(hr->port), addr.sin6_scope_id);
+          GRPC_CARES_TRACE_LOG(
+              "request:%p c-ares resolver gets a AF_INET6 result: \n"
+              "  addr: %s\n  port: %d\n  sin6_scope_id: %d\n",
+              r, output, ntohs(hr->port), addr.sin6_scope_id);
           break;
         }
         case AF_INET: {
@@ -226,10 +226,10 @@ static void on_hostbyname_done_locked(void* arg, int status, int timeouts,
           addresses.emplace_back(&addr, addr_len, args);
           char output[INET_ADDRSTRLEN];
           ares_inet_ntop(AF_INET, &addr.sin_addr, output, INET_ADDRSTRLEN);
-          gpr_log(GPR_DEBUG,
-                  "c-ares resolver gets a AF_INET result: \n"
-                  "  addr: %s\n  port: %d\n",
-                  output, ntohs(hr->port));
+          GRPC_CARES_TRACE_LOG(
+              "request:%p c-ares resolver gets a AF_INET result: \n"
+              "  addr: %s\n  port: %d\n",
+              r, output, ntohs(hr->port));
           break;
         }
       }
@@ -252,9 +252,9 @@ static void on_hostbyname_done_locked(void* arg, int status, int timeouts,
 static void on_srv_query_done_locked(void* arg, int status, int timeouts,
                                      unsigned char* abuf, int alen) {
   grpc_ares_request* r = static_cast<grpc_ares_request*>(arg);
-  gpr_log(GPR_DEBUG, "on_query_srv_done_locked");
+  GRPC_CARES_TRACE_LOG("request:%p on_query_srv_done_locked", r);
   if (status == ARES_SUCCESS) {
-    gpr_log(GPR_DEBUG, "on_query_srv_done_locked ARES_SUCCESS");
+    GRPC_CARES_TRACE_LOG("request:%p on_query_srv_done_locked ARES_SUCCESS", r);
     struct ares_srv_reply* reply;
     const int parse_status = ares_parse_srv_reply(abuf, alen, &reply);
     if (parse_status == ARES_SUCCESS) {
@@ -297,9 +297,9 @@ static const char g_service_config_attribute_prefix[] = "grpc_config=";
 
 static void on_txt_done_locked(void* arg, int status, int timeouts,
                                unsigned char* buf, int len) {
-  gpr_log(GPR_DEBUG, "on_txt_done_locked");
   char* error_msg;
   grpc_ares_request* r = static_cast<grpc_ares_request*>(arg);
+  GRPC_CARES_TRACE_LOG("request:%p on_txt_done_locked", r);
   const size_t prefix_len = sizeof(g_service_config_attribute_prefix) - 1;
   struct ares_txt_ext* result = nullptr;
   struct ares_txt_ext* reply = nullptr;
@@ -332,7 +332,8 @@ static void on_txt_done_locked(void* arg, int status, int timeouts,
       service_config_len += result->length;
     }
     (*r->service_config_json_out)[service_config_len] = '\0';
-    gpr_log(GPR_INFO, "found service config: %s", *r->service_config_json_out);
+    GRPC_CARES_TRACE_LOG("request:%p found service config: %s", r,
+                         *r->service_config_json_out);
   }
   // Clean up.
   ares_free_data(reply);
@@ -358,12 +359,6 @@ void grpc_dns_lookup_ares_continue_after_check_localhost_and_ip_literals_locked(
   grpc_error* error = GRPC_ERROR_NONE;
   grpc_ares_hostbyname_request* hr = nullptr;
   ares_channel* channel = nullptr;
-  /* TODO(zyc): Enable tracing after #9603 is checked in */
-  /* if (grpc_dns_trace) {
-      gpr_log(GPR_DEBUG, "resolve_address (blocking): name=%s, default_port=%s",
-              name, default_port);
-     } */
-
   /* parse name, splitting it into host and port parts */
   char* host;
   char* port;
@@ -388,7 +383,7 @@ void grpc_dns_lookup_ares_continue_after_check_localhost_and_ip_literals_locked(
   channel = grpc_ares_ev_driver_get_channel_locked(r->ev_driver);
   // If dns_server is specified, use it.
   if (dns_server != nullptr) {
-    gpr_log(GPR_INFO, "Using DNS server %s", dns_server);
+    GRPC_CARES_TRACE_LOG("request:%p Using DNS server %s", r, dns_server);
     grpc_resolved_address addr;
     if (grpc_parse_ipv4_hostport(dns_server, &addr, false /* log_errors */)) {
       r->dns_server_addr.family = AF_INET;
@@ -513,7 +508,7 @@ static bool resolve_as_ip_literal_locked(
 static bool target_matches_localhost_inner(const char* name, char** host,
                                            char** port) {
   if (!gpr_split_host_port(name, host, port)) {
-    gpr_log(GPR_INFO, "Unable to split host and port for name: %s", name);
+    gpr_log(GPR_ERROR, "Unable to split host and port for name: %s", name);
     return false;
   }
   if (gpr_stricmp(*host, "localhost") == 0) {
@@ -547,6 +542,10 @@ static grpc_ares_request* grpc_dns_lookup_ares_locked_impl(
   r->success = false;
   r->error = GRPC_ERROR_NONE;
   r->pending_queries = 0;
+  GRPC_CARES_TRACE_LOG(
+      "request:%p c-ares grpc_dns_lookup_ares_locked_impl name=%s, "
+      "default_port=%s",
+      r, name, default_port);
   // Early out if the target is an ipv4 or ipv6 literal.
   if (resolve_as_ip_literal_locked(name, default_port, addrs)) {
     GRPC_CLOSURE_SCHED(on_done, GRPC_ERROR_NONE);