Repository: brooklyn-server Updated Branches: refs/heads/master 615c63574 -> bfaaa909e
Test framework: avoid repeated stacktrace logging Project: http://git-wip-us.apache.org/repos/asf/brooklyn-server/repo Commit: http://git-wip-us.apache.org/repos/asf/brooklyn-server/commit/816dc56a Tree: http://git-wip-us.apache.org/repos/asf/brooklyn-server/tree/816dc56a Diff: http://git-wip-us.apache.org/repos/asf/brooklyn-server/diff/816dc56a Branch: refs/heads/master Commit: 816dc56a6eec32f426b5d6a758e4b8890d523e3e Parents: b11c87d Author: Aled Sage <aled.s...@gmail.com> Authored: Thu Dec 1 11:39:40 2016 +0000 Committer: Aled Sage <aled.s...@gmail.com> Committed: Thu Dec 1 16:16:19 2016 +0000 ---------------------------------------------------------------------- .../brooklyn/test/framework/TestSensorTest.java | 62 +++++++++++++++++++- .../org/apache/brooklyn/test/LogWatcher.java | 24 +++++++- .../apache/brooklyn/util/repeat/Repeater.java | 9 ++- 3 files changed, 92 insertions(+), 3 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/brooklyn-server/blob/816dc56a/test-framework/src/test/java/org/apache/brooklyn/test/framework/TestSensorTest.java ---------------------------------------------------------------------- diff --git a/test-framework/src/test/java/org/apache/brooklyn/test/framework/TestSensorTest.java b/test-framework/src/test/java/org/apache/brooklyn/test/framework/TestSensorTest.java index d0a5ebc..906b25f 100644 --- a/test-framework/src/test/java/org/apache/brooklyn/test/framework/TestSensorTest.java +++ b/test-framework/src/test/java/org/apache/brooklyn/test/framework/TestSensorTest.java @@ -19,6 +19,9 @@ package org.apache.brooklyn.test.framework; +import static org.testng.Assert.assertEquals; +import static org.testng.Assert.assertTrue; + import java.util.ArrayList; import java.util.List; import java.util.Map; @@ -28,20 +31,25 @@ import java.util.concurrent.Executors; import org.apache.brooklyn.api.entity.Entity; import org.apache.brooklyn.api.entity.EntitySpec; import org.apache.brooklyn.api.location.Location; +import org.apache.brooklyn.api.mgmt.Task; import org.apache.brooklyn.api.sensor.AttributeSensor; import org.apache.brooklyn.core.config.ConfigKeys; import org.apache.brooklyn.core.entity.Attributes; import org.apache.brooklyn.core.entity.Entities; import org.apache.brooklyn.core.entity.EntityAsserts; import org.apache.brooklyn.core.entity.lifecycle.Lifecycle; +import org.apache.brooklyn.core.entity.trait.Startable; import org.apache.brooklyn.core.sensor.AttributeSensorAndConfigKey; import org.apache.brooklyn.core.sensor.Sensors; import org.apache.brooklyn.core.test.BrooklynAppUnitTestSupport; import org.apache.brooklyn.core.test.entity.TestApplication; import org.apache.brooklyn.core.test.entity.TestEntity; import org.apache.brooklyn.test.Asserts; +import org.apache.brooklyn.test.LogWatcher; +import org.apache.brooklyn.test.LogWatcher.EventPredicates; import org.apache.brooklyn.util.exceptions.Exceptions; import org.apache.brooklyn.util.exceptions.PropagatedRuntimeException; +import org.apache.brooklyn.util.repeat.Repeater; import org.apache.brooklyn.util.text.Identifiers; import org.apache.brooklyn.util.time.Duration; import org.apache.brooklyn.util.time.Time; @@ -50,11 +58,14 @@ import org.testng.annotations.AfterMethod; import org.testng.annotations.BeforeMethod; import org.testng.annotations.Test; +import com.google.common.base.Predicate; import com.google.common.base.Predicates; import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableMap; import com.google.common.collect.Iterables; +import ch.qos.logback.classic.spi.ILoggingEvent; + public class TestSensorTest extends BrooklynAppUnitTestSupport { private static final AttributeSensorAndConfigKey<Boolean, Boolean> BOOLEAN_SENSOR = ConfigKeys.newSensorAndConfigKey(Boolean.class, "boolean-sensor", "Boolean Sensor"); @@ -332,6 +343,55 @@ public class TestSensorTest extends BrooklynAppUnitTestSupport { assertStartFails(app, NullPointerException.class, Asserts.DEFAULT_LONG_TIMEOUT); } + @Test + public void testDoesNotLogStacktraceRepeatedly() throws Exception { + final long time = System.currentTimeMillis(); + final String sensorValue = String.format("%s%s%s", Identifiers.makeRandomId(8), time, Identifiers.makeRandomId(8)); + + // Test case will repeatedly fail until we have finished our logging assertions. + // Then we'll let it complete by setting the sensor. + TestSensor testCase = app.createAndManageChild(EntitySpec.create(TestSensor.class) + .configure(TestSensor.TIMEOUT, Asserts.DEFAULT_LONG_TIMEOUT) + .configure(TestSensor.TARGET_ENTITY, app) + .configure(TestSensor.SENSOR_NAME, STRING_SENSOR.getName()) + .configure(TestSensor.ASSERTIONS, newListAssertion("matches", String.format(".*%s.*", time)))); + + String loggerName = Repeater.class.getName(); + ch.qos.logback.classic.Level logLevel = ch.qos.logback.classic.Level.DEBUG; + Predicate<ILoggingEvent> repeatedFailureMsgMatcher = EventPredicates.containsMessage("repeated failure; excluding stacktrace"); + Predicate<ILoggingEvent> stacktraceMatcher = EventPredicates.containsExceptionStackLine(TestFrameworkAssertions.class, "checkActualAgainstAssertions"); + Predicate<ILoggingEvent> filter = Predicates.or(repeatedFailureMsgMatcher, stacktraceMatcher); + LogWatcher watcher = new LogWatcher(loggerName, logLevel, filter); + + watcher.start(); + try { + // Invoke async; will let it complete after we see the log messages we expect + Task<?> task = Entities.invokeEffector(app, app, Startable.START, ImmutableMap.of("locations", locs)); + + // Expect "excluding stacktrace" message at least once + List<ILoggingEvent> repeatedFailureMsgEvents = watcher.assertHasEventEventually(repeatedFailureMsgMatcher); + assertTrue(repeatedFailureMsgEvents.size() > 0, "repeatedFailureMsgEvents="+repeatedFailureMsgEvents.size()); + + // Expect stacktrace just once + List<ILoggingEvent> stacktraceEvents = watcher.assertHasEventEventually(stacktraceMatcher); + assertEquals(Integer.valueOf(stacktraceEvents.size()), Integer.valueOf(1), "stacktraceEvents="+stacktraceEvents.size()); + + //Set STRING sensor + app.sensors().set(STRING_SENSOR, sensorValue); + task.get(Asserts.DEFAULT_LONG_TIMEOUT); + + assertTestSensorSucceeds(testCase); + + // And for good measure (in case we just checked too early last time), check again + // that we didn't get another stacktrace + stacktraceEvents = watcher.getEvents(stacktraceMatcher); + assertEquals(Integer.valueOf(stacktraceEvents.size()), Integer.valueOf(1), "stacktraceEvents="+stacktraceEvents.size()); + + } finally { + watcher.close(); + } + } + protected void assertStartFails(TestApplication app, Class<? extends Throwable> clazz) throws Exception { assertStartFails(app, clazz, null); } @@ -360,7 +420,7 @@ public class TestSensorTest extends BrooklynAppUnitTestSupport { Entity entity = Iterables.find(Entities.descendantsWithoutSelf(app), Predicates.instanceOf(TestSensor.class)); assertTestSensorFails((TestSensor) entity); } - + protected void assertTestSensorSucceeds(TestSensor entity) { EntityAsserts.assertAttributeEqualsEventually(entity, Attributes.SERVICE_STATE_ACTUAL, Lifecycle.RUNNING); EntityAsserts.assertAttributeEqualsEventually(entity, Attributes.SERVICE_UP, true); http://git-wip-us.apache.org/repos/asf/brooklyn-server/blob/816dc56a/test-support/src/main/java/org/apache/brooklyn/test/LogWatcher.java ---------------------------------------------------------------------- diff --git a/test-support/src/main/java/org/apache/brooklyn/test/LogWatcher.java b/test-support/src/main/java/org/apache/brooklyn/test/LogWatcher.java index 6baa852..ba29ad7 100644 --- a/test-support/src/main/java/org/apache/brooklyn/test/LogWatcher.java +++ b/test-support/src/main/java/org/apache/brooklyn/test/LogWatcher.java @@ -26,6 +26,7 @@ import java.io.Closeable; import java.util.Collections; import java.util.List; import java.util.concurrent.atomic.AtomicBoolean; +import java.util.concurrent.atomic.AtomicReference; import org.mockito.Mockito; import org.mockito.invocation.InvocationOnMock; @@ -36,6 +37,7 @@ import org.slf4j.LoggerFactory; import com.google.common.annotations.Beta; import com.google.common.base.Predicate; import com.google.common.collect.ImmutableList; +import com.google.common.collect.Iterables; import com.google.common.collect.Lists; import ch.qos.logback.classic.Level; @@ -134,11 +136,25 @@ public class LogWatcher implements Closeable { assertFalse(events.isEmpty()); } - public void assertHasEventEventually() { + public List<ILoggingEvent> assertHasEventEventually() { Asserts.succeedsEventually(new Runnable() { public void run() { assertFalse(events.isEmpty()); }}); + return getEvents(); + } + + public List<ILoggingEvent> assertHasEventEventually(final Predicate<? super ILoggingEvent> filter) { + final AtomicReference<List<ILoggingEvent>> result = new AtomicReference<>(); + Asserts.succeedsEventually(new Runnable() { + public void run() { + synchronized (events) { + Iterable<ILoggingEvent> filtered = Iterables.filter(events, filter); + assertFalse(Iterables.isEmpty(filtered)); + result.set(ImmutableList.copyOf(filtered)); + } + }}); + return result.get(); } public List<ILoggingEvent> getEvents() { @@ -146,4 +162,10 @@ public class LogWatcher implements Closeable { return ImmutableList.copyOf(events); } } + + public List<ILoggingEvent> getEvents(Predicate<? super ILoggingEvent> filter) { + synchronized (events) { + return ImmutableList.copyOf(Iterables.filter(events, filter)); + } + } } http://git-wip-us.apache.org/repos/asf/brooklyn-server/blob/816dc56a/utils/common/src/main/java/org/apache/brooklyn/util/repeat/Repeater.java ---------------------------------------------------------------------- diff --git a/utils/common/src/main/java/org/apache/brooklyn/util/repeat/Repeater.java b/utils/common/src/main/java/org/apache/brooklyn/util/repeat/Repeater.java index 581a61b..a7fdc42 100644 --- a/utils/common/src/main/java/org/apache/brooklyn/util/repeat/Repeater.java +++ b/utils/common/src/main/java/org/apache/brooklyn/util/repeat/Repeater.java @@ -315,6 +315,7 @@ public class Repeater implements Callable<Boolean> { Preconditions.checkState(exitCondition != null, "until() method has not been called to set the exit condition"); Preconditions.checkState(delayOnIteration != null, "every() method (or other delaySupplier() / backoff() method) has not been called to set the loop delay"); + boolean hasLoggedTransientException = false; Throwable lastError = null; int iterations = 0; CountdownTimer timer = timeLimit!=null ? CountdownTimer.newInstanceStarted(timeLimit) : CountdownTimer.newInstancePaused(Duration.PRACTICALLY_FOREVER); @@ -334,8 +335,14 @@ public class Repeater implements Callable<Boolean> { try { lastError = null; done = exitCondition.call(); + hasLoggedTransientException = false; } catch (Throwable e) { - if (log.isDebugEnabled()) log.debug(description, e); + if (hasLoggedTransientException) { + if (log.isDebugEnabled()) log.debug(description + " (repeated failure; excluding stacktrace): " + e); + } else { + if (log.isDebugEnabled()) log.debug(description, e); + hasLoggedTransientException = true; + } lastError = e; if (rethrowImmediatelyCondition.apply(e)) throw Exceptions.propagate(e); }
