Merge master

pull/37149/head
tanvi-jagtap 5 months ago
commit 91c40bbf6a
  1. 5
      src/core/BUILD
  2. 10
      src/core/ext/filters/backend_metrics/backend_metric_filter.cc
  3. 10
      src/core/ext/filters/channel_idle/legacy_channel_idle_filter.cc
  4. 6
      src/core/ext/filters/fault_injection/fault_injection_filter.cc
  5. 25
      src/core/ext/filters/http/message_compress/compression_filter.cc
  6. 6
      src/core/ext/filters/http/server/http_server_filter.cc
  7. 17
      src/core/ext/filters/load_reporting/server_load_reporting_filter.cc
  8. 9
      src/core/ext/filters/logging/logging_filter.cc
  9. 8
      src/core/ext/filters/message_size/message_size_filter.cc
  10. 60
      src/core/ext/transport/binder/wire_format/wire_reader_impl.cc
  11. 62
      src/core/lib/iomgr/call_combiner.cc
  12. 65
      src/core/lib/iomgr/combiner.cc
  13. 46
      src/core/lib/iomgr/endpoint_cfstream.cc
  14. 69
      src/core/lib/iomgr/ev_epoll1_linux.cc
  15. 113
      src/core/lib/iomgr/timer_generic.cc
  16. 14
      src/core/lib/surface/call.cc
  17. 10
      src/core/lib/surface/call_utils.cc
  18. 12
      src/core/lib/surface/channel_init.cc
  19. 36
      src/core/lib/surface/completion_queue.cc
  20. 10
      src/core/lib/surface/legacy_channel.cc
  21. 16
      src/core/lib/transport/bdp_estimator.cc
  22. 10
      src/core/lib/transport/bdp_estimator.h
  23. 12
      src/core/lib/transport/call_filters.cc
  24. 53
      src/core/lib/transport/connectivity_state.cc
  25. 10
      src/core/lib/transport/transport.h
  26. 36
      src/core/resolver/dns/c_ares/grpc_ares_wrapper.cc
  27. 4
      src/core/resolver/dns/c_ares/grpc_ares_wrapper.h
  28. 5
      src/core/resolver/dns/event_engine/event_engine_client_channel_resolver.cc
  29. 13
      src/core/resolver/dns/native/dns_resolver.cc
  30. 61
      src/core/resolver/xds/xds_resolver.cc
  31. 32
      src/core/server/server.cc
  32. 49
      src/core/server/xds_server_config_fetcher.cc

@ -7846,7 +7846,10 @@ grpc_cc_library(
hdrs = [ hdrs = [
"lib/transport/call_filters.h", "lib/transport/call_filters.h",
], ],
external_deps = ["absl/log:check"], external_deps = [
"absl/log:check",
"absl/log:log",
],
deps = [ deps = [
"call_final_info", "call_final_info",
"call_state", "call_state",

@ -24,13 +24,13 @@
#include <memory> #include <memory>
#include <utility> #include <utility>
#include "absl/log/log.h"
#include "absl/strings/string_view.h" #include "absl/strings/string_view.h"
#include "upb/base/string_view.h" #include "upb/base/string_view.h"
#include "upb/mem/arena.hpp" #include "upb/mem/arena.hpp"
#include "xds/data/orca/v3/orca_load_report.upb.h" #include "xds/data/orca/v3/orca_load_report.upb.h"
#include <grpc/impl/channel_arg_names.h> #include <grpc/impl/channel_arg_names.h>
#include <grpc/support/log.h>
#include "src/core/lib/channel/channel_stack.h" #include "src/core/lib/channel/channel_stack.h"
#include "src/core/lib/channel/promise_based_filter.h" #include "src/core/lib/channel/promise_based_filter.h"
@ -129,20 +129,20 @@ void BackendMetricFilter::Call::OnServerTrailingMetadata(ServerMetadata& md) {
auto* ctx = MaybeGetContext<BackendMetricProvider>(); auto* ctx = MaybeGetContext<BackendMetricProvider>();
if (ctx == nullptr) { if (ctx == nullptr) {
if (GRPC_TRACE_FLAG_ENABLED(backend_metric_filter)) { if (GRPC_TRACE_FLAG_ENABLED(backend_metric_filter)) {
gpr_log(GPR_INFO, "[%p] No BackendMetricProvider.", this); LOG(INFO) << "[" << this << "] No BackendMetricProvider.";
} }
return; return;
} }
absl::optional<std::string> serialized = MaybeSerializeBackendMetrics(ctx); absl::optional<std::string> serialized = MaybeSerializeBackendMetrics(ctx);
if (serialized.has_value() && !serialized->empty()) { if (serialized.has_value() && !serialized->empty()) {
if (GRPC_TRACE_FLAG_ENABLED(backend_metric_filter)) { if (GRPC_TRACE_FLAG_ENABLED(backend_metric_filter)) {
gpr_log(GPR_INFO, "[%p] Backend metrics serialized. size: %" PRIuPTR, LOG(INFO) << "[" << this
this, serialized->size()); << "] Backend metrics serialized. size: " << serialized->size();
} }
md.Set(EndpointLoadMetricsBinMetadata(), md.Set(EndpointLoadMetricsBinMetadata(),
Slice::FromCopiedString(std::move(*serialized))); Slice::FromCopiedString(std::move(*serialized)));
} else if (GRPC_TRACE_FLAG_ENABLED(backend_metric_filter)) { } else if (GRPC_TRACE_FLAG_ENABLED(backend_metric_filter)) {
gpr_log(GPR_INFO, "[%p] No backend metrics.", this); LOG(INFO) << "[" << this << "] No backend metrics.";
} }
} }

@ -71,13 +71,6 @@ const auto kMaxConnectionAgeJitter = 0.1;
} // namespace } // 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) { Duration GetClientIdleTimeout(const ChannelArgs& args) {
return args.GetDurationFromIntMillis(GRPC_ARG_CLIENT_IDLE_TIMEOUT_MS) return args.GetDurationFromIntMillis(GRPC_ARG_CLIENT_IDLE_TIMEOUT_MS)
.value_or(kDefaultIdleTimeout); .value_or(kDefaultIdleTimeout);
@ -259,7 +252,8 @@ void LegacyChannelIdleFilter::DecreaseCallCount() {
} }
void LegacyChannelIdleFilter::StartIdleTimer() { 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_; auto idle_filter_state = idle_filter_state_;
// Hold a ref to the channel stack for the timer callback. // Hold a ref to the channel stack for the timer callback.
auto channel_stack = channel_stack_->Ref(); auto channel_stack = channel_stack_->Ref();

@ -27,6 +27,7 @@
#include <type_traits> #include <type_traits>
#include <utility> #include <utility>
#include "absl/log/log.h"
#include "absl/meta/type_traits.h" #include "absl/meta/type_traits.h"
#include "absl/status/status.h" #include "absl/status/status.h"
#include "absl/status/statusor.h" #include "absl/status/statusor.h"
@ -36,7 +37,6 @@
#include "absl/types/optional.h" #include "absl/types/optional.h"
#include <grpc/status.h> #include <grpc/status.h>
#include <grpc/support/log.h>
#include "src/core/ext/filters/fault_injection/fault_injection_service_config_parser.h" #include "src/core/ext/filters/fault_injection/fault_injection_service_config_parser.h"
#include "src/core/lib/channel/channel_stack.h" #include "src/core/lib/channel/channel_stack.h"
@ -151,8 +151,8 @@ ArenaPromise<absl::Status> FaultInjectionFilter::Call::OnClientInitialMetadata(
ClientMetadata& md, FaultInjectionFilter* filter) { ClientMetadata& md, FaultInjectionFilter* filter) {
auto decision = filter->MakeInjectionDecision(md); auto decision = filter->MakeInjectionDecision(md);
if (GRPC_TRACE_FLAG_ENABLED(fault_injection_filter)) { if (GRPC_TRACE_FLAG_ENABLED(fault_injection_filter)) {
gpr_log(GPR_INFO, "chand=%p: Fault injection triggered %s", this, LOG(INFO) << "chand=" << this << ": Fault injection triggered "
decision.ToString().c_str()); << decision.ToString();
} }
auto delay = decision.DelayUntil(); auto delay = decision.DelayUntil();
return TrySeq(Sleep(delay), [decision = std::move(decision)]() { return TrySeq(Sleep(delay), [decision = std::move(decision)]() {

@ -32,7 +32,6 @@
#include <grpc/grpc.h> #include <grpc/grpc.h>
#include <grpc/impl/channel_arg_names.h> #include <grpc/impl/channel_arg_names.h>
#include <grpc/impl/compression_types.h> #include <grpc/impl/compression_types.h>
#include <grpc/support/log.h>
#include "src/core/ext/filters/message_size/message_size_filter.h" #include "src/core/ext/filters/message_size/message_size_filter.h"
#include "src/core/lib/channel/channel_args.h" #include "src/core/lib/channel/channel_args.h"
@ -104,9 +103,8 @@ ChannelCompression::ChannelCompression(const ChannelArgs& args)
&name)) { &name)) {
name = "<unknown>"; name = "<unknown>";
} }
gpr_log(GPR_ERROR, LOG(ERROR) << "default compression algorithm " << name
"default compression algorithm %s not enabled: switching to none", << " not enabled: switching to none";
name);
default_compression_algorithm_ = GRPC_COMPRESS_NONE; default_compression_algorithm_ = GRPC_COMPRESS_NONE;
} }
} }
@ -114,8 +112,8 @@ ChannelCompression::ChannelCompression(const ChannelArgs& args)
MessageHandle ChannelCompression::CompressMessage( MessageHandle ChannelCompression::CompressMessage(
MessageHandle message, grpc_compression_algorithm algorithm) const { MessageHandle message, grpc_compression_algorithm algorithm) const {
if (GRPC_TRACE_FLAG_ENABLED(compression)) { if (GRPC_TRACE_FLAG_ENABLED(compression)) {
gpr_log(GPR_INFO, "CompressMessage: len=%" PRIdPTR " alg=%d flags=%d", LOG(INFO) << "CompressMessage: len=" << message->payload()->Length()
message->payload()->Length(), algorithm, message->flags()); << " alg=" << algorithm << " flags=" << message->flags();
} }
auto* call_tracer = MaybeGetContext<CallTracerInterface>(); auto* call_tracer = MaybeGetContext<CallTracerInterface>();
if (call_tracer != nullptr) { if (call_tracer != nullptr) {
@ -144,7 +142,7 @@ MessageHandle ChannelCompression::CompressMessage(
const float savings_ratio = 1.0f - static_cast<float>(after_size) / const float savings_ratio = 1.0f - static_cast<float>(after_size) /
static_cast<float>(before_size); static_cast<float>(before_size);
CHECK(grpc_compression_algorithm_name(algorithm, &algo_name)); CHECK(grpc_compression_algorithm_name(algorithm, &algo_name));
gpr_log(GPR_INFO, LOG(INFO) << absl::StrFormat(
"Compressed[%s] %" PRIuPTR " bytes vs. %" PRIuPTR "Compressed[%s] %" PRIuPTR " bytes vs. %" PRIuPTR
" bytes (%.2f%% savings)", " bytes (%.2f%% savings)",
algo_name, before_size, after_size, 100 * savings_ratio); algo_name, before_size, after_size, 100 * savings_ratio);
@ -158,10 +156,9 @@ MessageHandle ChannelCompression::CompressMessage(
if (GRPC_TRACE_FLAG_ENABLED(compression)) { if (GRPC_TRACE_FLAG_ENABLED(compression)) {
const char* algo_name; const char* algo_name;
CHECK(grpc_compression_algorithm_name(algorithm, &algo_name)); CHECK(grpc_compression_algorithm_name(algorithm, &algo_name));
gpr_log(GPR_INFO, LOG(INFO) << "Algorithm '" << algo_name
"Algorithm '%s' enabled but decided not to compress. Input size: " << "' enabled but decided not to compress. Input size: "
"%" PRIuPTR, << payload->Length();
algo_name, payload->Length());
} }
} }
return message; return message;
@ -170,9 +167,9 @@ MessageHandle ChannelCompression::CompressMessage(
absl::StatusOr<MessageHandle> ChannelCompression::DecompressMessage( absl::StatusOr<MessageHandle> ChannelCompression::DecompressMessage(
bool is_client, MessageHandle message, DecompressArgs args) const { bool is_client, MessageHandle message, DecompressArgs args) const {
if (GRPC_TRACE_FLAG_ENABLED(compression)) { if (GRPC_TRACE_FLAG_ENABLED(compression)) {
gpr_log(GPR_INFO, "DecompressMessage: len=%" PRIdPTR " max=%d alg=%d", LOG(INFO) << "DecompressMessage: len=" << message->payload()->Length()
message->payload()->Length(), << " max=" << args.max_recv_message_length.value_or(-1)
args.max_recv_message_length.value_or(-1), args.algorithm); << " alg=" << args.algorithm;
} }
auto* call_tracer = MaybeGetContext<CallTracerInterface>(); auto* call_tracer = MaybeGetContext<CallTracerInterface>();
if (call_tracer != nullptr) { if (call_tracer != nullptr) {

@ -25,12 +25,12 @@
#include <utility> #include <utility>
#include "absl/base/attributes.h" #include "absl/base/attributes.h"
#include "absl/log/log.h"
#include "absl/strings/string_view.h" #include "absl/strings/string_view.h"
#include "absl/types/optional.h" #include "absl/types/optional.h"
#include <grpc/impl/channel_arg_names.h> #include <grpc/impl/channel_arg_names.h>
#include <grpc/status.h> #include <grpc/status.h>
#include <grpc/support/log.h>
#include "src/core/lib/channel/channel_args.h" #include "src/core/lib/channel/channel_args.h"
#include "src/core/lib/channel/channel_stack.h" #include "src/core/lib/channel/channel_stack.h"
@ -140,8 +140,8 @@ ServerMetadataHandle HttpServerFilter::Call::OnClientInitialMetadata(
void HttpServerFilter::Call::OnServerInitialMetadata(ServerMetadata& md) { void HttpServerFilter::Call::OnServerInitialMetadata(ServerMetadata& md) {
if (GRPC_TRACE_FLAG_ENABLED(call)) { if (GRPC_TRACE_FLAG_ENABLED(call)) {
gpr_log(GPR_INFO, "%s[http-server] Write metadata", LOG(INFO) << GetContext<Activity>()->DebugTag()
GetContext<Activity>()->DebugTag().c_str()); << "[http-server] Write metadata";
} }
FilterOutgoingMetadata(&md); FilterOutgoingMetadata(&md);
md.Set(HttpStatusMetadata(), 200); md.Set(HttpStatusMetadata(), 200);

@ -29,6 +29,7 @@
#include <utility> #include <utility>
#include "absl/container/inlined_vector.h" #include "absl/container/inlined_vector.h"
#include "absl/log/log.h"
#include "absl/status/status.h" #include "absl/status/status.h"
#include "absl/strings/ascii.h" #include "absl/strings/ascii.h"
#include "absl/strings/str_cat.h" #include "absl/strings/str_cat.h"
@ -41,7 +42,6 @@
#include <grpc/grpc_security.h> #include <grpc/grpc_security.h>
#include <grpc/impl/channel_arg_names.h> #include <grpc/impl/channel_arg_names.h>
#include <grpc/status.h> #include <grpc/status.h>
#include <grpc/support/log.h>
#include <grpc/support/time.h> #include <grpc/support/time.h>
#include "src/core/ext/filters/load_reporting/registered_opencensus_objects.h" #include "src/core/ext/filters/load_reporting/registered_opencensus_objects.h"
@ -103,26 +103,23 @@ std::string GetCensusSafeClientIpString(
// Find the client URI string. // Find the client URI string.
const Slice* client_uri_slice = initial_metadata.get_pointer(PeerString()); const Slice* client_uri_slice = initial_metadata.get_pointer(PeerString());
if (client_uri_slice == nullptr) { if (client_uri_slice == nullptr) {
gpr_log(GPR_ERROR, LOG(ERROR) << "Unable to extract client URI string (peer string) from gRPC "
"Unable to extract client URI string (peer string) from gRPC " "metadata.";
"metadata.");
return ""; return "";
} }
absl::StatusOr<URI> client_uri = absl::StatusOr<URI> client_uri =
URI::Parse(client_uri_slice->as_string_view()); URI::Parse(client_uri_slice->as_string_view());
if (!client_uri.ok()) { if (!client_uri.ok()) {
gpr_log(GPR_ERROR, LOG(ERROR) << "Unable to parse the client URI string (peer string) to a "
"Unable to parse the client URI string (peer string) to a client " "client URI. Error: "
"URI. Error: %s", << client_uri.status();
client_uri.status().ToString().c_str());
return ""; return "";
} }
// Parse the client URI into grpc_resolved_address. // Parse the client URI into grpc_resolved_address.
grpc_resolved_address resolved_address; grpc_resolved_address resolved_address;
bool success = grpc_parse_uri(*client_uri, &resolved_address); bool success = grpc_parse_uri(*client_uri, &resolved_address);
if (!success) { if (!success) {
gpr_log(GPR_ERROR, LOG(ERROR) << "Unable to parse client URI into a grpc_resolved_address.";
"Unable to parse client URI into a grpc_resolved_address.");
return ""; return "";
} }
// Convert the socket address in the grpc_resolved_address into a hex string // Convert the socket address in the grpc_resolved_address into a hex string

@ -46,7 +46,6 @@
#include <grpc/impl/channel_arg_names.h> #include <grpc/impl/channel_arg_names.h>
#include <grpc/slice.h> #include <grpc/slice.h>
#include <grpc/status.h> #include <grpc/status.h>
#include <grpc/support/log.h>
#include "src/core/client_channel/client_channel_filter.h" #include "src/core/client_channel/client_channel_filter.h"
#include "src/core/ext/filters/logging/logging_sink.h" #include "src/core/ext/filters/logging/logging_sink.h"
@ -106,11 +105,9 @@ class MetadataEncoder {
} }
uint64_t mdentry_len = key.length() + value.length(); uint64_t mdentry_len = key.length() + value.length();
if (mdentry_len > log_len_) { if (mdentry_len > log_len_) {
gpr_log( VLOG(2) << "Skipped metadata key because of max metadata logging bytes "
GPR_DEBUG, << mdentry_len << " (current) vs " << log_len_
"Skipped metadata key because of max metadata logging bytes %" PRIu64 << " (max less already accounted metadata)";
" (current) vs %" PRIu64 " (max less already accounted metadata)",
mdentry_len, log_len_);
truncated_ = true; truncated_ = true;
return; return;
} }

@ -23,11 +23,11 @@
#include <functional> #include <functional>
#include <utility> #include <utility>
#include "absl/log/log.h"
#include "absl/strings/str_format.h" #include "absl/strings/str_format.h"
#include <grpc/impl/channel_arg_names.h> #include <grpc/impl/channel_arg_names.h>
#include <grpc/status.h> #include <grpc/status.h>
#include <grpc/support/log.h>
#include "src/core/lib/channel/channel_args.h" #include "src/core/lib/channel/channel_args.h"
#include "src/core/lib/channel/channel_stack.h" #include "src/core/lib/channel/channel_stack.h"
@ -160,9 +160,9 @@ ServerMetadataHandle CheckPayload(const Message& msg,
bool is_client, bool is_send) { bool is_client, bool is_send) {
if (!max_length.has_value()) return nullptr; if (!max_length.has_value()) return nullptr;
if (GRPC_TRACE_FLAG_ENABLED(call)) { if (GRPC_TRACE_FLAG_ENABLED(call)) {
gpr_log(GPR_INFO, "%s[message_size] %s len:%" PRIdPTR " max:%d", LOG(INFO) << GetContext<Activity>()->DebugTag() << "[message_size] "
GetContext<Activity>()->DebugTag().c_str(), << (is_send ? "send" : "recv")
is_send ? "send" : "recv", msg.payload()->Length(), *max_length); << " len:" << msg.payload()->Length() << " max:" << *max_length;
} }
if (msg.payload()->Length() <= *max_length) return nullptr; if (msg.payload()->Length() <= *max_length) return nullptr;
auto r = Arena::MakePooled<ServerMetadata>(); auto r = Arena::MakePooled<ServerMetadata>();

@ -30,8 +30,6 @@
#include "absl/memory/memory.h" #include "absl/memory/memory.h"
#include "absl/status/statusor.h" #include "absl/status/statusor.h"
#include <grpc/support/log.h>
#include "src/core/ext/transport/binder/utils/transport_stream_receiver.h" #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/binder.h"
#include "src/core/ext/transport/binder/wire_format/wire_writer.h" #include "src/core/ext/transport/binder/wire_format/wire_writer.h"
@ -109,11 +107,12 @@ std::shared_ptr<WireWriter> WireReaderImpl::SetupTransport(
void WireReaderImpl::SendSetupTransport(Binder* binder) { void WireReaderImpl::SendSetupTransport(Binder* binder) {
binder->Initialize(); binder->Initialize();
gpr_log(GPR_DEBUG, "prepare transaction = %d", const absl::Status prep_transaction_status = binder->PrepareTransaction();
binder->PrepareTransaction().ok()); VLOG(2) << "prepare transaction = " << prep_transaction_status;
WritableParcel* writable_parcel = binder->GetWritableParcel(); WritableParcel* writable_parcel = binder->GetWritableParcel();
gpr_log(GPR_DEBUG, "write int32 = %d", const absl::Status write_status =
writable_parcel->WriteInt32(kWireFormatVersion).ok()); 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 lifetime of the transaction receiver is the same as the wire writer's.
// The transaction receiver is responsible for not calling the on-transact // The transaction receiver is responsible for not calling the on-transact
// callback when it's dead. // callback when it's dead.
@ -127,11 +126,13 @@ void WireReaderImpl::SendSetupTransport(Binder* binder) {
return this->ProcessTransaction(code, readable_parcel, uid); return this->ProcessTransaction(code, readable_parcel, uid);
}); });
gpr_log(GPR_DEBUG, "tx_receiver = %p", tx_receiver_->GetRawBinder()); VLOG(2) << "tx_receiver = " << tx_receiver_->GetRawBinder();
gpr_log(GPR_DEBUG, "AParcel_writeStrongBinder = %d", const absl::Status write_binder_status =
writable_parcel->WriteBinder(tx_receiver_.get()).ok()); writable_parcel->WriteBinder(tx_receiver_.get());
gpr_log(GPR_DEBUG, "AIBinder_transact = %d", VLOG(2) << "AParcel_writeStrongBinder = " << write_binder_status;
binder->Transact(BinderTransportTxCode::SETUP_TRANSPORT).ok()); const absl::Status transact_status =
binder->Transact(BinderTransportTxCode::SETUP_TRANSPORT);
VLOG(2) << "AIBinder_transact = " << transact_status;
} }
std::unique_ptr<Binder> WireReaderImpl::RecvSetupTransport() { std::unique_ptr<Binder> WireReaderImpl::RecvSetupTransport() {
@ -181,7 +182,7 @@ absl::Status WireReaderImpl::ProcessTransaction(transaction_code_t code,
} }
recvd_setup_transport_ = true; recvd_setup_transport_ = true;
gpr_log(GPR_DEBUG, "calling uid = %d", uid); VLOG(2) << "calling uid = " << uid;
if (!security_policy_->IsAuthorized(uid)) { if (!security_policy_->IsAuthorized(uid)) {
return absl::PermissionDeniedError( return absl::PermissionDeniedError(
"UID " + std::to_string(uid) + "UID " + std::to_string(uid) +
@ -191,14 +192,13 @@ absl::Status WireReaderImpl::ProcessTransaction(transaction_code_t code,
int version; int version;
GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&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 // We only support this single lowest possible version, so server must
// respond that version too. // respond that version too.
if (version != kWireFormatVersion) { if (version != kWireFormatVersion) {
gpr_log(GPR_ERROR, LOG(ERROR) << "The other end respond with version = " << version
"The other end respond with version = %d, but we requested " << ", but we requested version " << kWireFormatVersion
"version %d, trying to continue anyway", << ", trying to continue anyway";
version, kWireFormatVersion);
} }
std::unique_ptr<Binder> binder{}; std::unique_ptr<Binder> binder{};
GRPC_RETURN_IF_ERROR(parcel->ReadBinder(&binder)); GRPC_RETURN_IF_ERROR(parcel->ReadBinder(&binder));
@ -218,7 +218,7 @@ absl::Status WireReaderImpl::ProcessTransaction(transaction_code_t code,
case BinderTransportTxCode::ACKNOWLEDGE_BYTES: { case BinderTransportTxCode::ACKNOWLEDGE_BYTES: {
int64_t num_bytes = -1; int64_t num_bytes = -1;
GRPC_RETURN_IF_ERROR(parcel->ReadInt64(&num_bytes)); 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( if (!wire_writer_ready_notification_.WaitForNotificationWithTimeout(
absl::Seconds(5))) { absl::Seconds(5))) {
return absl::DeadlineExceededError( return absl::DeadlineExceededError(
@ -233,14 +233,14 @@ absl::Status WireReaderImpl::ProcessTransaction(transaction_code_t code,
} }
int ping_id = -1; int ping_id = -1;
GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&ping_id)); 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. // TODO(waynetu): Ping back.
break; break;
} }
case BinderTransportTxCode::PING_RESPONSE: { case BinderTransportTxCode::PING_RESPONSE: {
int value = -1; int value = -1;
GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&value)); GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&value));
gpr_log(GPR_DEBUG, "received ping response = %d", value); VLOG(2) << "received ping response = " << value;
break; break;
} }
} }
@ -283,8 +283,8 @@ absl::Status WireReaderImpl::ProcessStreamingTransaction(
} }
if (!tx_process_result.ok()) { if (!tx_process_result.ok()) {
gpr_log(GPR_ERROR, "Failed to process streaming transaction: %s", LOG(ERROR) << "Failed to process streaming transaction: "
tx_process_result.ToString().c_str()); << tx_process_result.ToString();
// Something went wrong when receiving transaction. Cancel failed requests. // Something went wrong when receiving transaction. Cancel failed requests.
if (cancellation_flags & kFlagPrefix) { if (cancellation_flags & kFlagPrefix) {
LOG(INFO) << "cancelling initial metadata"; LOG(INFO) << "cancelling initial metadata";
@ -327,7 +327,7 @@ absl::Status WireReaderImpl::ProcessStreamingTransactionImpl(
std::queue<absl::AnyInvocable<void() &&>>& deferred_func_queue) { std::queue<absl::AnyInvocable<void() &&>>& deferred_func_queue) {
CHECK(cancellation_flags); CHECK(cancellation_flags);
num_incoming_bytes_ += parcel->GetDataSize(); 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; int flags;
GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&flags)); GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&flags));
@ -344,10 +344,10 @@ absl::Status WireReaderImpl::ProcessStreamingTransactionImpl(
} }
int status = flags >> 16; int status = flags >> 16;
gpr_log(GPR_DEBUG, "status = %d", status); VLOG(2) << "status = " << status;
gpr_log(GPR_DEBUG, "FLAG_PREFIX = %d", (flags & kFlagPrefix)); VLOG(2) << "FLAG_PREFIX = " << (flags & kFlagPrefix);
gpr_log(GPR_DEBUG, "FLAG_MESSAGE_DATA = %d", (flags & kFlagMessageData)); VLOG(2) << "FLAG_MESSAGE_DATA = " << (flags & kFlagMessageData);
gpr_log(GPR_DEBUG, "FLAG_SUFFIX = %d", (flags & kFlagSuffix)); VLOG(2) << "FLAG_SUFFIX = " << (flags & kFlagSuffix);
int seq_num; int seq_num;
GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&seq_num)); GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&seq_num));
// TODO(waynetu): For now we'll just assume that the transactions commit in // 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<int32_t>::max()) CHECK(expectation < std::numeric_limits<int32_t>::max())
<< "Sequence number too large"; << "Sequence number too large";
expectation++; expectation++;
gpr_log(GPR_DEBUG, "sequence number = %d", seq_num); VLOG(2) << "sequence number = " << seq_num;
if (flags & kFlagPrefix) { if (flags & kFlagPrefix) {
std::string method_ref; std::string method_ref;
if (!is_client_) { if (!is_client_) {
@ -405,7 +405,7 @@ absl::Status WireReaderImpl::ProcessStreamingTransactionImpl(
if (flags & kFlagMessageData) { if (flags & kFlagMessageData) {
int count; int count;
GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&count)); GRPC_RETURN_IF_ERROR(parcel->ReadInt32(&count));
gpr_log(GPR_DEBUG, "count = %d", count); VLOG(2) << "count = " << count;
std::string msg_data{}; std::string msg_data{};
if (count > 0) { if (count > 0) {
GRPC_RETURN_IF_ERROR(parcel->ReadByteArray(&msg_data)); GRPC_RETURN_IF_ERROR(parcel->ReadByteArray(&msg_data));
@ -425,7 +425,7 @@ absl::Status WireReaderImpl::ProcessStreamingTransactionImpl(
// FLAG_STATUS_DESCRIPTION set // FLAG_STATUS_DESCRIPTION set
std::string desc; std::string desc;
GRPC_RETURN_IF_ERROR(parcel->ReadString(&desc)); GRPC_RETURN_IF_ERROR(parcel->ReadString(&desc));
gpr_log(GPR_DEBUG, "description = %s", desc.c_str()); VLOG(2) << "description = " << desc;
} }
Metadata trailing_metadata; Metadata trailing_metadata;
if (is_client_) { if (is_client_) {

@ -23,7 +23,6 @@
#include "absl/log/check.h" #include "absl/log/check.h"
#include "absl/log/log.h" #include "absl/log/log.h"
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include "src/core/lib/gprpp/crash.h" #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, void CallCombiner::Start(grpc_closure* closure, grpc_error_handle error,
DEBUG_ARGS const char* reason) { DEBUG_ARGS const char* reason) {
if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { GRPC_TRACE_LOG(call_combiner, INFO) << absl::StrFormat(
gpr_log(GPR_INFO,
"==> CallCombiner::Start() [%p] closure=%s [" DEBUG_FMT_STR "==> CallCombiner::Start() [%p] closure=%s [" DEBUG_FMT_STR
"%s] error=%s", "%s] error=%s",
this, closure->DebugString().c_str() DEBUG_FMT_ARGS, reason, this, closure->DebugString().c_str() DEBUG_FMT_ARGS, reason,
StatusToString(error).c_str()); StatusToString(error).c_str());
}
size_t prev_size = size_t prev_size =
static_cast<size_t>(gpr_atm_full_fetch_add(&size_, (gpr_atm)1)); static_cast<size_t>(gpr_atm_full_fetch_add(&size_, (gpr_atm)1));
if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { GRPC_TRACE_LOG(call_combiner, INFO)
gpr_log(GPR_INFO, " size: %" PRIdPTR " -> %" PRIdPTR, prev_size, << " size: " << prev_size << " -> " << prev_size + 1;
prev_size + 1);
}
if (prev_size == 0) { if (prev_size == 0) {
GRPC_TRACE_LOG(call_combiner, INFO) << " EXECUTING IMMEDIATELY"; GRPC_TRACE_LOG(call_combiner, INFO) << " EXECUTING IMMEDIATELY";
// Queue was empty, so execute this closure 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) { void CallCombiner::Stop(DEBUG_ARGS const char* reason) {
if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { GRPC_TRACE_LOG(call_combiner, INFO)
gpr_log(GPR_INFO, "==> CallCombiner::Stop() [%p] [" DEBUG_FMT_STR "%s]", << absl::StrFormat("==> CallCombiner::Stop() [%p] [" DEBUG_FMT_STR "%s]",
this DEBUG_FMT_ARGS, reason); this DEBUG_FMT_ARGS, reason);
}
size_t prev_size = size_t prev_size =
static_cast<size_t>(gpr_atm_full_fetch_add(&size_, (gpr_atm)-1)); static_cast<size_t>(gpr_atm_full_fetch_add(&size_, (gpr_atm)-1));
if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { GRPC_TRACE_LOG(call_combiner, INFO)
gpr_log(GPR_INFO, " size: %" PRIdPTR " -> %" PRIdPTR, prev_size, << " size: " << prev_size << " -> " << prev_size - 1;
prev_size - 1);
}
CHECK_GE(prev_size, 1u); CHECK_GE(prev_size, 1u);
if (prev_size > 1) { if (prev_size > 1) {
while (true) { while (true) {
@ -168,10 +160,9 @@ void CallCombiner::Stop(DEBUG_ARGS const char* reason) {
grpc_error_handle error = grpc_error_handle error =
internal::StatusMoveFromHeapPtr(closure->error_data.error); internal::StatusMoveFromHeapPtr(closure->error_data.error);
closure->error_data.error = 0; closure->error_data.error = 0;
if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { GRPC_TRACE_LOG(call_combiner, INFO)
gpr_log(GPR_INFO, " EXECUTING FROM QUEUE: closure=%s error=%s", << " EXECUTING FROM QUEUE: closure=" << closure->DebugString()
closure->DebugString().c_str(), StatusToString(error).c_str()); << " error=" << StatusToString(error);
}
ScheduleClosure(closure, error); ScheduleClosure(closure, error);
break; break;
} }
@ -187,31 +178,26 @@ void CallCombiner::SetNotifyOnCancel(grpc_closure* closure) {
// If error is set, invoke the cancellation closure immediately. // If error is set, invoke the cancellation closure immediately.
// Otherwise, store the new closure. // Otherwise, store the new closure.
if (!original_error.ok()) { if (!original_error.ok()) {
if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { GRPC_TRACE_LOG(call_combiner, INFO)
gpr_log(GPR_INFO, << "call_combiner=" << this
"call_combiner=%p: scheduling notify_on_cancel callback=%p " << ": scheduling notify_on_cancel callback=" << closure
"for pre-existing cancellation", << " for pre-existing cancellation";
this, closure);
}
ExecCtx::Run(DEBUG_LOCATION, closure, original_error); ExecCtx::Run(DEBUG_LOCATION, closure, original_error);
break; break;
} else { } else {
if (gpr_atm_full_cas(&cancel_state_, original_state, if (gpr_atm_full_cas(&cancel_state_, original_state,
reinterpret_cast<gpr_atm>(closure))) { reinterpret_cast<gpr_atm>(closure))) {
if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { GRPC_TRACE_LOG(call_combiner, INFO)
gpr_log(GPR_INFO, "call_combiner=%p: setting notify_on_cancel=%p", << "call_combiner=" << this
this, closure); << ": setting notify_on_cancel=" << closure;
}
// If we replaced an earlier closure, invoke the original // If we replaced an earlier closure, invoke the original
// closure with absl::OkStatus(). This allows callers to clean // closure with absl::OkStatus(). This allows callers to clean
// up any resources they may be holding for the callback. // up any resources they may be holding for the callback.
if (original_state != 0) { if (original_state != 0) {
closure = reinterpret_cast<grpc_closure*>(original_state); closure = reinterpret_cast<grpc_closure*>(original_state);
if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { GRPC_TRACE_LOG(call_combiner, INFO)
gpr_log(GPR_INFO, << "call_combiner=" << this
"call_combiner=%p: scheduling old cancel callback=%p", this, << ": scheduling old cancel callback=" << closure;
closure);
}
ExecCtx::Run(DEBUG_LOCATION, closure, absl::OkStatus()); ExecCtx::Run(DEBUG_LOCATION, closure, absl::OkStatus());
} }
break; break;
@ -235,11 +221,9 @@ void CallCombiner::Cancel(grpc_error_handle error) {
if (original_state != 0) { if (original_state != 0) {
grpc_closure* notify_on_cancel = grpc_closure* notify_on_cancel =
reinterpret_cast<grpc_closure*>(original_state); reinterpret_cast<grpc_closure*>(original_state);
if (GRPC_TRACE_FLAG_ENABLED(call_combiner)) { GRPC_TRACE_LOG(call_combiner, INFO)
gpr_log(GPR_INFO, << "call_combiner=" << this
"call_combiner=%p: scheduling notify_on_cancel callback=%p", << ": scheduling notify_on_cancel callback=" << notify_on_cancel;
this, notify_on_cancel);
}
ExecCtx::Run(DEBUG_LOCATION, notify_on_cancel, error); ExecCtx::Run(DEBUG_LOCATION, notify_on_cancel, error);
} }
break; break;

@ -23,9 +23,9 @@
#include <string.h> #include <string.h>
#include "absl/log/check.h" #include "absl/log/check.h"
#include "absl/log/log.h"
#include <grpc/support/alloc.h> #include <grpc/support/alloc.h>
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include "src/core/lib/experiments/experiments.h" #include "src/core/lib/experiments/experiments.h"
@ -34,13 +34,6 @@
#include "src/core/lib/iomgr/executor.h" #include "src/core/lib/iomgr/executor.h"
#include "src/core/lib/iomgr/iomgr_internal.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_UNORPHANED 1
#define STATE_ELEM_COUNT_LOW_BIT 2 #define STATE_ELEM_COUNT_LOW_BIT 2
@ -58,20 +51,20 @@ grpc_core::Combiner* grpc_combiner_create(
gpr_ref_init(&lock->refs, 1); gpr_ref_init(&lock->refs, 1);
gpr_atm_no_barrier_store(&lock->state, STATE_UNORPHANED); gpr_atm_no_barrier_store(&lock->state, STATE_UNORPHANED);
grpc_closure_list_init(&lock->final_list); 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; return lock;
} }
static void really_destroy(grpc_core::Combiner* 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); CHECK_EQ(gpr_atm_no_barrier_load(&lock->state), 0);
delete lock; delete lock;
} }
static void start_destroy(grpc_core::Combiner* lock) { static void start_destroy(grpc_core::Combiner* lock) {
gpr_atm old_state = gpr_atm_full_fetch_add(&lock->state, -STATE_UNORPHANED); gpr_atm old_state = gpr_atm_full_fetch_add(&lock->state, -STATE_UNORPHANED);
GRPC_COMBINER_TRACE(gpr_log( GRPC_TRACE_LOG(combiner, INFO)
GPR_INFO, "C:%p really_destroy old_state=%" PRIdPTR, lock, old_state)); << "C:" << lock << " really_destroy old_state=" << old_state;
if (old_state == 1) { if (old_state == 1) {
really_destroy(lock); really_destroy(lock);
} }
@ -80,10 +73,11 @@ static void start_destroy(grpc_core::Combiner* lock) {
#ifndef NDEBUG #ifndef NDEBUG
#define GRPC_COMBINER_DEBUG_SPAM(op, delta) \ #define GRPC_COMBINER_DEBUG_SPAM(op, delta) \
if (GRPC_TRACE_FLAG_ENABLED(combiner)) { \ if (GRPC_TRACE_FLAG_ENABLED(combiner)) { \
gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG, \ VLOG(2).AtLocation(file, line) \
"C:%p %s %" PRIdPTR " --> %" PRIdPTR " %s", lock, (op), \ << "C:" << lock << " " << (op) << " " \
gpr_atm_no_barrier_load(&lock->refs.count), \ << gpr_atm_no_barrier_load(&lock->refs.count) << " --> " \
gpr_atm_no_barrier_load(&lock->refs.count) + (delta), reason); \ << gpr_atm_no_barrier_load(&lock->refs.count) + (delta) << " " \
<< reason; \
} }
#else #else
#define GRPC_COMBINER_DEBUG_SPAM(op, delta) #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, static void combiner_exec(grpc_core::Combiner* lock, grpc_closure* cl,
grpc_error_handle error) { grpc_error_handle error) {
gpr_atm last = gpr_atm_full_fetch_add(&lock->state, STATE_ELEM_COUNT_LOW_BIT); gpr_atm last = gpr_atm_full_fetch_add(&lock->state, STATE_ELEM_COUNT_LOW_BIT);
GRPC_COMBINER_TRACE(gpr_log(GPR_INFO, GRPC_TRACE_LOG(combiner, INFO)
"C:%p grpc_combiner_execute c=%p last=%" PRIdPTR, << "C:" << lock << " grpc_combiner_execute c=" << cl << " last=" << last;
lock, cl, last));
if (last == 1) { if (last == 1) {
gpr_atm_no_barrier_store( gpr_atm_no_barrier_store(
&lock->initiating_exec_ctx_or_null, &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 // Make the combiner look uncontended by storing a non-null value here, so
// that we don't immediately offload again. // that we don't immediately offload again.
gpr_atm_no_barrier_store(&lock->initiating_exec_ctx_or_null, 1); 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] { lock->event_engine->Run([lock] {
grpc_core::ApplicationCallbackExecCtx callback_exec_ctx; grpc_core::ApplicationCallbackExecCtx callback_exec_ctx;
grpc_core::ExecCtx exec_ctx(0); grpc_core::ExecCtx exec_ctx(0);
@ -188,14 +181,11 @@ bool grpc_combiner_continue_exec_ctx() {
bool contended = bool contended =
gpr_atm_no_barrier_load(&lock->initiating_exec_ctx_or_null) == 0; gpr_atm_no_barrier_load(&lock->initiating_exec_ctx_or_null) == 0;
GRPC_COMBINER_TRACE(gpr_log(GPR_INFO, GRPC_TRACE_LOG(combiner, INFO)
"C:%p grpc_combiner_continue_exec_ctx " << "C:" << lock << " grpc_combiner_continue_exec_ctx "
"contended=%d " << "contended=" << contended << " exec_ctx_ready_to_finish="
"exec_ctx_ready_to_finish=%d " << grpc_core::ExecCtx::Get()->IsReadyToFinish()
"time_to_execute_final_list=%d", << " time_to_execute_final_list=" << lock->time_to_execute_final_list;
lock, contended,
grpc_core::ExecCtx::Get()->IsReadyToFinish(),
lock->time_to_execute_final_list));
// offload only if both (1) the combiner is contended and has more than one // 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 // closure to execute, and (2) the current execution context needs to finish
@ -212,8 +202,9 @@ bool grpc_combiner_continue_exec_ctx() {
// priority // priority
(gpr_atm_acq_load(&lock->state) >> 1) > 1) { (gpr_atm_acq_load(&lock->state) >> 1) > 1) {
grpc_core::MultiProducerSingleConsumerQueue::Node* n = lock->queue.Pop(); grpc_core::MultiProducerSingleConsumerQueue::Node* n = lock->queue.Pop();
GRPC_COMBINER_TRACE( GRPC_TRACE_LOG(combiner, INFO)
gpr_log(GPR_INFO, "C:%p maybe_finish_one n=%p", lock, n)); << "C:" << lock << " maybe_finish_one n=" << n;
if (n == nullptr) { if (n == nullptr) {
// queue is in an inconsistent state: use this as a cue that we should // 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) // 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); grpc_closure_list_init(&lock->final_list);
int loops = 0; int loops = 0;
while (c != nullptr) { while (c != nullptr) {
GRPC_COMBINER_TRACE( GRPC_TRACE_LOG(combiner, INFO)
gpr_log(GPR_INFO, "C:%p execute_final[%d] c=%p", lock, loops, c)); << "C:" << lock << " execute_final[" << loops << "] c=" << c;
grpc_closure* next = c->next_data.next; grpc_closure* next = c->next_data.next;
#ifndef NDEBUG #ifndef NDEBUG
c->scheduled = false; c->scheduled = false;
@ -252,8 +243,8 @@ bool grpc_combiner_continue_exec_ctx() {
lock->time_to_execute_final_list = false; lock->time_to_execute_final_list = false;
gpr_atm old_state = gpr_atm old_state =
gpr_atm_full_fetch_add(&lock->state, -STATE_ELEM_COUNT_LOW_BIT); gpr_atm_full_fetch_add(&lock->state, -STATE_ELEM_COUNT_LOW_BIT);
GRPC_COMBINER_TRACE( GRPC_TRACE_LOG(combiner, INFO)
gpr_log(GPR_INFO, "C:%p finish old_state=%" PRIdPTR, lock, old_state)); << "C:" << lock << " finish old_state=" << old_state;
// Define a macro to ease readability of the following switch statement. // Define a macro to ease readability of the following switch statement.
#define OLD_STATE_WAS(orphaned, elem_count) \ #define OLD_STATE_WAS(orphaned, elem_count) \
(((orphaned) ? 0 : STATE_UNORPHANED) | \ (((orphaned) ? 0 : STATE_UNORPHANED) | \
@ -294,9 +285,9 @@ static void combiner_finally_exec(grpc_core::Combiner* lock,
grpc_closure* closure, grpc_closure* closure,
grpc_error_handle error) { grpc_error_handle error) {
CHECK_NE(lock, nullptr); CHECK_NE(lock, nullptr);
GRPC_COMBINER_TRACE(gpr_log( GRPC_TRACE_LOG(combiner, INFO)
GPR_INFO, "C:%p grpc_combiner_execute_finally c=%p; ac=%p", lock, closure, << "C:" << lock << " grpc_combiner_execute_finally c=" << closure
grpc_core::ExecCtx::Get()->combiner_data()->active_combiner)); << "; ac=" << grpc_core::ExecCtx::Get()->combiner_data()->active_combiner;
if (grpc_core::ExecCtx::Get()->combiner_data()->active_combiner != lock) { if (grpc_core::ExecCtx::Get()->combiner_data()->active_combiner != lock) {
// Using error_data.scratch to store the combiner so that it can be accessed // Using error_data.scratch to store the combiner so that it can be accessed
// in enqueue_finally. // in enqueue_finally.

@ -25,6 +25,7 @@
#import <CoreFoundation/CoreFoundation.h> #import <CoreFoundation/CoreFoundation.h>
#include "absl/log/check.h" #include "absl/log/check.h"
#include "absl/log/log.h"
#include <grpc/slice_buffer.h> #include <grpc/slice_buffer.h>
#include <grpc/support/alloc.h> #include <grpc/support/alloc.h>
@ -75,9 +76,8 @@ static void CFStreamUnref(CFStreamEndpoint* ep, const char* reason,
const char* file, int line) { const char* file, int line) {
if (GRPC_TRACE_FLAG_ENABLED(tcp)) { if (GRPC_TRACE_FLAG_ENABLED(tcp)) {
gpr_atm val = gpr_atm_no_barrier_load(&ep->refcount.count); gpr_atm val = gpr_atm_no_barrier_load(&ep->refcount.count);
gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG, VLOG(2) << "CFStream endpoint unref " << ep << " : " << reason << " " << val
"CFStream endpoint unref %p : %s %" PRIdPTR " -> %" PRIdPTR, ep, << " -> " << val - 1;
reason, val, val - 1);
} }
if (gpr_unref(&ep->refcount)) { if (gpr_unref(&ep->refcount)) {
CFStreamFree(ep); CFStreamFree(ep);
@ -87,9 +87,8 @@ static void CFStreamRef(CFStreamEndpoint* ep, const char* reason,
const char* file, int line) { const char* file, int line) {
if (GRPC_TRACE_FLAG_ENABLED(tcp)) { if (GRPC_TRACE_FLAG_ENABLED(tcp)) {
gpr_atm val = gpr_atm_no_barrier_load(&ep->refcount.count); gpr_atm val = gpr_atm_no_barrier_load(&ep->refcount.count);
gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG, VLOG(2) << "CFStream endpoint ref " << ep << " : " << reason << " " << val
"CFStream endpoint ref %p : %s %" PRIdPTR " -> %" PRIdPTR, ep, << " -> " << val + 1;
reason, val, val + 1);
} }
gpr_ref(&ep->refcount); 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) { static void CallReadCb(CFStreamEndpoint* ep, grpc_error_handle error) {
if (GRPC_TRACE_FLAG_ENABLED(tcp) && ABSL_VLOG_IS_ON(2)) { 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, VLOG(2) << "CFStream endpoint:" << ep << " call_read_cb " << ep->read_cb
ep->read_cb, ep->read_cb->cb, ep->read_cb->cb_arg); << " " << ep->read_cb->cb << ":" << ep->read_cb->cb_arg;
size_t i; size_t i;
gpr_log(GPR_DEBUG, "read: error=%s", VLOG(2) << "read: error=" << grpc_core::StatusToString(error);
grpc_core::StatusToString(error).c_str());
for (i = 0; i < ep->read_slices->count; i++) { for (i = 0; i < ep->read_slices->count; i++) {
char* dump = grpc_dump_slice(ep->read_slices->slices[i], char* dump = grpc_dump_slice(ep->read_slices->slices[i],
GPR_DUMP_HEX | GPR_DUMP_ASCII); GPR_DUMP_HEX | GPR_DUMP_ASCII);
gpr_log(GPR_DEBUG, "READ %p (peer=%s): %s", ep, ep->peer_string.c_str(), VLOG(2) << "READ " << ep << " (peer=" << ep->peer_string << "): " << dump;
dump);
gpr_free(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) { static void CallWriteCb(CFStreamEndpoint* ep, grpc_error_handle error) {
if (GRPC_TRACE_FLAG_ENABLED(tcp)) { if (GRPC_TRACE_FLAG_ENABLED(tcp)) {
gpr_log(GPR_DEBUG, "CFStream endpoint:%p call_write_cb %p %p:%p", ep, VLOG(2) << "CFStream endpoint:" << ep << " call_write_cb " << ep->write_cb
ep->write_cb, ep->write_cb->cb, ep->write_cb->cb_arg); << " " << ep->write_cb->cb << ":" << ep->write_cb->cb_arg;
gpr_log(GPR_DEBUG, "write: error=%s", VLOG(2) << "write: error=" << grpc_core::StatusToString(error);
grpc_core::StatusToString(error).c_str());
} }
grpc_closure* cb = ep->write_cb; grpc_closure* cb = ep->write_cb;
ep->write_cb = nullptr; 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)) { if (GRPC_TRACE_FLAG_ENABLED(tcp) && ABSL_VLOG_IS_ON(2)) {
grpc_slice trace_slice = grpc_slice_sub(slice, 0, write_size); grpc_slice trace_slice = grpc_slice_sub(slice, 0, write_size);
char* dump = grpc_dump_slice(trace_slice, GPR_DUMP_HEX | GPR_DUMP_ASCII); 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(), VLOG(2) << "WRITE " << ep << " (peer=" << ep->peer_string
dump); << "): " << dump;
gpr_free(dump); gpr_free(dump);
grpc_core::CSliceUnref(trace_slice); grpc_core::CSliceUnref(trace_slice);
} }
@ -238,8 +234,8 @@ static void CFStreamRead(grpc_endpoint* ep, grpc_slice_buffer* slices,
int /*min_progress_size*/) { int /*min_progress_size*/) {
CFStreamEndpoint* ep_impl = reinterpret_cast<CFStreamEndpoint*>(ep); CFStreamEndpoint* ep_impl = reinterpret_cast<CFStreamEndpoint*>(ep);
if (GRPC_TRACE_FLAG_ENABLED(tcp)) { if (GRPC_TRACE_FLAG_ENABLED(tcp)) {
gpr_log(GPR_DEBUG, "CFStream endpoint:%p read (%p, %p) length:%zu", ep_impl, VLOG(2) << "CFStream endpoint:" << ep_impl << " read (" << slices << ", "
slices, cb, slices->length); << cb << ") length:" << slices->length;
} }
CHECK_EQ(ep_impl->read_cb, nullptr); CHECK_EQ(ep_impl->read_cb, nullptr);
ep_impl->read_cb = cb; ep_impl->read_cb = cb;
@ -256,8 +252,8 @@ static void CFStreamWrite(grpc_endpoint* ep, grpc_slice_buffer* slices,
int /*max_frame_size*/) { int /*max_frame_size*/) {
CFStreamEndpoint* ep_impl = reinterpret_cast<CFStreamEndpoint*>(ep); CFStreamEndpoint* ep_impl = reinterpret_cast<CFStreamEndpoint*>(ep);
if (GRPC_TRACE_FLAG_ENABLED(tcp)) { if (GRPC_TRACE_FLAG_ENABLED(tcp)) {
gpr_log(GPR_DEBUG, "CFStream endpoint:%p write (%p, %p) length:%zu", VLOG(2) << "CFStream endpoint:" << ep_impl << " write (" << slices << ", "
ep_impl, slices, cb, slices->length); << cb << ") length:" << slices->length;
} }
CHECK_EQ(ep_impl->write_cb, nullptr); CHECK_EQ(ep_impl->write_cb, nullptr);
ep_impl->write_cb = cb; ep_impl->write_cb = cb;
@ -313,9 +309,9 @@ grpc_endpoint* grpc_cfstream_endpoint_create(CFReadStreamRef read_stream,
CFStreamHandle* stream_sync) { CFStreamHandle* stream_sync) {
CFStreamEndpoint* ep_impl = new CFStreamEndpoint; CFStreamEndpoint* ep_impl = new CFStreamEndpoint;
if (GRPC_TRACE_FLAG_ENABLED(tcp)) { if (GRPC_TRACE_FLAG_ENABLED(tcp)) {
gpr_log(GPR_DEBUG, VLOG(2) << "CFStream endpoint:" << ep_impl
"CFStream endpoint:%p create readStream:%p writeStream: %p", << " create readStream:" << read_stream
ep_impl, read_stream, write_stream); << " writeStream: " << write_stream;
} }
ep_impl->base.vtable = &vtable; ep_impl->base.vtable = &vtable;
gpr_ref_init(&ep_impl->refcount, 1); gpr_ref_init(&ep_impl->refcount, 1);

@ -16,9 +16,6 @@
// //
// //
#include "absl/log/check.h"
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include "src/core/lib/gprpp/crash.h" #include "src/core/lib/gprpp/crash.h"
@ -41,6 +38,7 @@
#include <string> #include <string>
#include <vector> #include <vector>
#include "absl/log/check.h"
#include "absl/log/log.h" #include "absl/log/log.h"
#include "absl/strings/str_cat.h" #include "absl/strings/str_cat.h"
#include "absl/strings/str_format.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); fork_fd_list_add_grpc_fd(new_fd);
#ifndef NDEBUG #ifndef NDEBUG
if (GRPC_TRACE_FLAG_ENABLED(fd_refcount)) { 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 #endif
@ -377,8 +375,7 @@ static grpc_fd* fd_create(int fd, const char* name, bool track_err) {
ev.data.ptr = reinterpret_cast<void*>(reinterpret_cast<intptr_t>(new_fd) | ev.data.ptr = reinterpret_cast<void*>(reinterpret_cast<intptr_t>(new_fd) |
(track_err ? 1 : 0)); (track_err ? 1 : 0));
if (epoll_ctl(g_epoll_set.epfd, EPOLL_CTL_ADD, fd, &ev) != 0) { if (epoll_ctl(g_epoll_set.epfd, EPOLL_CTL_ADD, fd, &ev) != 0) {
gpr_log(GPR_ERROR, "epoll_ctl failed: %s", LOG(ERROR) << "epoll_ctl failed: " << grpc_core::StrError(errno);
grpc_core::StrError(errno).c_str());
} }
return new_fd; return new_fd;
@ -401,8 +398,7 @@ static void fd_shutdown_internal(grpc_fd* fd, grpc_error_handle why,
epoll_event phony_event; epoll_event phony_event;
if (epoll_ctl(g_epoll_set.epfd, EPOLL_CTL_DEL, fd->fd, &phony_event) != if (epoll_ctl(g_epoll_set.epfd, EPOLL_CTL_DEL, fd->fd, &phony_event) !=
0) { 0) {
gpr_log(GPR_ERROR, "epoll_ctl failed: %s", LOG(ERROR) << "epoll_ctl failed: " << grpc_core::StrError(errno);
grpc_core::StrError(errno).c_str());
} }
} }
fd->write_closure->SetShutdown(why); 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 (r < 0) return GRPC_OS_ERROR(errno, "epoll_wait");
if (GRPC_TRACE_FLAG_ENABLED(polling)) { 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); 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++; pollset->begin_refs++;
if (GRPC_TRACE_FLAG_ENABLED(polling)) { 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) { 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(&neighborhood->mu);
gpr_mu_lock(&pollset->mu); gpr_mu_lock(&pollset->mu);
if (GRPC_TRACE_FLAG_ENABLED(polling)) { if (GRPC_TRACE_FLAG_ENABLED(polling)) {
gpr_log(GPR_INFO, "PS:%p BEGIN_REORG:%p kick_state=%s is_reassigning=%d", LOG(INFO) << "PS:" << pollset << " BEGIN_REORG:" << worker
pollset, worker, kick_state_string(worker->state), << " kick_state=" << kick_state_string(worker->state)
is_reassigning); << " is_reassigning=" << is_reassigning;
} }
if (pollset->seen_inactive) { if (pollset->seen_inactive) {
if (neighborhood != pollset->neighborhood) { if (neighborhood != pollset->neighborhood) {
@ -823,9 +819,9 @@ static bool begin_worker(grpc_pollset* pollset, grpc_pollset_worker* worker,
gpr_cv_init(&worker->cv); gpr_cv_init(&worker->cv);
while (worker->state == UNKICKED && !pollset->shutting_down) { while (worker->state == UNKICKED && !pollset->shutting_down) {
if (GRPC_TRACE_FLAG_ENABLED(polling)) { if (GRPC_TRACE_FLAG_ENABLED(polling)) {
gpr_log(GPR_INFO, "PS:%p BEGIN_WAIT:%p kick_state=%s shutdown=%d", LOG(INFO) << "PS:" << pollset << " BEGIN_WAIT:" << worker
pollset, worker, kick_state_string(worker->state), << " kick_state=" << kick_state_string(worker->state)
pollset->shutting_down); << " shutdown=" << pollset->shutting_down;
} }
if (gpr_cv_wait(&worker->cv, &pollset->mu, 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)) { if (GRPC_TRACE_FLAG_ENABLED(polling)) {
gpr_log(GPR_INFO, LOG(INFO) << "PS:" << pollset << " BEGIN_DONE:" << worker
"PS:%p BEGIN_DONE:%p kick_state=%s shutdown=%d " << " kick_state=" << kick_state_string(worker->state)
"kicked_without_poller: %d", << " shutdown=" << pollset->shutting_down
pollset, worker, kick_state_string(worker->state), << " kicked_without_poller: " << pollset->kicked_without_poller;
pollset->shutting_down, pollset->kicked_without_poller);
} }
// We release pollset lock in this function at a couple of places: // 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, &g_active_poller, 0,
reinterpret_cast<gpr_atm>(inspect_worker))) { reinterpret_cast<gpr_atm>(inspect_worker))) {
if (GRPC_TRACE_FLAG_ENABLED(polling)) { if (GRPC_TRACE_FLAG_ENABLED(polling)) {
gpr_log(GPR_INFO, " .. choose next poller to be %p", LOG(INFO) << " .. choose next poller to be " << inspect_worker;
inspect_worker);
} }
SET_KICK_STATE(inspect_worker, DESIGNATED_POLLER); SET_KICK_STATE(inspect_worker, DESIGNATED_POLLER);
if (inspect_worker->initialized_cv) { if (inspect_worker->initialized_cv) {
@ -910,7 +904,7 @@ static bool check_neighborhood_for_available_poller(
} }
if (!found_worker) { if (!found_worker) {
if (GRPC_TRACE_FLAG_ENABLED(polling)) { 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; inspect->seen_inactive = true;
if (inspect == neighborhood->active_root) { 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, static void end_worker(grpc_pollset* pollset, grpc_pollset_worker* worker,
grpc_pollset_worker** worker_hdl) { grpc_pollset_worker** worker_hdl) {
if (GRPC_TRACE_FLAG_ENABLED(polling)) { 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; if (worker_hdl != nullptr) *worker_hdl = nullptr;
// Make sure we appear kicked // Make sure we appear kicked
@ -940,7 +934,7 @@ static void end_worker(grpc_pollset* pollset, grpc_pollset_worker* worker,
reinterpret_cast<gpr_atm>(worker)) { reinterpret_cast<gpr_atm>(worker)) {
if (worker->next != worker && worker->next->state == UNKICKED) { if (worker->next != worker && worker->next->state == UNKICKED) {
if (GRPC_TRACE_FLAG_ENABLED(polling)) { 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); CHECK(worker->next->initialized_cv);
gpr_atm_no_barrier_store(&g_active_poller, (gpr_atm)worker->next); 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", log.push_back(absl::StrFormat(" worker_kick_state=%s",
kick_state_string(specific_worker->state))); 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) { 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; grpc_pollset_worker* next_worker = root_worker->next;
if (root_worker->state == KICKED) { if (root_worker->state == KICKED) {
if (GRPC_TRACE_FLAG_ENABLED(polling)) { 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); SET_KICK_STATE(root_worker, KICKED);
goto done; goto done;
} else if (next_worker->state == KICKED) { } else if (next_worker->state == KICKED) {
if (GRPC_TRACE_FLAG_ENABLED(polling)) { 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); SET_KICK_STATE(next_worker, KICKED);
goto done; goto done;
@ -1105,14 +1099,14 @@ static grpc_error_handle pollset_kick(grpc_pollset* pollset,
reinterpret_cast<grpc_pollset_worker*>( reinterpret_cast<grpc_pollset_worker*>(
gpr_atm_no_barrier_load(&g_active_poller))) { gpr_atm_no_barrier_load(&g_active_poller))) {
if (GRPC_TRACE_FLAG_ENABLED(polling)) { 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); SET_KICK_STATE(root_worker, KICKED);
ret_err = grpc_wakeup_fd_wakeup(&global_wakeup_fd); ret_err = grpc_wakeup_fd_wakeup(&global_wakeup_fd);
goto done; goto done;
} else if (next_worker->state == UNKICKED) { } else if (next_worker->state == UNKICKED) {
if (GRPC_TRACE_FLAG_ENABLED(polling)) { if (GRPC_TRACE_FLAG_ENABLED(polling)) {
gpr_log(GPR_INFO, " .. kicked %p", next_worker); LOG(INFO) << " .. kicked " << next_worker;
} }
CHECK(next_worker->initialized_cv); CHECK(next_worker->initialized_cv);
SET_KICK_STATE(next_worker, KICKED); 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) { } else if (next_worker->state == DESIGNATED_POLLER) {
if (root_worker->state != DESIGNATED_POLLER) { if (root_worker->state != DESIGNATED_POLLER) {
if (GRPC_TRACE_FLAG_ENABLED(polling)) { if (GRPC_TRACE_FLAG_ENABLED(polling)) {
gpr_log( LOG(INFO) << " .. kicked root non-poller " << root_worker
GPR_INFO, << " (initialized_cv=" << root_worker->initialized_cv
" .. kicked root non-poller %p (initialized_cv=%d) (poller=%p)", << ") (poller=" << next_worker << ")";
root_worker, root_worker->initialized_cv, next_worker);
} }
SET_KICK_STATE(root_worker, KICKED); SET_KICK_STATE(root_worker, KICKED);
if (root_worker->initialized_cv) { if (root_worker->initialized_cv) {
@ -1133,8 +1126,8 @@ static grpc_error_handle pollset_kick(grpc_pollset* pollset,
goto done; goto done;
} else { } else {
if (GRPC_TRACE_FLAG_ENABLED(polling)) { if (GRPC_TRACE_FLAG_ENABLED(polling)) {
gpr_log(GPR_INFO, " .. non-root poller %p (root=%p)", next_worker, LOG(INFO) << " .. non-root poller " << next_worker
root_worker); << " (root=" << root_worker << ")";
} }
SET_KICK_STATE(next_worker, KICKED); SET_KICK_STATE(next_worker, KICKED);
ret_err = grpc_wakeup_fd_wakeup(&global_wakeup_fd); ret_err = grpc_wakeup_fd_wakeup(&global_wakeup_fd);
@ -1162,7 +1155,7 @@ static grpc_error_handle pollset_kick(grpc_pollset* pollset,
goto done; goto done;
} else if (g_current_thread_worker == specific_worker) { } else if (g_current_thread_worker == specific_worker) {
if (GRPC_TRACE_FLAG_ENABLED(polling)) { 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); SET_KICK_STATE(specific_worker, KICKED);
goto done; goto done;

@ -21,12 +21,12 @@
#include <string> #include <string>
#include "absl/log/check.h" #include "absl/log/check.h"
#include "absl/log/log.h"
#include "absl/strings/str_cat.h" #include "absl/strings/str_cat.h"
#include "absl/strings/str_format.h" #include "absl/strings/str_format.h"
#include <grpc/support/alloc.h> #include <grpc/support/alloc.h>
#include <grpc/support/cpu.h> #include <grpc/support/cpu.h>
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include <grpc/support/sync.h> #include <grpc/support/sync.h>
@ -335,10 +335,10 @@ static void timer_init(grpc_timer* timer, grpc_core::Timestamp deadline,
#endif #endif
if (GRPC_TRACE_FLAG_ENABLED(timer)) { if (GRPC_TRACE_FLAG_ENABLED(timer)) {
gpr_log(GPR_DEBUG, "TIMER %p: SET %" PRId64 " now %" PRId64 " call %p[%p]", VLOG(2) << "TIMER " << timer << ": SET "
timer, deadline.milliseconds_after_process_epoch(), << deadline.milliseconds_after_process_epoch() << " now "
grpc_core::Timestamp::Now().milliseconds_after_process_epoch(), << grpc_core::Timestamp::Now().milliseconds_after_process_epoch()
closure, closure->cb); << " call " << closure << "[" << closure->cb << "]";
} }
if (!g_shared_mutables.initialized) { 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); list_join(&shard->list, timer);
} }
if (GRPC_TRACE_FLAG_ENABLED(timer)) { if (GRPC_TRACE_FLAG_ENABLED(timer)) {
gpr_log(GPR_DEBUG, VLOG(2) << " .. add to shard " << (shard - g_shards)
" .. add to shard %d with queue_deadline_cap=%" PRId64 << " with queue_deadline_cap="
" => is_first_timer=%s", << shard->queue_deadline_cap.milliseconds_after_process_epoch()
static_cast<int>(shard - g_shards), << " => is_first_timer=" << (is_first_timer ? "true" : "false");
shard->queue_deadline_cap.milliseconds_after_process_epoch(),
is_first_timer ? "true" : "false");
} }
gpr_mu_unlock(&shard->mu); gpr_mu_unlock(&shard->mu);
@ -394,8 +392,8 @@ static void timer_init(grpc_timer* timer, grpc_core::Timestamp deadline,
if (is_first_timer) { if (is_first_timer) {
gpr_mu_lock(&g_shared_mutables.mu); gpr_mu_lock(&g_shared_mutables.mu);
if (GRPC_TRACE_FLAG_ENABLED(timer)) { if (GRPC_TRACE_FLAG_ENABLED(timer)) {
gpr_log(GPR_DEBUG, " .. old shard min_deadline=%" PRId64, VLOG(2) << " .. old shard min_deadline="
shard->min_deadline.milliseconds_after_process_epoch()); << shard->min_deadline.milliseconds_after_process_epoch();
} }
if (deadline < shard->min_deadline) { if (deadline < shard->min_deadline) {
grpc_core::Timestamp old_min_deadline = g_shard_queue[0]->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)]; timer_shard* shard = &g_shards[grpc_core::HashPointer(timer, g_num_shards)];
gpr_mu_lock(&shard->mu); gpr_mu_lock(&shard->mu);
if (GRPC_TRACE_FLAG_ENABLED(timer)) { if (GRPC_TRACE_FLAG_ENABLED(timer)) {
gpr_log(GPR_DEBUG, "TIMER %p: CANCEL pending=%s", timer, VLOG(2) << "TIMER " << timer
timer->pending ? "true" : "false"); << ": CANCEL pending=" << (timer->pending ? "true" : "false");
} }
if (timer->pending) { if (timer->pending) {
@ -477,9 +475,9 @@ static bool refill_heap(timer_shard* shard, grpc_core::Timestamp now) {
grpc_core::Duration::FromSecondsAsDouble(deadline_delta); grpc_core::Duration::FromSecondsAsDouble(deadline_delta);
if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { if (GRPC_TRACE_FLAG_ENABLED(timer_check)) {
gpr_log(GPR_DEBUG, " .. shard[%d]->queue_deadline_cap --> %" PRId64, VLOG(2) << " .. shard[" << (shard - g_shards)
static_cast<int>(shard - g_shards), << "]->queue_deadline_cap --> "
shard->queue_deadline_cap.milliseconds_after_process_epoch()); << shard->queue_deadline_cap.milliseconds_after_process_epoch();
} }
for (timer = shard->list.next; timer != &shard->list; timer = next) { for (timer = shard->list.next; timer != &shard->list; timer = next) {
next = 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 (timer_deadline < shard->queue_deadline_cap) {
if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { if (GRPC_TRACE_FLAG_ENABLED(timer_check)) {
gpr_log(GPR_DEBUG, " .. add timer with deadline %" PRId64 " to heap", VLOG(2) << " .. add timer with deadline "
timer_deadline.milliseconds_after_process_epoch()); << timer_deadline.milliseconds_after_process_epoch()
<< " to heap";
} }
list_remove(timer); list_remove(timer);
grpc_timer_heap_add(&shard->heap, 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; grpc_timer* timer;
for (;;) { for (;;) {
if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { if (GRPC_TRACE_FLAG_ENABLED(timer_check)) {
gpr_log(GPR_DEBUG, " .. shard[%d]: heap_empty=%s", VLOG(2) << " .. shard[" << (shard - g_shards) << "]: heap_empty="
static_cast<int>(shard - g_shards), << (grpc_timer_heap_is_empty(&shard->heap) ? "true" : "false");
grpc_timer_heap_is_empty(&shard->heap) ? "true" : "false");
} }
if (grpc_timer_heap_is_empty(&shard->heap)) { if (grpc_timer_heap_is_empty(&shard->heap)) {
if (now < shard->queue_deadline_cap) return nullptr; 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( grpc_core::Timestamp::FromMillisecondsAfterProcessEpoch(
timer->deadline); timer->deadline);
if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { if (GRPC_TRACE_FLAG_ENABLED(timer_check)) {
gpr_log(GPR_DEBUG, VLOG(2) << " .. check top timer deadline="
" .. check top timer deadline=%" PRId64 " now=%" PRId64, << timer_deadline.milliseconds_after_process_epoch()
timer_deadline.milliseconds_after_process_epoch(), << " now=" << now.milliseconds_after_process_epoch();
now.milliseconds_after_process_epoch());
} }
if (timer_deadline > now) return nullptr; if (timer_deadline > now) return nullptr;
if (GRPC_TRACE_FLAG_ENABLED(timer)) { if (GRPC_TRACE_FLAG_ENABLED(timer)) {
gpr_log(GPR_DEBUG, "TIMER %p: FIRE %" PRId64 "ms late", timer, VLOG(2) << "TIMER " << timer << ": FIRE "
(now - timer_deadline).millis()); << (now - timer_deadline).millis() << "ms late";
} }
timer->pending = false; timer->pending = false;
grpc_timer_heap_pop(&shard->heap); 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); *new_min_deadline = compute_min_deadline(shard);
gpr_mu_unlock(&shard->mu); gpr_mu_unlock(&shard->mu);
if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { if (GRPC_TRACE_FLAG_ENABLED(timer_check)) {
gpr_log(GPR_DEBUG, " .. shard[%d] popped %" PRIdPTR, VLOG(2) << " .. shard[" << (shard - g_shards) << "] popped " << n;
static_cast<int>(shard - g_shards), n);
} }
return n; return n;
} }
@ -589,10 +585,10 @@ static grpc_timer_check_result run_some_expired_timers(
result = GRPC_TIMERS_CHECKED_AND_EMPTY; result = GRPC_TIMERS_CHECKED_AND_EMPTY;
if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { if (GRPC_TRACE_FLAG_ENABLED(timer_check)) {
gpr_log( VLOG(2)
GPR_DEBUG, " .. shard[%d]->min_deadline = %" PRId64, << " .. shard[" << (g_shard_queue[0] - g_shards)
static_cast<int>(g_shard_queue[0] - g_shards), << "]->min_deadline = "
g_shard_queue[0]->min_deadline.milliseconds_after_process_epoch()); << g_shard_queue[0]->min_deadline.milliseconds_after_process_epoch();
} }
while (g_shard_queue[0]->min_deadline < now || 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)) { if (GRPC_TRACE_FLAG_ENABLED(timer_check)) {
gpr_log( VLOG(2)
GPR_DEBUG, << " .. result --> " << result << ", shard["
" .. result --> %d" << (g_shard_queue[0] - g_shards) << "]->min_deadline "
", shard[%d]->min_deadline %" PRId64 " --> %" PRId64 << g_shard_queue[0]->min_deadline.milliseconds_after_process_epoch()
", now=%" PRId64, << " --> " << new_min_deadline.milliseconds_after_process_epoch()
result, static_cast<int>(g_shard_queue[0] - g_shards), << ", now=" << now.milliseconds_after_process_epoch();
g_shard_queue[0]->min_deadline.milliseconds_after_process_epoch(),
new_min_deadline.milliseconds_after_process_epoch(),
now.milliseconds_after_process_epoch());
} }
// An grpc_timer_init() on the shard could intervene here, adding a new // 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); *next = std::min(*next, min_timer);
} }
if (GRPC_TRACE_FLAG_ENABLED(timer_check)) { if (GRPC_TRACE_FLAG_ENABLED(timer_check)) {
gpr_log(GPR_DEBUG, "TIMER CHECK SKIP: now=%" PRId64 " min_timer=%" PRId64, VLOG(2) << "TIMER CHECK SKIP: now="
now.milliseconds_after_process_epoch(), << now.milliseconds_after_process_epoch()
min_timer.milliseconds_after_process_epoch()); << " min_timer=" << min_timer.milliseconds_after_process_epoch();
} }
return GRPC_TIMERS_CHECKED_AND_EMPTY; 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()); next_str = absl::StrCat(next->milliseconds_after_process_epoch());
} }
#if GPR_ARCH_64 #if GPR_ARCH_64
gpr_log( VLOG(2) << "TIMER CHECK BEGIN: now="
GPR_DEBUG, << now.milliseconds_after_process_epoch() << " next=" << next_str
"TIMER CHECK BEGIN: now=%" PRId64 " next=%s tls_min=%" PRId64 << " tls_min=" << min_timer.milliseconds_after_process_epoch()
" glob_min=%" PRId64, << " glob_min="
now.milliseconds_after_process_epoch(), next_str.c_str(), << grpc_core::Timestamp::FromMillisecondsAfterProcessEpoch(
min_timer.milliseconds_after_process_epoch(), gpr_atm_no_barrier_load(
grpc_core::Timestamp::FromMillisecondsAfterProcessEpoch( (gpr_atm*)(&g_shared_mutables.min_timer)))
gpr_atm_no_barrier_load((gpr_atm*)(&g_shared_mutables.min_timer))) .milliseconds_after_process_epoch();
.milliseconds_after_process_epoch());
#else #else
gpr_log(GPR_DEBUG, VLOG(2) << "TIMER CHECK BEGIN: now="
"TIMER CHECK BEGIN: now=%" PRId64 " next=%s min=%" PRId64, << now.milliseconds_after_process_epoch() << " next=" << next_str
now.milliseconds_after_process_epoch(), next_str.c_str(), << " min=" << min_timer.milliseconds_after_process_epoch();
min_timer.milliseconds_after_process_epoch());
#endif #endif
} }
// actual code // actual code
@ -716,7 +707,7 @@ static grpc_timer_check_result timer_check(grpc_core::Timestamp* next) {
} else { } else {
next_str = absl::StrCat(next->milliseconds_after_process_epoch()); 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; return r;
} }

@ -54,7 +54,6 @@
#include <grpc/status.h> #include <grpc/status.h>
#include <grpc/support/alloc.h> #include <grpc/support/alloc.h>
#include <grpc/support/atm.h> #include <grpc/support/atm.h>
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include <grpc/support/string_util.h> #include <grpc/support/string_util.h>
@ -319,11 +318,9 @@ void Call::HandleCompressionAlgorithmNotAccepted(
grpc_compression_algorithm compression_algorithm) { grpc_compression_algorithm compression_algorithm) {
const char* algo_name = nullptr; const char* algo_name = nullptr;
grpc_compression_algorithm_name(compression_algorithm, &algo_name); grpc_compression_algorithm_name(compression_algorithm, &algo_name);
gpr_log(GPR_ERROR, LOG(ERROR) << "Compression algorithm ('" << algo_name
"Compression algorithm ('%s') not present in the " << "') not present in the accepted encodings ("
"accepted encodings (%s)", << encodings_accepted_by_peer_.ToString() << ")";
algo_name,
std::string(encodings_accepted_by_peer_.ToString()).c_str());
} }
void Call::HandleCompressionAlgorithmDisabled( void Call::HandleCompressionAlgorithmDisabled(
@ -341,8 +338,9 @@ void Call::HandleCompressionAlgorithmDisabled(
void Call::UpdateDeadline(Timestamp deadline) { void Call::UpdateDeadline(Timestamp deadline) {
ReleasableMutexLock lock(&deadline_mu_); ReleasableMutexLock lock(&deadline_mu_);
if (GRPC_TRACE_FLAG_ENABLED(call)) { if (GRPC_TRACE_FLAG_ENABLED(call)) {
gpr_log(GPR_DEBUG, "[call %p] UpdateDeadline from=%s to=%s", this, VLOG(2) << "[call " << this
deadline_.ToString().c_str(), deadline.ToString().c_str()); << "] UpdateDeadline from=" << deadline_.ToString()
<< " to=" << deadline.ToString();
} }
if (deadline >= deadline_) return; if (deadline >= deadline_) return;
if (deadline < Timestamp::Now()) { if (deadline < Timestamp::Now()) {

@ -28,6 +28,7 @@
#include <utility> #include <utility>
#include "absl/log/check.h" #include "absl/log/check.h"
#include "absl/log/log.h"
#include "absl/status/status.h" #include "absl/status/status.h"
#include "absl/strings/str_cat.h" #include "absl/strings/str_cat.h"
#include "absl/strings/str_format.h" #include "absl/strings/str_format.h"
@ -44,7 +45,6 @@
#include <grpc/status.h> #include <grpc/status.h>
#include <grpc/support/alloc.h> #include <grpc/support/alloc.h>
#include <grpc/support/atm.h> #include <grpc/support/atm.h>
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include <grpc/support/string_util.h> #include <grpc/support/string_util.h>
@ -88,11 +88,9 @@ void CToMetadata(grpc_metadata* metadata, size_t count,
if (key == "content-length") continue; if (key == "content-length") continue;
b->Append(key, Slice(CSliceRef(md->value)), b->Append(key, Slice(CSliceRef(md->value)),
[md](absl::string_view error, const Slice& value) { [md](absl::string_view error, const Slice& value) {
gpr_log(GPR_DEBUG, "Append error: %s", VLOG(2) << "Append error: key=" << StringViewFromSlice(md->key)
absl::StrCat("key=", StringViewFromSlice(md->key), << " error=" << error
" error=", error, << " value=" << value.as_string_view();
" value=", value.as_string_view())
.c_str());
}); });
} }
} }

@ -34,7 +34,6 @@
#include "absl/strings/string_view.h" #include "absl/strings/string_view.h"
#include "absl/types/optional.h" #include "absl/types/optional.h"
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include "src/core/lib/debug/trace.h" #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, // 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. // either by supplying a valid configuration or by including an opt-out flag.
if (terminal_filters.empty() && type != GRPC_CLIENT_DYNAMIC) { if (terminal_filters.empty() && type != GRPC_CLIENT_DYNAMIC) {
gpr_log( LOG(ERROR) << "No terminal filters registered for channel stack type "
GPR_ERROR, << grpc_channel_stack_type_string(type)
"No terminal filters registered for channel stack type %s; this is " << "; this is common for unit tests messing with "
"common for unit tests messing with CoreConfiguration, but will result " "CoreConfiguration, but will result in a "
"in a ChannelInit::CreateStack that never completes successfully.", "ChannelInit::CreateStack that never completes successfully.";
grpc_channel_stack_type_string(type));
} }
return StackConfig{std::move(filters), std::move(terminal_filters), return StackConfig{std::move(filters), std::move(terminal_filters),
std::move(post_processor_functions)}; std::move(post_processor_functions)};

@ -36,7 +36,6 @@
#include <grpc/grpc.h> #include <grpc/grpc.h>
#include <grpc/support/alloc.h> #include <grpc/support/alloc.h>
#include <grpc/support/atm.h> #include <grpc/support/atm.h>
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include <grpc/support/sync.h> #include <grpc/support/sync.h>
#include <grpc/support/time.h> #include <grpc/support/time.h>
@ -443,8 +442,8 @@ static const cq_vtable g_cq_vtable[] = {
if (GRPC_TRACE_FLAG_ENABLED(api) && \ if (GRPC_TRACE_FLAG_ENABLED(api) && \
(GRPC_TRACE_FLAG_ENABLED(queue_pluck) || \ (GRPC_TRACE_FLAG_ENABLED(queue_pluck) || \
(event)->type != GRPC_QUEUE_TIMEOUT)) { \ (event)->type != GRPC_QUEUE_TIMEOUT)) { \
gpr_log(GPR_INFO, "RETURN_EVENT[%p]: %s", cq, \ LOG(INFO) << "RETURN_EVENT[" << (cq) \
grpc_event_string(event).c_str()); \ << "]: " << grpc_event_string(event); \
} \ } \
} while (0) } while (0)
@ -703,8 +702,7 @@ static void cq_end_op_for_next(
"done=%p, done_arg=%p, storage=%p)", "done=%p, done_arg=%p, storage=%p)",
6, (cq, tag, errmsg.c_str(), done, done_arg, storage)); 6, (cq, tag, errmsg.c_str(), done, done_arg, storage));
if (GRPC_TRACE_FLAG_ENABLED(op_failure) && !error.ok()) { if (GRPC_TRACE_FLAG_ENABLED(op_failure) && !error.ok()) {
gpr_log(GPR_INFO, "Operation failed: tag=%p, error=%s", tag, LOG(INFO) << "Operation failed: tag=" << tag << ", error=" << errmsg;
errmsg.c_str());
} }
} }
cq_next_data* cqd = static_cast<cq_next_data*> DATA_FROM_CQ(cq); cq_next_data* cqd = static_cast<cq_next_data*> DATA_FROM_CQ(cq);
@ -737,8 +735,8 @@ static void cq_end_op_for_next(
gpr_mu_unlock(cq->mu); gpr_mu_unlock(cq->mu);
if (!kick_error.ok()) { if (!kick_error.ok()) {
gpr_log(GPR_ERROR, "Kick failed: %s", LOG(ERROR) << "Kick failed: "
grpc_core::StatusToString(kick_error).c_str()); << grpc_core::StatusToString(kick_error);
} }
} }
if (cqd->pending_events.fetch_sub(1, std::memory_order_acq_rel) == 1) { 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)", "done=%p, done_arg=%p, storage=%p)",
6, (cq, tag, errmsg.c_str(), done, done_arg, storage)); 6, (cq, tag, errmsg.c_str(), done, done_arg, storage));
if (GRPC_TRACE_FLAG_ENABLED(op_failure) && !error.ok()) { if (GRPC_TRACE_FLAG_ENABLED(op_failure) && !error.ok()) {
gpr_log(GPR_ERROR, "Operation failed: tag=%p, error=%s", tag, LOG(ERROR) << "Operation failed: tag=" << tag << ", error=" << errmsg;
errmsg.c_str());
} }
} }
@ -813,8 +810,7 @@ static void cq_end_op_for_pluck(
cq->poller_vtable->kick(POLLSET_FROM_CQ(cq), pluck_worker); cq->poller_vtable->kick(POLLSET_FROM_CQ(cq), pluck_worker);
gpr_mu_unlock(cq->mu); gpr_mu_unlock(cq->mu);
if (!kick_error.ok()) { if (!kick_error.ok()) {
gpr_log(GPR_ERROR, "Kick failed: %s", LOG(ERROR) << "Kick failed: " << kick_error;
grpc_core::StatusToString(kick_error).c_str());
} }
} }
} }
@ -839,8 +835,7 @@ static void cq_end_op_for_callback(
"done=%p, done_arg=%p, storage=%p)", "done=%p, done_arg=%p, storage=%p)",
6, (cq, tag, errmsg.c_str(), done, done_arg, storage)); 6, (cq, tag, errmsg.c_str(), done, done_arg, storage));
if (GRPC_TRACE_FLAG_ENABLED(op_failure) && !error.ok()) { if (GRPC_TRACE_FLAG_ENABLED(op_failure) && !error.ok()) {
gpr_log(GPR_ERROR, "Operation failed: tag=%p, error=%s", tag, LOG(ERROR) << "Operation failed: tag=" << tag << ", error=" << errmsg;
errmsg.c_str());
} }
} }
@ -1039,8 +1034,8 @@ static grpc_event cq_next(grpc_completion_queue* cq, gpr_timespec deadline,
gpr_mu_unlock(cq->mu); gpr_mu_unlock(cq->mu);
if (!err.ok()) { if (!err.ok()) {
gpr_log(GPR_ERROR, "Completion queue next failed: %s", LOG(ERROR) << "Completion queue next failed: "
grpc_core::StatusToString(err).c_str()); << grpc_core::StatusToString(err);
if (err == absl::CancelledError()) { if (err == absl::CancelledError()) {
ret.type = GRPC_QUEUE_SHUTDOWN; ret.type = GRPC_QUEUE_SHUTDOWN;
} else { } else {
@ -1253,10 +1248,9 @@ static grpc_event cq_pluck(grpc_completion_queue* cq, void* tag,
break; break;
} }
if (!add_plucker(cq, tag, &worker)) { if (!add_plucker(cq, tag, &worker)) {
gpr_log(GPR_DEBUG, VLOG(2) << "Too many outstanding grpc_completion_queue_pluck calls: "
"Too many outstanding grpc_completion_queue_pluck calls: maximum " "maximum is "
"is %d", << GRPC_MAX_COMPLETION_QUEUE_PLUCKERS;
GRPC_MAX_COMPLETION_QUEUE_PLUCKERS);
gpr_mu_unlock(cq->mu); gpr_mu_unlock(cq->mu);
// TODO(ctiller): should we use a different result here // TODO(ctiller): should we use a different result here
ret.type = GRPC_QUEUE_TIMEOUT; ret.type = GRPC_QUEUE_TIMEOUT;
@ -1279,8 +1273,8 @@ static grpc_event cq_pluck(grpc_completion_queue* cq, void* tag,
if (!err.ok()) { if (!err.ok()) {
del_plucker(cq, tag, &worker); del_plucker(cq, tag, &worker);
gpr_mu_unlock(cq->mu); gpr_mu_unlock(cq->mu);
gpr_log(GPR_ERROR, "Completion queue pluck failed: %s", LOG(ERROR) << "Completion queue pluck failed: "
grpc_core::StatusToString(err).c_str()); << grpc_core::StatusToString(err);
ret.type = GRPC_QUEUE_TIMEOUT; ret.type = GRPC_QUEUE_TIMEOUT;
ret.success = 0; ret.success = 0;
dump_pending_tags(cq); dump_pending_tags(cq);

@ -20,6 +20,7 @@
#include "absl/base/thread_annotations.h" #include "absl/base/thread_annotations.h"
#include "absl/log/check.h" #include "absl/log/check.h"
#include "absl/log/log.h"
#include "absl/status/status.h" #include "absl/status/status.h"
#include "absl/types/optional.h" #include "absl/types/optional.h"
@ -27,7 +28,6 @@
#include <grpc/grpc.h> #include <grpc/grpc.h>
#include <grpc/impl/connectivity_state.h> #include <grpc/impl/connectivity_state.h>
#include <grpc/support/alloc.h> #include <grpc/support/alloc.h>
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include "src/core/channelz/channelz.h" #include "src/core/channelz/channelz.h"
@ -86,8 +86,7 @@ absl::StatusOr<RefCountedPtr<Channel>> LegacyChannel::Create(
absl::StatusOr<RefCountedPtr<grpc_channel_stack>> r = builder.Build(); absl::StatusOr<RefCountedPtr<grpc_channel_stack>> r = builder.Build();
if (!r.ok()) { if (!r.ok()) {
auto status = r.status(); auto status = r.status();
gpr_log(GPR_ERROR, "channel stack builder failed: %s", LOG(ERROR) << "channel stack builder failed: " << status;
status.ToString().c_str());
return status; return status;
} }
if (channel_stack_type == GRPC_SERVER_CHANNEL) { if (channel_stack_type == GRPC_SERVER_CHANNEL) {
@ -210,9 +209,8 @@ grpc_connectivity_state LegacyChannel::CheckConnectivityState(
ClientChannelFilter* client_channel = GetClientChannelFilter(); ClientChannelFilter* client_channel = GetClientChannelFilter();
if (GPR_UNLIKELY(client_channel == nullptr)) { if (GPR_UNLIKELY(client_channel == nullptr)) {
if (IsLame()) return GRPC_CHANNEL_TRANSIENT_FAILURE; if (IsLame()) return GRPC_CHANNEL_TRANSIENT_FAILURE;
gpr_log(GPR_ERROR, LOG(ERROR) << "grpc_channel_check_connectivity_state called on something "
"grpc_channel_check_connectivity_state called on something that is " "that is not a client channel";
"not a client channel");
return GRPC_CHANNEL_SHUTDOWN; return GRPC_CHANNEL_SHUTDOWN;
} }
return client_channel->CheckConnectivityState(try_to_connect); return client_channel->CheckConnectivityState(try_to_connect);

@ -24,6 +24,7 @@
#include <algorithm> #include <algorithm>
#include "absl/log/check.h" #include "absl/log/check.h"
#include "absl/log/log.h"
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
@ -47,19 +48,16 @@ Timestamp BdpEstimator::CompletePing() {
double bw = dt > 0 ? (static_cast<double>(accumulator_) / dt) : 0; double bw = dt > 0 ? (static_cast<double>(accumulator_) / dt) : 0;
Duration start_inter_ping_delay = inter_ping_delay_; Duration start_inter_ping_delay = inter_ping_delay_;
if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) { if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) {
gpr_log(GPR_INFO, LOG(INFO) << "bdp[" << name_ << "]:complete acc=" << accumulator_
"bdp[%s]:complete acc=%" PRId64 " est=%" PRId64 << " est=" << estimate_ << " dt=" << dt << " bw=" << bw / 125000.0
" dt=%lf bw=%lfMbs bw_est=%lfMbs", << "Mbs bw_est=" << bw_est_ / 125000.0 << "Mbs";
std::string(name_).c_str(), accumulator_, estimate_, dt,
bw / 125000.0, bw_est_ / 125000.0);
} }
CHECK(ping_state_ == PingState::STARTED); CHECK(ping_state_ == PingState::STARTED);
if (accumulator_ > 2 * estimate_ / 3 && bw > bw_est_) { if (accumulator_ > 2 * estimate_ / 3 && bw > bw_est_) {
estimate_ = std::max(accumulator_, estimate_ * 2); estimate_ = std::max(accumulator_, estimate_ * 2);
bw_est_ = bw; bw_est_ = bw;
if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) { if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) {
gpr_log(GPR_INFO, "bdp[%s]: estimate increased to %" PRId64, LOG(INFO) << "bdp[" << name_ << "]: estimate increased to " << estimate_;
std::string(name_).c_str(), estimate_);
} }
inter_ping_delay_ /= 2; // if the ping estimate changes, inter_ping_delay_ /= 2; // if the ping estimate changes,
// exponentially get faster at probing // exponentially get faster at probing
@ -74,8 +72,8 @@ Timestamp BdpEstimator::CompletePing() {
if (start_inter_ping_delay != inter_ping_delay_) { if (start_inter_ping_delay != inter_ping_delay_) {
stable_estimate_count_ = 0; stable_estimate_count_ = 0;
if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) { if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) {
gpr_log(GPR_INFO, "bdp[%s]:update_inter_time to %" PRId64 "ms", LOG(INFO) << "bdp[" << name_ << "]:update_inter_time to "
std::string(name_).c_str(), inter_ping_delay_.millis()); << inter_ping_delay_.millis() << "ms";
} }
} }
ping_state_ = PingState::UNSCHEDULED; ping_state_ = PingState::UNSCHEDULED;

@ -24,9 +24,9 @@
#include <string> #include <string>
#include "absl/log/check.h" #include "absl/log/check.h"
#include "absl/log/log.h"
#include "absl/strings/string_view.h" #include "absl/strings/string_view.h"
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include <grpc/support/time.h> #include <grpc/support/time.h>
@ -50,8 +50,8 @@ class BdpEstimator {
// transport (but not necessarily started) // transport (but not necessarily started)
void SchedulePing() { void SchedulePing() {
if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) { if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) {
gpr_log(GPR_INFO, "bdp[%s]:sched acc=%" PRId64 " est=%" PRId64, LOG(INFO) << "bdp[" << name_ << "]:sched acc=" << accumulator_
std::string(name_).c_str(), accumulator_, estimate_); << " est=" << estimate_;
} }
CHECK(ping_state_ == PingState::UNSCHEDULED); CHECK(ping_state_ == PingState::UNSCHEDULED);
ping_state_ = PingState::SCHEDULED; ping_state_ = PingState::SCHEDULED;
@ -63,8 +63,8 @@ class BdpEstimator {
// the ping is on the wire // the ping is on the wire
void StartPing() { void StartPing() {
if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) { if (GRPC_TRACE_FLAG_ENABLED(bdp_estimator)) {
gpr_log(GPR_INFO, "bdp[%s]:start acc=%" PRId64 " est=%" PRId64, LOG(INFO) << "bdp[" << name_ << "]:start acc=" << accumulator_
std::string(name_).c_str(), accumulator_, estimate_); << " est=" << estimate_;
} }
CHECK(ping_state_ == PingState::SCHEDULED); CHECK(ping_state_ == PingState::SCHEDULED);
ping_state_ = PingState::STARTED; ping_state_ = PingState::STARTED;

@ -15,6 +15,7 @@
#include "src/core/lib/transport/call_filters.h" #include "src/core/lib/transport/call_filters.h"
#include "absl/log/check.h" #include "absl/log/check.h"
#include "absl/log/log.h"
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
@ -188,9 +189,8 @@ void CallFilters::CancelDueToFailedPipeOperation(SourceLocation but_where) {
// We expect something cancelled before now // We expect something cancelled before now
if (push_server_trailing_metadata_ == nullptr) return; if (push_server_trailing_metadata_ == nullptr) return;
if (GRPC_TRACE_FLAG_ENABLED(promise_primitives)) { if (GRPC_TRACE_FLAG_ENABLED(promise_primitives)) {
gpr_log(but_where.file(), but_where.line(), GPR_LOG_SEVERITY_DEBUG, VLOG(2).AtLocation(but_where.file(), but_where.line())
"Cancelling due to failed pipe operation: %s", << "Cancelling due to failed pipe operation: " << DebugString();
DebugString().c_str());
} }
auto status = auto status =
ServerMetadataFromStatus(absl::CancelledError("Failed pipe operation")); ServerMetadataFromStatus(absl::CancelledError("Failed pipe operation"));
@ -201,9 +201,9 @@ void CallFilters::CancelDueToFailedPipeOperation(SourceLocation but_where) {
void CallFilters::PushServerTrailingMetadata(ServerMetadataHandle md) { void CallFilters::PushServerTrailingMetadata(ServerMetadataHandle md) {
CHECK(md != nullptr); CHECK(md != nullptr);
if (GRPC_TRACE_FLAG_ENABLED(call)) { if (GRPC_TRACE_FLAG_ENABLED(call)) {
gpr_log(GPR_INFO, "%s PushServerTrailingMetadata[%p]: %s into %s", LOG(INFO) << GetContext<Activity>()->DebugTag()
GetContext<Activity>()->DebugTag().c_str(), this, << " PushServerTrailingMetadata[" << this
md->DebugString().c_str(), DebugString().c_str()); << "]: " << md->DebugString() << " into " << DebugString();
} }
CHECK(md != nullptr); CHECK(md != nullptr);
if (call_state_.PushServerTrailingMetadata( if (call_state_.PushServerTrailingMetadata(

@ -18,7 +18,8 @@
#include "src/core/lib/transport/connectivity_state.h" #include "src/core/lib/transport/connectivity_state.h"
#include <grpc/support/log.h> #include "absl/log/log.h"
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include "src/core/lib/gprpp/debug_location.h" #include "src/core/lib/gprpp/debug_location.h"
@ -72,9 +73,10 @@ class AsyncConnectivityStateWatcherInterface::Notifier {
static void SendNotification(void* arg, grpc_error_handle /*ignored*/) { static void SendNotification(void* arg, grpc_error_handle /*ignored*/) {
Notifier* self = static_cast<Notifier*>(arg); Notifier* self = static_cast<Notifier*>(arg);
if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) {
gpr_log(GPR_INFO, "watcher %p: delivering async notification for %s (%s)", LOG(INFO) << "watcher " << self->watcher_.get()
self->watcher_.get(), ConnectivityStateName(self->state_), << ": delivering async notification for "
self->status_.ToString().c_str()); << ConnectivityStateName(self->state_) << " ("
<< self->status_.ToString() << ")";
} }
self->watcher_->OnConnectivityStateChange(self->state_, self->status_); self->watcher_->OnConnectivityStateChange(self->state_, self->status_);
delete self; delete self;
@ -103,10 +105,10 @@ ConnectivityStateTracker::~ConnectivityStateTracker() {
if (current_state == GRPC_CHANNEL_SHUTDOWN) return; if (current_state == GRPC_CHANNEL_SHUTDOWN) return;
for (const auto& p : watchers_) { for (const auto& p : watchers_) {
if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) {
gpr_log(GPR_INFO, LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this
"ConnectivityStateTracker %s[%p]: notifying watcher %p: %s -> %s", << "]: notifying watcher " << p.first << ": "
name_, this, p.first, ConnectivityStateName(current_state), << ConnectivityStateName(current_state) << " -> "
ConnectivityStateName(GRPC_CHANNEL_SHUTDOWN)); << ConnectivityStateName(GRPC_CHANNEL_SHUTDOWN);
} }
p.second->Notify(GRPC_CHANNEL_SHUTDOWN, absl::Status()); p.second->Notify(GRPC_CHANNEL_SHUTDOWN, absl::Status());
} }
@ -116,17 +118,17 @@ void ConnectivityStateTracker::AddWatcher(
grpc_connectivity_state initial_state, grpc_connectivity_state initial_state,
OrphanablePtr<ConnectivityStateWatcherInterface> watcher) { OrphanablePtr<ConnectivityStateWatcherInterface> watcher) {
if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) {
gpr_log(GPR_INFO, "ConnectivityStateTracker %s[%p]: add watcher %p", name_, LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this
this, watcher.get()); << "]: add watcher " << watcher.get();
} }
grpc_connectivity_state current_state = grpc_connectivity_state current_state =
state_.load(std::memory_order_relaxed); state_.load(std::memory_order_relaxed);
if (initial_state != current_state) { if (initial_state != current_state) {
if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) {
gpr_log(GPR_INFO, LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this
"ConnectivityStateTracker %s[%p]: notifying watcher %p: %s -> %s", << "]: notifying watcher " << watcher.get() << ": "
name_, this, watcher.get(), ConnectivityStateName(initial_state), << ConnectivityStateName(initial_state) << " -> "
ConnectivityStateName(current_state)); << ConnectivityStateName(current_state);
} }
watcher->Notify(current_state, status_); watcher->Notify(current_state, status_);
} }
@ -140,8 +142,8 @@ void ConnectivityStateTracker::AddWatcher(
void ConnectivityStateTracker::RemoveWatcher( void ConnectivityStateTracker::RemoveWatcher(
ConnectivityStateWatcherInterface* watcher) { ConnectivityStateWatcherInterface* watcher) {
if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) {
gpr_log(GPR_INFO, "ConnectivityStateTracker %s[%p]: remove watcher %p", LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this
name_, this, watcher); << "]: remove watcher " << watcher;
} }
watchers_.erase(watcher); watchers_.erase(watcher);
} }
@ -153,18 +155,19 @@ void ConnectivityStateTracker::SetState(grpc_connectivity_state state,
state_.load(std::memory_order_relaxed); state_.load(std::memory_order_relaxed);
if (state == current_state) return; if (state == current_state) return;
if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) {
gpr_log(GPR_INFO, "ConnectivityStateTracker %s[%p]: %s -> %s (%s, %s)", LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this
name_, this, ConnectivityStateName(current_state), << "]: " << ConnectivityStateName(current_state) << " -> "
ConnectivityStateName(state), reason, status.ToString().c_str()); << ConnectivityStateName(state) << " (" << reason << ", "
<< status.ToString() << ")";
} }
state_.store(state, std::memory_order_relaxed); state_.store(state, std::memory_order_relaxed);
status_ = status; status_ = status;
for (const auto& p : watchers_) { for (const auto& p : watchers_) {
if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) {
gpr_log(GPR_INFO, LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this
"ConnectivityStateTracker %s[%p]: notifying watcher %p: %s -> %s", << "]: notifying watcher " << p.first << ": "
name_, this, p.first, ConnectivityStateName(current_state), << ConnectivityStateName(current_state) << " -> "
ConnectivityStateName(state)); << ConnectivityStateName(state);
} }
p.second->Notify(state, status); 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 ConnectivityStateTracker::state() const {
grpc_connectivity_state state = state_.load(std::memory_order_relaxed); grpc_connectivity_state state = state_.load(std::memory_order_relaxed);
if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) { if (GRPC_TRACE_FLAG_ENABLED(connectivity_state)) {
gpr_log(GPR_INFO, "ConnectivityStateTracker %s[%p]: get current state: %s", LOG(INFO) << "ConnectivityStateTracker " << name_ << "[" << this
name_, this, ConnectivityStateName(state)); << "]: get current state: " << ConnectivityStateName(state);
} }
return state; return state;
} }

@ -28,6 +28,7 @@
#include <utility> #include <utility>
#include "absl/functional/any_invocable.h" #include "absl/functional/any_invocable.h"
#include "absl/log/log.h"
#include "absl/status/status.h" #include "absl/status/status.h"
#include "absl/strings/string_view.h" #include "absl/strings/string_view.h"
#include "absl/types/optional.h" #include "absl/types/optional.h"
@ -35,7 +36,6 @@
#include <grpc/impl/connectivity_state.h> #include <grpc/impl/connectivity_state.h>
#include <grpc/slice.h> #include <grpc/slice.h>
#include <grpc/status.h> #include <grpc/status.h>
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include <grpc/support/time.h> #include <grpc/support/time.h>
@ -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, inline void grpc_stream_ref(grpc_stream_refcount* refcount,
const char* reason) { const char* reason) {
if (GRPC_TRACE_FLAG_ENABLED(stream_refcount)) { if (GRPC_TRACE_FLAG_ENABLED(stream_refcount)) {
gpr_log(GPR_DEBUG, "%s %p:%p REF %s", refcount->object_type, refcount, VLOG(2) << refcount->object_type << " " << refcount << ":"
refcount->destroy.cb_arg, reason); << refcount->destroy.cb_arg << " REF " << reason;
} }
refcount->refs.RefNonZero(DEBUG_LOCATION, 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, inline void grpc_stream_unref(grpc_stream_refcount* refcount,
const char* reason) { const char* reason) {
if (GRPC_TRACE_FLAG_ENABLED(stream_refcount)) { if (GRPC_TRACE_FLAG_ENABLED(stream_refcount)) {
gpr_log(GPR_DEBUG, "%s %p:%p UNREF %s", refcount->object_type, refcount, VLOG(2) << refcount->object_type << " " << refcount << ":"
refcount->destroy.cb_arg, reason); << refcount->destroy.cb_arg << " UNREF " << reason;
} }
if (GPR_UNLIKELY(refcount->refs.Unref(DEBUG_LOCATION, reason))) { if (GPR_UNLIKELY(refcount->refs.Unref(DEBUG_LOCATION, reason))) {
grpc_stream_destroy(refcount); grpc_stream_destroy(refcount);

@ -19,7 +19,6 @@
#include <algorithm> #include <algorithm>
#include <vector> #include <vector>
#include "absl/log/log.h"
#include "absl/strings/string_view.h" #include "absl/strings/string_view.h"
#include <grpc/impl/channel_arg_names.h> #include <grpc/impl/channel_arg_names.h>
@ -48,13 +47,13 @@
#include <ares.h> #include <ares.h>
#include "absl/log/check.h" #include "absl/log/check.h"
#include "absl/log/log.h"
#include "absl/status/status.h" #include "absl/status/status.h"
#include "absl/status/statusor.h" #include "absl/status/statusor.h"
#include "absl/strings/str_cat.h" #include "absl/strings/str_cat.h"
#include "absl/strings/str_format.h" #include "absl/strings/str_format.h"
#include <grpc/support/alloc.h> #include <grpc/support/alloc.h>
#include <grpc/support/log.h>
#include <grpc/support/string_util.h> #include <grpc/support/string_util.h>
#include <grpc/support/sync.h> #include <grpc/support/sync.h>
@ -556,11 +555,10 @@ static void log_address_sorting_list(const grpc_ares_request* r,
const char* input_output_str) { const char* input_output_str) {
for (size_t i = 0; i < addresses.size(); i++) { for (size_t i = 0; i < addresses.size(); i++) {
auto addr_str = grpc_sockaddr_to_string(&addresses[i].address(), true); auto addr_str = grpc_sockaddr_to_string(&addresses[i].address(), true);
gpr_log(GPR_INFO, LOG(INFO) << "(c-ares resolver) request:" << r
"(c-ares resolver) request:%p c-ares address sorting: %s[%" PRIuPTR << " c-ares address sorting: " << input_output_str << "[" << i
"]=%s", << "]="
r, input_output_str, i, << (addr_str.ok() ? addr_str->c_str()
addr_str.ok() ? addr_str->c_str()
: addr_str.status().ToString().c_str()); : addr_str.status().ToString().c_str());
} }
} }
@ -901,18 +899,14 @@ static bool inner_resolve_as_ip_literal_locked(
std::unique_ptr<grpc_core::EndpointAddressesList>* addrs, std::string* host, std::unique_ptr<grpc_core::EndpointAddressesList>* addrs, std::string* host,
std::string* port, std::string* hostport) { std::string* port, std::string* hostport) {
if (!grpc_core::SplitHostPort(name, host, port)) { if (!grpc_core::SplitHostPort(name, host, port)) {
gpr_log(GPR_ERROR, LOG(ERROR) << "Failed to parse " << name
"Failed to parse %s to host:port while attempting to resolve as ip " << " to host:port while attempting to resolve as ip literal.";
"literal.",
name);
return false; return false;
} }
if (port->empty()) { if (port->empty()) {
if (default_port == nullptr || strlen(default_port) == 0) { if (default_port == nullptr || strlen(default_port) == 0) {
gpr_log(GPR_ERROR, LOG(ERROR) << "No port or default port for " << name
"No port or default port for %s while attempting to resolve as " << " while attempting to resolve as ip literal.";
"ip literal.",
name);
return false; return false;
} }
*port = default_port; *port = default_port;
@ -964,18 +958,14 @@ static bool inner_maybe_resolve_localhost_manually_locked(
std::string* port) { std::string* port) {
grpc_core::SplitHostPort(name, host, port); grpc_core::SplitHostPort(name, host, port);
if (host->empty()) { if (host->empty()) {
gpr_log(GPR_ERROR, LOG(ERROR) << "Failed to parse " << name
"Failed to parse %s into host:port during manual localhost " << " into host:port during manual localhost resolution check.";
"resolution check.",
name);
return false; return false;
} }
if (port->empty()) { if (port->empty()) {
if (default_port == nullptr || strlen(default_port) == 0) { if (default_port == nullptr || strlen(default_port) == 0) {
gpr_log(GPR_ERROR, LOG(ERROR) << "No port or default port for " << name
"No port or default port for %s during manual localhost " << " during manual localhost resolution check.";
"resolution check.",
name);
return false; return false;
} }
*port = default_port; *port = default_port;

@ -26,8 +26,8 @@
#include <ares.h> #include <ares.h>
#include "absl/base/thread_annotations.h" #include "absl/base/thread_annotations.h"
#include "absl/log/log.h"
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include "src/core/lib/debug/trace.h" #include "src/core/lib/debug/trace.h"
@ -42,7 +42,7 @@
#define GRPC_CARES_TRACE_LOG(format, ...) \ #define GRPC_CARES_TRACE_LOG(format, ...) \
do { \ do { \
if (GRPC_TRACE_FLAG_ENABLED(cares_resolver)) { \ if (GRPC_TRACE_FLAG_ENABLED(cares_resolver)) { \
gpr_log(GPR_DEBUG, "(c-ares resolver) " format, __VA_ARGS__); \ VLOG(2) << "(c-ares resolver) " << absl::StrFormat(format, __VA_ARGS__); \
} \ } \
} while (0) } while (0)

@ -36,7 +36,6 @@
#include <grpc/event_engine/event_engine.h> #include <grpc/event_engine/event_engine.h>
#include <grpc/impl/channel_arg_names.h> #include <grpc/impl/channel_arg_names.h>
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include "src/core/lib/backoff/backoff.h" #include "src/core/lib/backoff/backoff.h"
@ -80,8 +79,8 @@ using grpc_event_engine::experimental::EventEngine;
#define GRPC_EVENT_ENGINE_RESOLVER_TRACE(format, ...) \ #define GRPC_EVENT_ENGINE_RESOLVER_TRACE(format, ...) \
if (GRPC_TRACE_FLAG_ENABLED(event_engine_client_channel_resolver)) { \ if (GRPC_TRACE_FLAG_ENABLED(event_engine_client_channel_resolver)) { \
gpr_log(GPR_DEBUG, "(event_engine client channel resolver) " format, \ VLOG(2) << "(event_engine client channel resolver) " \
__VA_ARGS__); \ << absl::StrFormat(format, __VA_ARGS__); \
} }
// ---------------------------------------------------------------------------- // ----------------------------------------------------------------------------

@ -29,7 +29,6 @@
#include "absl/types/optional.h" #include "absl/types/optional.h"
#include <grpc/impl/channel_arg_names.h> #include <grpc/impl/channel_arg_names.h>
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include "src/core/lib/backoff/backoff.h" #include "src/core/lib/backoff/backoff.h"
@ -92,13 +91,13 @@ NativeClientChannelDNSResolver::NativeClientChannelDNSResolver(
GRPC_DNS_RECONNECT_MAX_BACKOFF_SECONDS * 1000)), GRPC_DNS_RECONNECT_MAX_BACKOFF_SECONDS * 1000)),
&dns_resolver_trace) { &dns_resolver_trace) {
if (GRPC_TRACE_FLAG_ENABLED(dns_resolver)) { if (GRPC_TRACE_FLAG_ENABLED(dns_resolver)) {
gpr_log(GPR_DEBUG, "[dns_resolver=%p] created", this); VLOG(2) << "[dns_resolver=" << this << "] created";
} }
} }
NativeClientChannelDNSResolver::~NativeClientChannelDNSResolver() { NativeClientChannelDNSResolver::~NativeClientChannelDNSResolver() {
if (GRPC_TRACE_FLAG_ENABLED(dns_resolver)) { 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<Orphanable> NativeClientChannelDNSResolver::StartRequest() {
name_to_resolve(), kDefaultSecurePort, kDefaultDNSRequestTimeout, name_to_resolve(), kDefaultSecurePort, kDefaultDNSRequestTimeout,
interested_parties(), /*name_server=*/""); interested_parties(), /*name_server=*/"");
if (GRPC_TRACE_FLAG_ENABLED(dns_resolver)) { if (GRPC_TRACE_FLAG_ENABLED(dns_resolver)) {
gpr_log(GPR_DEBUG, "[dns_resolver=%p] starting request=%p", this, VLOG(2) << "[dns_resolver=" << this << "] starting request="
DNSResolver::HandleToString(dns_request_handle).c_str()); << DNSResolver::HandleToString(dns_request_handle);
} }
return MakeOrphanable<Request>(); return MakeOrphanable<Request>();
} }
@ -118,8 +117,8 @@ OrphanablePtr<Orphanable> NativeClientChannelDNSResolver::StartRequest() {
void NativeClientChannelDNSResolver::OnResolved( void NativeClientChannelDNSResolver::OnResolved(
absl::StatusOr<std::vector<grpc_resolved_address>> addresses_or) { absl::StatusOr<std::vector<grpc_resolved_address>> addresses_or) {
if (GRPC_TRACE_FLAG_ENABLED(dns_resolver)) { if (GRPC_TRACE_FLAG_ENABLED(dns_resolver)) {
gpr_log(GPR_DEBUG, "[dns_resolver=%p] request complete, status=\"%s\"", VLOG(2) << "[dns_resolver=" << this
this, addresses_or.status().ToString().c_str()); << "] request complete, status=" << addresses_or.status();
} }
// Convert result from iomgr DNS API into Resolver::Result. // Convert result from iomgr DNS API into Resolver::Result.
Result result; Result result;

@ -27,6 +27,7 @@
#include <vector> #include <vector>
#include "absl/log/check.h" #include "absl/log/check.h"
#include "absl/log/log.h"
#include "absl/meta/type_traits.h" #include "absl/meta/type_traits.h"
#include "absl/random/random.h" #include "absl/random/random.h"
#include "absl/status/status.h" #include "absl/status/status.h"
@ -45,7 +46,6 @@
#include <grpc/impl/channel_arg_names.h> #include <grpc/impl/channel_arg_names.h>
#include <grpc/slice.h> #include <grpc/slice.h>
#include <grpc/status.h> #include <grpc/status.h>
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include "src/core/client_channel/client_channel_internal.h" #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)), data_plane_authority_(std::move(data_plane_authority)),
channel_id_(absl::Uniform<uint64_t>(absl::BitGen())) { channel_id_(absl::Uniform<uint64_t>(absl::BitGen())) {
if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) {
gpr_log( LOG(INFO) << "[xds_resolver " << this << "] created for URI "
GPR_INFO, << uri_.ToString() << "; data plane authority is "
"[xds_resolver %p] created for URI %s; data plane authority is %s", << data_plane_authority_;
this, uri_.ToString().c_str(), data_plane_authority_.c_str());
} }
} }
~XdsResolver() override { ~XdsResolver() override {
if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { 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, XdsResolver* resolver, const XdsRouteConfigResource::Route& route,
const Duration& default_max_stream_duration) { const Duration& default_max_stream_duration) {
if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) {
gpr_log(GPR_INFO, "[xds_resolver %p] XdsConfigSelector %p: route: %s", LOG(INFO) << "[xds_resolver " << resolver << "] XdsConfigSelector " << this
resolver, this, route.ToString().c_str()); << ": route: " << route.ToString();
} }
routes_.emplace_back(route); routes_.emplace_back(route);
auto* route_entry = &routes_.back(); auto* route_entry = &routes_.back();
@ -630,8 +629,8 @@ XdsResolver::XdsConfigSelector::XdsConfigSelector(
: resolver_(std::move(resolver)), : resolver_(std::move(resolver)),
route_config_data_(std::move(route_config_data)) { route_config_data_(std::move(route_config_data)) {
if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) {
gpr_log(GPR_INFO, "[xds_resolver %p] creating XdsConfigSelector %p", LOG(INFO) << "[xds_resolver " << resolver_.get()
resolver_.get(), this); << "] creating XdsConfigSelector " << this;
} }
// Populate filter list. // Populate filter list.
const auto& http_filter_registry = const auto& http_filter_registry =
@ -653,8 +652,8 @@ XdsResolver::XdsConfigSelector::XdsConfigSelector(
XdsResolver::XdsConfigSelector::~XdsConfigSelector() { XdsResolver::XdsConfigSelector::~XdsConfigSelector() {
if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) {
gpr_log(GPR_INFO, "[xds_resolver %p] destroying XdsConfigSelector %p", LOG(INFO) << "[xds_resolver " << resolver_.get()
resolver_.get(), this); << "] destroying XdsConfigSelector " << this;
} }
route_config_data_.reset(); route_config_data_.reset();
if (!IsWorkSerializerDispatchEnabled()) { if (!IsWorkSerializerDispatchEnabled()) {
@ -897,10 +896,9 @@ void XdsResolver::StartLocked() {
auto xds_client = auto xds_client =
GrpcXdsClient::GetOrCreate(uri_.ToString(), args_, "xds resolver"); GrpcXdsClient::GetOrCreate(uri_.ToString(), args_, "xds resolver");
if (!xds_client.ok()) { if (!xds_client.ok()) {
gpr_log(GPR_ERROR, LOG(ERROR) << "Failed to create xds client -- channel will remain in "
"Failed to create xds client -- channel will remain in " "TRANSIENT_FAILURE: "
"TRANSIENT_FAILURE: %s", << xds_client.status();
xds_client.status().ToString().c_str());
absl::Status status = absl::UnavailableError(absl::StrCat( absl::Status status = absl::UnavailableError(absl::StrCat(
"Failed to create XdsClient: ", xds_client.status().message())); "Failed to create XdsClient: ", xds_client.status().message()));
Result result; Result result;
@ -956,8 +954,8 @@ void XdsResolver::StartLocked() {
absl::StrReplaceAll(name_template, {{"%s", resource_name_fragment}}); absl::StrReplaceAll(name_template, {{"%s", resource_name_fragment}});
} }
if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) {
gpr_log(GPR_INFO, "[xds_resolver %p] Started with lds_resource_name %s.", LOG(INFO) << "[xds_resolver " << this << "] Started with lds_resource_name "
this, lds_resource_name_.c_str()); << lds_resource_name_;
} }
// Start watch for xDS config. // Start watch for xDS config.
dependency_mgr_ = MakeOrphanable<XdsDependencyManager>( dependency_mgr_ = MakeOrphanable<XdsDependencyManager>(
@ -968,7 +966,7 @@ void XdsResolver::StartLocked() {
void XdsResolver::ShutdownLocked() { void XdsResolver::ShutdownLocked() {
if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { 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) { if (xds_client_ != nullptr) {
dependency_mgr_.reset(); dependency_mgr_.reset();
@ -981,7 +979,7 @@ void XdsResolver::ShutdownLocked() {
void XdsResolver::OnUpdate( void XdsResolver::OnUpdate(
RefCountedPtr<const XdsDependencyManager::XdsConfig> config) { RefCountedPtr<const XdsDependencyManager::XdsConfig> config) {
if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { 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; if (xds_client_ == nullptr) return;
current_config_ = std::move(config); current_config_ = std::move(config);
@ -989,8 +987,9 @@ void XdsResolver::OnUpdate(
} }
void XdsResolver::OnError(absl::string_view context, absl::Status status) { void XdsResolver::OnError(absl::string_view context, absl::Status status) {
gpr_log(GPR_ERROR, "[xds_resolver %p] received error from XdsClient: %s: %s", LOG(ERROR) << "[xds_resolver " << this
this, std::string(context).c_str(), status.ToString().c_str()); << "] received error from XdsClient: " << context << ": "
<< status;
if (xds_client_ == nullptr) return; if (xds_client_ == nullptr) return;
status = status =
absl::UnavailableError(absl::StrCat(context, ": ", status.ToString())); 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) { void XdsResolver::OnResourceDoesNotExist(std::string context) {
gpr_log(GPR_ERROR, LOG(ERROR) << "[xds_resolver " << this
"[xds_resolver %p] LDS/RDS resource does not exist -- clearing " << "] LDS/RDS resource does not exist -- clearing "
"update and returning empty service config", "update and returning empty service config";
this);
if (xds_client_ == nullptr) return; if (xds_client_ == nullptr) return;
current_config_.reset(); current_config_.reset();
Result result; Result result;
@ -1080,10 +1078,10 @@ void XdsResolver::GenerateResult() {
result.addresses.emplace(); result.addresses.emplace();
result.service_config = CreateServiceConfig(); result.service_config = CreateServiceConfig();
if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) { if (GRPC_TRACE_FLAG_ENABLED(xds_resolver)) {
gpr_log(GPR_INFO, "[xds_resolver %p] generated service config: %s", this, LOG(INFO) << "[xds_resolver " << this << "] generated service config: "
result.service_config.ok() << (result.service_config.ok()
? std::string((*result.service_config)->json_string()).c_str() ? ((*result.service_config)->json_string())
: result.service_config.status().ToString().c_str()); : result.service_config.status().ToString());
} }
result.args = result.args =
args_.SetObject(xds_client_.Ref(DEBUG_LOCATION, "xds resolver result")) 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 { bool IsValidUri(const URI& uri) const override {
if (uri.path().empty() || uri.path().back() == '/') { if (uri.path().empty() || uri.path().back() == '/') {
gpr_log(GPR_ERROR, LOG(ERROR) << "URI path does not contain valid data plane authority";
"URI path does not contain valid data plane authority");
return false; return false;
} }
return true; return true;

@ -43,7 +43,6 @@
#include <grpc/impl/connectivity_state.h> #include <grpc/impl/connectivity_state.h>
#include <grpc/slice.h> #include <grpc/slice.h>
#include <grpc/status.h> #include <grpc/status.h>
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include <grpc/support/time.h> #include <grpc/support/time.h>
@ -1050,19 +1049,18 @@ Server::RegisteredMethod* Server::RegisterMethod(
} }
if (!method) { if (!method) {
gpr_log(GPR_ERROR, LOG(ERROR) << "grpc_server_register_method method string cannot be NULL";
"grpc_server_register_method method string cannot be NULL");
return nullptr; return nullptr;
} }
auto key = std::make_pair(host ? host : "", method); auto key = std::make_pair(host ? host : "", method);
if (registered_methods_.find(key) != registered_methods_.end()) { if (registered_methods_.find(key) != registered_methods_.end()) {
gpr_log(GPR_ERROR, "duplicate registration for %s@%s", method, LOG(ERROR) << "duplicate registration for " << method << "@"
host ? host : "*"); << (host ? host : "*");
return nullptr; return nullptr;
} }
if (flags != 0) { if (flags != 0) {
gpr_log(GPR_ERROR, "grpc_server_register_method invalid flags 0x%08x", LOG(ERROR) << "grpc_server_register_method invalid flags "
flags); << absl::StrFormat("0x%08x", flags);
return nullptr; return nullptr;
} }
auto it = registered_methods_.emplace( auto it = registered_methods_.emplace(
@ -1100,12 +1098,11 @@ void Server::MaybeFinishShutdown() {
last_shutdown_message_time_), last_shutdown_message_time_),
gpr_time_from_seconds(1, GPR_TIMESPAN)) >= 0) { gpr_time_from_seconds(1, GPR_TIMESPAN)) >= 0) {
last_shutdown_message_time_ = gpr_now(GPR_CLOCK_REALTIME); last_shutdown_message_time_ = gpr_now(GPR_CLOCK_REALTIME);
gpr_log(GPR_DEBUG, VLOG(2) << "Waiting for " << channels_.size() << " channels "
"Waiting for %" PRIuPTR " channels %" PRIuPTR << connections_open_ << " connections and "
" connections and %" PRIuPTR "/%" PRIuPTR << listeners_.size() - listeners_destroyed_ << "/"
" listeners to be destroyed before shutting down server", << listeners_.size()
channels_.size(), connections_open_, << " listeners to be destroyed before shutting down server";
listeners_.size() - listeners_destroyed_, listeners_.size());
} }
return; return;
} }
@ -1673,8 +1670,7 @@ void Server::CallData::RecvInitialMetadataBatchComplete(
grpc_call_element* elem = static_cast<grpc_call_element*>(arg); grpc_call_element* elem = static_cast<grpc_call_element*>(arg);
auto* calld = static_cast<Server::CallData*>(elem->call_data); auto* calld = static_cast<Server::CallData*>(elem->call_data);
if (!error.ok()) { if (!error.ok()) {
gpr_log(GPR_DEBUG, "Failed call creation: %s", VLOG(2) << "Failed call creation: " << StatusToString(error);
StatusToString(error).c_str());
calld->FailCallCreation(); calld->FailCallCreation();
return; return;
} }
@ -1798,10 +1794,8 @@ void grpc_server_register_completion_queue(grpc_server* server,
CHECK(!reserved); CHECK(!reserved);
auto cq_type = grpc_get_cq_completion_type(cq); auto cq_type = grpc_get_cq_completion_type(cq);
if (cq_type != GRPC_CQ_NEXT && cq_type != GRPC_CQ_CALLBACK) { if (cq_type != GRPC_CQ_NEXT && cq_type != GRPC_CQ_CALLBACK) {
gpr_log(GPR_INFO, LOG(INFO) << "Completion queue of type " << static_cast<int>(cq_type)
"Completion queue of type %d is being registered as a " << " is being registered as a server-completion-queue";
"server-completion-queue",
static_cast<int>(cq_type));
// Ideally we should log an error and abort but ruby-wrapped-language API // Ideally we should log an error and abort but ruby-wrapped-language API
// calls grpc_completion_queue_pluck() on server completion queues // calls grpc_completion_queue_pluck() on server completion queues
} }

@ -28,6 +28,7 @@
#include "absl/base/thread_annotations.h" #include "absl/base/thread_annotations.h"
#include "absl/log/check.h" #include "absl/log/check.h"
#include "absl/log/log.h"
#include "absl/status/status.h" #include "absl/status/status.h"
#include "absl/status/statusor.h" #include "absl/status/statusor.h"
#include "absl/strings/match.h" #include "absl/strings/match.h"
@ -44,7 +45,6 @@
#include <grpc/grpc_security.h> #include <grpc/grpc_security.h>
#include <grpc/slice.h> #include <grpc/slice.h>
#include <grpc/status.h> #include <grpc/status.h>
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include "src/core/lib/address_utils/parse_address.h" #include "src/core/lib/address_utils/parse_address.h"
@ -588,9 +588,9 @@ void XdsServerConfigFetcher::ListenerWatcher::OnResourceChanged(
std::shared_ptr<const XdsListenerResource> listener, std::shared_ptr<const XdsListenerResource> listener,
RefCountedPtr<ReadDelayHandle> /* read_delay_handle */) { RefCountedPtr<ReadDelayHandle> /* read_delay_handle */) {
if (GRPC_TRACE_FLAG_ENABLED(xds_server_config_fetcher)) { if (GRPC_TRACE_FLAG_ENABLED(xds_server_config_fetcher)) {
gpr_log(GPR_INFO, LOG(INFO) << "[ListenerWatcher " << this
"[ListenerWatcher %p] Received LDS update from xds client %p: %s", << "] Received LDS update from xds client " << xds_client_.get()
this, xds_client_.get(), listener->ToString().c_str()); << ": " << listener->ToString();
} }
auto* tcp_listener = auto* tcp_listener =
absl::get_if<XdsListenerResource::TcpListener>(&listener->listener); absl::get_if<XdsListenerResource::TcpListener>(&listener->listener);
@ -628,20 +628,19 @@ void XdsServerConfigFetcher::ListenerWatcher::OnError(
MutexLock lock(&mu_); MutexLock lock(&mu_);
if (filter_chain_match_manager_ != nullptr || if (filter_chain_match_manager_ != nullptr ||
pending_filter_chain_match_manager_ != nullptr) { pending_filter_chain_match_manager_ != nullptr) {
gpr_log(GPR_ERROR, LOG(ERROR) << "ListenerWatcher:" << this
"ListenerWatcher:%p XdsClient reports error: %s for %s; " << " XdsClient reports error: " << status << " for "
"ignoring in favor of existing resource", << listening_address_
this, status.ToString().c_str(), listening_address_.c_str()); << "; ignoring in favor of existing resource";
} else { } else {
if (serving_status_notifier_.on_serving_status_update != nullptr) { if (serving_status_notifier_.on_serving_status_update != nullptr) {
serving_status_notifier_.on_serving_status_update( serving_status_notifier_.on_serving_status_update(
serving_status_notifier_.user_data, listening_address_.c_str(), serving_status_notifier_.user_data, listening_address_.c_str(),
{GRPC_STATUS_UNAVAILABLE, status.ToString().c_str()}); {GRPC_STATUS_UNAVAILABLE, status.ToString().c_str()});
} else { } else {
gpr_log(GPR_ERROR, LOG(ERROR) << "ListenerWatcher:" << this
"ListenerWatcher:%p error obtaining xDS Listener resource: %s; " << " error obtaining xDS Listener resource: " << status
"not serving on %s", << "; not serving on " << listening_address_;
this, status.ToString().c_str(), listening_address_.c_str());
} }
} }
} }
@ -661,9 +660,8 @@ void XdsServerConfigFetcher::ListenerWatcher::OnFatalError(
{static_cast<grpc_status_code>(status.raw_code()), {static_cast<grpc_status_code>(status.raw_code()),
std::string(status.message()).c_str()}); std::string(status.message()).c_str()});
} else { } else {
gpr_log(GPR_ERROR, LOG(ERROR) << "ListenerWatcher:" << this << " Encountered fatal error "
"ListenerWatcher:%p Encountered fatal error %s; not serving on %s", << status << "; not serving on " << listening_address_;
this, status.ToString().c_str(), listening_address_.c_str());
} }
} }
@ -689,9 +687,8 @@ void XdsServerConfigFetcher::ListenerWatcher::
serving_status_notifier_.user_data, listening_address_.c_str(), serving_status_notifier_.user_data, listening_address_.c_str(),
{GRPC_STATUS_OK, ""}); {GRPC_STATUS_OK, ""});
} else { } else {
gpr_log(GPR_INFO, LOG(INFO) << "xDS Listener resource obtained; will start serving on "
"xDS Listener resource obtained; will start serving on %s", << listening_address_;
listening_address_.c_str());
} }
} }
// Promote the pending FilterChainMatchManager // Promote the pending FilterChainMatchManager
@ -996,8 +993,8 @@ const XdsListenerResource::FilterChainData* FindFilterChainDataForSourceType(
} }
auto source_addr = StringToSockaddr(host, 0); // Port doesn't matter here. auto source_addr = StringToSockaddr(host, 0); // Port doesn't matter here.
if (!source_addr.ok()) { if (!source_addr.ok()) {
gpr_log(GPR_DEBUG, "Could not parse \"%s\" as socket address: %s", VLOG(2) << "Could not parse \"" << host
host.c_str(), source_addr.status().ToString().c_str()); << "\" as socket address: " << source_addr.status();
return nullptr; return nullptr;
} }
// Use kAny only if kSameIporLoopback and kExternal are empty // Use kAny only if kSameIporLoopback and kExternal are empty
@ -1045,8 +1042,8 @@ const XdsListenerResource::FilterChainData* FindFilterChainDataForDestinationIp(
auto destination_addr = auto destination_addr =
StringToSockaddr(host, 0); // Port doesn't matter here. StringToSockaddr(host, 0); // Port doesn't matter here.
if (!destination_addr.ok()) { if (!destination_addr.ok()) {
gpr_log(GPR_DEBUG, "Could not parse \"%s\" as socket address: %s", VLOG(2) << "Could not parse \"" << host
host.c_str(), destination_addr.status().ToString().c_str()); << "\" as socket address: " << destination_addr.status();
return nullptr; return nullptr;
} }
const XdsListenerResource::FilterChainMap::DestinationIp* best_match = 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, grpc_core::GrpcXdsClient::kServerKey, channel_args,
"XdsServerConfigFetcher"); "XdsServerConfigFetcher");
if (!xds_client.ok()) { if (!xds_client.ok()) {
gpr_log(GPR_ERROR, "Failed to create xds client: %s", LOG(ERROR) << "Failed to create xds client: " << xds_client.status();
xds_client.status().ToString().c_str());
return nullptr; return nullptr;
} }
if (static_cast<const grpc_core::GrpcXdsBootstrap&>( if (static_cast<const grpc_core::GrpcXdsBootstrap&>(
(*xds_client)->bootstrap()) (*xds_client)->bootstrap())
.server_listener_resource_name_template() .server_listener_resource_name_template()
.empty()) { .empty()) {
gpr_log(GPR_ERROR, LOG(ERROR) << "server_listener_resource_name_template not provided in "
"server_listener_resource_name_template not provided in bootstrap " "bootstrap file.";
"file.");
return nullptr; return nullptr;
} }
return new grpc_core::XdsServerConfigFetcher(std::move(*xds_client), return new grpc_core::XdsServerConfigFetcher(std::move(*xds_client),

Loading…
Cancel
Save