From 86dec11f7bfb8fcd86fc677024c56bb83f633f59 Mon Sep 17 00:00:00 2001
From: zpencer <spencerfang@google.com>
Date: Thu, 14 Sep 2017 11:39:19 -0700
Subject: [PATCH] context: log severe warning if ancestry chain too long
 (#3459)

If a context has an unreasonable number of ancestors, then
chances are this is an application error. Log the stack trace to
notify the user and aid in debugging.
---
 context/src/main/java/io/grpc/Context.java    | 30 ++++++++++++++--
 .../src/test/java/io/grpc/ContextTest.java    | 34 +++++++++++++++++++
 2 files changed, 62 insertions(+), 2 deletions(-)

diff --git a/context/src/main/java/io/grpc/Context.java b/context/src/main/java/io/grpc/Context.java
index 806c5a3ee2..910233fae7 100644
--- a/context/src/main/java/io/grpc/Context.java
+++ b/context/src/main/java/io/grpc/Context.java
@@ -99,6 +99,11 @@ public class Context {
   private static final PersistentHashArrayMappedTrie<Key<?>, Object> EMPTY_ENTRIES =
       new PersistentHashArrayMappedTrie<Key<?>, Object>();
 
+  // Long chains of contexts are suspicious and usually indicate a misuse of Context.
+  // The threshold is arbitrarily chosen.
+  // VisibleForTesting
+  static final int CONTEXT_DEPTH_WARN_THRESH = 1000;
+
   /**
    * The logical root context which is the ultimate ancestor of all contexts. This context
    * is not cancellable and so will not cascade cancellation or retain listeners.
@@ -181,13 +186,17 @@ public class Context {
   private CancellationListener parentListener = new ParentListener();
   final CancellableContext cancellableAncestor;
   final PersistentHashArrayMappedTrie<Key<?>, Object> keyValueEntries;
+  // The number parents between this context and the root context.
+  final int generation;
 
   /**
    * Construct a context that cannot be cancelled and will not cascade cancellation from its parent.
    */
-  private Context(PersistentHashArrayMappedTrie<Key<?>, Object> keyValueEntries) {
+  private Context(PersistentHashArrayMappedTrie<Key<?>, Object> keyValueEntries, int generation) {
     cancellableAncestor = null;
     this.keyValueEntries = keyValueEntries;
+    this.generation = generation;
+    validateGeneration(generation);
   }
 
   /**
@@ -197,6 +206,8 @@ public class Context {
   private Context(Context parent, PersistentHashArrayMappedTrie<Key<?>, Object> keyValueEntries) {
     cancellableAncestor = cancellableAncestor(parent);
     this.keyValueEntries = keyValueEntries;
+    this.generation = parent == null ? 0 : parent.generation + 1;
+    validateGeneration(generation);
   }
 
   /**
@@ -337,7 +348,7 @@ public class Context {
    * cancellation.
    */
   public Context fork() {
-    return new Context(keyValueEntries);
+    return new Context(keyValueEntries, generation + 1);
   }
 
   boolean canBeCancelled() {
@@ -993,4 +1004,19 @@ public class Context {
     // Bypass the parent and reference the ancestor directly (may be null).
     return parent.cancellableAncestor;
   }
+
+  /**
+   * If the ancestry chain length is unreasonably long, then print an error to the log and record
+   * the stack trace.
+   */
+  private static void validateGeneration(int generation) {
+    if (generation == CONTEXT_DEPTH_WARN_THRESH) {
+      log.log(
+          Level.SEVERE,
+          "Context ancestry chain length is abnormally long. "
+              + "This suggests an error in application code. "
+              + "Length exceeded: " + CONTEXT_DEPTH_WARN_THRESH,
+          new Exception());
+    }
+  }
 }
diff --git a/context/src/test/java/io/grpc/ContextTest.java b/context/src/test/java/io/grpc/ContextTest.java
index 7e703f398e..b6ae7d38bb 100644
--- a/context/src/test/java/io/grpc/ContextTest.java
+++ b/context/src/test/java/io/grpc/ContextTest.java
@@ -922,6 +922,40 @@ public class ContextTest {
     assertNull(fork.cancellableAncestor);
   }
 
+  @Test
+  public void errorWhenAncestryLengthLong() {
+    final AtomicReference<LogRecord> logRef = new AtomicReference<LogRecord>();
+    Handler handler = new Handler() {
+      @Override
+      public void publish(LogRecord record) {
+        logRef.set(record);
+      }
+
+      @Override
+      public void flush() {
+      }
+
+      @Override
+      public void close() throws SecurityException {
+      }
+    };
+    Logger logger = Logger.getLogger(Context.class.getName());
+    try {
+      logger.addHandler(handler);
+      Context ctx = Context.current();
+      for (int i = 0; i < Context.CONTEXT_DEPTH_WARN_THRESH ; i++) {
+        assertNull(logRef.get());
+        ctx = ctx.fork();
+      }
+      ctx = ctx.fork();
+      assertNotNull(logRef.get());
+      assertNotNull(logRef.get().getThrown());
+      assertEquals(Level.SEVERE, logRef.get().getLevel());
+    } finally {
+      logger.removeHandler(handler);
+    }
+  }
+
   // UsedReflectively
   public static final class LoadMeWithStaticTestingClassLoader implements Runnable {
     @Override