diff options
| -rw-r--r-- | doc/environment_variables.md | 1 | ||||
| -rw-r--r-- | src/core/ext/filters/client_channel/http_connect_handshaker.cc | 2 | ||||
| -rw-r--r-- | src/core/lib/channel/channel_args.cc | 27 | ||||
| -rw-r--r-- | src/core/lib/channel/channel_args.h | 4 | ||||
| -rw-r--r-- | src/core/lib/channel/handshaker.cc | 44 | ||||
| -rw-r--r-- | src/core/lib/channel/handshaker.h | 4 | ||||
| -rw-r--r-- | src/core/lib/security/transport/security_handshaker.cc | 4 | ||||
| -rw-r--r-- | test/core/handshake/readahead_handshaker_server_ssl.cc | 2 |
8 files changed, 84 insertions, 4 deletions
diff --git a/doc/environment_variables.md b/doc/environment_variables.md index ed46a48e5e..587ab83ebd 100644 --- a/doc/environment_variables.md +++ b/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 diff --git a/src/core/ext/filters/client_channel/http_connect_handshaker.cc b/src/core/ext/filters/client_channel/http_connect_handshaker.cc index fb29fa788d..4e8b8b71db 100644 --- a/src/core/ext/filters/client_channel/http_connect_handshaker.cc +++ b/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 = 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 diff --git a/src/core/lib/security/transport/security_handshaker.cc b/src/core/lib/security/transport/security_handshaker.cc index 0c97dfa6b3..57dd3406bc 100644 --- a/src/core/lib/security/transport/security_handshaker.cc +++ b/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))); diff --git a/test/core/handshake/readahead_handshaker_server_ssl.cc b/test/core/handshake/readahead_handshaker_server_ssl.cc index 9788320e0d..97e9c20ee4 100644 --- a/test/core/handshake/readahead_handshaker_server_ssl.cc +++ b/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 = |