Merge pull request grpc#22865 from apolcyn/more_context_in_dns_errors

apolcyn · web-flow · commit 662141e90c53 · 2020-05-07T15:48:58.000-07:00
Include the query type and name in all c-ares DNS error messages
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
@@ -75,6 +75,8 @@ struct grpc_ares_request {
   grpc_error* error;
 };
 
+// TODO(apolcyn): make grpc_ares_hostbyname_request a sub-class
+// of GrpcAresQuery.
 typedef struct grpc_ares_hostbyname_request {
   /** following members are set in create_hostbyname_request_locked
    */
@@ -86,8 +88,37 @@ typedef struct grpc_ares_hostbyname_request {
   uint16_t port;
   /** is it a grpclb address */
   bool is_balancer;
+  /** for logging and errors: the query type ("A" or "AAAA") */
+  const char* qtype;
 } grpc_ares_hostbyname_request;
 
+static void grpc_ares_request_ref_locked(grpc_ares_request* r);
+static void grpc_ares_request_unref_locked(grpc_ares_request* r);
+
+// TODO(apolcyn): as a part of C++-ification, find a way to
+// organize per-query and per-resolution information in such a way
+// that doesn't involve allocating a number of different data
+// structures.
+class GrpcAresQuery {
+ public:
+  explicit GrpcAresQuery(grpc_ares_request* r, const std::string& name)
+      : r_(r), name_(name) {
+    grpc_ares_request_ref_locked(r_);
+  }
+
+  ~GrpcAresQuery() { grpc_ares_request_unref_locked(r_); }
+
+  grpc_ares_request* parent_request() { return r_; }
+
+  const std::string& name() { return name_; }
+
+ private:
+  /* the top level request instance */
+  grpc_ares_request* r_;
+  /** for logging and errors */
+  const std::string name_;
+};
+
 static void log_address_sorting_list(const grpc_ares_request* r,
                                      const ServerAddressList& addresses,
                                      const char* input_output_str) {
@@ -162,19 +193,21 @@ void grpc_ares_complete_request_locked(grpc_ares_request* r) {
   grpc_core::ExecCtx::Run(DEBUG_LOCATION, r->on_done, r->error);
 }
 
+/* Note that the returned object takes a reference to qtype, so
+ * qtype must outlive it. */
 static grpc_ares_hostbyname_request* create_hostbyname_request_locked(
     grpc_ares_request* parent_request, const char* host, uint16_t port,
-    bool is_balancer) {
+    bool is_balancer, const char* qtype) {
   GRPC_CARES_TRACE_LOG(
       "request:%p create_hostbyname_request_locked host:%s port:%d "
-      "is_balancer:%d",
-      parent_request, host, port, is_balancer);
-  grpc_ares_hostbyname_request* hr = static_cast<grpc_ares_hostbyname_request*>(
-      gpr_zalloc(sizeof(grpc_ares_hostbyname_request)));
+      "is_balancer:%d qtype:%s",
+      parent_request, host, port, is_balancer, qtype);
+  grpc_ares_hostbyname_request* hr = new grpc_ares_hostbyname_request();
   hr->parent_request = parent_request;
   hr->host = gpr_strdup(host);
   hr->port = port;
   hr->is_balancer = is_balancer;
+  hr->qtype = qtype;
   grpc_ares_request_ref_locked(parent_request);
   return hr;
 }
@@ -183,7 +216,7 @@ static void destroy_hostbyname_request_locked(
     grpc_ares_hostbyname_request* hr) {
   grpc_ares_request_unref_locked(hr->parent_request);
   gpr_free(hr->host);
-  gpr_free(hr);
+  delete hr;
 }
 
 static void on_hostbyname_done_locked(void* arg, int status, int /*timeouts*/,
@@ -193,8 +226,8 @@ static void on_hostbyname_done_locked(void* arg, int status, int /*timeouts*/,
   grpc_ares_request* r = hr->parent_request;
   if (status == ARES_SUCCESS) {
     GRPC_CARES_TRACE_LOG(
-        "request:%p on_hostbyname_done_locked host=%s ARES_SUCCESS", r,
-        hr->host);
+        "request:%p on_hostbyname_done_locked qtype=%s host=%s ARES_SUCCESS", r,
+        hr->qtype, hr->host);
     std::unique_ptr<ServerAddressList>* address_list_ptr =
         hr->is_balancer ? r->balancer_addresses_out : r->addresses_out;
     if (*address_list_ptr == nullptr) {
@@ -248,10 +281,12 @@ static void on_hostbyname_done_locked(void* arg, int status, int /*timeouts*/,
     }
   } else {
     char* error_msg;
-    gpr_asprintf(&error_msg, "C-ares status is not ARES_SUCCESS: %s",
-                 ares_strerror(status));
-    GRPC_CARES_TRACE_LOG("request:%p on_hostbyname_done_locked host=%s %s", r,
-                         hr->host, error_msg);
+    gpr_asprintf(&error_msg,
+                 "C-ares status is not ARES_SUCCESS "
+                 "qtype=%s name=%s is_balancer=%d: %s",
+                 hr->qtype, hr->host, hr->is_balancer, ares_strerror(status));
+    GRPC_CARES_TRACE_LOG("request:%p on_hostbyname_done_locked: %s", r,
+                         error_msg);
     grpc_error* error = GRPC_ERROR_CREATE_FROM_COPIED_STRING(error_msg);
     gpr_free(error_msg);
     r->error = grpc_error_add_child(error, r->error);
@@ -261,9 +296,12 @@ 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);
+  GrpcAresQuery* q = static_cast<GrpcAresQuery*>(arg);
+  grpc_ares_request* r = q->parent_request();
   if (status == ARES_SUCCESS) {
-    GRPC_CARES_TRACE_LOG("request:%p on_srv_query_done_locked ARES_SUCCESS", r);
+    GRPC_CARES_TRACE_LOG(
+        "request:%p on_srv_query_done_locked name=%s ARES_SUCCESS", r,
+        q->name().c_str());
     struct ares_srv_reply* reply;
     const int parse_status = ares_parse_srv_reply(abuf, alen, &reply);
     GRPC_CARES_TRACE_LOG("request:%p ares_parse_srv_reply: %d", r,
@@ -275,12 +313,13 @@ static void on_srv_query_done_locked(void* arg, int status, int /*timeouts*/,
            srv_it = srv_it->next) {
         if (grpc_ares_query_ipv6()) {
           grpc_ares_hostbyname_request* hr = create_hostbyname_request_locked(
-              r, srv_it->host, htons(srv_it->port), true /* is_balancer */);
+              r, srv_it->host, htons(srv_it->port), true /* is_balancer */,
+              "AAAA");
           ares_gethostbyname(*channel, hr->host, AF_INET6,
                              on_hostbyname_done_locked, hr);
         }
         grpc_ares_hostbyname_request* hr = create_hostbyname_request_locked(
-            r, srv_it->host, htons(srv_it->port), true /* is_balancer */);
+            r, srv_it->host, htons(srv_it->port), true /* is_balancer */, "A");
         ares_gethostbyname(*channel, hr->host, AF_INET,
                            on_hostbyname_done_locked, hr);
         grpc_ares_ev_driver_start_locked(r->ev_driver);
@@ -291,29 +330,33 @@ static void on_srv_query_done_locked(void* arg, int status, int /*timeouts*/,
     }
   } else {
     char* error_msg;
-    gpr_asprintf(&error_msg, "C-ares status is not ARES_SUCCESS: %s",
-                 ares_strerror(status));
-    GRPC_CARES_TRACE_LOG("request:%p on_srv_query_done_locked %s", r,
+    gpr_asprintf(&error_msg,
+                 "C-ares status is not ARES_SUCCESS "
+                 "qtype=SRV name=%s: %s",
+                 q->name().c_str(), ares_strerror(status));
+    GRPC_CARES_TRACE_LOG("request:%p on_srv_query_done_locked: %s", r,
                          error_msg);
     grpc_error* error = GRPC_ERROR_CREATE_FROM_COPIED_STRING(error_msg);
     gpr_free(error_msg);
     r->error = grpc_error_add_child(error, r->error);
   }
-  grpc_ares_request_unref_locked(r);
+  delete q;
 }
 
 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) {
   char* error_msg;
-  grpc_ares_request* r = static_cast<grpc_ares_request*>(arg);
+  GrpcAresQuery* q = static_cast<GrpcAresQuery*>(arg);
+  grpc_ares_request* r = q->parent_request();
   const size_t prefix_len = sizeof(g_service_config_attribute_prefix) - 1;
   struct ares_txt_ext* result = nullptr;
   struct ares_txt_ext* reply = nullptr;
   grpc_error* error = GRPC_ERROR_NONE;
   if (status != ARES_SUCCESS) goto fail;
-  GRPC_CARES_TRACE_LOG("request:%p on_txt_done_locked ARES_SUCCESS", r);
+  GRPC_CARES_TRACE_LOG("request:%p on_txt_done_locked name=%s ARES_SUCCESS", r,
+                       q->name().c_str());
   status = ares_parse_txt_reply_ext(buf, len, &reply);
   if (status != ARES_SUCCESS) goto fail;
   // Find service config in TXT record.
@@ -348,14 +391,16 @@ static void on_txt_done_locked(void* arg, int status, int /*timeouts*/,
   ares_free_data(reply);
   goto done;
 fail:
-  gpr_asprintf(&error_msg, "C-ares TXT lookup status is not ARES_SUCCESS: %s",
-               ares_strerror(status));
+  gpr_asprintf(&error_msg,
+               "C-ares status is not ARES_SUCCESS "
+               "qtype=TXT name=%s: %s",
+               q->name().c_str(), ares_strerror(status));
   error = GRPC_ERROR_CREATE_FROM_COPIED_STRING(error_msg);
   GRPC_CARES_TRACE_LOG("request:%p on_txt_done_locked %s", r, error_msg);
   gpr_free(error_msg);
   r->error = grpc_error_add_child(error, r->error);
 done:
-  grpc_ares_request_unref_locked(r);
+  delete q;
 }
 
 void grpc_dns_lookup_ares_continue_after_check_localhost_and_ip_literals_locked(
@@ -429,30 +474,30 @@ void grpc_dns_lookup_ares_continue_after_check_localhost_and_ip_literals_locked(
   if (grpc_ares_query_ipv6()) {
     hr = create_hostbyname_request_locked(r, host.c_str(),
                                           grpc_strhtons(port.c_str()),
-                                          /*is_balancer=*/false);
+                                          /*is_balancer=*/false, "AAAA");
     ares_gethostbyname(*channel, hr->host, AF_INET6, on_hostbyname_done_locked,
                        hr);
   }
   hr = create_hostbyname_request_locked(r, host.c_str(),
                                         grpc_strhtons(port.c_str()),
-                                        /*is_balancer=*/false);
+                                        /*is_balancer=*/false, "A");
   ares_gethostbyname(*channel, hr->host, AF_INET, on_hostbyname_done_locked,
                      hr);
   if (r->balancer_addresses_out != nullptr) {
     /* Query the SRV record */
-    grpc_ares_request_ref_locked(r);
     char* service_name;
     gpr_asprintf(&service_name, "_grpclb._tcp.%s", host.c_str());
+    GrpcAresQuery* srv_query = new GrpcAresQuery(r, service_name);
     ares_query(*channel, service_name, ns_c_in, ns_t_srv,
-               on_srv_query_done_locked, r);
+               on_srv_query_done_locked, srv_query);
     gpr_free(service_name);
   }
   if (r->service_config_json_out != nullptr) {
-    grpc_ares_request_ref_locked(r);
     char* config_name;
     gpr_asprintf(&config_name, "_grpc_config.%s", host.c_str());
+    GrpcAresQuery* txt_query = new GrpcAresQuery(r, config_name);
     ares_search(*channel, config_name, ns_c_in, ns_t_txt, on_txt_done_locked,
-                r);
+                txt_query);
     gpr_free(config_name);
   }
   grpc_ares_ev_driver_start_locked(r->ev_driver);
