4 files changed, 79 insertions, 0 deletions

diff --git a/src/core/lib/channel/channel_args.cc b/src/core/lib/channel/channel_args.cc
index 66a86c2286..2c93117dfc 100644
--- a/src/core/lib/channel/channel_args.cc
+++ b/src/core/lib/channel/channel_args.cc
@@ -411,3 +411,30 @@ grpc_arg grpc_channel_arg_pointer_create(
   arg.value.pointer.vtable = vtable;
   return arg;
 }
+
+char* grpc_channel_args_string(const grpc_channel_args* args) {
+  gpr_strvec v;
+  gpr_strvec_init(&v);
+  for (size_t i = 0; i < args->num_args; ++i) {
+    const grpc_arg& arg = args->args[i];
+    char* s;
+    switch (arg.type) {
+      case GRPC_ARG_INTEGER:
+        gpr_asprintf(&s, "%s=%d", arg.key, arg.value.integer);
+        break;
+      case GRPC_ARG_STRING:
+        gpr_asprintf(&s, "%s=%s", arg.key, arg.value.string);
+        break;
+      case GRPC_ARG_POINTER:
+        gpr_asprintf(&s, "%s=%p", arg.key, arg.value.pointer.p);
+        break;
+      default:
+        gpr_asprintf(&s, "arg with unknown type");
+    }
+    gpr_strvec_add(&v, s);
+  }
+  char* result =
+      gpr_strjoin_sep(const_cast<const char**>(v.strs), v.count, ", ", nullptr);
+  gpr_strvec_destroy(&v);
+  return result;
+}
diff --git a/src/core/lib/channel/channel_args.h b/src/core/lib/channel/channel_args.h
index c0d6a17356..5ff303a9dc 100644
--- a/src/core/lib/channel/channel_args.h
+++ b/src/core/lib/channel/channel_args.h
@@ -124,4 +124,8 @@ grpc_arg grpc_channel_arg_integer_create(char* name, int value);
 grpc_arg grpc_channel_arg_pointer_create(char* name, void* value,
                                          const grpc_arg_pointer_vtable* vtable);
 
+// Returns a string representing channel args in human-readable form.
+// Callers takes ownership of result.
+char* grpc_channel_args_string(const grpc_channel_args* args);
+
 #endif /* GRPC_CORE_LIB_CHANNEL_CHANNEL_ARGS_H */
diff --git a/src/core/lib/channel/handshaker.cc b/src/core/lib/channel/handshaker.cc
index 9b1af8d6cb..00cca9a518 100644
--- a/src/core/lib/channel/handshaker.cc
+++ b/src/core/lib/channel/handshaker.cc
@@ -22,11 +22,15 @@
 
 #include <grpc/support/alloc.h>
 #include <grpc/support/log.h>
+#include <grpc/support/string_util.h>
 
 #include "src/core/lib/channel/channel_args.h"
 #include "src/core/lib/channel/handshaker.h"
+#include "src/core/lib/debug/trace.h"
 #include "src/core/lib/iomgr/timer.h"
 
+grpc_core::TraceFlag grpc_handshaker_trace(false, "handshaker");
+
 //
 // grpc_handshaker
 //
@@ -52,6 +56,10 @@ void grpc_handshaker_do_handshake(grpc_handshaker* handshaker,
                                    args);
 }
 
+const char* grpc_handshaker_name(grpc_handshaker* handshaker) {
+  return handshaker->vtable->name;
+}
+
 //
 // grpc_handshake_manager
 //
@@ -127,6 +135,12 @@ static bool is_power_of_2(size_t n) { return (n & (n - 1)) == 0; }
 
 void grpc_handshake_manager_add(grpc_handshake_manager* mgr,
                                 grpc_handshaker* handshaker) {
+  if (grpc_handshaker_trace.enabled()) {
+    gpr_log(
+        GPR_DEBUG,
+        "handshake_manager %p: adding handshaker %s [%p] at index %" PRIuPTR,
+        mgr, grpc_handshaker_name(handshaker), handshaker, mgr->count);
+  }
   gpr_mu_lock(&mgr->mu);
   // To avoid allocating memory for each handshaker we add, we double
   // the number of elements every time we need more.
@@ -172,23 +186,53 @@ void grpc_handshake_manager_shutdown(grpc_handshake_manager* mgr,
   GRPC_ERROR_UNREF(why);
 }
 
+static char* handshaker_args_string(grpc_handshaker_args* args) {
+  char* args_str = grpc_channel_args_string(args->args);
+  char* str;
+  gpr_asprintf(&str,
+               "{endpoint=%p, args=%p {size=%" PRIuPTR
+               ": %s}, read_buffer=%p (length=%" PRIuPTR "), exit_early=%d}",
+               args->endpoint, args->args, args->args->num_args, args_str,
+               args->read_buffer, args->read_buffer->length, args->exit_early);
+  gpr_free(args_str);
+  return str;
+}
+
 // Helper function to call either the next handshaker or the
 // on_handshake_done callback.
 // Returns true if we've scheduled the on_handshake_done callback.
 static bool call_next_handshaker_locked(grpc_handshake_manager* mgr,
                                         grpc_error* error) {
+  if (grpc_handshaker_trace.enabled()) {
+    char* args_str = handshaker_args_string(&mgr->args);
+    gpr_log(GPR_DEBUG,
+            "handshake_manager %p: error=%s shutdown=%d index=%" PRIuPTR
+            ", args=%s",
+            mgr, grpc_error_string(error), mgr->shutdown, mgr->index, args_str);
+    gpr_free(args_str);
+  }
   GPR_ASSERT(mgr->index <= mgr->count);
   // If we got an error or we've been shut down or we're exiting early or
   // we've finished the last handshaker, invoke the on_handshake_done
   // callback.  Otherwise, call the next handshaker.
   if (error != GRPC_ERROR_NONE || mgr->shutdown || mgr->args.exit_early ||
       mgr->index == mgr->count) {
+    if (grpc_handshaker_trace.enabled()) {
+      gpr_log(GPR_DEBUG, "handshake_manager %p: handshaking complete", mgr);
+    }
     // Cancel deadline timer, since we're invoking the on_handshake_done
     // callback now.
     grpc_timer_cancel(&mgr->deadline_timer);
     GRPC_CLOSURE_SCHED(&mgr->on_handshake_done, error);
     mgr->shutdown = true;
   } else {
+    if (grpc_handshaker_trace.enabled()) {
+      gpr_log(
+          GPR_DEBUG,
+          "handshake_manager %p: calling handshaker %s [%p] at index %" PRIuPTR,
+          mgr, grpc_handshaker_name(mgr->handshakers[mgr->index]),
+          mgr->handshakers[mgr->index], mgr->index);
+    }
     grpc_handshaker_do_handshake(mgr->handshakers[mgr->index], mgr->acceptor,
                                  &mgr->call_next_handshaker, &mgr->args);
   }
diff --git a/src/core/lib/channel/handshaker.h b/src/core/lib/channel/handshaker.h
index dfecd81004..be7fd127e4 100644
--- a/src/core/lib/channel/handshaker.h
+++ b/src/core/lib/channel/handshaker.h
@@ -84,6 +84,9 @@ typedef struct {
                        grpc_tcp_server_acceptor* acceptor,
                        grpc_closure* on_handshake_done,
                        grpc_handshaker_args* args);
+
+  /// The name of the handshaker, for debugging purposes.
+  const char* name;
 } grpc_handshaker_vtable;
 
 /// Base struct.  To subclass, make this the first member of the
@@ -102,6 +105,7 @@ void grpc_handshaker_do_handshake(grpc_handshaker* handshaker,
                                   grpc_tcp_server_acceptor* acceptor,
                                   grpc_closure* on_handshake_done,
                                   grpc_handshaker_args* args);
+const char* grpc_handshaker_name(grpc_handshaker* handshaker);
 
 ///
 /// grpc_handshake_manager