From de93c6aa8704cdd08016ee768e52c25ed4081bcd Mon Sep 17 00:00:00 2001 From: Spencer Fang Date: Wed, 13 Sep 2017 19:46:20 -0700 Subject: [PATCH 1/3] context: log at SEVERE if context length > 200 --- context/src/main/java/io/grpc/Context.java | 32 +++++++++++++++-- .../src/test/java/io/grpc/ContextTest.java | 34 +++++++++++++++++++ 2 files changed, 64 insertions(+), 2 deletions(-) diff --git a/context/src/main/java/io/grpc/Context.java b/context/src/main/java/io/grpc/Context.java index 806c5a3ee24..37a92215f6a 100644 --- a/context/src/main/java/io/grpc/Context.java +++ b/context/src/main/java/io/grpc/Context.java @@ -99,6 +99,12 @@ public class Context { private static final PersistentHashArrayMappedTrie, Object> EMPTY_ENTRIES = new PersistentHashArrayMappedTrie, Object>(); + // Long chains of contexts are suspicious and usually indicate a misuse of Context. + // The threshold and interval are arbitrarily chosen. + // VisibleForTesting + static final int CONTEXT_DEPTH_WARN_THRESH = 200; + private static final int CONTEXT_WARN_INTERVAL = 20; + /** * 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 +187,17 @@ public static Context current() { private CancellationListener parentListener = new ParentListener(); final CancellableContext cancellableAncestor; final PersistentHashArrayMappedTrie, 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, Object> keyValueEntries) { + private Context(PersistentHashArrayMappedTrie, Object> keyValueEntries, int generation) { cancellableAncestor = null; this.keyValueEntries = keyValueEntries; + this.generation = generation; + validateGeneration(generation); } /** @@ -197,6 +207,8 @@ private Context(PersistentHashArrayMappedTrie, Object> keyValueEntries) { private Context(Context parent, PersistentHashArrayMappedTrie, Object> keyValueEntries) { cancellableAncestor = cancellableAncestor(parent); this.keyValueEntries = keyValueEntries; + this.generation = parent == null ? 1 : parent.generation + 1; + validateGeneration(generation); } /** @@ -337,7 +349,7 @@ public Context withValues(Key k1, V1 v1, Key k2, V2 v2, * cancellation. */ public Context fork() { - return new Context(keyValueEntries); + return new Context(keyValueEntries, generation + 1); } boolean canBeCancelled() { @@ -993,4 +1005,20 @@ static CancellableContext cancellableAncestor(Context parent) { // 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 + && (generation - CONTEXT_DEPTH_WARN_THRESH) % CONTEXT_WARN_INTERVAL == 0) { + log.log( + Level.SEVERE, + String.format("Context ancestry chain length is abnormally long. " + + "This suggests an error in application code. " + + "length=%s", generation), + new Exception()); + } + } } diff --git a/context/src/test/java/io/grpc/ContextTest.java b/context/src/test/java/io/grpc/ContextTest.java index 7e703f398e1..43fc949ec67 100644 --- a/context/src/test/java/io/grpc/ContextTest.java +++ b/context/src/test/java/io/grpc/ContextTest.java @@ -922,6 +922,40 @@ public void cancellableAncestorFork() { assertNull(fork.cancellableAncestor); } + @Test + public void errorWhenAncestryLengthLong() { + final AtomicReference logRef = new AtomicReference(); + 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 - 1; 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 From 23cf5b7c7910d9ac1e3b925a3e3e56f1b1df59dc Mon Sep 17 00:00:00 2001 From: Spencer Fang Date: Wed, 13 Sep 2017 19:59:36 -0700 Subject: [PATCH 2/3] count from 0 for more natural test --- context/src/main/java/io/grpc/Context.java | 2 +- context/src/test/java/io/grpc/ContextTest.java | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/context/src/main/java/io/grpc/Context.java b/context/src/main/java/io/grpc/Context.java index 37a92215f6a..d6eee426005 100644 --- a/context/src/main/java/io/grpc/Context.java +++ b/context/src/main/java/io/grpc/Context.java @@ -207,7 +207,7 @@ private Context(PersistentHashArrayMappedTrie, Object> keyValueEntries, i private Context(Context parent, PersistentHashArrayMappedTrie, Object> keyValueEntries) { cancellableAncestor = cancellableAncestor(parent); this.keyValueEntries = keyValueEntries; - this.generation = parent == null ? 1 : parent.generation + 1; + this.generation = parent == null ? 0 : parent.generation + 1; validateGeneration(generation); } diff --git a/context/src/test/java/io/grpc/ContextTest.java b/context/src/test/java/io/grpc/ContextTest.java index 43fc949ec67..b6ae7d38bbe 100644 --- a/context/src/test/java/io/grpc/ContextTest.java +++ b/context/src/test/java/io/grpc/ContextTest.java @@ -943,7 +943,7 @@ public void close() throws SecurityException { try { logger.addHandler(handler); Context ctx = Context.current(); - for (int i = 0; i < Context.CONTEXT_DEPTH_WARN_THRESH - 1; i++) { + for (int i = 0; i < Context.CONTEXT_DEPTH_WARN_THRESH ; i++) { assertNull(logRef.get()); ctx = ctx.fork(); } From b084f8b172da9b66a671641abd1156aa6ddee7a2 Mon Sep 17 00:00:00 2001 From: Spencer Fang Date: Thu, 14 Sep 2017 09:18:01 -0700 Subject: [PATCH 3/3] bump threshold to 1000, remove interval --- context/src/main/java/io/grpc/Context.java | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/context/src/main/java/io/grpc/Context.java b/context/src/main/java/io/grpc/Context.java index d6eee426005..910233fae7c 100644 --- a/context/src/main/java/io/grpc/Context.java +++ b/context/src/main/java/io/grpc/Context.java @@ -100,10 +100,9 @@ public class Context { new PersistentHashArrayMappedTrie, Object>(); // Long chains of contexts are suspicious and usually indicate a misuse of Context. - // The threshold and interval are arbitrarily chosen. + // The threshold is arbitrarily chosen. // VisibleForTesting - static final int CONTEXT_DEPTH_WARN_THRESH = 200; - private static final int CONTEXT_WARN_INTERVAL = 20; + static final int CONTEXT_DEPTH_WARN_THRESH = 1000; /** * The logical root context which is the ultimate ancestor of all contexts. This context @@ -1011,13 +1010,12 @@ static CancellableContext cancellableAncestor(Context parent) { * the stack trace. */ private static void validateGeneration(int generation) { - if (generation >= CONTEXT_DEPTH_WARN_THRESH - && (generation - CONTEXT_DEPTH_WARN_THRESH) % CONTEXT_WARN_INTERVAL == 0) { + if (generation == CONTEXT_DEPTH_WARN_THRESH) { log.log( Level.SEVERE, - String.format("Context ancestry chain length is abnormally long. " + "Context ancestry chain length is abnormally long. " + "This suggests an error in application code. " - + "length=%s", generation), + + "Length exceeded: " + CONTEXT_DEPTH_WARN_THRESH, new Exception()); } }