Fix LongGCDisruption to be aware of log4j2 #20348

bleskes · 2016-09-06T20:17:16Z

LongGCDisruption simulates a Long GC by suspending all threads belonging to a node. That's fine, unless those threads hold shared locks that can prevent other nodes from running. Concretely the logging infrastructure, which is shared between the nodes, can cause some deadlocks. LongGCDisruption has protection for this, but it needs to be updated to point at log4j2 classes, introduced in #20235

This commit also fixes improper handling of retry logic in LongGCDisruption and adds a protection against deadlocking the test code which activates the disruption (and uses logging too! :)).

On top of that we have some new, evil and nasty tests.

LongGCDisruption simulates a Long GC by suspending all threads belonging to a node. That's fine, unless those threads hold shared locks that can prevent other nodes from running. Concretely the logging infrastructure, which is shared between the nodes, can cause some deadlocks. LongGCDisruption has protection for this, but it needs to be updated to point at log4j2 classes, introduced in elastic#20235 This commit also fixes improper handling of retry logic in LongGCDisruption and adds a protection against deadlocking the test code which activates the disruption (and uses logging too! :)). On top of that we have some new, evil and nasty tests.

bleskes · 2016-09-06T20:17:42Z

@jasontedor all yours :)

jasontedor · 2016-09-08T02:03:16Z

retest this please

jasontedor · 2016-09-08T02:04:07Z

test/framework/src/main/java/org/elasticsearch/test/disruption/LongGCDisruption.java

+            try {
+                suspendedThreads = ConcurrentHashMap.newKeySet();
+
+                final String currentThreadNamme = Thread.currentThread().getName();


Nit: currentThreadNamme -> currentThreadName

jasontedor

Thanks @bleskes. I left some comments.

jasontedor · 2016-09-14T18:22:44Z

test/framework/src/main/java/org/elasticsearch/test/disruption/LongGCDisruption.java

@@ -35,7 +37,7 @@

    private static final Pattern[] unsafeClasses = new Pattern[]{
            // logging has shared JVM locks - we may suspend a thread and block other nodes from doing their thing


Nit: the indentation of this comment is off.

jasontedor · 2016-09-14T18:25:07Z

test/framework/src/main/java/org/elasticsearch/test/disruption/LongGCDisruption.java

@@ -77,6 +132,14 @@ public TimeValue expectedTimeToHeal() {

    @SuppressWarnings("deprecation") // stops/resumes threads intentionally
    @SuppressForbidden(reason = "stops/resumes threads intentionally")
+    /**


I think that this Javadoc comment is misplaced, I think that it has to be above the annotations to be considered a Javadoc.

jasontedor · 2016-09-14T18:36:48Z

test/framework/src/main/java/org/elasticsearch/test/disruption/LongGCDisruption.java

        } else {
            throw new IllegalStateException("can't disrupt twice, call stopDisrupting() first");
        }
    }

+    private String stackTrace(Thread thread) {
+        String result = "";


How about return Arrays.stream(thread.currentThread().getStackTrace()).map(Object::toString).collect(Collectors.joining("\n")); since StackTraceElement#toString includes all the information that you're including, with some smarts for handling things like line numbers that do not exist, etc.?

thx! changed

jasontedor · 2016-09-14T18:42:01Z

test/framework/src/main/java/org/elasticsearch/test/disruption/LongGCDisruption.java

+                try {
+                    stoppingThread.join(getStoppingTimeoutInMillis());
+                } catch (InterruptedException e) {
+                    Thread.currentThread().interrupt();


Why are we still marching on after being interrupted?

changed to throw an exception and stop the underlying thread

jasontedor · 2016-09-14T18:43:52Z

test/framework/src/main/java/org/elasticsearch/test/disruption/LongGCDisruption.java

+                if (success == false) {
+                    // resume threads if failed
+                    resumeThreads(suspendedThreads);
+                    suspendedThreads = null;


Do we also need to indicate higher up that the disruption failed to be applied?

if we're here, it's because an exception was thrown, so I think we're good?

Oh, silly me. 😄

jasontedor · 2016-09-14T20:22:35Z

test/framework/src/main/java/org/elasticsearch/test/disruption/LongGCDisruptionTest.java

+        final CountDownLatch underLock = new CountDownLatch(1);
+        final CountDownLatch pauseUnderLock = new CountDownLatch(1);
+        final LockedExecutor lockedExecutor = new LockedExecutor();
+        final AtomicLong ops = new AtomicLong();


I do not see the point of this variable, it's incremented but otherwise never read?

I wanted to give the thread something to do

jasontedor · 2016-09-14T20:25:11Z

test/framework/src/main/java/org/elasticsearch/test/disruption/LongGCDisruption.java

+                if (stoppingThread.isAlive()) {
+                    logger.warn("failed to stop node [{}]'s threads within [{}] millis. Stopping thread stack trace:\n {}"
+                        , disruptedNode, getStoppingTimeoutInMillis(), stackTrace(stoppingThread));
+                    stoppingThread.interrupt(); // best effort;


I don't see where the interrupt flag is ever checked on the stopping thread, what am I missing?

nothing :) I added a check

jasontedor · 2016-09-14T20:29:48Z

test/framework/src/main/java/org/elasticsearch/test/disruption/LongGCDisruptionTest.java

+            @Override
+            protected Pattern[] getUnsafeClasses() {
+                return new Pattern[]{
+                    Pattern.compile("LockedExecutor")


"LockedExecutor" -> LockedExecutor.class.getSimpleName()?

jasontedor · 2016-09-14T20:30:10Z

test/framework/src/main/java/org/elasticsearch/test/disruption/LongGCDisruptionTest.java

+            @Override
+            protected Pattern[] getUnsafeClasses() {
+                return new Pattern[]{
+                    Pattern.compile("LockedExecutor")


"LockedExecutor" -> LockedExecutor.class.getSimpleName()?

jasontedor · 2016-09-14T20:38:31Z

test/framework/src/main/java/org/elasticsearch/test/disruption/LongGCDisruptionTest.java

+        }
+    }
+
+    public void testNotBlockingUnsafeStackTraces() throws Exception {


I think this test could use some comments explaining what is happening here, it's quite tricky. 😄

bleskes · 2016-09-14T22:42:14Z

Thx @jasontedor I addressed all points

jasontedor

LGTM

jasontedor · 2016-09-15T02:18:06Z

retest this please

bleskes · 2016-09-15T06:51:21Z

Thx @jasontedor

LongGCDisruption simulates a Long GC by suspending all threads belonging to a node. That's fine, unless those threads hold shared locks that can prevent other nodes from running. Concretely the logging infrastructure, which is shared between the nodes, can cause some deadlocks. LongGCDisruption has protection for this, but it needs to be updated to point at log4j2 classes, introduced in #20235 This commit also fixes improper handling of retry logic in LongGCDisruption and adds a protection against deadlocking the test code which activates the disruption (and uses logging too! :)). On top of that we have some new, evil and nasty tests.

bleskes added >bug >test Issues or PRs that are addressing/adding tests v5.0.0-beta1 labels Sep 6, 2016

bleskes changed the title ~~Fix LongGCDisruption to be aware of log4j~~ Fix LongGCDisruption to be aware of log4j2 Sep 6, 2016

tweaks

b546a62

clintongormley removed the >bug label Sep 7, 2016

jasontedor reviewed Sep 8, 2016
View reviewed changes

typo

d105b2c

bleskes mentioned this pull request Sep 8, 2016

Add current cluster state version to zen pings and use them in master election #20384

Merged

jasontedor self-assigned this Sep 14, 2016

clintongormley removed the v5.0.0-beta1 label Sep 14, 2016

jasontedor reviewed Sep 14, 2016

View reviewed changes

bleskes added 2 commits September 15, 2016 00:25

Merge remote-tracking branch 'upstream/master' into gc_disrupt_log4j

794e7b1

feedback

7f0693f

jasontedor approved these changes Sep 15, 2016

View reviewed changes

bleskes merged commit 8469c98 into elastic:master Sep 15, 2016

bleskes deleted the gc_disrupt_log4j branch September 15, 2016 06:50

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix LongGCDisruption to be aware of log4j2 #20348

Fix LongGCDisruption to be aware of log4j2 #20348

bleskes commented Sep 6, 2016

bleskes commented Sep 6, 2016

jasontedor commented Sep 8, 2016

jasontedor Sep 8, 2016

jasontedor left a comment

jasontedor Sep 14, 2016

bleskes Sep 14, 2016

jasontedor Sep 14, 2016

bleskes Sep 14, 2016

jasontedor Sep 14, 2016 •

edited

Loading

bleskes Sep 14, 2016

jasontedor Sep 14, 2016

bleskes Sep 14, 2016

jasontedor Sep 14, 2016

bleskes Sep 14, 2016

jasontedor Sep 15, 2016

jasontedor Sep 14, 2016

bleskes Sep 14, 2016

jasontedor Sep 14, 2016

bleskes Sep 14, 2016

jasontedor Sep 14, 2016 •

edited

Loading

jasontedor Sep 14, 2016

bleskes Sep 14, 2016

jasontedor Sep 14, 2016

bleskes Sep 14, 2016

bleskes commented Sep 14, 2016

jasontedor left a comment

jasontedor commented Sep 15, 2016

bleskes commented Sep 15, 2016

		@@ -35,7 +37,7 @@

		private static final Pattern[] unsafeClasses = new Pattern[]{
		// logging has shared JVM locks - we may suspend a thread and block other nodes from doing their thing

Fix LongGCDisruption to be aware of log4j2 #20348

Fix LongGCDisruption to be aware of log4j2 #20348

Conversation

bleskes commented Sep 6, 2016

bleskes commented Sep 6, 2016

jasontedor commented Sep 8, 2016

Choose a reason for hiding this comment

jasontedor left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jasontedor Sep 14, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jasontedor Sep 14, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bleskes commented Sep 14, 2016

jasontedor left a comment

Choose a reason for hiding this comment

jasontedor commented Sep 15, 2016

bleskes commented Sep 15, 2016

jasontedor Sep 14, 2016 •

edited

Loading

jasontedor Sep 14, 2016 •

edited

Loading