Merge pull request grpc#15090 from markdroth/handshaker_trace

Add tracer for handshakers.

doc/environment_variables.md

@@ -50,6 +50,7 @@ some configuration as environment variables that can be set.
   - channel_stack_builder - traces information about channel stacks being built
   - executor - traces grpc's internal thread pool ('the executor')
   - glb - traces the grpclb load balancer
+  - handshaker - traces handshaking state
   - http - traces state in the http2 transport engine
   - http2_stream_state - traces all http2 stream state mutations.
   - http1 - traces HTTP/1.x operations performed by gRPC

src/core/ext/filters/client_channel/http_connect_handshaker.cc

@@ -326,7 +326,7 @@ static void http_connect_handshaker_do_handshake(
 
 static const grpc_handshaker_vtable http_connect_handshaker_vtable = {
     http_connect_handshaker_destroy, http_connect_handshaker_shutdown,
-    http_connect_handshaker_do_handshake};
+    http_connect_handshaker_do_handshake, "http_connect"};
 
 static grpc_handshaker* grpc_http_connect_handshaker_create() {
   http_connect_handshaker* handshaker =

src/core/lib/channel/channel_args.cc

@@ -411,3 +411,31 @@ grpc_arg grpc_channel_arg_pointer_create(
   arg.value.pointer.vtable = vtable;
   return arg;
 }
+
+char* grpc_channel_args_string(const grpc_channel_args* args) {
+  if (args == nullptr) return nullptr;
+  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;
+}

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 */

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,56 @@ 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);
+  size_t num_args = args->args != nullptr ? args->args->num_args : 0;
+  size_t read_buffer_length =
+      args->read_buffer != nullptr ? args->read_buffer->length : 0;
+  char* str;
+  gpr_asprintf(&str,
+               "{endpoint=%p, args=%p {size=%" PRIuPTR
+               ": %s}, read_buffer=%p (length=%" PRIuPTR "), exit_early=%d}",
+               args->endpoint, args->args, num_args, args_str,
+               args->read_buffer, 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);
   }

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

src/core/lib/security/transport/security_handshaker.cc

@@ -406,7 +406,7 @@ static void security_handshaker_do_handshake(grpc_handshaker* handshaker,
 
 static const grpc_handshaker_vtable security_handshaker_vtable = {
     security_handshaker_destroy, security_handshaker_shutdown,
-    security_handshaker_do_handshake};
+    security_handshaker_do_handshake, "security"};
 
 static grpc_handshaker* security_handshaker_create(
     tsi_handshaker* handshaker, grpc_security_connector* connector) {
@@ -456,7 +456,7 @@ static void fail_handshaker_do_handshake(grpc_handshaker* handshaker,
 
 static const grpc_handshaker_vtable fail_handshaker_vtable = {
     fail_handshaker_destroy, fail_handshaker_shutdown,
-    fail_handshaker_do_handshake};
+    fail_handshaker_do_handshake, "security_fail"};
 
 static grpc_handshaker* fail_handshaker_create() {
   grpc_handshaker* h = static_cast<grpc_handshaker*>(gpr_malloc(sizeof(*h)));

test/core/handshake/readahead_handshaker_server_ssl.cc

@@ -64,7 +64,7 @@ static void readahead_handshaker_do_handshake(
 
 const grpc_handshaker_vtable readahead_handshaker_vtable = {
     readahead_handshaker_destroy, readahead_handshaker_shutdown,
-    readahead_handshaker_do_handshake};
+    readahead_handshaker_do_handshake, "read_ahead"};
 
 static grpc_handshaker* readahead_handshaker_create() {
   grpc_handshaker* h =