Chiebot-Mirror
/
grpc
mirror of https://github.com/grpc/grpc.git
8
0
Fork 0
Code Issues Projects Releases Wiki Activity

Merge pull request #17495 from apolcyn/revise_ares_logging

Browse Source 
Put most c-ares logs under a tracer
pull/17529/head
apolcyn 6 years ago committed by GitHub
parent c542d44cb0 5ea2ed602b
commit 462d6143c9
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 74 additions and 58 deletions
Whitespace
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Split View
Diff Options
Show Stats Download Patch File Download Diff File
  1. 40
      src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc
  2. 43
      src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_ev_driver.cc
  3. 39
      src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_wrapper.cc

40
src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc
Unescape View File

@ -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
GRPC_CARES_TRACE_LOG(
"resolver:%p In cooldown from last resolution (from %" PRId64
" ms ago). Will resolve again in %" PRId64 " ms",
last_resolution_ago, ms_until_next_resolution);
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_;

43
src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_ev_driver.cc
Unescape View File

@ -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,7 +303,8 @@ 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",
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,7 +313,8 @@ 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",
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(
@ -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);

39
src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_wrapper.cc
Unescape View File

@ -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"
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",
output, ntohs(hr->port), addr.sin6_scope_id);
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"
GRPC_CARES_TRACE_LOG(
"request:%p c-ares resolver gets a AF_INET result: \n"
" addr: %s\n port: %d\n",
output, ntohs(hr->port));
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);

Write Preview
Loading…
Cancel
Save