clean up subchannel logging (#27661)

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<char*>(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<void**>(&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));
   }

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) {

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.