From 8e9e3f7f251fdb4cea333dc3b2721bef08f4d4e3 Mon Sep 17 00:00:00 2001 From: Tanvi Jagtap <139093547+tanvi-jagtap@users.noreply.github.com> Date: Thu, 4 Jul 2024 05:41:34 -0700 Subject: [PATCH 1/6] [Gpr_To_Absl_Logging] Migrating from gpr to absl logging - gpr_log (#37141) [Gpr_To_Absl_Logging] Migrating from gpr to absl logging - gpr_log In this CL we are migrating from gRPCs own gpr logging mechanism to absl logging mechanism. The intention is to deprecate gpr_log in the future. We have the following mapping 1. gpr_log(GPR_INFO,...) -> LOG(INFO) 2. gpr_log(GPR_ERROR,...) -> LOG(ERROR) 3. gpr_log(GPR_DEBUG,...) -> VLOG(2) Reviewers need to check : 1. If the above mapping is correct. 2. The content of the log is as before. gpr_log format strings did not use string_view or std::string . absl LOG accepts these. So there will be some elimination of string_view and std::string related conversions. This is expected. Closes #37141 COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/37141 from tanvi-jagtap:src_core_resolver_server bb2bf0de507c97c81258b3ec502b545a87277f17 PiperOrigin-RevId: 649385274 --- .../resolver/dns/c_ares/grpc_ares_wrapper.cc | 38 +++++------- .../resolver/dns/c_ares/grpc_ares_wrapper.h | 12 ++-- .../event_engine_client_channel_resolver.cc | 9 ++- src/core/resolver/dns/native/dns_resolver.cc | 13 ++-- src/core/resolver/xds/xds_resolver.cc | 61 +++++++++---------- src/core/server/server.cc | 32 ++++------ src/core/server/xds_server_config_fetcher.cc | 49 +++++++-------- 7 files changed, 94 insertions(+), 120 deletions(-) diff --git a/src/core/resolver/dns/c_ares/grpc_ares_wrapper.cc b/src/core/resolver/dns/c_ares/grpc_ares_wrapper.cc index b4b1df2d5ae..373727a9902 100644 --- a/src/core/resolver/dns/c_ares/grpc_ares_wrapper.cc +++ b/src/core/resolver/dns/c_ares/grpc_ares_wrapper.cc @@ -19,7 +19,6 @@ #include #include -#include "absl/log/log.h" #include "absl/strings/string_view.h" #include @@ -48,13 +47,13 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/status/statusor.h" #include "absl/strings/str_cat.h" #include "absl/strings/str_format.h" #include -#include #include #include @@ -556,12 +555,11 @@ static void log_address_sorting_list(const grpc_ares_request* r, const char* input_output_str) { for (size_t i = 0; i < addresses.size(); i++) { auto addr_str = grpc_sockaddr_to_string(&addresses[i].address(), true); - gpr_log(GPR_INFO, - "(c-ares resolver) request:%p c-ares address sorting: %s[%" PRIuPTR - "]=%s", - r, input_output_str, i, - addr_str.ok() ? addr_str->c_str() - : addr_str.status().ToString().c_str()); + LOG(INFO) << "(c-ares resolver) request:" << r + << " c-ares address sorting: " << input_output_str << "[" << i + << "]=" + << (addr_str.ok() ? addr_str->c_str() + : addr_str.status().ToString().c_str()); } } @@ -901,18 +899,14 @@ static bool inner_resolve_as_ip_literal_locked( std::unique_ptr* addrs, std::string* host, std::string* port, std::string* hostport) { if (!grpc_core::SplitHostPort(name, host, port)) { - gpr_log(GPR_ERROR, - "Failed to parse %s to host:port while attempting to resolve as ip " - "literal.", - name); + LOG(ERROR) << "Failed to parse " << name + << " to host:port while attempting to resolve as ip literal."; return false; } if (port->empty()) { if (default_port == nullptr || strlen(default_port) == 0) { - gpr_log(GPR_ERROR, - "No port or default port for %s while attempting to resolve as " - "ip literal.", - name); + LOG(ERROR) << "No port or default port for " << name + << " while attempting to resolve as ip literal."; return false; } *port = default_port; @@ -964,18 +958,14 @@ static bool inner_maybe_resolve_localhost_manually_locked( std::string* port) { grpc_core::SplitHostPort(name, host, port); if (host->empty()) { - gpr_log(GPR_ERROR, - "Failed to parse %s into host:port during manual localhost " - "resolution check.", - name); + LOG(ERROR) << "Failed to parse " << name + << " into host:port during manual localhost resolution check."; return false; } if (port->empty()) { if (default_port == nullptr || strlen(default_port) == 0) { - gpr_log(GPR_ERROR, - "No port or default port for %s during manual localhost " - "resolution check.", - name); + LOG(ERROR) << "No port or default port for " << name + << " during manual localhost resolution check."; return false; } *port = default_port; diff --git a/src/core/resolver/dns/c_ares/grpc_ares_wrapper.h b/src/core/resolver/dns/c_ares/grpc_ares_wrapper.h index 62a6d6471b8..9fdb94c0da8 100644 --- a/src/core/resolver/dns/c_ares/grpc_ares_wrapper.h +++ b/src/core/resolver/dns/c_ares/grpc_ares_wrapper.h @@ -26,8 +26,8 @@ #include #include "absl/base/thread_annotations.h" +#include "absl/log/log.h" -#include #include #include "src/core/lib/debug/trace.h" @@ -39,11 +39,11 @@ #define GRPC_DNS_ARES_DEFAULT_QUERY_TIMEOUT_MS 120000 -#define GRPC_CARES_TRACE_LOG(format, ...) \ - do { \ - if (GRPC_TRACE_FLAG_ENABLED(cares_resolver)) { \ - gpr_log(GPR_DEBUG, "(c-ares resolver) " format, __VA_ARGS__); \ - } \ +#define GRPC_CARES_TRACE_LOG(format, ...) \ + do { \ + if (GRPC_TRACE_FLAG_ENABLED(cares_resolver)) { \ + VLOG(2) << "(c-ares resolver) " << absl::StrFormat(format, __VA_ARGS__); \ + } \ } while (0) typedef struct grpc_ares_ev_driver grpc_ares_ev_driver; diff --git a/src/core/resolver/dns/event_engine/event_engine_client_channel_resolver.cc b/src/core/resolver/dns/event_engine/event_engine_client_channel_resolver.cc index d01c4abebaf..44ad3995857 100644 --- a/src/core/resolver/dns/event_engine/event_engine_client_channel_resolver.cc +++ b/src/core/resolver/dns/event_engine/event_engine_client_channel_resolver.cc @@ -36,7 +36,6 @@ #include #include -#include #include #include "src/core/lib/backoff/backoff.h" @@ -78,10 +77,10 @@ using grpc_event_engine::experimental::EventEngine; // TODO(hork): Add a test that checks for proper authority from balancer // addresses. -#define GRPC_EVENT_ENGINE_RESOLVER_TRACE(format, ...) \ - if (GRPC_TRACE_FLAG_ENABLED(event_engine_client_channel_resolver)) { \ - gpr_log(GPR_DEBUG, "(event_engine client channel resolver) " format, \ - __VA_ARGS__); \ +#define GRPC_EVENT_ENGINE_RESOLVER_TRACE(format, ...) \ + if (GRPC_TRACE_FLAG_ENABLED(event_engine_client_channel_resolver)) { \ + VLOG(2) << "(event_engine client channel resolver) " \ + << absl::StrFormat(format, __VA_ARGS__); \ } // ---------------------------------------------------------------------------- diff --git a/src/core/resolver/dns/native/dns_resolver.cc b/src/core/resolver/dns/native/dns_resolver.cc index 90432554059..0fb59889d06 100644 --- a/src/core/resolver/dns/native/dns_resolver.cc +++ b/src/core/resolver/dns/native/dns_resolver.cc @@ -29,7 +29,6 @@ #include "absl/types/optional.h" #include -#include #include #include "src/core/lib/backoff/backoff.h" @@ -92,13 +91,13 @@ NativeClientChannelDNSResolver::NativeClientChannelDNSResolver( GRPC_DNS_RECONNECT_MAX_BACKOFF_SECONDS * 1000)), &dns_resolver_trace) { if (GRPC_TRACE_FLAG_ENABLED(dns_resolver)) { - gpr_log(GPR_DEBUG, "[dns_resolver=%p] created", this); + VLOG(2) << "[dns_resolver=" << this << "] created"; } } NativeClientChannelDNSResolver::~NativeClientChannelDNSResolver() { if (GRPC_TRACE_FLAG_ENABLED(dns_resolver)) { - gpr_log(GPR_DEBUG, "[dns_resolver=%p] destroyed", this); + VLOG(2) << "[dns_resolver=" << this << "] destroyed"; } } @@ -109,8 +108,8 @@ OrphanablePtr NativeClientChannelDNSResolver::StartRequest() { name_to_resolve(), kDefaultSecurePort, kDefaultDNSRequestTimeout, interested_parties(), /*name_server=*/""); if (GRPC_TRACE_FLAG_ENABLED(dns_resolver)) { - gpr_log(GPR_DEBUG, "[dns_resolver=%p] starting request=%p", this, - DNSResolver::HandleToString(dns_request_handle).c_str()); + VLOG(2) << "[dns_resolver=" << this << "] starting request=" + << DNSResolver::HandleToString(dns_request_handle); } return MakeOrphanable(); } @@ -118,8 +117,8 @@ OrphanablePtr NativeClientChannelDNSResolver::StartRequest() { void NativeClientChannelDNSResolver::OnResolved( absl::StatusOr> addresses_or) { if (GRPC_TRACE_FLAG_ENABLED(dns_resolver)) { - gpr_log(GPR_DEBUG, "[dns_resolver=%p] request complete, status=\"%s\"", - this, addresses_or.status().ToString().c_str()); + VLOG(2) << "[dns_resolver=" << this + << "] request complete, status=" << addresses_or.status(); } // Convert result from iomgr DNS API into Resolver::Result. Result result; diff --git a/src/core/resolver/xds/xds_resolver.cc b/src/core/resolver/xds/xds_resolver.cc index 4933d5f1954..30b17f22c0f 100644 --- a/src/core/resolver/xds/xds_resolver.cc +++ b/src/core/resolver/xds/xds_resolver.cc @@ -27,6 +27,7 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/meta/type_traits.h" #include "absl/random/random.h" #include "absl/status/status.h" @@ -45,7 +46,6 @@ #include #include #include -#include #include #include "src/core/client_channel/client_channel_internal.h" @@ -111,16 +111,15 @@ class XdsResolver final : public Resolver { data_plane_authority_(std::move(data_plane_authority)), channel_id_(absl::Uniform(absl::BitGen())) { if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { - gpr_log( - GPR_INFO, - "[xds_resolver %p] created for URI %s; data plane authority is %s", - this, uri_.ToString().c_str(), data_plane_authority_.c_str()); + LOG(INFO) << "[xds_resolver " << this << "] created for URI " + << uri_.ToString() << "; data plane authority is " + << data_plane_authority_; } } ~XdsResolver() override { if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { - gpr_log(GPR_INFO, "[xds_resolver %p] destroyed", this); + LOG(INFO) << "[xds_resolver " << this << "] destroyed"; } } @@ -538,8 +537,8 @@ absl::Status XdsResolver::RouteConfigData::AddRouteEntry( XdsResolver* resolver, const XdsRouteConfigResource::Route& route, const Duration& default_max_stream_duration) { if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { - gpr_log(GPR_INFO, "[xds_resolver %p] XdsConfigSelector %p: route: %s", - resolver, this, route.ToString().c_str()); + LOG(INFO) << "[xds_resolver " << resolver << "] XdsConfigSelector " << this + << ": route: " << route.ToString(); } routes_.emplace_back(route); auto* route_entry = &routes_.back(); @@ -630,8 +629,8 @@ XdsResolver::XdsConfigSelector::XdsConfigSelector( : resolver_(std::move(resolver)), route_config_data_(std::move(route_config_data)) { if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { - gpr_log(GPR_INFO, "[xds_resolver %p] creating XdsConfigSelector %p", - resolver_.get(), this); + LOG(INFO) << "[xds_resolver " << resolver_.get() + << "] creating XdsConfigSelector " << this; } // Populate filter list. const auto& http_filter_registry = @@ -653,8 +652,8 @@ XdsResolver::XdsConfigSelector::XdsConfigSelector( XdsResolver::XdsConfigSelector::~XdsConfigSelector() { if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { - gpr_log(GPR_INFO, "[xds_resolver %p] destroying XdsConfigSelector %p", - resolver_.get(), this); + LOG(INFO) << "[xds_resolver " << resolver_.get() + << "] destroying XdsConfigSelector " << this; } route_config_data_.reset(); if (!IsWorkSerializerDispatchEnabled()) { @@ -897,10 +896,9 @@ void XdsResolver::StartLocked() { auto xds_client = GrpcXdsClient::GetOrCreate(uri_.ToString(), args_, "xds resolver"); if (!xds_client.ok()) { - gpr_log(GPR_ERROR, - "Failed to create xds client -- channel will remain in " - "TRANSIENT_FAILURE: %s", - xds_client.status().ToString().c_str()); + LOG(ERROR) << "Failed to create xds client -- channel will remain in " + "TRANSIENT_FAILURE: " + << xds_client.status(); absl::Status status = absl::UnavailableError(absl::StrCat( "Failed to create XdsClient: ", xds_client.status().message())); Result result; @@ -956,8 +954,8 @@ void XdsResolver::StartLocked() { absl::StrReplaceAll(name_template, {{"%s", resource_name_fragment}}); } if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { - gpr_log(GPR_INFO, "[xds_resolver %p] Started with lds_resource_name %s.", - this, lds_resource_name_.c_str()); + LOG(INFO) << "[xds_resolver " << this << "] Started with lds_resource_name " + << lds_resource_name_; } // Start watch for xDS config. dependency_mgr_ = MakeOrphanable( @@ -968,7 +966,7 @@ void XdsResolver::StartLocked() { void XdsResolver::ShutdownLocked() { if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { - gpr_log(GPR_INFO, "[xds_resolver %p] shutting down", this); + LOG(INFO) << "[xds_resolver " << this << "] shutting down"; } if (xds_client_ != nullptr) { dependency_mgr_.reset(); @@ -981,7 +979,7 @@ void XdsResolver::ShutdownLocked() { void XdsResolver::OnUpdate( RefCountedPtr config) { if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { - gpr_log(GPR_INFO, "[xds_resolver %p] received updated xDS config", this); + LOG(INFO) << "[xds_resolver " << this << "] received updated xDS config"; } if (xds_client_ == nullptr) return; current_config_ = std::move(config); @@ -989,8 +987,9 @@ void XdsResolver::OnUpdate( } void XdsResolver::OnError(absl::string_view context, absl::Status status) { - gpr_log(GPR_ERROR, "[xds_resolver %p] received error from XdsClient: %s: %s", - this, std::string(context).c_str(), status.ToString().c_str()); + LOG(ERROR) << "[xds_resolver " << this + << "] received error from XdsClient: " << context << ": " + << status; if (xds_client_ == nullptr) return; status = absl::UnavailableError(absl::StrCat(context, ": ", status.ToString())); @@ -1003,10 +1002,9 @@ void XdsResolver::OnError(absl::string_view context, absl::Status status) { } void XdsResolver::OnResourceDoesNotExist(std::string context) { - gpr_log(GPR_ERROR, - "[xds_resolver %p] LDS/RDS resource does not exist -- clearing " - "update and returning empty service config", - this); + LOG(ERROR) << "[xds_resolver " << this + << "] LDS/RDS resource does not exist -- clearing " + "update and returning empty service config"; if (xds_client_ == nullptr) return; current_config_.reset(); Result result; @@ -1080,10 +1078,10 @@ void XdsResolver::GenerateResult() { result.addresses.emplace(); result.service_config = CreateServiceConfig(); if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { - gpr_log(GPR_INFO, "[xds_resolver %p] generated service config: %s", this, - result.service_config.ok() - ? std::string((*result.service_config)->json_string()).c_str() - : result.service_config.status().ToString().c_str()); + LOG(INFO) << "[xds_resolver " << this << "] generated service config: " + << (result.service_config.ok() + ? ((*result.service_config)->json_string()) + : result.service_config.status().ToString()); } result.args = args_.SetObject(xds_client_.Ref(DEBUG_LOCATION, "xds resolver result")) @@ -1117,8 +1115,7 @@ class XdsResolverFactory final : public ResolverFactory { bool IsValidUri(const URI& uri) const override { if (uri.path().empty() || uri.path().back() == '/') { - gpr_log(GPR_ERROR, - "URI path does not contain valid data plane authority"); + LOG(ERROR) << "URI path does not contain valid data plane authority"; return false; } return true; diff --git a/src/core/server/server.cc b/src/core/server/server.cc index 6b1ead984db..8e7ce047562 100644 --- a/src/core/server/server.cc +++ b/src/core/server/server.cc @@ -43,7 +43,6 @@ #include #include #include -#include #include #include @@ -1050,19 +1049,18 @@ Server::RegisteredMethod* Server::RegisterMethod( } if (!method) { - gpr_log(GPR_ERROR, - "grpc_server_register_method method string cannot be NULL"); + LOG(ERROR) << "grpc_server_register_method method string cannot be NULL"; return nullptr; } auto key = std::make_pair(host ? host : "", method); if (registered_methods_.find(key) != registered_methods_.end()) { - gpr_log(GPR_ERROR, "duplicate registration for %s@%s", method, - host ? host : "*"); + LOG(ERROR) << "duplicate registration for " << method << "@" + << (host ? host : "*"); return nullptr; } if (flags != 0) { - gpr_log(GPR_ERROR, "grpc_server_register_method invalid flags 0x%08x", - flags); + LOG(ERROR) << "grpc_server_register_method invalid flags " + << absl::StrFormat("0x%08x", flags); return nullptr; } auto it = registered_methods_.emplace( @@ -1100,12 +1098,11 @@ void Server::MaybeFinishShutdown() { last_shutdown_message_time_), gpr_time_from_seconds(1, GPR_TIMESPAN)) >= 0) { last_shutdown_message_time_ = gpr_now(GPR_CLOCK_REALTIME); - gpr_log(GPR_DEBUG, - "Waiting for %" PRIuPTR " channels %" PRIuPTR - " connections and %" PRIuPTR "/%" PRIuPTR - " listeners to be destroyed before shutting down server", - channels_.size(), connections_open_, - listeners_.size() - listeners_destroyed_, listeners_.size()); + VLOG(2) << "Waiting for " << channels_.size() << " channels " + << connections_open_ << " connections and " + << listeners_.size() - listeners_destroyed_ << "/" + << listeners_.size() + << " listeners to be destroyed before shutting down server"; } return; } @@ -1673,8 +1670,7 @@ void Server::CallData::RecvInitialMetadataBatchComplete( grpc_call_element* elem = static_cast(arg); auto* calld = static_cast(elem->call_data); if (!error.ok()) { - gpr_log(GPR_DEBUG, "Failed call creation: %s", - StatusToString(error).c_str()); + VLOG(2) << "Failed call creation: " << StatusToString(error); calld->FailCallCreation(); return; } @@ -1798,10 +1794,8 @@ void grpc_server_register_completion_queue(grpc_server* server, CHECK(!reserved); auto cq_type = grpc_get_cq_completion_type(cq); if (cq_type != GRPC_CQ_NEXT && cq_type != GRPC_CQ_CALLBACK) { - gpr_log(GPR_INFO, - "Completion queue of type %d is being registered as a " - "server-completion-queue", - static_cast(cq_type)); + LOG(INFO) << "Completion queue of type " << static_cast(cq_type) + << " is being registered as a server-completion-queue"; // Ideally we should log an error and abort but ruby-wrapped-language API // calls grpc_completion_queue_pluck() on server completion queues } diff --git a/src/core/server/xds_server_config_fetcher.cc b/src/core/server/xds_server_config_fetcher.cc index 1366b0702fa..3592baba176 100644 --- a/src/core/server/xds_server_config_fetcher.cc +++ b/src/core/server/xds_server_config_fetcher.cc @@ -28,6 +28,7 @@ #include "absl/base/thread_annotations.h" #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/status/statusor.h" #include "absl/strings/match.h" @@ -44,7 +45,6 @@ #include #include #include -#include #include #include "src/core/lib/address_utils/parse_address.h" @@ -588,9 +588,9 @@ void XdsServerConfigFetcher::ListenerWatcher::OnResourceChanged( std::shared_ptr listener, RefCountedPtr /* read_delay_handle */) { if (GRPC_TRACE_FLAG_ENABLED(xds_server_config_fetcher)) { - gpr_log(GPR_INFO, - "[ListenerWatcher %p] Received LDS update from xds client %p: %s", - this, xds_client_.get(), listener->ToString().c_str()); + LOG(INFO) << "[ListenerWatcher " << this + << "] Received LDS update from xds client " << xds_client_.get() + << ": " << listener->ToString(); } auto* tcp_listener = absl::get_if(&listener->listener); @@ -628,20 +628,19 @@ void XdsServerConfigFetcher::ListenerWatcher::OnError( MutexLock lock(&mu_); if (filter_chain_match_manager_ != nullptr || pending_filter_chain_match_manager_ != nullptr) { - gpr_log(GPR_ERROR, - "ListenerWatcher:%p XdsClient reports error: %s for %s; " - "ignoring in favor of existing resource", - this, status.ToString().c_str(), listening_address_.c_str()); + LOG(ERROR) << "ListenerWatcher:" << this + << " XdsClient reports error: " << status << " for " + << listening_address_ + << "; ignoring in favor of existing resource"; } else { if (serving_status_notifier_.on_serving_status_update != nullptr) { serving_status_notifier_.on_serving_status_update( serving_status_notifier_.user_data, listening_address_.c_str(), {GRPC_STATUS_UNAVAILABLE, status.ToString().c_str()}); } else { - gpr_log(GPR_ERROR, - "ListenerWatcher:%p error obtaining xDS Listener resource: %s; " - "not serving on %s", - this, status.ToString().c_str(), listening_address_.c_str()); + LOG(ERROR) << "ListenerWatcher:" << this + << " error obtaining xDS Listener resource: " << status + << "; not serving on " << listening_address_; } } } @@ -661,9 +660,8 @@ void XdsServerConfigFetcher::ListenerWatcher::OnFatalError( {static_cast(status.raw_code()), std::string(status.message()).c_str()}); } else { - gpr_log(GPR_ERROR, - "ListenerWatcher:%p Encountered fatal error %s; not serving on %s", - this, status.ToString().c_str(), listening_address_.c_str()); + LOG(ERROR) << "ListenerWatcher:" << this << " Encountered fatal error " + << status << "; not serving on " << listening_address_; } } @@ -689,9 +687,8 @@ void XdsServerConfigFetcher::ListenerWatcher:: serving_status_notifier_.user_data, listening_address_.c_str(), {GRPC_STATUS_OK, ""}); } else { - gpr_log(GPR_INFO, - "xDS Listener resource obtained; will start serving on %s", - listening_address_.c_str()); + LOG(INFO) << "xDS Listener resource obtained; will start serving on " + << listening_address_; } } // Promote the pending FilterChainMatchManager @@ -996,8 +993,8 @@ const XdsListenerResource::FilterChainData* FindFilterChainDataForSourceType( } auto source_addr = StringToSockaddr(host, 0); // Port doesn't matter here. if (!source_addr.ok()) { - gpr_log(GPR_DEBUG, "Could not parse \"%s\" as socket address: %s", - host.c_str(), source_addr.status().ToString().c_str()); + VLOG(2) << "Could not parse \"" << host + << "\" as socket address: " << source_addr.status(); return nullptr; } // Use kAny only if kSameIporLoopback and kExternal are empty @@ -1045,8 +1042,8 @@ const XdsListenerResource::FilterChainData* FindFilterChainDataForDestinationIp( auto destination_addr = StringToSockaddr(host, 0); // Port doesn't matter here. if (!destination_addr.ok()) { - gpr_log(GPR_DEBUG, "Could not parse \"%s\" as socket address: %s", - host.c_str(), destination_addr.status().ToString().c_str()); + VLOG(2) << "Could not parse \"" << host + << "\" as socket address: " << destination_addr.status(); return nullptr; } const XdsListenerResource::FilterChainMap::DestinationIp* best_match = @@ -1376,17 +1373,15 @@ grpc_server_config_fetcher* grpc_server_config_fetcher_xds_create( grpc_core::GrpcXdsClient::kServerKey, channel_args, "XdsServerConfigFetcher"); if (!xds_client.ok()) { - gpr_log(GPR_ERROR, "Failed to create xds client: %s", - xds_client.status().ToString().c_str()); + LOG(ERROR) << "Failed to create xds client: " << xds_client.status(); return nullptr; } if (static_cast( (*xds_client)->bootstrap()) .server_listener_resource_name_template() .empty()) { - gpr_log(GPR_ERROR, - "server_listener_resource_name_template not provided in bootstrap " - "file."); + LOG(ERROR) << "server_listener_resource_name_template not provided in " + "bootstrap file."; return nullptr; } return new grpc_core::XdsServerConfigFetcher(std::move(*xds_client), From f91af6587d9d46eb56e45c4c45c732a509220fff Mon Sep 17 00:00:00 2001 From: Tanvi Jagtap Date: Thu, 4 Jul 2024 06:32:34 -0700 Subject: [PATCH 2/6] [Gpr_To_Absl_Logging] Remove custom gpr_log macros Removing GRPC_IDLE_FILTER_LOG. Replacing with GRPC_TRACE_LOG. Reference : https://github.com/search?q=repo%3Agrpc%2Fgrpc+%22%23define+GRPC_TRACE_LOG%22&type=code PiperOrigin-RevId: 649395611 --- .../filters/channel_idle/legacy_channel_idle_filter.cc | 10 ++-------- 1 file changed, 2 insertions(+), 8 deletions(-) diff --git a/src/core/ext/filters/channel_idle/legacy_channel_idle_filter.cc b/src/core/ext/filters/channel_idle/legacy_channel_idle_filter.cc index 22cfdc00baf..6d16ac68b7d 100644 --- a/src/core/ext/filters/channel_idle/legacy_channel_idle_filter.cc +++ b/src/core/ext/filters/channel_idle/legacy_channel_idle_filter.cc @@ -71,13 +71,6 @@ const auto kMaxConnectionAgeJitter = 0.1; } // namespace -#define GRPC_IDLE_FILTER_LOG(format, ...) \ - do { \ - if (GRPC_TRACE_FLAG_ENABLED(client_idle_filter)) { \ - gpr_log(GPR_INFO, "(client idle filter) " format, ##__VA_ARGS__); \ - } \ - } while (0) - Duration GetClientIdleTimeout(const ChannelArgs& args) { return args.GetDurationFromIntMillis(GRPC_ARG_CLIENT_IDLE_TIMEOUT_MS) .value_or(kDefaultIdleTimeout); @@ -259,7 +252,8 @@ void LegacyChannelIdleFilter::DecreaseCallCount() { } void LegacyChannelIdleFilter::StartIdleTimer() { - GRPC_IDLE_FILTER_LOG("timer has started"); + GRPC_TRACE_LOG(client_idle_filter, INFO) + << "(client idle filter) timer has started"; auto idle_filter_state = idle_filter_state_; // Hold a ref to the channel stack for the timer callback. auto channel_stack = channel_stack_->Ref(); From 1a1c36b1ce1d65e71b32543f6adde9efe2ee2f85 Mon Sep 17 00:00:00 2001 From: Tanvi Jagtap <139093547+tanvi-jagtap@users.noreply.github.com> Date: Thu, 4 Jul 2024 07:30:14 -0700 Subject: [PATCH 3/6] [Gpr_To_Absl_Logging] Migrating from gpr to absl logging - gpr_log (#37066) [Gpr_To_Absl_Logging] Migrating from gpr to absl logging - gpr_log In this CL we are migrating from gRPCs own gpr logging mechanism to absl logging mechanism. The intention is to deprecate gpr_log in the future. We have the following mapping 1. gpr_log(GPR_INFO,...) -> LOG(INFO) 2. gpr_log(GPR_ERROR,...) -> LOG(ERROR) 3. gpr_log(GPR_DEBUG,...) -> VLOG(2) Reviewers need to check : 1. If the above mapping is correct. 2. The content of the log is as before. gpr_log format strings did not use string_view or std::string . absl LOG accepts these. So there will be some elimination of string_view and std::string related conversions. This is expected. Closes #37066 COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/37066 from tanvi-jagtap:src_core_lib_iomgr e525aa11f141ef7dafe11f116c501a9c053ce865 PiperOrigin-RevId: 649406608 --- src/core/lib/iomgr/call_combiner.cc | 72 ++++++--------- src/core/lib/iomgr/combiner.cc | 69 +++++++-------- src/core/lib/iomgr/endpoint_cfstream.cc | 46 +++++----- src/core/lib/iomgr/ev_epoll1_linux.cc | 69 +++++++-------- src/core/lib/iomgr/timer_generic.cc | 113 +++++++++++------------- 5 files changed, 162 insertions(+), 207 deletions(-) diff --git a/src/core/lib/iomgr/call_combiner.cc b/src/core/lib/iomgr/call_combiner.cc index 21d9edef063..26bb7b881db 100644 --- a/src/core/lib/iomgr/call_combiner.cc +++ b/src/core/lib/iomgr/call_combiner.cc @@ -23,7 +23,6 @@ #include "absl/log/check.h" #include "absl/log/log.h" -#include #include #include "src/core/lib/gprpp/crash.h" @@ -114,19 +113,15 @@ void CallCombiner::ScheduleClosure(grpc_closure* closure, void CallCombiner::Start(grpc_closure* closure, grpc_error_handle error, DEBUG_ARGS const char* reason) { - if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { - gpr_log(GPR_INFO, - "==> CallCombiner::Start() [%p] closure=%s [" DEBUG_FMT_STR - "%s] error=%s", - this, closure->DebugString().c_str() DEBUG_FMT_ARGS, reason, - StatusToString(error).c_str()); - } + GRPC_TRACE_LOG(call_combiner, INFO) << absl::StrFormat( + "==> CallCombiner::Start() [%p] closure=%s [" DEBUG_FMT_STR + "%s] error=%s", + this, closure->DebugString().c_str() DEBUG_FMT_ARGS, reason, + StatusToString(error).c_str()); size_t prev_size = static_cast(gpr_atm_full_fetch_add(&size_, (gpr_atm)1)); - if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { - gpr_log(GPR_INFO, " size: %" PRIdPTR " -> %" PRIdPTR, prev_size, - prev_size + 1); - } + GRPC_TRACE_LOG(call_combiner, INFO) + << " size: " << prev_size << " -> " << prev_size + 1; if (prev_size == 0) { GRPC_TRACE_LOG(call_combiner, INFO) << " EXECUTING IMMEDIATELY"; // Queue was empty, so execute this closure immediately. @@ -141,16 +136,13 @@ void CallCombiner::Start(grpc_closure* closure, grpc_error_handle error, } void CallCombiner::Stop(DEBUG_ARGS const char* reason) { - if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { - gpr_log(GPR_INFO, "==> CallCombiner::Stop() [%p] [" DEBUG_FMT_STR "%s]", - this DEBUG_FMT_ARGS, reason); - } + GRPC_TRACE_LOG(call_combiner, INFO) + << absl::StrFormat("==> CallCombiner::Stop() [%p] [" DEBUG_FMT_STR "%s]", + this DEBUG_FMT_ARGS, reason); size_t prev_size = static_cast(gpr_atm_full_fetch_add(&size_, (gpr_atm)-1)); - if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { - gpr_log(GPR_INFO, " size: %" PRIdPTR " -> %" PRIdPTR, prev_size, - prev_size - 1); - } + GRPC_TRACE_LOG(call_combiner, INFO) + << " size: " << prev_size << " -> " << prev_size - 1; CHECK_GE(prev_size, 1u); if (prev_size > 1) { while (true) { @@ -168,10 +160,9 @@ void CallCombiner::Stop(DEBUG_ARGS const char* reason) { grpc_error_handle error = internal::StatusMoveFromHeapPtr(closure->error_data.error); closure->error_data.error = 0; - if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { - gpr_log(GPR_INFO, " EXECUTING FROM QUEUE: closure=%s error=%s", - closure->DebugString().c_str(), StatusToString(error).c_str()); - } + GRPC_TRACE_LOG(call_combiner, INFO) + << " EXECUTING FROM QUEUE: closure=" << closure->DebugString() + << " error=" << StatusToString(error); ScheduleClosure(closure, error); break; } @@ -187,31 +178,26 @@ void CallCombiner::SetNotifyOnCancel(grpc_closure* closure) { // If error is set, invoke the cancellation closure immediately. // Otherwise, store the new closure. if (!original_error.ok()) { - if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { - gpr_log(GPR_INFO, - "call_combiner=%p: scheduling notify_on_cancel callback=%p " - "for pre-existing cancellation", - this, closure); - } + GRPC_TRACE_LOG(call_combiner, INFO) + << "call_combiner=" << this + << ": scheduling notify_on_cancel callback=" << closure + << " for pre-existing cancellation"; ExecCtx::Run(DEBUG_LOCATION, closure, original_error); break; } else { if (gpr_atm_full_cas(&cancel_state_, original_state, reinterpret_cast(closure))) { - if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { - gpr_log(GPR_INFO, "call_combiner=%p: setting notify_on_cancel=%p", - this, closure); - } + GRPC_TRACE_LOG(call_combiner, INFO) + << "call_combiner=" << this + << ": setting notify_on_cancel=" << closure; // If we replaced an earlier closure, invoke the original // closure with absl::OkStatus(). This allows callers to clean // up any resources they may be holding for the callback. if (original_state != 0) { closure = reinterpret_cast(original_state); - if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { - gpr_log(GPR_INFO, - "call_combiner=%p: scheduling old cancel callback=%p", this, - closure); - } + GRPC_TRACE_LOG(call_combiner, INFO) + << "call_combiner=" << this + << ": scheduling old cancel callback=" << closure; ExecCtx::Run(DEBUG_LOCATION, closure, absl::OkStatus()); } break; @@ -235,11 +221,9 @@ void CallCombiner::Cancel(grpc_error_handle error) { if (original_state != 0) { grpc_closure* notify_on_cancel = reinterpret_cast(original_state); - if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { - gpr_log(GPR_INFO, - "call_combiner=%p: scheduling notify_on_cancel callback=%p", - this, notify_on_cancel); - } + GRPC_TRACE_LOG(call_combiner, INFO) + << "call_combiner=" << this + << ": scheduling notify_on_cancel callback=" << notify_on_cancel; ExecCtx::Run(DEBUG_LOCATION, notify_on_cancel, error); } break; diff --git a/src/core/lib/iomgr/combiner.cc b/src/core/lib/iomgr/combiner.cc index 348df4a0cb6..7032c40f768 100644 --- a/src/core/lib/iomgr/combiner.cc +++ b/src/core/lib/iomgr/combiner.cc @@ -23,9 +23,9 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include -#include #include #include "src/core/lib/experiments/experiments.h" @@ -34,13 +34,6 @@ #include "src/core/lib/iomgr/executor.h" #include "src/core/lib/iomgr/iomgr_internal.h" -#define GRPC_COMBINER_TRACE(fn) \ - do { \ - if (GRPC_TRACE_FLAG_ENABLED(combiner)) { \ - fn; \ - } \ - } while (0) - #define STATE_UNORPHANED 1 #define STATE_ELEM_COUNT_LOW_BIT 2 @@ -58,32 +51,33 @@ grpc_core::Combiner* grpc_combiner_create( gpr_ref_init(&lock->refs, 1); gpr_atm_no_barrier_store(&lock->state, STATE_UNORPHANED); grpc_closure_list_init(&lock->final_list); - GRPC_COMBINER_TRACE(gpr_log(GPR_INFO, "C:%p create", lock)); + GRPC_TRACE_LOG(combiner, INFO) << "C:" << lock << " create"; return lock; } static void really_destroy(grpc_core::Combiner* lock) { - GRPC_COMBINER_TRACE(gpr_log(GPR_INFO, "C:%p really_destroy", lock)); + GRPC_TRACE_LOG(combiner, INFO) << "C:" << lock << " really_destroy"; CHECK_EQ(gpr_atm_no_barrier_load(&lock->state), 0); delete lock; } static void start_destroy(grpc_core::Combiner* lock) { gpr_atm old_state = gpr_atm_full_fetch_add(&lock->state, -STATE_UNORPHANED); - GRPC_COMBINER_TRACE(gpr_log( - GPR_INFO, "C:%p really_destroy old_state=%" PRIdPTR, lock, old_state)); + GRPC_TRACE_LOG(combiner, INFO) + << "C:" << lock << " really_destroy old_state=" << old_state; if (old_state == 1) { really_destroy(lock); } } #ifndef NDEBUG -#define GRPC_COMBINER_DEBUG_SPAM(op, delta) \ - if (GRPC_TRACE_FLAG_ENABLED(combiner)) { \ - gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG, \ - "C:%p %s %" PRIdPTR " --> %" PRIdPTR " %s", lock, (op), \ - gpr_atm_no_barrier_load(&lock->refs.count), \ - gpr_atm_no_barrier_load(&lock->refs.count) + (delta), reason); \ +#define GRPC_COMBINER_DEBUG_SPAM(op, delta) \ + if (GRPC_TRACE_FLAG_ENABLED(combiner)) { \ + VLOG(2).AtLocation(file, line) \ + << "C:" << lock << " " << (op) << " " \ + << gpr_atm_no_barrier_load(&lock->refs.count) << " --> " \ + << gpr_atm_no_barrier_load(&lock->refs.count) + (delta) << " " \ + << reason; \ } #else #define GRPC_COMBINER_DEBUG_SPAM(op, delta) @@ -128,9 +122,8 @@ static void push_first_on_exec_ctx(grpc_core::Combiner* lock) { static void combiner_exec(grpc_core::Combiner* lock, grpc_closure* cl, grpc_error_handle error) { gpr_atm last = gpr_atm_full_fetch_add(&lock->state, STATE_ELEM_COUNT_LOW_BIT); - GRPC_COMBINER_TRACE(gpr_log(GPR_INFO, - "C:%p grpc_combiner_execute c=%p last=%" PRIdPTR, - lock, cl, last)); + GRPC_TRACE_LOG(combiner, INFO) + << "C:" << lock << " grpc_combiner_execute c=" << cl << " last=" << last; if (last == 1) { gpr_atm_no_barrier_store( &lock->initiating_exec_ctx_or_null, @@ -169,7 +162,7 @@ static void queue_offload(grpc_core::Combiner* lock) { // Make the combiner look uncontended by storing a non-null value here, so // that we don't immediately offload again. gpr_atm_no_barrier_store(&lock->initiating_exec_ctx_or_null, 1); - GRPC_COMBINER_TRACE(gpr_log(GPR_INFO, "C:%p queue_offload", lock)); + GRPC_TRACE_LOG(combiner, INFO) << "C:" << lock << " queue_offload"; lock->event_engine->Run([lock] { grpc_core::ApplicationCallbackExecCtx callback_exec_ctx; grpc_core::ExecCtx exec_ctx(0); @@ -188,14 +181,11 @@ bool grpc_combiner_continue_exec_ctx() { bool contended = gpr_atm_no_barrier_load(&lock->initiating_exec_ctx_or_null) == 0; - GRPC_COMBINER_TRACE(gpr_log(GPR_INFO, - "C:%p grpc_combiner_continue_exec_ctx " - "contended=%d " - "exec_ctx_ready_to_finish=%d " - "time_to_execute_final_list=%d", - lock, contended, - grpc_core::ExecCtx::Get()->IsReadyToFinish(), - lock->time_to_execute_final_list)); + GRPC_TRACE_LOG(combiner, INFO) + << "C:" << lock << " grpc_combiner_continue_exec_ctx " + << "contended=" << contended << " exec_ctx_ready_to_finish=" + << grpc_core::ExecCtx::Get()->IsReadyToFinish() + << " time_to_execute_final_list=" << lock->time_to_execute_final_list; // offload only if both (1) the combiner is contended and has more than one // closure to execute, and (2) the current execution context needs to finish @@ -212,8 +202,9 @@ bool grpc_combiner_continue_exec_ctx() { // priority (gpr_atm_acq_load(&lock->state) >> 1) > 1) { grpc_core::MultiProducerSingleConsumerQueue::Node* n = lock->queue.Pop(); - GRPC_COMBINER_TRACE( - gpr_log(GPR_INFO, "C:%p maybe_finish_one n=%p", lock, n)); + GRPC_TRACE_LOG(combiner, INFO) + << "C:" << lock << " maybe_finish_one n=" << n; + if (n == nullptr) { // queue is in an inconsistent state: use this as a cue that we should // go off and do something else for a while (and come back later) @@ -234,8 +225,8 @@ bool grpc_combiner_continue_exec_ctx() { grpc_closure_list_init(&lock->final_list); int loops = 0; while (c != nullptr) { - GRPC_COMBINER_TRACE( - gpr_log(GPR_INFO, "C:%p execute_final[%d] c=%p", lock, loops, c)); + GRPC_TRACE_LOG(combiner, INFO) + << "C:" << lock << " execute_final[" << loops << "] c=" << c; grpc_closure* next = c->next_data.next; #ifndef NDEBUG c->scheduled = false; @@ -252,8 +243,8 @@ bool grpc_combiner_continue_exec_ctx() { lock->time_to_execute_final_list = false; gpr_atm old_state = gpr_atm_full_fetch_add(&lock->state, -STATE_ELEM_COUNT_LOW_BIT); - GRPC_COMBINER_TRACE( - gpr_log(GPR_INFO, "C:%p finish old_state=%" PRIdPTR, lock, old_state)); + GRPC_TRACE_LOG(combiner, INFO) + << "C:" << lock << " finish old_state=" << old_state; // Define a macro to ease readability of the following switch statement. #define OLD_STATE_WAS(orphaned, elem_count) \ (((orphaned) ? 0 : STATE_UNORPHANED) | \ @@ -294,9 +285,9 @@ static void combiner_finally_exec(grpc_core::Combiner* lock, grpc_closure* closure, grpc_error_handle error) { CHECK_NE(lock, nullptr); - GRPC_COMBINER_TRACE(gpr_log( - GPR_INFO, "C:%p grpc_combiner_execute_finally c=%p; ac=%p", lock, closure, - grpc_core::ExecCtx::Get()->combiner_data()->active_combiner)); + GRPC_TRACE_LOG(combiner, INFO) + << "C:" << lock << " grpc_combiner_execute_finally c=" << closure + << "; ac=" << grpc_core::ExecCtx::Get()->combiner_data()->active_combiner; if (grpc_core::ExecCtx::Get()->combiner_data()->active_combiner != lock) { // Using error_data.scratch to store the combiner so that it can be accessed // in enqueue_finally. diff --git a/src/core/lib/iomgr/endpoint_cfstream.cc b/src/core/lib/iomgr/endpoint_cfstream.cc index 3ce89bf7aa9..1cc776a13bd 100644 --- a/src/core/lib/iomgr/endpoint_cfstream.cc +++ b/src/core/lib/iomgr/endpoint_cfstream.cc @@ -25,6 +25,7 @@ #import #include "absl/log/check.h" +#include "absl/log/log.h" #include #include @@ -75,9 +76,8 @@ static void CFStreamUnref(CFStreamEndpoint* ep, const char* reason, const char* file, int line) { if (GRPC_TRACE_FLAG_ENABLED(tcp)) { gpr_atm val = gpr_atm_no_barrier_load(&ep->refcount.count); - gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG, - "CFStream endpoint unref %p : %s %" PRIdPTR " -> %" PRIdPTR, ep, - reason, val, val - 1); + VLOG(2) << "CFStream endpoint unref " << ep << " : " << reason << " " << val + << " -> " << val - 1; } if (gpr_unref(&ep->refcount)) { CFStreamFree(ep); @@ -87,9 +87,8 @@ static void CFStreamRef(CFStreamEndpoint* ep, const char* reason, const char* file, int line) { if (GRPC_TRACE_FLAG_ENABLED(tcp)) { gpr_atm val = gpr_atm_no_barrier_load(&ep->refcount.count); - gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG, - "CFStream endpoint ref %p : %s %" PRIdPTR " -> %" PRIdPTR, ep, - reason, val, val + 1); + VLOG(2) << "CFStream endpoint ref " << ep << " : " << reason << " " << val + << " -> " << val + 1; } gpr_ref(&ep->refcount); } @@ -111,17 +110,15 @@ static grpc_error_handle CFStreamAnnotateError(grpc_error_handle src_error) { static void CallReadCb(CFStreamEndpoint* ep, grpc_error_handle error) { if (GRPC_TRACE_FLAG_ENABLED(tcp) && ABSL_VLOG_IS_ON(2)) { - gpr_log(GPR_DEBUG, "CFStream endpoint:%p call_read_cb %p %p:%p", ep, - ep->read_cb, ep->read_cb->cb, ep->read_cb->cb_arg); + VLOG(2) << "CFStream endpoint:" << ep << " call_read_cb " << ep->read_cb + << " " << ep->read_cb->cb << ":" << ep->read_cb->cb_arg; size_t i; - gpr_log(GPR_DEBUG, "read: error=%s", - grpc_core::StatusToString(error).c_str()); + VLOG(2) << "read: error=" << grpc_core::StatusToString(error); for (i = 0; i < ep->read_slices->count; i++) { char* dump = grpc_dump_slice(ep->read_slices->slices[i], GPR_DUMP_HEX | GPR_DUMP_ASCII); - gpr_log(GPR_DEBUG, "READ %p (peer=%s): %s", ep, ep->peer_string.c_str(), - dump); + VLOG(2) << "READ " << ep << " (peer=" << ep->peer_string << "): " << dump; gpr_free(dump); } } @@ -133,10 +130,9 @@ static void CallReadCb(CFStreamEndpoint* ep, grpc_error_handle error) { static void CallWriteCb(CFStreamEndpoint* ep, grpc_error_handle error) { if (GRPC_TRACE_FLAG_ENABLED(tcp)) { - gpr_log(GPR_DEBUG, "CFStream endpoint:%p call_write_cb %p %p:%p", ep, - ep->write_cb, ep->write_cb->cb, ep->write_cb->cb_arg); - gpr_log(GPR_DEBUG, "write: error=%s", - grpc_core::StatusToString(error).c_str()); + VLOG(2) << "CFStream endpoint:" << ep << " call_write_cb " << ep->write_cb + << " " << ep->write_cb->cb << ":" << ep->write_cb->cb_arg; + VLOG(2) << "write: error=" << grpc_core::StatusToString(error); } grpc_closure* cb = ep->write_cb; ep->write_cb = nullptr; @@ -224,8 +220,8 @@ static void WriteAction(void* arg, grpc_error_handle error) { if (GRPC_TRACE_FLAG_ENABLED(tcp) && ABSL_VLOG_IS_ON(2)) { grpc_slice trace_slice = grpc_slice_sub(slice, 0, write_size); char* dump = grpc_dump_slice(trace_slice, GPR_DUMP_HEX | GPR_DUMP_ASCII); - gpr_log(GPR_DEBUG, "WRITE %p (peer=%s): %s", ep, ep->peer_string.c_str(), - dump); + VLOG(2) << "WRITE " << ep << " (peer=" << ep->peer_string + << "): " << dump; gpr_free(dump); grpc_core::CSliceUnref(trace_slice); } @@ -238,8 +234,8 @@ static void CFStreamRead(grpc_endpoint* ep, grpc_slice_buffer* slices, int /*min_progress_size*/) { CFStreamEndpoint* ep_impl = reinterpret_cast(ep); if (GRPC_TRACE_FLAG_ENABLED(tcp)) { - gpr_log(GPR_DEBUG, "CFStream endpoint:%p read (%p, %p) length:%zu", ep_impl, - slices, cb, slices->length); + VLOG(2) << "CFStream endpoint:" << ep_impl << " read (" << slices << ", " + << cb << ") length:" << slices->length; } CHECK_EQ(ep_impl->read_cb, nullptr); ep_impl->read_cb = cb; @@ -256,8 +252,8 @@ static void CFStreamWrite(grpc_endpoint* ep, grpc_slice_buffer* slices, int /*max_frame_size*/) { CFStreamEndpoint* ep_impl = reinterpret_cast(ep); if (GRPC_TRACE_FLAG_ENABLED(tcp)) { - gpr_log(GPR_DEBUG, "CFStream endpoint:%p write (%p, %p) length:%zu", - ep_impl, slices, cb, slices->length); + VLOG(2) << "CFStream endpoint:" << ep_impl << " write (" << slices << ", " + << cb << ") length:" << slices->length; } CHECK_EQ(ep_impl->write_cb, nullptr); ep_impl->write_cb = cb; @@ -313,9 +309,9 @@ grpc_endpoint* grpc_cfstream_endpoint_create(CFReadStreamRef read_stream, CFStreamHandle* stream_sync) { CFStreamEndpoint* ep_impl = new CFStreamEndpoint; if (GRPC_TRACE_FLAG_ENABLED(tcp)) { - gpr_log(GPR_DEBUG, - "CFStream endpoint:%p create readStream:%p writeStream: %p", - ep_impl, read_stream, write_stream); + VLOG(2) << "CFStream endpoint:" << ep_impl + << " create readStream:" << read_stream + << " writeStream: " << write_stream; } ep_impl->base.vtable = &vtable; gpr_ref_init(&ep_impl->refcount, 1); diff --git a/src/core/lib/iomgr/ev_epoll1_linux.cc b/src/core/lib/iomgr/ev_epoll1_linux.cc index 6b4ebacac99..6217ba26667 100644 --- a/src/core/lib/iomgr/ev_epoll1_linux.cc +++ b/src/core/lib/iomgr/ev_epoll1_linux.cc @@ -16,9 +16,6 @@ // // -#include "absl/log/check.h" - -#include #include #include "src/core/lib/gprpp/crash.h" @@ -41,6 +38,7 @@ #include #include +#include "absl/log/check.h" #include "absl/log/log.h" #include "absl/strings/str_cat.h" #include "absl/strings/str_format.h" @@ -363,7 +361,7 @@ static grpc_fd* fd_create(int fd, const char* name, bool track_err) { fork_fd_list_add_grpc_fd(new_fd); #ifndef NDEBUG if (GRPC_TRACE_FLAG_ENABLED(fd_refcount)) { - gpr_log(GPR_DEBUG, "FD %d %p create %s", fd, new_fd, fd_name.c_str()); + VLOG(2) << "FD " << fd << " " << new_fd << " create " << fd_name; } #endif @@ -377,8 +375,7 @@ static grpc_fd* fd_create(int fd, const char* name, bool track_err) { ev.data.ptr = reinterpret_cast(reinterpret_cast(new_fd) | (track_err ? 1 : 0)); if (epoll_ctl(g_epoll_set.epfd, EPOLL_CTL_ADD, fd, &ev) != 0) { - gpr_log(GPR_ERROR, "epoll_ctl failed: %s", - grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "epoll_ctl failed: " << grpc_core::StrError(errno); } return new_fd; @@ -401,8 +398,7 @@ static void fd_shutdown_internal(grpc_fd* fd, grpc_error_handle why, epoll_event phony_event; if (epoll_ctl(g_epoll_set.epfd, EPOLL_CTL_DEL, fd->fd, &phony_event) != 0) { - gpr_log(GPR_ERROR, "epoll_ctl failed: %s", - grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "epoll_ctl failed: " << grpc_core::StrError(errno); } } fd->write_closure->SetShutdown(why); @@ -732,7 +728,7 @@ static grpc_error_handle do_epoll_wait(grpc_pollset* ps, if (r < 0) return GRPC_OS_ERROR(errno, "epoll_wait"); if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, "ps: %p poll got %d events", ps, r); + LOG(INFO) << "ps: " << ps << " poll got " << r << " events"; } gpr_atm_rel_store(&g_epoll_set.num_events, r); @@ -751,7 +747,7 @@ static bool begin_worker(grpc_pollset* pollset, grpc_pollset_worker* worker, pollset->begin_refs++; if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, "PS:%p BEGIN_STARTS:%p", pollset, worker); + LOG(INFO) << "PS:" << pollset << " BEGIN_STARTS:" << worker; } if (pollset->seen_inactive) { @@ -770,9 +766,9 @@ static bool begin_worker(grpc_pollset* pollset, grpc_pollset_worker* worker, gpr_mu_lock(&neighborhood->mu); gpr_mu_lock(&pollset->mu); if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, "PS:%p BEGIN_REORG:%p kick_state=%s is_reassigning=%d", - pollset, worker, kick_state_string(worker->state), - is_reassigning); + LOG(INFO) << "PS:" << pollset << " BEGIN_REORG:" << worker + << " kick_state=" << kick_state_string(worker->state) + << " is_reassigning=" << is_reassigning; } if (pollset->seen_inactive) { if (neighborhood != pollset->neighborhood) { @@ -823,9 +819,9 @@ static bool begin_worker(grpc_pollset* pollset, grpc_pollset_worker* worker, gpr_cv_init(&worker->cv); while (worker->state == UNKICKED && !pollset->shutting_down) { if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, "PS:%p BEGIN_WAIT:%p kick_state=%s shutdown=%d", - pollset, worker, kick_state_string(worker->state), - pollset->shutting_down); + LOG(INFO) << "PS:" << pollset << " BEGIN_WAIT:" << worker + << " kick_state=" << kick_state_string(worker->state) + << " shutdown=" << pollset->shutting_down; } if (gpr_cv_wait(&worker->cv, &pollset->mu, @@ -840,11 +836,10 @@ static bool begin_worker(grpc_pollset* pollset, grpc_pollset_worker* worker, } if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, - "PS:%p BEGIN_DONE:%p kick_state=%s shutdown=%d " - "kicked_without_poller: %d", - pollset, worker, kick_state_string(worker->state), - pollset->shutting_down, pollset->kicked_without_poller); + LOG(INFO) << "PS:" << pollset << " BEGIN_DONE:" << worker + << " kick_state=" << kick_state_string(worker->state) + << " shutdown=" << pollset->shutting_down + << " kicked_without_poller: " << pollset->kicked_without_poller; } // We release pollset lock in this function at a couple of places: @@ -883,8 +878,7 @@ static bool check_neighborhood_for_available_poller( &g_active_poller, 0, reinterpret_cast(inspect_worker))) { if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, " .. choose next poller to be %p", - inspect_worker); + LOG(INFO) << " .. choose next poller to be " << inspect_worker; } SET_KICK_STATE(inspect_worker, DESIGNATED_POLLER); if (inspect_worker->initialized_cv) { @@ -910,7 +904,7 @@ static bool check_neighborhood_for_available_poller( } if (!found_worker) { if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, " .. mark pollset %p inactive", inspect); + LOG(INFO) << " .. mark pollset " << inspect << " inactive"; } inspect->seen_inactive = true; if (inspect == neighborhood->active_root) { @@ -929,7 +923,7 @@ static bool check_neighborhood_for_available_poller( static void end_worker(grpc_pollset* pollset, grpc_pollset_worker* worker, grpc_pollset_worker** worker_hdl) { if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, "PS:%p END_WORKER:%p", pollset, worker); + LOG(INFO) << "PS:" << pollset << " END_WORKER:" << worker; } if (worker_hdl != nullptr) *worker_hdl = nullptr; // Make sure we appear kicked @@ -940,7 +934,7 @@ static void end_worker(grpc_pollset* pollset, grpc_pollset_worker* worker, reinterpret_cast(worker)) { if (worker->next != worker && worker->next->state == UNKICKED) { if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, " .. choose next poller to be peer %p", worker); + LOG(INFO) << " .. choose next poller to be peer " << worker; } CHECK(worker->next->initialized_cv); gpr_atm_no_barrier_store(&g_active_poller, (gpr_atm)worker->next); @@ -1073,7 +1067,7 @@ static grpc_error_handle pollset_kick(grpc_pollset* pollset, log.push_back(absl::StrFormat(" worker_kick_state=%s", kick_state_string(specific_worker->state))); } - gpr_log(GPR_DEBUG, "%s", absl::StrJoin(log, "").c_str()); + VLOG(2) << absl::StrJoin(log, ""); } if (specific_worker == nullptr) { @@ -1089,13 +1083,13 @@ static grpc_error_handle pollset_kick(grpc_pollset* pollset, grpc_pollset_worker* next_worker = root_worker->next; if (root_worker->state == KICKED) { if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, " .. already kicked %p", root_worker); + LOG(INFO) << " .. already kicked " << root_worker; } SET_KICK_STATE(root_worker, KICKED); goto done; } else if (next_worker->state == KICKED) { if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, " .. already kicked %p", next_worker); + LOG(INFO) << " .. already kicked " << next_worker; } SET_KICK_STATE(next_worker, KICKED); goto done; @@ -1105,14 +1099,14 @@ static grpc_error_handle pollset_kick(grpc_pollset* pollset, reinterpret_cast( gpr_atm_no_barrier_load(&g_active_poller))) { if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, " .. kicked %p", root_worker); + LOG(INFO) << " .. kicked " << root_worker; } SET_KICK_STATE(root_worker, KICKED); ret_err = grpc_wakeup_fd_wakeup(&global_wakeup_fd); goto done; } else if (next_worker->state == UNKICKED) { if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, " .. kicked %p", next_worker); + LOG(INFO) << " .. kicked " << next_worker; } CHECK(next_worker->initialized_cv); SET_KICK_STATE(next_worker, KICKED); @@ -1121,10 +1115,9 @@ static grpc_error_handle pollset_kick(grpc_pollset* pollset, } else if (next_worker->state == DESIGNATED_POLLER) { if (root_worker->state != DESIGNATED_POLLER) { if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log( - GPR_INFO, - " .. kicked root non-poller %p (initialized_cv=%d) (poller=%p)", - root_worker, root_worker->initialized_cv, next_worker); + LOG(INFO) << " .. kicked root non-poller " << root_worker + << " (initialized_cv=" << root_worker->initialized_cv + << ") (poller=" << next_worker << ")"; } SET_KICK_STATE(root_worker, KICKED); if (root_worker->initialized_cv) { @@ -1133,8 +1126,8 @@ static grpc_error_handle pollset_kick(grpc_pollset* pollset, goto done; } else { if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, " .. non-root poller %p (root=%p)", next_worker, - root_worker); + LOG(INFO) << " .. non-root poller " << next_worker + << " (root=" << root_worker << ")"; } SET_KICK_STATE(next_worker, KICKED); ret_err = grpc_wakeup_fd_wakeup(&global_wakeup_fd); @@ -1162,7 +1155,7 @@ static grpc_error_handle pollset_kick(grpc_pollset* pollset, goto done; } else if (g_current_thread_worker == specific_worker) { if (GRPC_TRACE_FLAG_ENABLED(polling)) { - gpr_log(GPR_INFO, " .. mark %p kicked", specific_worker); + LOG(INFO) << " .. mark " << specific_worker << " kicked"; } SET_KICK_STATE(specific_worker, KICKED); goto done; diff --git a/src/core/lib/iomgr/timer_generic.cc b/src/core/lib/iomgr/timer_generic.cc index 91813830818..f931658c670 100644 --- a/src/core/lib/iomgr/timer_generic.cc +++ b/src/core/lib/iomgr/timer_generic.cc @@ -21,12 +21,12 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/strings/str_cat.h" #include "absl/strings/str_format.h" #include #include -#include #include #include @@ -335,10 +335,10 @@ static void timer_init(grpc_timer* timer, grpc_core::Timestamp deadline, #endif if (GRPC_TRACE_FLAG_ENABLED(timer)) { - gpr_log(GPR_DEBUG, "TIMER %p: SET %" PRId64 " now %" PRId64 " call %p[%p]", - timer, deadline.milliseconds_after_process_epoch(), - grpc_core::Timestamp::Now().milliseconds_after_process_epoch(), - closure, closure->cb); + VLOG(2) << "TIMER " << timer << ": SET " + << deadline.milliseconds_after_process_epoch() << " now " + << grpc_core::Timestamp::Now().milliseconds_after_process_epoch() + << " call " << closure << "[" << closure->cb << "]"; } if (!g_shared_mutables.initialized) { @@ -371,12 +371,10 @@ static void timer_init(grpc_timer* timer, grpc_core::Timestamp deadline, list_join(&shard->list, timer); } if (GRPC_TRACE_FLAG_ENABLED(timer)) { - gpr_log(GPR_DEBUG, - " .. add to shard %d with queue_deadline_cap=%" PRId64 - " => is_first_timer=%s", - static_cast(shard - g_shards), - shard->queue_deadline_cap.milliseconds_after_process_epoch(), - is_first_timer ? "true" : "false"); + VLOG(2) << " .. add to shard " << (shard - g_shards) + << " with queue_deadline_cap=" + << shard->queue_deadline_cap.milliseconds_after_process_epoch() + << " => is_first_timer=" << (is_first_timer ? "true" : "false"); } gpr_mu_unlock(&shard->mu); @@ -394,8 +392,8 @@ static void timer_init(grpc_timer* timer, grpc_core::Timestamp deadline, if (is_first_timer) { gpr_mu_lock(&g_shared_mutables.mu); if (GRPC_TRACE_FLAG_ENABLED(timer)) { - gpr_log(GPR_DEBUG, " .. old shard min_deadline=%" PRId64, - shard->min_deadline.milliseconds_after_process_epoch()); + VLOG(2) << " .. old shard min_deadline=" + << shard->min_deadline.milliseconds_after_process_epoch(); } if (deadline < shard->min_deadline) { grpc_core::Timestamp old_min_deadline = g_shard_queue[0]->min_deadline; @@ -436,8 +434,8 @@ static void timer_cancel(grpc_timer* timer) { timer_shard* shard = &g_shards[grpc_core::HashPointer(timer, g_num_shards)]; gpr_mu_lock(&shard->mu); if (GRPC_TRACE_FLAG_ENABLED(timer)) { - gpr_log(GPR_DEBUG, "TIMER %p: CANCEL pending=%s", timer, - timer->pending ? "true" : "false"); + VLOG(2) << "TIMER " << timer + << ": CANCEL pending=" << (timer->pending ? "true" : "false"); } if (timer->pending) { @@ -477,9 +475,9 @@ static bool refill_heap(timer_shard* shard, grpc_core::Timestamp now) { grpc_core::Duration::FromSecondsAsDouble(deadline_delta); if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { - gpr_log(GPR_DEBUG, " .. shard[%d]->queue_deadline_cap --> %" PRId64, - static_cast(shard - g_shards), - shard->queue_deadline_cap.milliseconds_after_process_epoch()); + VLOG(2) << " .. shard[" << (shard - g_shards) + << "]->queue_deadline_cap --> " + << shard->queue_deadline_cap.milliseconds_after_process_epoch(); } for (timer = shard->list.next; timer != &shard->list; timer = next) { next = timer->next; @@ -489,8 +487,9 @@ static bool refill_heap(timer_shard* shard, grpc_core::Timestamp now) { if (timer_deadline < shard->queue_deadline_cap) { if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { - gpr_log(GPR_DEBUG, " .. add timer with deadline %" PRId64 " to heap", - timer_deadline.milliseconds_after_process_epoch()); + VLOG(2) << " .. add timer with deadline " + << timer_deadline.milliseconds_after_process_epoch() + << " to heap"; } list_remove(timer); grpc_timer_heap_add(&shard->heap, timer); @@ -506,9 +505,8 @@ static grpc_timer* pop_one(timer_shard* shard, grpc_core::Timestamp now) { grpc_timer* timer; for (;;) { if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { - gpr_log(GPR_DEBUG, " .. shard[%d]: heap_empty=%s", - static_cast(shard - g_shards), - grpc_timer_heap_is_empty(&shard->heap) ? "true" : "false"); + VLOG(2) << " .. shard[" << (shard - g_shards) << "]: heap_empty=" + << (grpc_timer_heap_is_empty(&shard->heap) ? "true" : "false"); } if (grpc_timer_heap_is_empty(&shard->heap)) { if (now < shard->queue_deadline_cap) return nullptr; @@ -519,15 +517,14 @@ static grpc_timer* pop_one(timer_shard* shard, grpc_core::Timestamp now) { grpc_core::Timestamp::FromMillisecondsAfterProcessEpoch( timer->deadline); if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { - gpr_log(GPR_DEBUG, - " .. check top timer deadline=%" PRId64 " now=%" PRId64, - timer_deadline.milliseconds_after_process_epoch(), - now.milliseconds_after_process_epoch()); + VLOG(2) << " .. check top timer deadline=" + << timer_deadline.milliseconds_after_process_epoch() + << " now=" << now.milliseconds_after_process_epoch(); } if (timer_deadline > now) return nullptr; if (GRPC_TRACE_FLAG_ENABLED(timer)) { - gpr_log(GPR_DEBUG, "TIMER %p: FIRE %" PRId64 "ms late", timer, - (now - timer_deadline).millis()); + VLOG(2) << "TIMER " << timer << ": FIRE " + << (now - timer_deadline).millis() << "ms late"; } timer->pending = false; grpc_timer_heap_pop(&shard->heap); @@ -550,8 +547,7 @@ static size_t pop_timers(timer_shard* shard, grpc_core::Timestamp now, *new_min_deadline = compute_min_deadline(shard); gpr_mu_unlock(&shard->mu); if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { - gpr_log(GPR_DEBUG, " .. shard[%d] popped %" PRIdPTR, - static_cast(shard - g_shards), n); + VLOG(2) << " .. shard[" << (shard - g_shards) << "] popped " << n; } return n; } @@ -589,10 +585,10 @@ static grpc_timer_check_result run_some_expired_timers( result = GRPC_TIMERS_CHECKED_AND_EMPTY; if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { - gpr_log( - GPR_DEBUG, " .. shard[%d]->min_deadline = %" PRId64, - static_cast(g_shard_queue[0] - g_shards), - g_shard_queue[0]->min_deadline.milliseconds_after_process_epoch()); + VLOG(2) + << " .. shard[" << (g_shard_queue[0] - g_shards) + << "]->min_deadline = " + << g_shard_queue[0]->min_deadline.milliseconds_after_process_epoch(); } while (g_shard_queue[0]->min_deadline < now || @@ -608,15 +604,12 @@ static grpc_timer_check_result run_some_expired_timers( } if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { - gpr_log( - GPR_DEBUG, - " .. result --> %d" - ", shard[%d]->min_deadline %" PRId64 " --> %" PRId64 - ", now=%" PRId64, - result, static_cast(g_shard_queue[0] - g_shards), - g_shard_queue[0]->min_deadline.milliseconds_after_process_epoch(), - new_min_deadline.milliseconds_after_process_epoch(), - now.milliseconds_after_process_epoch()); + VLOG(2) + << " .. result --> " << result << ", shard[" + << (g_shard_queue[0] - g_shards) << "]->min_deadline " + << g_shard_queue[0]->min_deadline.milliseconds_after_process_epoch() + << " --> " << new_min_deadline.milliseconds_after_process_epoch() + << ", now=" << now.milliseconds_after_process_epoch(); } // An grpc_timer_init() on the shard could intervene here, adding a new @@ -668,9 +661,9 @@ static grpc_timer_check_result timer_check(grpc_core::Timestamp* next) { *next = std::min(*next, min_timer); } if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { - gpr_log(GPR_DEBUG, "TIMER CHECK SKIP: now=%" PRId64 " min_timer=%" PRId64, - now.milliseconds_after_process_epoch(), - min_timer.milliseconds_after_process_epoch()); + VLOG(2) << "TIMER CHECK SKIP: now=" + << now.milliseconds_after_process_epoch() + << " min_timer=" << min_timer.milliseconds_after_process_epoch(); } return GRPC_TIMERS_CHECKED_AND_EMPTY; } @@ -689,20 +682,18 @@ static grpc_timer_check_result timer_check(grpc_core::Timestamp* next) { next_str = absl::StrCat(next->milliseconds_after_process_epoch()); } #if GPR_ARCH_64 - gpr_log( - GPR_DEBUG, - "TIMER CHECK BEGIN: now=%" PRId64 " next=%s tls_min=%" PRId64 - " glob_min=%" PRId64, - now.milliseconds_after_process_epoch(), next_str.c_str(), - min_timer.milliseconds_after_process_epoch(), - grpc_core::Timestamp::FromMillisecondsAfterProcessEpoch( - gpr_atm_no_barrier_load((gpr_atm*)(&g_shared_mutables.min_timer))) - .milliseconds_after_process_epoch()); + VLOG(2) << "TIMER CHECK BEGIN: now=" + << now.milliseconds_after_process_epoch() << " next=" << next_str + << " tls_min=" << min_timer.milliseconds_after_process_epoch() + << " glob_min=" + << grpc_core::Timestamp::FromMillisecondsAfterProcessEpoch( + gpr_atm_no_barrier_load( + (gpr_atm*)(&g_shared_mutables.min_timer))) + .milliseconds_after_process_epoch(); #else - gpr_log(GPR_DEBUG, - "TIMER CHECK BEGIN: now=%" PRId64 " next=%s min=%" PRId64, - now.milliseconds_after_process_epoch(), next_str.c_str(), - min_timer.milliseconds_after_process_epoch()); + VLOG(2) << "TIMER CHECK BEGIN: now=" + << now.milliseconds_after_process_epoch() << " next=" << next_str + << " min=" << min_timer.milliseconds_after_process_epoch(); #endif } // actual code @@ -716,7 +707,7 @@ static grpc_timer_check_result timer_check(grpc_core::Timestamp* next) { } else { next_str = absl::StrCat(next->milliseconds_after_process_epoch()); } - gpr_log(GPR_DEBUG, "TIMER CHECK END: r=%d; next=%s", r, next_str.c_str()); + VLOG(2) << "TIMER CHECK END: r=" << r << "; next=" << next_str.c_str(); } return r; } From 98cd95cfce3bbef43d79bc04c0aad45ba574bebd Mon Sep 17 00:00:00 2001 From: Tanvi Jagtap <139093547+tanvi-jagtap@users.noreply.github.com> Date: Thu, 4 Jul 2024 07:58:31 -0700 Subject: [PATCH 4/6] [Gpr_To_Absl_Logging] Migrating from gpr to absl logging - gpr_log (#37091) [Gpr_To_Absl_Logging] Migrating from gpr to absl logging - gpr_log In this CL we are migrating from gRPCs own gpr logging mechanism to absl logging mechanism. The intention is to deprecate gpr_log in the future. We have the following mapping 1. gpr_log(GPR_INFO,...) -> LOG(INFO) 2. gpr_log(GPR_ERROR,...) -> LOG(ERROR) 3. gpr_log(GPR_DEBUG,...) -> VLOG(2) Reviewers need to check : 1. If the above mapping is correct. 2. The content of the log is as before. gpr_log format strings did not use string_view or std::string . absl LOG accepts these. So there will be some elimination of string_view and std::string related conversions. This is expected. Closes #37091 COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/37091 from tanvi-jagtap:src_core_ext_transport_binder_reduced 3e7af7614888a6ca1687f48de206f1dd586e4590 PiperOrigin-RevId: 649414136 --- .../binder/wire_format/wire_reader_impl.cc | 60 +++++++++---------- 1 file changed, 30 insertions(+), 30 deletions(-) diff --git a/src/core/ext/transport/binder/wire_format/wire_reader_impl.cc b/src/core/ext/transport/binder/wire_format/wire_reader_impl.cc index 02cd6cf09cd..bb01c892319 100644 --- a/src/core/ext/transport/binder/wire_format/wire_reader_impl.cc +++ b/src/core/ext/transport/binder/wire_format/wire_reader_impl.cc @@ -30,8 +30,6 @@ #include "absl/memory/memory.h" #include "absl/status/statusor.h" -#include - #include "src/core/ext/transport/binder/utils/transport_stream_receiver.h" #include "src/core/ext/transport/binder/wire_format/binder.h" #include "src/core/ext/transport/binder/wire_format/wire_writer.h" @@ -109,11 +107,12 @@ std::shared_ptr WireReaderImpl::SetupTransport( void WireReaderImpl::SendSetupTransport(Binder* binder) { binder->Initialize(); - gpr_log(GPR_DEBUG, "prepare transaction = %d", - binder->PrepareTransaction().ok()); + const absl::Status prep_transaction_status = binder->PrepareTransaction(); + VLOG(2) << "prepare transaction = " << prep_transaction_status; WritableParcel* writable_parcel = binder->GetWritableParcel(); - gpr_log(GPR_DEBUG, "write int32 = %d", - writable_parcel->WriteInt32(kWireFormatVersion).ok()); + const absl::Status write_status = + writable_parcel->WriteInt32(kWireFormatVersion); + VLOG(2) << "write int32 = " << write_status; // The lifetime of the transaction receiver is the same as the wire writer's. // The transaction receiver is responsible for not calling the on-transact // callback when it's dead. @@ -127,11 +126,13 @@ void WireReaderImpl::SendSetupTransport(Binder* binder) { return this->ProcessTransaction(code, readable_parcel, uid); }); - gpr_log(GPR_DEBUG, "tx_receiver = %p", tx_receiver_->GetRawBinder()); - gpr_log(GPR_DEBUG, "AParcel_writeStrongBinder = %d", - writable_parcel->WriteBinder(tx_receiver_.get()).ok()); - gpr_log(GPR_DEBUG, "AIBinder_transact = %d", - binder->Transact(BinderTransportTxCode::SETUP_TRANSPORT).ok()); + VLOG(2) << "tx_receiver = " << tx_receiver_->GetRawBinder(); + const absl::Status write_binder_status = + writable_parcel->WriteBinder(tx_receiver_.get()); + VLOG(2) << "AParcel_writeStrongBinder = " << write_binder_status; + const absl::Status transact_status = + binder->Transact(BinderTransportTxCode::SETUP_TRANSPORT); + VLOG(2) << "AIBinder_transact = " << transact_status; } std::unique_ptr WireReaderImpl::RecvSetupTransport() { @@ -181,7 +182,7 @@ absl::Status WireReaderImpl::ProcessTransaction(transaction_code_t code, } recvd_setup_transport_ = true; - gpr_log(GPR_DEBUG, "calling uid = %d", uid); + VLOG(2) << "calling uid = " << uid; if (!security_policy_->IsAuthorized(uid)) { return absl::PermissionDeniedError( "UID " + std::to_string(uid) + @@ -191,14 +192,13 @@ absl::Status WireReaderImpl::ProcessTransaction(transaction_code_t code, int version; GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&version)); - gpr_log(GPR_DEBUG, "The other end respond with version = %d", version); + VLOG(2) << "The other end respond with version = " << version; // We only support this single lowest possible version, so server must // respond that version too. if (version != kWireFormatVersion) { - gpr_log(GPR_ERROR, - "The other end respond with version = %d, but we requested " - "version %d, trying to continue anyway", - version, kWireFormatVersion); + LOG(ERROR) << "The other end respond with version = " << version + << ", but we requested version " << kWireFormatVersion + << ", trying to continue anyway"; } std::unique_ptr binder{}; GRPC_RETURN_IF_ERROR(parcel->ReadBinder(&binder)); @@ -218,7 +218,7 @@ absl::Status WireReaderImpl::ProcessTransaction(transaction_code_t code, case BinderTransportTxCode::ACKNOWLEDGE_BYTES: { int64_t num_bytes = -1; GRPC_RETURN_IF_ERROR(parcel->ReadInt64(&num_bytes)); - gpr_log(GPR_DEBUG, "received acknowledge bytes = %" PRId64, num_bytes); + VLOG(2) << "received acknowledge bytes = " << num_bytes; if (!wire_writer_ready_notification_.WaitForNotificationWithTimeout( absl::Seconds(5))) { return absl::DeadlineExceededError( @@ -233,14 +233,14 @@ absl::Status WireReaderImpl::ProcessTransaction(transaction_code_t code, } int ping_id = -1; GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&ping_id)); - gpr_log(GPR_DEBUG, "received ping id = %d", ping_id); + VLOG(2) << "received ping id = " << ping_id; // TODO(waynetu): Ping back. break; } case BinderTransportTxCode::PING_RESPONSE: { int value = -1; GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&value)); - gpr_log(GPR_DEBUG, "received ping response = %d", value); + VLOG(2) << "received ping response = " << value; break; } } @@ -283,8 +283,8 @@ absl::Status WireReaderImpl::ProcessStreamingTransaction( } if (!tx_process_result.ok()) { - gpr_log(GPR_ERROR, "Failed to process streaming transaction: %s", - tx_process_result.ToString().c_str()); + LOG(ERROR) << "Failed to process streaming transaction: " + << tx_process_result.ToString(); // Something went wrong when receiving transaction. Cancel failed requests. if (cancellation_flags & kFlagPrefix) { LOG(INFO) << "cancelling initial metadata"; @@ -327,7 +327,7 @@ absl::Status WireReaderImpl::ProcessStreamingTransactionImpl( std::queue>& deferred_func_queue) { CHECK(cancellation_flags); num_incoming_bytes_ += parcel->GetDataSize(); - gpr_log(GPR_INFO, "Total incoming bytes: %" PRId64, num_incoming_bytes_); + LOG(INFO) << "Total incoming bytes: " << num_incoming_bytes_; int flags; GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&flags)); @@ -344,10 +344,10 @@ absl::Status WireReaderImpl::ProcessStreamingTransactionImpl( } int status = flags >> 16; - gpr_log(GPR_DEBUG, "status = %d", status); - gpr_log(GPR_DEBUG, "FLAG_PREFIX = %d", (flags & kFlagPrefix)); - gpr_log(GPR_DEBUG, "FLAG_MESSAGE_DATA = %d", (flags & kFlagMessageData)); - gpr_log(GPR_DEBUG, "FLAG_SUFFIX = %d", (flags & kFlagSuffix)); + VLOG(2) << "status = " << status; + VLOG(2) << "FLAG_PREFIX = " << (flags & kFlagPrefix); + VLOG(2) << "FLAG_MESSAGE_DATA = " << (flags & kFlagMessageData); + VLOG(2) << "FLAG_SUFFIX = " << (flags & kFlagSuffix); int seq_num; GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&seq_num)); // TODO(waynetu): For now we'll just assume that the transactions commit in @@ -365,7 +365,7 @@ absl::Status WireReaderImpl::ProcessStreamingTransactionImpl( CHECK(expectation < std::numeric_limits::max()) << "Sequence number too large"; expectation++; - gpr_log(GPR_DEBUG, "sequence number = %d", seq_num); + VLOG(2) << "sequence number = " << seq_num; if (flags & kFlagPrefix) { std::string method_ref; if (!is_client_) { @@ -405,7 +405,7 @@ absl::Status WireReaderImpl::ProcessStreamingTransactionImpl( if (flags & kFlagMessageData) { int count; GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&count)); - gpr_log(GPR_DEBUG, "count = %d", count); + VLOG(2) << "count = " << count; std::string msg_data{}; if (count > 0) { GRPC_RETURN_IF_ERROR(parcel->ReadByteArray(&msg_data)); @@ -425,7 +425,7 @@ absl::Status WireReaderImpl::ProcessStreamingTransactionImpl( // FLAG_STATUS_DESCRIPTION set std::string desc; GRPC_RETURN_IF_ERROR(parcel->ReadString(&desc)); - gpr_log(GPR_DEBUG, "description = %s", desc.c_str()); + VLOG(2) << "description = " << desc; } Metadata trailing_metadata; if (is_client_) { From 21ccffcc62e24931cb268626f85dc0a24ef736f5 Mon Sep 17 00:00:00 2001 From: Tanvi Jagtap <139093547+tanvi-jagtap@users.noreply.github.com> Date: Thu, 4 Jul 2024 19:13:46 -0700 Subject: [PATCH 5/6] [Gpr_To_Absl_Logging] Migrating from gpr to absl logging - gpr_log (#37146) [Gpr_To_Absl_Logging] Migrating from gpr to absl logging - gpr_log In this CL we are migrating from gRPCs own gpr logging mechanism to absl logging mechanism. The intention is to deprecate gpr_log in the future. We have the following mapping 1. gpr_log(GPR_INFO,...) -> LOG(INFO) 2. gpr_log(GPR_ERROR,...) -> LOG(ERROR) 3. gpr_log(GPR_DEBUG,...) -> VLOG(2) Reviewers need to check : 1. If the above mapping is correct. 2. The content of the log is as before. gpr_log format strings did not use string_view or std::string . absl LOG accepts these. So there will be some elimination of string_view and std::string related conversions. This is expected. Closes #37146 COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/37146 from tanvi-jagtap:src_core_lib_transport_surface 728c3dedb2ec1445d903258d465b5772cbe57b02 PiperOrigin-RevId: 649518102 --- src/core/BUILD | 5 +- src/core/lib/surface/call.cc | 14 +++--- src/core/lib/surface/call_utils.cc | 10 ++-- src/core/lib/surface/channel_init.cc | 12 ++--- src/core/lib/surface/completion_queue.cc | 48 ++++++++---------- src/core/lib/surface/legacy_channel.cc | 10 ++-- src/core/lib/transport/bdp_estimator.cc | 16 +++--- src/core/lib/transport/bdp_estimator.h | 10 ++-- src/core/lib/transport/call_filters.cc | 12 ++--- src/core/lib/transport/connectivity_state.cc | 53 +++++++++++--------- src/core/lib/transport/transport.h | 10 ++-- 11 files changed, 95 insertions(+), 105 deletions(-) diff --git a/src/core/BUILD b/src/core/BUILD index e1b6c0ac465..3f9aebcbf9a 100644 --- a/src/core/BUILD +++ b/src/core/BUILD @@ -7846,7 +7846,10 @@ grpc_cc_library( hdrs = [ "lib/transport/call_filters.h", ], - external_deps = ["absl/log:check"], + external_deps = [ + "absl/log:check", + "absl/log:log", + ], deps = [ "call_final_info", "call_state", diff --git a/src/core/lib/surface/call.cc b/src/core/lib/surface/call.cc index a5c65fdf05c..08f2a314413 100644 --- a/src/core/lib/surface/call.cc +++ b/src/core/lib/surface/call.cc @@ -54,7 +54,6 @@ #include #include #include -#include #include #include @@ -319,11 +318,9 @@ void Call::HandleCompressionAlgorithmNotAccepted( grpc_compression_algorithm compression_algorithm) { const char* algo_name = nullptr; grpc_compression_algorithm_name(compression_algorithm, &algo_name); - gpr_log(GPR_ERROR, - "Compression algorithm ('%s') not present in the " - "accepted encodings (%s)", - algo_name, - std::string(encodings_accepted_by_peer_.ToString()).c_str()); + LOG(ERROR) << "Compression algorithm ('" << algo_name + << "') not present in the accepted encodings (" + << encodings_accepted_by_peer_.ToString() << ")"; } void Call::HandleCompressionAlgorithmDisabled( @@ -341,8 +338,9 @@ void Call::HandleCompressionAlgorithmDisabled( void Call::UpdateDeadline(Timestamp deadline) { ReleasableMutexLock lock(&deadline_mu_); if (GRPC_TRACE_FLAG_ENABLED(call)) { - gpr_log(GPR_DEBUG, "[call %p] UpdateDeadline from=%s to=%s", this, - deadline_.ToString().c_str(), deadline.ToString().c_str()); + VLOG(2) << "[call " << this + << "] UpdateDeadline from=" << deadline_.ToString() + << " to=" << deadline.ToString(); } if (deadline >= deadline_) return; if (deadline < Timestamp::Now()) { diff --git a/src/core/lib/surface/call_utils.cc b/src/core/lib/surface/call_utils.cc index afc2b34e5d4..f5c5f32b84e 100644 --- a/src/core/lib/surface/call_utils.cc +++ b/src/core/lib/surface/call_utils.cc @@ -28,6 +28,7 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/strings/str_cat.h" #include "absl/strings/str_format.h" @@ -44,7 +45,6 @@ #include #include #include -#include #include #include @@ -88,11 +88,9 @@ void CToMetadata(grpc_metadata* metadata, size_t count, if (key == "content-length") continue; b->Append(key, Slice(CSliceRef(md->value)), [md](absl::string_view error, const Slice& value) { - gpr_log(GPR_DEBUG, "Append error: %s", - absl::StrCat("key=", StringViewFromSlice(md->key), - " error=", error, - " value=", value.as_string_view()) - .c_str()); + VLOG(2) << "Append error: key=" << StringViewFromSlice(md->key) + << " error=" << error + << " value=" << value.as_string_view(); }); } } diff --git a/src/core/lib/surface/channel_init.cc b/src/core/lib/surface/channel_init.cc index 3beea8c22b0..eb0744f760e 100644 --- a/src/core/lib/surface/channel_init.cc +++ b/src/core/lib/surface/channel_init.cc @@ -34,7 +34,6 @@ #include "absl/strings/string_view.h" #include "absl/types/optional.h" -#include #include #include "src/core/lib/debug/trace.h" @@ -311,12 +310,11 @@ ChannelInit::StackConfig ChannelInit::BuildStackConfig( // Right now it forces too many tests to know about channel initialization, // either by supplying a valid configuration or by including an opt-out flag. if (terminal_filters.empty() && type != GRPC_CLIENT_DYNAMIC) { - gpr_log( - GPR_ERROR, - "No terminal filters registered for channel stack type %s; this is " - "common for unit tests messing with CoreConfiguration, but will result " - "in a ChannelInit::CreateStack that never completes successfully.", - grpc_channel_stack_type_string(type)); + LOG(ERROR) << "No terminal filters registered for channel stack type " + << grpc_channel_stack_type_string(type) + << "; this is common for unit tests messing with " + "CoreConfiguration, but will result in a " + "ChannelInit::CreateStack that never completes successfully."; } return StackConfig{std::move(filters), std::move(terminal_filters), std::move(post_processor_functions)}; diff --git a/src/core/lib/surface/completion_queue.cc b/src/core/lib/surface/completion_queue.cc index 6619dd3bae7..9710c4dd37f 100644 --- a/src/core/lib/surface/completion_queue.cc +++ b/src/core/lib/surface/completion_queue.cc @@ -36,7 +36,6 @@ #include #include #include -#include #include #include #include @@ -438,14 +437,14 @@ static const cq_vtable g_cq_vtable[] = { #define POLLSET_FROM_CQ(cq) \ ((grpc_pollset*)((cq)->vtable->data_size + (char*)DATA_FROM_CQ(cq))) -#define GRPC_SURFACE_TRACE_RETURNED_EVENT(cq, event) \ - do { \ - if (GRPC_TRACE_FLAG_ENABLED(api) && \ - (GRPC_TRACE_FLAG_ENABLED(queue_pluck) || \ - (event)->type != GRPC_QUEUE_TIMEOUT)) { \ - gpr_log(GPR_INFO, "RETURN_EVENT[%p]: %s", cq, \ - grpc_event_string(event).c_str()); \ - } \ +#define GRPC_SURFACE_TRACE_RETURNED_EVENT(cq, event) \ + do { \ + if (GRPC_TRACE_FLAG_ENABLED(api) && \ + (GRPC_TRACE_FLAG_ENABLED(queue_pluck) || \ + (event)->type != GRPC_QUEUE_TIMEOUT)) { \ + LOG(INFO) << "RETURN_EVENT[" << (cq) \ + << "]: " << grpc_event_string(event); \ + } \ } while (0) static void on_pollset_shutdown_done(void* arg, grpc_error_handle error); @@ -703,8 +702,7 @@ static void cq_end_op_for_next( "done=%p, done_arg=%p, storage=%p)", 6, (cq, tag, errmsg.c_str(), done, done_arg, storage)); if (GRPC_TRACE_FLAG_ENABLED(op_failure) && !error.ok()) { - gpr_log(GPR_INFO, "Operation failed: tag=%p, error=%s", tag, - errmsg.c_str()); + LOG(INFO) << "Operation failed: tag=" << tag << ", error=" << errmsg; } } cq_next_data* cqd = static_cast DATA_FROM_CQ(cq); @@ -737,8 +735,8 @@ static void cq_end_op_for_next( gpr_mu_unlock(cq->mu); if (!kick_error.ok()) { - gpr_log(GPR_ERROR, "Kick failed: %s", - grpc_core::StatusToString(kick_error).c_str()); + LOG(ERROR) << "Kick failed: " + << grpc_core::StatusToString(kick_error); } } if (cqd->pending_events.fetch_sub(1, std::memory_order_acq_rel) == 1) { @@ -777,8 +775,7 @@ static void cq_end_op_for_pluck( "done=%p, done_arg=%p, storage=%p)", 6, (cq, tag, errmsg.c_str(), done, done_arg, storage)); if (GRPC_TRACE_FLAG_ENABLED(op_failure) && !error.ok()) { - gpr_log(GPR_ERROR, "Operation failed: tag=%p, error=%s", tag, - errmsg.c_str()); + LOG(ERROR) << "Operation failed: tag=" << tag << ", error=" << errmsg; } } @@ -813,8 +810,7 @@ static void cq_end_op_for_pluck( cq->poller_vtable->kick(POLLSET_FROM_CQ(cq), pluck_worker); gpr_mu_unlock(cq->mu); if (!kick_error.ok()) { - gpr_log(GPR_ERROR, "Kick failed: %s", - grpc_core::StatusToString(kick_error).c_str()); + LOG(ERROR) << "Kick failed: " << kick_error; } } } @@ -839,8 +835,7 @@ static void cq_end_op_for_callback( "done=%p, done_arg=%p, storage=%p)", 6, (cq, tag, errmsg.c_str(), done, done_arg, storage)); if (GRPC_TRACE_FLAG_ENABLED(op_failure) && !error.ok()) { - gpr_log(GPR_ERROR, "Operation failed: tag=%p, error=%s", tag, - errmsg.c_str()); + LOG(ERROR) << "Operation failed: tag=" << tag << ", error=" << errmsg; } } @@ -1039,8 +1034,8 @@ static grpc_event cq_next(grpc_completion_queue* cq, gpr_timespec deadline, gpr_mu_unlock(cq->mu); if (!err.ok()) { - gpr_log(GPR_ERROR, "Completion queue next failed: %s", - grpc_core::StatusToString(err).c_str()); + LOG(ERROR) << "Completion queue next failed: " + << grpc_core::StatusToString(err); if (err == absl::CancelledError()) { ret.type = GRPC_QUEUE_SHUTDOWN; } else { @@ -1253,10 +1248,9 @@ static grpc_event cq_pluck(grpc_completion_queue* cq, void* tag, break; } if (!add_plucker(cq, tag, &worker)) { - gpr_log(GPR_DEBUG, - "Too many outstanding grpc_completion_queue_pluck calls: maximum " - "is %d", - GRPC_MAX_COMPLETION_QUEUE_PLUCKERS); + VLOG(2) << "Too many outstanding grpc_completion_queue_pluck calls: " + "maximum is " + << GRPC_MAX_COMPLETION_QUEUE_PLUCKERS; gpr_mu_unlock(cq->mu); // TODO(ctiller): should we use a different result here ret.type = GRPC_QUEUE_TIMEOUT; @@ -1279,8 +1273,8 @@ static grpc_event cq_pluck(grpc_completion_queue* cq, void* tag, if (!err.ok()) { del_plucker(cq, tag, &worker); gpr_mu_unlock(cq->mu); - gpr_log(GPR_ERROR, "Completion queue pluck failed: %s", - grpc_core::StatusToString(err).c_str()); + LOG(ERROR) << "Completion queue pluck failed: " + << grpc_core::StatusToString(err); ret.type = GRPC_QUEUE_TIMEOUT; ret.success = 0; dump_pending_tags(cq); diff --git a/src/core/lib/surface/legacy_channel.cc b/src/core/lib/surface/legacy_channel.cc index d1986939ad5..f68a653d843 100644 --- a/src/core/lib/surface/legacy_channel.cc +++ b/src/core/lib/surface/legacy_channel.cc @@ -20,6 +20,7 @@ #include "absl/base/thread_annotations.h" #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/types/optional.h" @@ -27,7 +28,6 @@ #include #include #include -#include #include #include "src/core/channelz/channelz.h" @@ -86,8 +86,7 @@ absl::StatusOr> LegacyChannel::Create( absl::StatusOr> r = builder.Build(); if (!r.ok()) { auto status = r.status(); - gpr_log(GPR_ERROR, "channel stack builder failed: %s", - status.ToString().c_str()); + LOG(ERROR) << "channel stack builder failed: " << status; return status; } if (channel_stack_type == GRPC_SERVER_CHANNEL) { @@ -210,9 +209,8 @@ grpc_connectivity_state LegacyChannel::CheckConnectivityState( ClientChannelFilter* client_channel = GetClientChannelFilter(); if (GPR_UNLIKELY(client_channel == nullptr)) { if (IsLame()) return GRPC_CHANNEL_TRANSIENT_FAILURE; - gpr_log(GPR_ERROR, - "grpc_channel_check_connectivity_state called on something that is " - "not a client channel"); + LOG(ERROR) << "grpc_channel_check_connectivity_state called on something " + "that is not a client channel"; return GRPC_CHANNEL_SHUTDOWN; } return client_channel->CheckConnectivityState(try_to_connect); diff --git a/src/core/lib/transport/bdp_estimator.cc b/src/core/lib/transport/bdp_estimator.cc index 16d266ebdfd..29f9188a242 100644 --- a/src/core/lib/transport/bdp_estimator.cc +++ b/src/core/lib/transport/bdp_estimator.cc @@ -24,6 +24,7 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include @@ -47,19 +48,16 @@ Timestamp BdpEstimator::CompletePing() { double bw = dt > 0 ? (static_cast(accumulator_) / dt) : 0; Duration start_inter_ping_delay = inter_ping_delay_; if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) { - gpr_log(GPR_INFO, - "bdp[%s]:complete acc=%" PRId64 " est=%" PRId64 - " dt=%lf bw=%lfMbs bw_est=%lfMbs", - std::string(name_).c_str(), accumulator_, estimate_, dt, - bw / 125000.0, bw_est_ / 125000.0); + LOG(INFO) << "bdp[" << name_ << "]:complete acc=" << accumulator_ + << " est=" << estimate_ << " dt=" << dt << " bw=" << bw / 125000.0 + << "Mbs bw_est=" << bw_est_ / 125000.0 << "Mbs"; } CHECK(ping_state_ == PingState::STARTED); if (accumulator_ > 2 * estimate_ / 3 && bw > bw_est_) { estimate_ = std::max(accumulator_, estimate_ * 2); bw_est_ = bw; if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) { - gpr_log(GPR_INFO, "bdp[%s]: estimate increased to %" PRId64, - std::string(name_).c_str(), estimate_); + LOG(INFO) << "bdp[" << name_ << "]: estimate increased to " << estimate_; } inter_ping_delay_ /= 2; // if the ping estimate changes, // exponentially get faster at probing @@ -74,8 +72,8 @@ Timestamp BdpEstimator::CompletePing() { if (start_inter_ping_delay != inter_ping_delay_) { stable_estimate_count_ = 0; if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) { - gpr_log(GPR_INFO, "bdp[%s]:update_inter_time to %" PRId64 "ms", - std::string(name_).c_str(), inter_ping_delay_.millis()); + LOG(INFO) << "bdp[" << name_ << "]:update_inter_time to " + << inter_ping_delay_.millis() << "ms"; } } ping_state_ = PingState::UNSCHEDULED; diff --git a/src/core/lib/transport/bdp_estimator.h b/src/core/lib/transport/bdp_estimator.h index 872ea2a2752..d219a90900c 100644 --- a/src/core/lib/transport/bdp_estimator.h +++ b/src/core/lib/transport/bdp_estimator.h @@ -24,9 +24,9 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/strings/string_view.h" -#include #include #include @@ -50,8 +50,8 @@ class BdpEstimator { // transport (but not necessarily started) void SchedulePing() { if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) { - gpr_log(GPR_INFO, "bdp[%s]:sched acc=%" PRId64 " est=%" PRId64, - std::string(name_).c_str(), accumulator_, estimate_); + LOG(INFO) << "bdp[" << name_ << "]:sched acc=" << accumulator_ + << " est=" << estimate_; } CHECK(ping_state_ == PingState::UNSCHEDULED); ping_state_ = PingState::SCHEDULED; @@ -63,8 +63,8 @@ class BdpEstimator { // the ping is on the wire void StartPing() { if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) { - gpr_log(GPR_INFO, "bdp[%s]:start acc=%" PRId64 " est=%" PRId64, - std::string(name_).c_str(), accumulator_, estimate_); + LOG(INFO) << "bdp[" << name_ << "]:start acc=" << accumulator_ + << " est=" << estimate_; } CHECK(ping_state_ == PingState::SCHEDULED); ping_state_ = PingState::STARTED; diff --git a/src/core/lib/transport/call_filters.cc b/src/core/lib/transport/call_filters.cc index b2c481bd1a8..f19c100a75d 100644 --- a/src/core/lib/transport/call_filters.cc +++ b/src/core/lib/transport/call_filters.cc @@ -15,6 +15,7 @@ #include "src/core/lib/transport/call_filters.h" #include "absl/log/check.h" +#include "absl/log/log.h" #include @@ -188,9 +189,8 @@ void CallFilters::CancelDueToFailedPipeOperation(SourceLocation but_where) { // We expect something cancelled before now if (push_server_trailing_metadata_ == nullptr) return; if (GRPC_TRACE_FLAG_ENABLED(promise_primitives)) { - gpr_log(but_where.file(), but_where.line(), GPR_LOG_SEVERITY_DEBUG, - "Cancelling due to failed pipe operation: %s", - DebugString().c_str()); + VLOG(2).AtLocation(but_where.file(), but_where.line()) + << "Cancelling due to failed pipe operation: " << DebugString(); } auto status = ServerMetadataFromStatus(absl::CancelledError("Failed pipe operation")); @@ -201,9 +201,9 @@ void CallFilters::CancelDueToFailedPipeOperation(SourceLocation but_where) { void CallFilters::PushServerTrailingMetadata(ServerMetadataHandle md) { CHECK(md != nullptr); if (GRPC_TRACE_FLAG_ENABLED(call)) { - gpr_log(GPR_INFO, "%s PushServerTrailingMetadata[%p]: %s into %s", - GetContext()->DebugTag().c_str(), this, - md->DebugString().c_str(), DebugString().c_str()); + LOG(INFO) << GetContext()->DebugTag() + << " PushServerTrailingMetadata[" << this + << "]: " << md->DebugString() << " into " << DebugString(); } CHECK(md != nullptr); if (call_state_.PushServerTrailingMetadata( diff --git a/src/core/lib/transport/connectivity_state.cc b/src/core/lib/transport/connectivity_state.cc index 1f63e516597..8e4bb0be082 100644 --- a/src/core/lib/transport/connectivity_state.cc +++ b/src/core/lib/transport/connectivity_state.cc @@ -18,7 +18,8 @@ #include "src/core/lib/transport/connectivity_state.h" -#include +#include "absl/log/log.h" + #include #include "src/core/lib/gprpp/debug_location.h" @@ -72,9 +73,10 @@ class AsyncConnectivityStateWatcherInterface::Notifier { static void SendNotification(void* arg, grpc_error_handle /*ignored*/) { Notifier* self = static_cast(arg); if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { - gpr_log(GPR_INFO, "watcher %p: delivering async notification for %s (%s)", - self->watcher_.get(), ConnectivityStateName(self->state_), - self->status_.ToString().c_str()); + LOG(INFO) << "watcher " << self->watcher_.get() + << ": delivering async notification for " + << ConnectivityStateName(self->state_) << " (" + << self->status_.ToString() << ")"; } self->watcher_->OnConnectivityStateChange(self->state_, self->status_); delete self; @@ -103,10 +105,10 @@ ConnectivityStateTracker::~ConnectivityStateTracker() { if (current_state == GRPC_CHANNEL_SHUTDOWN) return; for (const auto& p : watchers_) { if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { - gpr_log(GPR_INFO, - "ConnectivityStateTracker %s[%p]: notifying watcher %p: %s -> %s", - name_, this, p.first, ConnectivityStateName(current_state), - ConnectivityStateName(GRPC_CHANNEL_SHUTDOWN)); + LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this + << "]: notifying watcher " << p.first << ": " + << ConnectivityStateName(current_state) << " -> " + << ConnectivityStateName(GRPC_CHANNEL_SHUTDOWN); } p.second->Notify(GRPC_CHANNEL_SHUTDOWN, absl::Status()); } @@ -116,17 +118,17 @@ void ConnectivityStateTracker::AddWatcher( grpc_connectivity_state initial_state, OrphanablePtr watcher) { if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { - gpr_log(GPR_INFO, "ConnectivityStateTracker %s[%p]: add watcher %p", name_, - this, watcher.get()); + LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this + << "]: add watcher " << watcher.get(); } grpc_connectivity_state current_state = state_.load(std::memory_order_relaxed); if (initial_state != current_state) { if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { - gpr_log(GPR_INFO, - "ConnectivityStateTracker %s[%p]: notifying watcher %p: %s -> %s", - name_, this, watcher.get(), ConnectivityStateName(initial_state), - ConnectivityStateName(current_state)); + LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this + << "]: notifying watcher " << watcher.get() << ": " + << ConnectivityStateName(initial_state) << " -> " + << ConnectivityStateName(current_state); } watcher->Notify(current_state, status_); } @@ -140,8 +142,8 @@ void ConnectivityStateTracker::AddWatcher( void ConnectivityStateTracker::RemoveWatcher( ConnectivityStateWatcherInterface* watcher) { if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { - gpr_log(GPR_INFO, "ConnectivityStateTracker %s[%p]: remove watcher %p", - name_, this, watcher); + LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this + << "]: remove watcher " << watcher; } watchers_.erase(watcher); } @@ -153,18 +155,19 @@ void ConnectivityStateTracker::SetState(grpc_connectivity_state state, state_.load(std::memory_order_relaxed); if (state == current_state) return; if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { - gpr_log(GPR_INFO, "ConnectivityStateTracker %s[%p]: %s -> %s (%s, %s)", - name_, this, ConnectivityStateName(current_state), - ConnectivityStateName(state), reason, status.ToString().c_str()); + LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this + << "]: " << ConnectivityStateName(current_state) << " -> " + << ConnectivityStateName(state) << " (" << reason << ", " + << status.ToString() << ")"; } state_.store(state, std::memory_order_relaxed); status_ = status; for (const auto& p : watchers_) { if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { - gpr_log(GPR_INFO, - "ConnectivityStateTracker %s[%p]: notifying watcher %p: %s -> %s", - name_, this, p.first, ConnectivityStateName(current_state), - ConnectivityStateName(state)); + LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this + << "]: notifying watcher " << p.first << ": " + << ConnectivityStateName(current_state) << " -> " + << ConnectivityStateName(state); } p.second->Notify(state, status); } @@ -176,8 +179,8 @@ void ConnectivityStateTracker::SetState(grpc_connectivity_state state, grpc_connectivity_state ConnectivityStateTracker::state() const { grpc_connectivity_state state = state_.load(std::memory_order_relaxed); if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { - gpr_log(GPR_INFO, "ConnectivityStateTracker %s[%p]: get current state: %s", - name_, this, ConnectivityStateName(state)); + LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this + << "]: get current state: " << ConnectivityStateName(state); } return state; } diff --git a/src/core/lib/transport/transport.h b/src/core/lib/transport/transport.h index b26d9c1bb3f..fa32ce2aed4 100644 --- a/src/core/lib/transport/transport.h +++ b/src/core/lib/transport/transport.h @@ -28,6 +28,7 @@ #include #include "absl/functional/any_invocable.h" +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/strings/string_view.h" #include "absl/types/optional.h" @@ -35,7 +36,6 @@ #include #include #include -#include #include #include @@ -191,8 +191,8 @@ void grpc_stream_ref_init(grpc_stream_refcount* refcount, int initial_refs, inline void grpc_stream_ref(grpc_stream_refcount* refcount, const char* reason) { if (GRPC_TRACE_FLAG_ENABLED(stream_refcount)) { - gpr_log(GPR_DEBUG, "%s %p:%p REF %s", refcount->object_type, refcount, - refcount->destroy.cb_arg, reason); + VLOG(2) << refcount->object_type << " " << refcount << ":" + << refcount->destroy.cb_arg << " REF " << reason; } refcount->refs.RefNonZero(DEBUG_LOCATION, reason); } @@ -208,8 +208,8 @@ void grpc_stream_destroy(grpc_stream_refcount* refcount); inline void grpc_stream_unref(grpc_stream_refcount* refcount, const char* reason) { if (GRPC_TRACE_FLAG_ENABLED(stream_refcount)) { - gpr_log(GPR_DEBUG, "%s %p:%p UNREF %s", refcount->object_type, refcount, - refcount->destroy.cb_arg, reason); + VLOG(2) << refcount->object_type << " " << refcount << ":" + << refcount->destroy.cb_arg << " UNREF " << reason; } if (GPR_UNLIKELY(refcount->refs.Unref(DEBUG_LOCATION, reason))) { grpc_stream_destroy(refcount); From 54660b1df3e6595690bd314166737bef5450f71f Mon Sep 17 00:00:00 2001 From: Tanvi Jagtap <139093547+tanvi-jagtap@users.noreply.github.com> Date: Thu, 4 Jul 2024 19:59:03 -0700 Subject: [PATCH 6/6] [Gpr_To_Absl_Logging] Migrating from gpr to absl logging - gpr_log (#37151) [Gpr_To_Absl_Logging] Migrating from gpr to absl logging - gpr_log In this CL we are migrating from gRPCs own gpr logging mechanism to absl logging mechanism. The intention is to deprecate gpr_log in the future. We have the following mapping 1. gpr_log(GPR_INFO,...) -> LOG(INFO) 2. gpr_log(GPR_ERROR,...) -> LOG(ERROR) 3. gpr_log(GPR_DEBUG,...) -> VLOG(2) Reviewers need to check : 1. If the above mapping is correct. 2. The content of the log is as before. gpr_log format strings did not use string_view or std::string . absl LOG accepts these. So there will be some elimination of string_view and std::string related conversions. This is expected. Closes #37151 COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/37151 from tanvi-jagtap:src_core_ext_filters 40c7f3ccbad91bef02251d6207e032af698c38b0 PiperOrigin-RevId: 649523690 --- .../backend_metrics/backend_metric_filter.cc | 10 +++--- .../fault_injection/fault_injection_filter.cc | 6 ++-- .../message_compress/compression_filter.cc | 31 +++++++++---------- .../filters/http/server/http_server_filter.cc | 6 ++-- .../server_load_reporting_filter.cc | 17 +++++----- .../ext/filters/logging/logging_filter.cc | 9 ++---- .../message_size/message_size_filter.cc | 8 ++--- 7 files changed, 39 insertions(+), 48 deletions(-) diff --git a/src/core/ext/filters/backend_metrics/backend_metric_filter.cc b/src/core/ext/filters/backend_metrics/backend_metric_filter.cc index ebe189f9bea..24ac03bc38d 100644 --- a/src/core/ext/filters/backend_metrics/backend_metric_filter.cc +++ b/src/core/ext/filters/backend_metrics/backend_metric_filter.cc @@ -24,13 +24,13 @@ #include #include +#include "absl/log/log.h" #include "absl/strings/string_view.h" #include "upb/base/string_view.h" #include "upb/mem/arena.hpp" #include "xds/data/orca/v3/orca_load_report.upb.h" #include -#include #include "src/core/lib/channel/channel_stack.h" #include "src/core/lib/channel/promise_based_filter.h" @@ -129,20 +129,20 @@ void BackendMetricFilter::Call::OnServerTrailingMetadata(ServerMetadata& md) { auto* ctx = MaybeGetContext(); if (ctx == nullptr) { if (GRPC_TRACE_FLAG_ENABLED(backend_metric_filter)) { - gpr_log(GPR_INFO, "[%p] No BackendMetricProvider.", this); + LOG(INFO) << "[" << this << "] No BackendMetricProvider."; } return; } absl::optional serialized = MaybeSerializeBackendMetrics(ctx); if (serialized.has_value() && !serialized->empty()) { if (GRPC_TRACE_FLAG_ENABLED(backend_metric_filter)) { - gpr_log(GPR_INFO, "[%p] Backend metrics serialized. size: %" PRIuPTR, - this, serialized->size()); + LOG(INFO) << "[" << this + << "] Backend metrics serialized. size: " << serialized->size(); } md.Set(EndpointLoadMetricsBinMetadata(), Slice::FromCopiedString(std::move(*serialized))); } else if (GRPC_TRACE_FLAG_ENABLED(backend_metric_filter)) { - gpr_log(GPR_INFO, "[%p] No backend metrics.", this); + LOG(INFO) << "[" << this << "] No backend metrics."; } } diff --git a/src/core/ext/filters/fault_injection/fault_injection_filter.cc b/src/core/ext/filters/fault_injection/fault_injection_filter.cc index 033f8ee99c3..b4bf623bbb1 100644 --- a/src/core/ext/filters/fault_injection/fault_injection_filter.cc +++ b/src/core/ext/filters/fault_injection/fault_injection_filter.cc @@ -27,6 +27,7 @@ #include #include +#include "absl/log/log.h" #include "absl/meta/type_traits.h" #include "absl/status/status.h" #include "absl/status/statusor.h" @@ -36,7 +37,6 @@ #include "absl/types/optional.h" #include -#include #include "src/core/ext/filters/fault_injection/fault_injection_service_config_parser.h" #include "src/core/lib/channel/channel_stack.h" @@ -151,8 +151,8 @@ ArenaPromise FaultInjectionFilter::Call::OnClientInitialMetadata( ClientMetadata& md, FaultInjectionFilter* filter) { auto decision = filter->MakeInjectionDecision(md); if (GRPC_TRACE_FLAG_ENABLED(fault_injection_filter)) { - gpr_log(GPR_INFO, "chand=%p: Fault injection triggered %s", this, - decision.ToString().c_str()); + LOG(INFO) << "chand=" << this << ": Fault injection triggered " + << decision.ToString(); } auto delay = decision.DelayUntil(); return TrySeq(Sleep(delay), [decision = std::move(decision)]() { diff --git a/src/core/ext/filters/http/message_compress/compression_filter.cc b/src/core/ext/filters/http/message_compress/compression_filter.cc index 00839eebe5b..33491f1e6c4 100644 --- a/src/core/ext/filters/http/message_compress/compression_filter.cc +++ b/src/core/ext/filters/http/message_compress/compression_filter.cc @@ -32,7 +32,6 @@ #include #include #include -#include #include "src/core/ext/filters/message_size/message_size_filter.h" #include "src/core/lib/channel/channel_args.h" @@ -104,9 +103,8 @@ ChannelCompression::ChannelCompression(const ChannelArgs& args) &name)) { name = ""; } - gpr_log(GPR_ERROR, - "default compression algorithm %s not enabled: switching to none", - name); + LOG(ERROR) << "default compression algorithm " << name + << " not enabled: switching to none"; default_compression_algorithm_ = GRPC_COMPRESS_NONE; } } @@ -114,8 +112,8 @@ ChannelCompression::ChannelCompression(const ChannelArgs& args) MessageHandle ChannelCompression::CompressMessage( MessageHandle message, grpc_compression_algorithm algorithm) const { if (GRPC_TRACE_FLAG_ENABLED(compression)) { - gpr_log(GPR_INFO, "CompressMessage: len=%" PRIdPTR " alg=%d flags=%d", - message->payload()->Length(), algorithm, message->flags()); + LOG(INFO) << "CompressMessage: len=" << message->payload()->Length() + << " alg=" << algorithm << " flags=" << message->flags(); } auto* call_tracer = MaybeGetContext(); if (call_tracer != nullptr) { @@ -144,10 +142,10 @@ MessageHandle ChannelCompression::CompressMessage( const float savings_ratio = 1.0f - static_cast(after_size) / static_cast(before_size); CHECK(grpc_compression_algorithm_name(algorithm, &algo_name)); - gpr_log(GPR_INFO, - "Compressed[%s] %" PRIuPTR " bytes vs. %" PRIuPTR - " bytes (%.2f%% savings)", - algo_name, before_size, after_size, 100 * savings_ratio); + LOG(INFO) << absl::StrFormat( + "Compressed[%s] %" PRIuPTR " bytes vs. %" PRIuPTR + " bytes (%.2f%% savings)", + algo_name, before_size, after_size, 100 * savings_ratio); } tmp.Swap(payload); flags |= GRPC_WRITE_INTERNAL_COMPRESS; @@ -158,10 +156,9 @@ MessageHandle ChannelCompression::CompressMessage( if (GRPC_TRACE_FLAG_ENABLED(compression)) { const char* algo_name; CHECK(grpc_compression_algorithm_name(algorithm, &algo_name)); - gpr_log(GPR_INFO, - "Algorithm '%s' enabled but decided not to compress. Input size: " - "%" PRIuPTR, - algo_name, payload->Length()); + LOG(INFO) << "Algorithm '" << algo_name + << "' enabled but decided not to compress. Input size: " + << payload->Length(); } } return message; @@ -170,9 +167,9 @@ MessageHandle ChannelCompression::CompressMessage( absl::StatusOr ChannelCompression::DecompressMessage( bool is_client, MessageHandle message, DecompressArgs args) const { if (GRPC_TRACE_FLAG_ENABLED(compression)) { - gpr_log(GPR_INFO, "DecompressMessage: len=%" PRIdPTR " max=%d alg=%d", - message->payload()->Length(), - args.max_recv_message_length.value_or(-1), args.algorithm); + LOG(INFO) << "DecompressMessage: len=" << message->payload()->Length() + << " max=" << args.max_recv_message_length.value_or(-1) + << " alg=" << args.algorithm; } auto* call_tracer = MaybeGetContext(); if (call_tracer != nullptr) { diff --git a/src/core/ext/filters/http/server/http_server_filter.cc b/src/core/ext/filters/http/server/http_server_filter.cc index 0e863638901..5cfe96f7170 100644 --- a/src/core/ext/filters/http/server/http_server_filter.cc +++ b/src/core/ext/filters/http/server/http_server_filter.cc @@ -25,12 +25,12 @@ #include #include "absl/base/attributes.h" +#include "absl/log/log.h" #include "absl/strings/string_view.h" #include "absl/types/optional.h" #include #include -#include #include "src/core/lib/channel/channel_args.h" #include "src/core/lib/channel/channel_stack.h" @@ -140,8 +140,8 @@ ServerMetadataHandle HttpServerFilter::Call::OnClientInitialMetadata( void HttpServerFilter::Call::OnServerInitialMetadata(ServerMetadata& md) { if (GRPC_TRACE_FLAG_ENABLED(call)) { - gpr_log(GPR_INFO, "%s[http-server] Write metadata", - GetContext()->DebugTag().c_str()); + LOG(INFO) << GetContext()->DebugTag() + << "[http-server] Write metadata"; } FilterOutgoingMetadata(&md); md.Set(HttpStatusMetadata(), 200); diff --git a/src/core/ext/filters/load_reporting/server_load_reporting_filter.cc b/src/core/ext/filters/load_reporting/server_load_reporting_filter.cc index 6b4f77bdae5..2023fb436d6 100644 --- a/src/core/ext/filters/load_reporting/server_load_reporting_filter.cc +++ b/src/core/ext/filters/load_reporting/server_load_reporting_filter.cc @@ -29,6 +29,7 @@ #include #include "absl/container/inlined_vector.h" +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/strings/ascii.h" #include "absl/strings/str_cat.h" @@ -41,7 +42,6 @@ #include #include #include -#include #include #include "src/core/ext/filters/load_reporting/registered_opencensus_objects.h" @@ -103,26 +103,23 @@ std::string GetCensusSafeClientIpString( // Find the client URI string. const Slice* client_uri_slice = initial_metadata.get_pointer(PeerString()); if (client_uri_slice == nullptr) { - gpr_log(GPR_ERROR, - "Unable to extract client URI string (peer string) from gRPC " - "metadata."); + LOG(ERROR) << "Unable to extract client URI string (peer string) from gRPC " + "metadata."; return ""; } absl::StatusOr client_uri = URI::Parse(client_uri_slice->as_string_view()); if (!client_uri.ok()) { - gpr_log(GPR_ERROR, - "Unable to parse the client URI string (peer string) to a client " - "URI. Error: %s", - client_uri.status().ToString().c_str()); + LOG(ERROR) << "Unable to parse the client URI string (peer string) to a " + "client URI. Error: " + << client_uri.status(); return ""; } // Parse the client URI into grpc_resolved_address. grpc_resolved_address resolved_address; bool success = grpc_parse_uri(*client_uri, &resolved_address); if (!success) { - gpr_log(GPR_ERROR, - "Unable to parse client URI into a grpc_resolved_address."); + LOG(ERROR) << "Unable to parse client URI into a grpc_resolved_address."; return ""; } // Convert the socket address in the grpc_resolved_address into a hex string diff --git a/src/core/ext/filters/logging/logging_filter.cc b/src/core/ext/filters/logging/logging_filter.cc index c0a749d315e..67d1b274691 100644 --- a/src/core/ext/filters/logging/logging_filter.cc +++ b/src/core/ext/filters/logging/logging_filter.cc @@ -46,7 +46,6 @@ #include #include #include -#include #include "src/core/client_channel/client_channel_filter.h" #include "src/core/ext/filters/logging/logging_sink.h" @@ -106,11 +105,9 @@ class MetadataEncoder { } uint64_t mdentry_len = key.length() + value.length(); if (mdentry_len > log_len_) { - gpr_log( - GPR_DEBUG, - "Skipped metadata key because of max metadata logging bytes %" PRIu64 - " (current) vs %" PRIu64 " (max less already accounted metadata)", - mdentry_len, log_len_); + VLOG(2) << "Skipped metadata key because of max metadata logging bytes " + << mdentry_len << " (current) vs " << log_len_ + << " (max less already accounted metadata)"; truncated_ = true; return; } diff --git a/src/core/ext/filters/message_size/message_size_filter.cc b/src/core/ext/filters/message_size/message_size_filter.cc index 580770ede7b..269bafd6c22 100644 --- a/src/core/ext/filters/message_size/message_size_filter.cc +++ b/src/core/ext/filters/message_size/message_size_filter.cc @@ -23,11 +23,11 @@ #include #include +#include "absl/log/log.h" #include "absl/strings/str_format.h" #include #include -#include #include "src/core/lib/channel/channel_args.h" #include "src/core/lib/channel/channel_stack.h" @@ -160,9 +160,9 @@ ServerMetadataHandle CheckPayload(const Message& msg, bool is_client, bool is_send) { if (!max_length.has_value()) return nullptr; if (GRPC_TRACE_FLAG_ENABLED(call)) { - gpr_log(GPR_INFO, "%s[message_size] %s len:%" PRIdPTR " max:%d", - GetContext()->DebugTag().c_str(), - is_send ? "send" : "recv", msg.payload()->Length(), *max_length); + LOG(INFO) << GetContext()->DebugTag() << "[message_size] " + << (is_send ? "send" : "recv") + << " len:" << msg.payload()->Length() << " max:" << *max_length; } if (msg.payload()->Length() <= *max_length) return nullptr; auto r = Arena::MakePooled();