Move most c-ares logs under a tracer
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 fc83fc4..abacd0c 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() {
- 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 @@
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::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 @@
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 @@
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 @@
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 @@
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::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 @@
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 @@
*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 8abc34c..d99c2e3 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 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 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 @@
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 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 @@
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 @@
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 @@
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 @@
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 @@
// 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 @@
// 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 @@
? 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 6897756..1a7e5d0 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 @@
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 @@
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 @@
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_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 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 @@
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 @@
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 @@
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 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 @@
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);
