Add tracer for plugin credentials.

grpc · markdroth · Sep 29, 2017 · Sep 1, 2017 · Sep 1, 2017 · Sep 5, 2017
commit 1a8bb821f4e978bc94f3cc4f87a8653d9de284e5
diff --git a/doc/environment_variables.md b/doc/environment_variables.md
@@ -58,6 +58,7 @@ some configuration as environment variables that can be set.
     completion queue
   - round_robin - traces the round_robin load balancing policy
   - pick_first - traces the pick first load balancing policy
+  - plugin_credentials - traces plugin credentials
   - resource_quota - trace resource quota objects internals
   - glb - traces the grpclb load balancer
   - queue_pluck

diff --git a/src/core/lib/security/credentials/plugin/plugin_credentials.c b/src/core/lib/security/credentials/plugin/plugin_credentials.c
@@ -31,6 +31,9 @@
 #include "src/core/lib/surface/api_trace.h"
 #include "src/core/lib/surface/validate_metadata.h"
 
+grpc_tracer_flag grpc_plugin_credentials_trace =
+    GRPC_TRACER_INITIALIZER(false, "plugin_credentials");
+
 static void plugin_destruct(grpc_exec_ctx *exec_ctx,
                             grpc_call_credentials *creds) {
   grpc_plugin_credentials *c = (grpc_plugin_credentials *)creds;
@@ -120,13 +123,24 @@ static void plugin_md_request_metadata_ready(void *request,
       NULL, NULL);
   grpc_plugin_credentials_pending_request *r =
       (grpc_plugin_credentials_pending_request *)request;
+  if (GRPC_TRACER_ON(grpc_plugin_credentials_trace)) {
+    gpr_log(GPR_INFO,
+            "plugin_credentials[%p]: request %p: plugin returned "
+            "asynchronously",
+            r->creds, r);
+  }
   // Remove request from pending list if not previously cancelled.
   pending_request_complete(&exec_ctx, r);
   // If it has not been cancelled, process it.
   if (!r->cancelled) {
     grpc_error *error =
         process_plugin_result(&exec_ctx, r, md, num_md, status, error_details);
     GRPC_CLOSURE_SCHED(&exec_ctx, r->on_request_metadata, error);
+  } else if (GRPC_TRACER_ON(grpc_plugin_credentials_trace)) {
+    gpr_log(GPR_INFO,
+            "plugin_credentials[%p]: request %p: plugin was previously "
+            "cancelled",
+            r->creds, r);
   }
   gpr_free(r);
   grpc_exec_ctx_finish(&exec_ctx);
@@ -158,6 +172,10 @@ static bool plugin_get_request_metadata(grpc_exec_ctx *exec_ctx,
     c->pending_requests = pending_request;
     gpr_mu_unlock(&c->mu);
     // Invoke the plugin.  The callback holds a ref to us.
+    if (GRPC_TRACER_ON(grpc_plugin_credentials_trace)) {
+      gpr_log(GPR_INFO, "plugin_credentials[%p]: request %p: invoking plugin",
+              c, pending_request);
+    }
     grpc_call_credentials_ref(creds);
     grpc_metadata creds_md[GRPC_METADATA_CREDENTIALS_PLUGIN_SYNC_MAX];
     size_t num_creds_md = 0;
@@ -167,6 +185,12 @@ static bool plugin_get_request_metadata(grpc_exec_ctx *exec_ctx,
                                 plugin_md_request_metadata_ready,
                                 pending_request, creds_md, &num_creds_md,
                                 &status, &error_details)) {
+      if (GRPC_TRACER_ON(grpc_plugin_credentials_trace)) {
+        gpr_log(GPR_INFO,
+                "plugin_credentials[%p]: request %p: plugin will return "
+                "asynchronously",
+                c, pending_request);
+      }
       return false;  // Asynchronous return.
     }
     // Returned synchronously.
@@ -176,8 +200,20 @@ static bool plugin_get_request_metadata(grpc_exec_ctx *exec_ctx,
     // asynchronously by plugin_cancel_get_request_metadata(), so return
     // false.  Otherwise, process the result.
     if (pending_request->cancelled) {
+      if (GRPC_TRACER_ON(grpc_plugin_credentials_trace)) {
+        gpr_log(GPR_INFO,
+                "plugin_credentials[%p]: request %p was cancelled, error "
+                "will be returned asynchronously",
+                c, pending_request);
+      }
       retval = false;
     } else {
+      if (GRPC_TRACER_ON(grpc_plugin_credentials_trace)) {
+        gpr_log(GPR_INFO,
+                "plugin_credentials[%p]: request %p: plugin returned "
+                "synchronously",
+                c, pending_request);
+      }
       *error = process_plugin_result(exec_ctx, pending_request, creds_md,
                                      num_creds_md, status, error_details);
     }
@@ -201,6 +237,10 @@ static void plugin_cancel_get_request_metadata(
            c->pending_requests;
        pending_request != NULL; pending_request = pending_request->next) {
     if (pending_request->md_array == md_array) {
+      if (GRPC_TRACER_ON(grpc_plugin_credentials_trace)) {
+        gpr_log(GPR_INFO, "plugin_credentials[%p]: cancelling request %p", c,
+                pending_request);
+      }
       pending_request->cancelled = true;
       GRPC_CLOSURE_SCHED(exec_ctx, pending_request->on_request_metadata,
                          GRPC_ERROR_REF(error));

diff --git a/src/core/lib/security/credentials/plugin/plugin_credentials.h b/src/core/lib/security/credentials/plugin/plugin_credentials.h
@@ -21,6 +21,8 @@
 
 #include "src/core/lib/security/credentials/credentials.h"
 
+extern grpc_tracer_flag grpc_plugin_credentials_trace;
+
 struct grpc_plugin_credentials;
 
 typedef struct grpc_plugin_credentials_pending_request {

diff --git a/src/core/lib/surface/init_secure.c b/src/core/lib/surface/init_secure.c
@@ -25,6 +25,7 @@
 
 #include "src/core/lib/debug/trace.h"
 #include "src/core/lib/security/credentials/credentials.h"
+#include "src/core/lib/security/credentials/plugin/plugin_credentials.h"
 #include "src/core/lib/security/transport/auth_filters.h"
 #include "src/core/lib/security/transport/secure_endpoint.h"
 #include "src/core/lib/security/transport/security_connector.h"
@@ -84,4 +85,7 @@ void grpc_register_security_filters(void) {
                                    maybe_prepend_server_auth_filter, NULL);
 }
 
-void grpc_security_init() { grpc_security_register_handshaker_factories(); }
+void grpc_security_init() {
+  grpc_security_register_handshaker_factories();
+  grpc_register_tracer(&grpc_plugin_credentials_trace);
+}