Skip to content

Commit

Permalink
[Gpr_To_Absl_Logging] Replacing GRPC_ARES_RESOLVER_TRACE_LOG with GRP…
Browse files Browse the repository at this point in the history 
…C_TRACE_LOG (grpc#37434)

[Gpr_To_Absl_Logging] Replacing GRPC_ARES_RESOLVER_TRACE_LOG with GRPC_TRACE_LOG

Also, moved definition of GRPC_ARES_RESOLVER_TRACE_LOG from header to the cpp where it is being used to avoid more people from trying to use this macro

Closes grpc#37434

COPYBARA_INTEGRATE_REVIEW=grpc#37434 from tanvi-jagtap:remove_GRPC_ARES_RESOLVER_TRACE_LOG e7883d7
PiperOrigin-RevId: 661297848
  • Loading branch information
@tanvi-jagtap @ctiller
tanvi-jagtap authored and ctiller committed Aug 9, 2024
1 parent 43181f4 commit 2fea3db
Show file tree
Hide file tree
Showing 3 changed files with 82 additions and 63 deletions.
129 changes: 74 additions & 55 deletions src/core/lib/event_engine/ares_resolver.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -124,7 +124,8 @@ bool IsIpv6LoopbackAvailable() {

absl::Status SetRequestDNSServer(absl::string_view dns_server,
ares_channel* channel) {
GRPC_ARES_RESOLVER_TRACE_LOG("Using DNS server %s", dns_server.data());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) Using DNS server " << dns_server;
grpc_resolved_address addr;
struct ares_addr_port_node dns_server_addr = {};
if (grpc_parse_ipv4_hostport(dns_server, &addr, /*log_errors=*/false)) {
Expand Down Expand Up @@ -251,8 +252,9 @@ void AresResolver::Orphan() {
}
for (const auto& fd_node : fd_node_list_) {
if (!fd_node->already_shutdown) {
GRPC_ARES_RESOLVER_TRACE_LOG("resolver: %p shutdown fd: %s", this,
fd_node->polled_fd->GetName());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver: " << this
<< " shutdown fd: " << fd_node->polled_fd->GetName();
CHECK(fd_node->polled_fd->ShutdownLocked(
absl::CancelledError("AresResolver::Orphan")));
fd_node->already_shutdown = true;
Expand Down Expand Up @@ -423,8 +425,9 @@ void AresResolver::CheckSocketsLocked() {
fd_node_list_.begin(), fd_node_list_.end(),
[sock = socks[i]](const auto& node) { return node->as == sock; });
if (iter == fd_node_list_.end()) {
GRPC_ARES_RESOLVER_TRACE_LOG("resolver:%p new fd: %d", this,
socks[i]);
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver:" << this
<< " new fd: " << socks[i];
new_list.push_back(std::make_unique<FdNode>(
socks[i], polled_fd_factory_->NewGrpcPolledFdLocked(socks[i])));
} else {
Expand All @@ -440,8 +443,9 @@ void AresResolver::CheckSocketsLocked() {
// to cope with the edge-triggered poller not getting an event if no
// new data arrives and c-ares hasn't read all the data in the
// previous ares_process_fd.
GRPC_ARES_RESOLVER_TRACE_LOG(
"resolver:%p schedule read directly on: %d", this, fd_node->as);
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver:" << this
<< " schedule read directly on: " << fd_node->as;
event_engine_->Run(
[self = Ref(DEBUG_LOCATION, "CheckSocketsLocked"),
fd_node]() mutable {
Expand All @@ -450,8 +454,9 @@ void AresResolver::CheckSocketsLocked() {
});
} else {
// Otherwise register with the poller for readable event.
GRPC_ARES_RESOLVER_TRACE_LOG("resolver:%p notify read on: %d", this,
fd_node->as);
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver:" << this
<< " notify read on: " << fd_node->as;
fd_node->polled_fd->RegisterForOnReadableLocked(
[self = Ref(DEBUG_LOCATION, "CheckSocketsLocked"),
fd_node](absl::Status status) mutable {
Expand All @@ -464,8 +469,9 @@ void AresResolver::CheckSocketsLocked() {
// has not been registered with this socket.
if (ARES_GETSOCK_WRITABLE(socks_bitmask, i) &&
!fd_node->writable_registered) {
GRPC_ARES_RESOLVER_TRACE_LOG("resolver:%p notify write on: %d", this,
fd_node->as);
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver:" << this
<< " notify write on: " << fd_node->as;
fd_node->writable_registered = true;
fd_node->polled_fd->RegisterForOnWriteableLocked(
[self = Ref(DEBUG_LOCATION, "CheckSocketsLocked"),
Expand All @@ -487,14 +493,16 @@ void AresResolver::CheckSocketsLocked() {
while (!fd_node_list_.empty()) {
FdNode* fd_node = fd_node_list_.front().get();
if (!fd_node->already_shutdown) {
GRPC_ARES_RESOLVER_TRACE_LOG("resolver: %p shutdown fd: %s", this,
fd_node->polled_fd->GetName());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver: " << this
<< " shutdown fd: " << fd_node->polled_fd->GetName();
fd_node->already_shutdown =
fd_node->polled_fd->ShutdownLocked(absl::OkStatus());
}
if (!fd_node->readable_registered && !fd_node->writable_registered) {
GRPC_ARES_RESOLVER_TRACE_LOG("resolver: %p delete fd: %s", this,
fd_node->polled_fd->GetName());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver: " << this
<< " delete fd: " << fd_node->polled_fd->GetName();
fd_node_list_.pop_front();
} else {
new_list.splice(new_list.end(), fd_node_list_, fd_node_list_.begin());
Expand All @@ -508,9 +516,10 @@ void AresResolver::MaybeStartTimerLocked() {
return;
}
// Initialize the backup poll alarm
GRPC_ARES_RESOLVER_TRACE_LOG(
"request:%p MaybeStartTimerLocked next ares process poll time in %zu ms",
this, Milliseconds(kAresBackupPollAlarmDuration));
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) request:" << this
<< " MaybeStartTimerLocked next ares process poll time in "
<< Milliseconds(kAresBackupPollAlarmDuration) << " ms";
ares_backup_poll_alarm_handle_ = event_engine_->RunAfter(
kAresBackupPollAlarmDuration,
[self = Ref(DEBUG_LOCATION, "MaybeStartTimerLocked")]() {
Expand All @@ -522,8 +531,9 @@ void AresResolver::OnReadable(FdNode* fd_node, absl::Status status) {
grpc_core::MutexLock lock(&mutex_);
CHECK(fd_node->readable_registered);
fd_node->readable_registered = false;
GRPC_ARES_RESOLVER_TRACE_LOG("OnReadable: fd: %d; request: %p; status: %s",
fd_node->as, this, status.ToString().c_str());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) OnReadable: fd: " << fd_node->as
<< "; request: " << this << "; status: " << status;
if (status.ok() && !shutting_down_) {
ares_process_fd(channel_, fd_node->as, ARES_SOCKET_BAD);
} else {
Expand All @@ -541,8 +551,9 @@ void AresResolver::OnWritable(FdNode* fd_node, absl::Status status) {
grpc_core::MutexLock lock(&mutex_);
CHECK(fd_node->writable_registered);
fd_node->writable_registered = false;
GRPC_ARES_RESOLVER_TRACE_LOG("OnWritable: fd: %d; request:%p; status: %s",
fd_node->as, this, status.ToString().c_str());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) OnWritable: fd: " << fd_node->as
<< "; request:" << this << "; status: " << status;
if (status.ok() && !shutting_down_) {
ares_process_fd(channel_, ARES_SOCKET_BAD, fd_node->as);
} else {
Expand All @@ -567,15 +578,16 @@ void AresResolver::OnWritable(FdNode* fd_node, absl::Status status) {
void AresResolver::OnAresBackupPollAlarm() {
grpc_core::MutexLock lock(&mutex_);
ares_backup_poll_alarm_handle_.reset();
GRPC_ARES_RESOLVER_TRACE_LOG(
"request:%p OnAresBackupPollAlarm shutting_down=%d.", this,
shutting_down_);
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) request:" << this
<< " OnAresBackupPollAlarm shutting_down=" << shutting_down_;
if (!shutting_down_) {
for (const auto& fd_node : fd_node_list_) {
if (!fd_node->already_shutdown) {
GRPC_ARES_RESOLVER_TRACE_LOG(
"request:%p OnAresBackupPollAlarm; ares_process_fd. fd=%s", this,
fd_node->polled_fd->GetName());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) request:" << this
<< " OnAresBackupPollAlarm; ares_process_fd. fd="
<< fd_node->polled_fd->GetName();
ares_socket_t as = fd_node->polled_fd->GetWrappedAresSocketLocked();
ares_process_fd(channel_, as, as);
}
Expand All @@ -595,13 +607,15 @@ void AresResolver::OnHostbynameDoneLocked(void* arg, int status,
std::string error_msg =
absl::StrFormat("address lookup failed for %s: %s",
hostname_qa->query_name, ares_strerror(status));
GRPC_ARES_RESOLVER_TRACE_LOG("resolver:%p OnHostbynameDoneLocked: %s",
ares_resolver, error_msg.c_str());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver:" << ares_resolver
<< " OnHostbynameDoneLocked: " << error_msg;
hostname_qa->error_status = AresStatusToAbslStatus(status, error_msg);
} else {
GRPC_ARES_RESOLVER_TRACE_LOG(
"resolver:%p OnHostbynameDoneLocked name=%s ARES_SUCCESS",
ares_resolver, hostname_qa->query_name.c_str());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver:" << ares_resolver
<< " OnHostbynameDoneLocked name=" << hostname_qa->query_name
<< " ARES_SUCCESS";
for (size_t i = 0; hostent->h_addr_list[i] != nullptr; i++) {
if (hostname_qa->result.size() == kMaxRecordSize) {
LOG(ERROR) << "A/AAAA response exceeds maximum record size of 65536";
Expand All @@ -620,10 +634,11 @@ void AresResolver::OnHostbynameDoneLocked(void* arg, int status,
reinterpret_cast<const sockaddr*>(&addr), addr_len);
char output[INET6_ADDRSTRLEN];
ares_inet_ntop(AF_INET6, &addr.sin6_addr, output, INET6_ADDRSTRLEN);
GRPC_ARES_RESOLVER_TRACE_LOG(
"resolver:%p c-ares resolver gets a AF_INET6 result: \n"
" addr: %s\n port: %d\n sin6_scope_id: %d\n",
ares_resolver, output, hostname_qa->port, addr.sin6_scope_id);
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver:" << ares_resolver
<< " c-ares resolver gets a AF_INET6 result: \n addr: " << output
<< "\n port: " << hostname_qa->port
<< "\n sin6_scope_id: " << addr.sin6_scope_id;
break;
}
case AF_INET: {
Expand All @@ -638,10 +653,10 @@ void AresResolver::OnHostbynameDoneLocked(void* arg, int status,
reinterpret_cast<const sockaddr*>(&addr), addr_len);
char output[INET_ADDRSTRLEN];
ares_inet_ntop(AF_INET, &addr.sin_addr, output, INET_ADDRSTRLEN);
GRPC_ARES_RESOLVER_TRACE_LOG(
"resolver:%p c-ares resolver gets a AF_INET result: \n"
" addr: %s\n port: %d\n",
ares_resolver, output, hostname_qa->port);
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver:" << ares_resolver
<< " c-ares resolver gets a AF_INET result: \n addr: " << output
<< "\n port: " << hostname_qa->port;
break;
}
default:
Expand Down Expand Up @@ -689,8 +704,9 @@ void AresResolver::OnSRVQueryDoneLocked(void* arg, int status, int /*timeouts*/,
auto fail = [&](absl::string_view prefix) {
std::string error_message = absl::StrFormat(
"%s for %s: %s", prefix, qa->query_name, ares_strerror(status));
GRPC_ARES_RESOLVER_TRACE_LOG("OnSRVQueryDoneLocked: %s",
error_message.c_str());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) OnSRVQueryDoneLocked: "
<< error_message;
ares_resolver->event_engine_->Run(
[callback = std::move(callback),
status = AresStatusToAbslStatus(status, error_message)]() mutable {
Expand All @@ -701,13 +717,14 @@ void AresResolver::OnSRVQueryDoneLocked(void* arg, int status, int /*timeouts*/,
fail("SRV lookup failed");
return;
}
GRPC_ARES_RESOLVER_TRACE_LOG(
"resolver:%p OnSRVQueryDoneLocked name=%s ARES_SUCCESS", ares_resolver,
qa->query_name.c_str());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver:" << ares_resolver
<< " OnSRVQueryDoneLocked name=" << qa->query_name << " ARES_SUCCESS";
struct ares_srv_reply* reply = nullptr;
status = ares_parse_srv_reply(abuf, alen, &reply);
GRPC_ARES_RESOLVER_TRACE_LOG("resolver:%p ares_parse_srv_reply: %d",
ares_resolver, status);
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver:" << ares_resolver
<< " ares_parse_srv_reply: " << status;
if (status != ARES_SUCCESS) {
fail("Failed to parse SRV reply");
return;
Expand Down Expand Up @@ -748,8 +765,9 @@ void AresResolver::OnTXTDoneLocked(void* arg, int status, int /*timeouts*/,
auto fail = [&](absl::string_view prefix) {
std::string error_message = absl::StrFormat(
"%s for %s: %s", prefix, qa->query_name, ares_strerror(status));
GRPC_ARES_RESOLVER_TRACE_LOG("resolver:%p OnTXTDoneLocked: %s",
ares_resolver, error_message.c_str());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver:" << ares_resolver
<< " OnTXTDoneLocked: " << error_message;
ares_resolver->event_engine_->Run(
[callback = std::move(callback),
status = AresStatusToAbslStatus(status, error_message)]() mutable {
Expand All @@ -760,9 +778,9 @@ void AresResolver::OnTXTDoneLocked(void* arg, int status, int /*timeouts*/,
fail("TXT lookup failed");
return;
}
GRPC_ARES_RESOLVER_TRACE_LOG(
"resolver:%p OnTXTDoneLocked name=%s ARES_SUCCESS", ares_resolver,
qa->query_name.c_str());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver:" << ares_resolver
<< " OnTXTDoneLocked name=" << qa->query_name << " ARES_SUCCESS";
struct ares_txt_ext* reply = nullptr;
status = ares_parse_txt_reply_ext(buf, len, &reply);
if (status != ARES_SUCCESS) {
Expand All @@ -779,8 +797,9 @@ void AresResolver::OnTXTDoneLocked(void* arg, int status, int /*timeouts*/,
std::string(reinterpret_cast<char*>(part->txt), part->length));
}
}
GRPC_ARES_RESOLVER_TRACE_LOG("resolver:%p Got %zu TXT records", ares_resolver,
result.size());
GRPC_TRACE_LOG(cares_resolver, INFO)
<< "(EventEngine c-ares resolver) resolver:" << ares_resolver << " Got "
<< result.size() << " TXT records";
if (GRPC_TRACE_FLAG_ENABLED(cares_resolver)) {
for (const auto& record : result) {
LOG(INFO) << record;
Expand Down
8 changes: 0 additions & 8 deletions src/core/lib/event_engine/ares_resolver.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -47,14 +47,6 @@
namespace grpc_event_engine {
namespace experimental {

#define GRPC_ARES_RESOLVER_TRACE_LOG(format, ...) \
do { \
if (GRPC_TRACE_FLAG_ENABLED(cares_resolver)) { \
LOG(INFO) << "(EventEngine c-ares resolver) " \
<< absl::StrFormat(format, __VA_ARGS__); \
} \
} while (0)

class AresResolver : public RefCountedDNSResolverInterface {
public:
static absl::StatusOr<grpc_core::OrphanablePtr<AresResolver>>
Expand Down
8 changes: 8 additions & 0 deletions src/core/lib/event_engine/windows/grpc_polled_fd_windows.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -53,6 +53,14 @@ namespace grpc_event_engine {
namespace experimental {
namespace {

#define GRPC_ARES_RESOLVER_TRACE_LOG(format, ...) \
do { \
if (GRPC_TRACE_FLAG_ENABLED(cares_resolver)) { \
LOG(INFO) << "(EventEngine c-ares resolver) " \
<< absl::StrFormat(format, __VA_ARGS__); \
} \
} while (0)

constexpr int kRecvFromSourceAddrSize = 200;
constexpr int kReadBufferSize = 4192;

Expand Down

0 comments on commit 2fea3db

Please sign in to comment.