diff --git a/src/core/ext/filters/client_channel/subchannel.cc b/src/core/ext/filters/client_channel/subchannel.cc index 0fdfbb6c347..373510515d8 100644 --- a/src/core/ext/filters/client_channel/subchannel.cc +++ b/src/core/ext/filters/client_channel/subchannel.cc @@ -317,11 +317,12 @@ class Subchannel::ConnectedSubchannelStateWatcher case GRPC_CHANNEL_TRANSIENT_FAILURE: case GRPC_CHANNEL_SHUTDOWN: { if (!c->disconnected_ && c->connected_subchannel_ != nullptr) { - if (grpc_trace_subchannel.enabled()) { + if (GRPC_TRACE_FLAG_ENABLED(grpc_trace_subchannel)) { gpr_log(GPR_INFO, - "Connected subchannel %p of subchannel %p has gone into " + "subchannel %p %s: Connected subchannel %p has gone into " "%s. Attempting to reconnect.", - c->connected_subchannel_.get(), c, + c, c->key_.ToString().c_str(), + c->connected_subchannel_.get(), ConnectivityStateName(new_state)); } c->connected_subchannel_.reset(); @@ -723,9 +724,9 @@ void Subchannel::ThrottleKeepaliveTime(int new_keepalive_time) { // Only update the value if the new keepalive time is larger. if (new_keepalive_time > keepalive_time_) { keepalive_time_ = new_keepalive_time; - if (grpc_trace_subchannel.enabled()) { - gpr_log(GPR_INFO, "Subchannel=%p: Throttling keepalive time to %d", this, - new_keepalive_time); + if (GRPC_TRACE_FLAG_ENABLED(grpc_trace_subchannel)) { + gpr_log(GPR_INFO, "subchannel %p %s: throttling keepalive time to %d", + this, key_.ToString().c_str(), new_keepalive_time); } const grpc_arg arg_to_add = grpc_channel_arg_integer_create( const_cast(GRPC_ARG_KEEPALIVE_TIME_MS), new_keepalive_time); @@ -886,10 +887,11 @@ void Subchannel::MaybeStartConnectingLocked() { const grpc_millis time_til_next = next_attempt_deadline_ - ExecCtx::Get()->Now(); if (time_til_next <= 0) { - gpr_log(GPR_INFO, "Subchannel %p: Retry immediately", this); + gpr_log(GPR_INFO, "subchannel %p %s: Retry immediately", this, + key_.ToString().c_str()); } else { - gpr_log(GPR_INFO, "Subchannel %p: Retry in %" PRId64 " milliseconds", - this, time_til_next); + gpr_log(GPR_INFO, "subchannel %p %s: Retry in %" PRId64 " milliseconds", + this, key_.ToString().c_str(), time_til_next); } GRPC_CLOSURE_INIT(&on_retry_alarm_, OnRetryAlarm, this, grpc_schedule_on_exec_ctx); @@ -911,7 +913,9 @@ void Subchannel::OnRetryAlarm(void* arg, grpc_error_handle error) { GRPC_ERROR_REF(error); } if (error == GRPC_ERROR_NONE) { - gpr_log(GPR_INFO, "Failed to connect to channel, retrying"); + gpr_log(GPR_INFO, + "subchannel %p %s: failed to connect to channel, retrying", c.get(), + c->key_.ToString().c_str()); c->ContinueConnectingLocked(); // Still connecting, keep ref around. Note that this stolen ref won't // be dropped without first acquiring c->mu_. @@ -944,8 +948,8 @@ void Subchannel::OnConnectingFinished(void* arg, grpc_error_handle error) { c->PublishTransportLocked()) { // Do nothing, transport was published. } else if (!c->disconnected_) { - gpr_log(GPR_INFO, "Connect failed: %s", - grpc_error_std_string(error).c_str()); + gpr_log(GPR_INFO, "subchannel %p %s: connect failed: %s", c.get(), + c->key_.ToString().c_str(), grpc_error_std_string(error).c_str()); c->SetConnectivityStateLocked(GRPC_CHANNEL_TRANSIENT_FAILURE, grpc_error_to_absl_status(error)); } @@ -982,8 +986,9 @@ bool Subchannel::PublishTransportLocked() { reinterpret_cast(&stk)); if (error != GRPC_ERROR_NONE) { grpc_transport_destroy(connecting_result_.transport); - gpr_log(GPR_ERROR, "error initializing subchannel stack: %s", - grpc_error_std_string(error).c_str()); + gpr_log(GPR_ERROR, + "subchannel %p %s: error initializing subchannel stack: %s", this, + key_.ToString().c_str(), grpc_error_std_string(error).c_str()); GRPC_ERROR_UNREF(error); return false; } @@ -998,8 +1003,10 @@ bool Subchannel::PublishTransportLocked() { // Publish. connected_subchannel_.reset( new ConnectedSubchannel(stk, args_, channelz_node_)); - gpr_log(GPR_INFO, "New connected subchannel at %p for subchannel %p", - connected_subchannel_.get(), this); + if (GRPC_TRACE_FLAG_ENABLED(grpc_trace_subchannel)) { + gpr_log(GPR_INFO, "subchannel %p %s: new connected subchannel at %p", this, + key_.ToString().c_str(), connected_subchannel_.get()); + } if (channelz_node_ != nullptr) { channelz_node_->SetChildSocket(std::move(socket)); } diff --git a/src/core/ext/filters/client_channel/subchannel_pool_interface.cc b/src/core/ext/filters/client_channel/subchannel_pool_interface.cc index 61b977dc236..6441129f8e5 100644 --- a/src/core/ext/filters/client_channel/subchannel_pool_interface.cc +++ b/src/core/ext/filters/client_channel/subchannel_pool_interface.cc @@ -20,6 +20,7 @@ #include "src/core/ext/filters/client_channel/subchannel_pool_interface.h" +#include "src/core/lib/address_utils/sockaddr_utils.h" #include "src/core/lib/gpr/useful.h" // The subchannel pool to reuse subchannels. @@ -82,6 +83,11 @@ void SubchannelKey::Init( args_ = copy_channel_args(args); } +std::string SubchannelKey::ToString() const { + return absl::StrCat("{address=", grpc_sockaddr_to_uri(&address_), + ", args=", grpc_channel_args_string(args_), "}"); +} + namespace { void* arg_copy(void* p) { diff --git a/src/core/ext/filters/client_channel/subchannel_pool_interface.h b/src/core/ext/filters/client_channel/subchannel_pool_interface.h index 7042f15574d..515104db86b 100644 --- a/src/core/ext/filters/client_channel/subchannel_pool_interface.h +++ b/src/core/ext/filters/client_channel/subchannel_pool_interface.h @@ -52,6 +52,9 @@ class SubchannelKey { const grpc_resolved_address& address() const { return address_; } const grpc_channel_args* args() const { return args_; } + // Human-readable string suitable for logging. + std::string ToString() const; + private: // Initializes the subchannel key with the given \a args and the function to // copy channel args.