From 5269eae582cf75adad9ff5d5db4958e5ded04867 Mon Sep 17 00:00:00 2001 From: lutovich Date: Thu, 7 Sep 2017 11:12:25 +0200 Subject: [PATCH] Improve log assertion in BoltFailuresIT Test `boltServerLogsRealErrorWhenDriverIsClosedWithRunningTransactions` was flaky because it did not properly wait for error message. It asserts that particular error message appears in logs after a driver transaction failure. This failure can be observed earlier then error is logged. This commit makes test wait up to 1 minute for the message to appear. --- .../neo4j/logging/AssertableLogProvider.java | 54 ++++++++++--------- .../java/org/neo4j/bolt/BoltFailuresIT.java | 25 +++++++-- 2 files changed, 51 insertions(+), 28 deletions(-) diff --git a/community/logging/src/test/java/org/neo4j/logging/AssertableLogProvider.java b/community/logging/src/test/java/org/neo4j/logging/AssertableLogProvider.java index 8065f4e3f850b..f15ae22519c10 100644 --- a/community/logging/src/test/java/org/neo4j/logging/AssertableLogProvider.java +++ b/community/logging/src/test/java/org/neo4j/logging/AssertableLogProvider.java @@ -28,7 +28,6 @@ import java.io.PrintStream; import java.util.ArrayList; import java.util.Arrays; -import java.util.HashSet; import java.util.IllegalFormatException; import java.util.Iterator; import java.util.List; @@ -38,6 +37,8 @@ import java.util.function.Function; import javax.annotation.Nonnull; +import org.neo4j.helpers.collection.Iterators; + import static java.lang.String.format; import static java.util.Arrays.asList; import static org.apache.commons.lang3.StringEscapeUtils.escapeJava; @@ -601,20 +602,10 @@ public void assertContainsThrowablesMatching( int logSkipCount, Throwable... th */ public void assertAtLeastOnce( LogMatcher... expected ) { - Set expectedMatchers = new HashSet<>( Arrays.asList( expected ) ); + Set expectedMatchers = Iterators.asSet( expected ); synchronized ( logCalls ) { - for ( LogCall logCall : logCalls ) - { - for ( LogMatcher matcher : expectedMatchers ) - { - if ( matcher.matches( logCall ) ) - { - expectedMatchers.remove( matcher ); - break; - } - } - } + expectedMatchers.removeIf( this::containsMatchingLogCall ); if ( expectedMatchers.size() > 0 ) { @@ -629,17 +620,12 @@ public void assertAtLeastOnce( LogMatcher... expected ) public void assertNone( LogMatcher notExpected ) { - synchronized ( logCalls ) + LogCall logCall = firstMatchingLogCall( notExpected ); + if ( logCall != null ) { - for ( LogCall logCall : logCalls ) - { - if ( notExpected.matches( logCall ) ) - { - fail( format( - "Log call was not expected, but occurred:\n%s\n", logCall.toString() - ) ); - } - } + fail( format( + "Log call was not expected, but occurred:\n%s\n", logCall.toString() + ) ); } } @@ -663,7 +649,7 @@ public void assertContainsLogCallContaining( String partOfMessage ) } } - boolean containsLogCallContaining( String partOfMessage ) + private boolean containsLogCallContaining( String partOfMessage ) { synchronized ( logCalls ) { @@ -678,6 +664,26 @@ boolean containsLogCallContaining( String partOfMessage ) return false; } + public boolean containsMatchingLogCall( LogMatcher logMatcher ) + { + return firstMatchingLogCall( logMatcher ) != null; + } + + private LogCall firstMatchingLogCall( LogMatcher logMatcher ) + { + synchronized ( logCalls ) + { + for ( LogCall logCall : logCalls ) + { + if ( logMatcher.matches( logCall ) ) + { + return logCall; + } + } + } + return null; + } + public void assertContainsMessageContaining( String partOfMessage ) { synchronized ( logCalls ) diff --git a/integrationtests/src/test/java/org/neo4j/bolt/BoltFailuresIT.java b/integrationtests/src/test/java/org/neo4j/bolt/BoltFailuresIT.java index 3b09333531f1a..c35fc1a066991 100644 --- a/integrationtests/src/test/java/org/neo4j/bolt/BoltFailuresIT.java +++ b/integrationtests/src/test/java/org/neo4j/bolt/BoltFailuresIT.java @@ -30,6 +30,7 @@ import java.util.concurrent.Future; import java.util.concurrent.TimeoutException; import java.util.function.Consumer; +import java.util.function.Supplier; import org.neo4j.bolt.v1.runtime.BoltFactory; import org.neo4j.bolt.v1.runtime.MonitoredWorkerFactory.SessionMonitor; @@ -52,6 +53,7 @@ import org.neo4j.kernel.impl.logging.LogService; import org.neo4j.kernel.monitoring.Monitors; import org.neo4j.logging.AssertableLogProvider; +import org.neo4j.logging.AssertableLogProvider.LogMatcher; import org.neo4j.logging.LogProvider; import org.neo4j.scheduler.JobScheduler; import org.neo4j.test.TestEnterpriseGraphDatabaseFactory; @@ -59,6 +61,7 @@ import static java.util.concurrent.CompletableFuture.runAsync; import static java.util.concurrent.TimeUnit.MINUTES; +import static java.util.concurrent.TimeUnit.SECONDS; import static org.hamcrest.Matchers.instanceOf; import static org.hamcrest.Matchers.startsWith; import static org.junit.Assert.assertThat; @@ -78,10 +81,13 @@ public class BoltFailuresIT { + private static final int TEST_TIMEOUT_SECONDS = 120; + private static final int PREDICATE_AWAIT_TIMEOUT_SECONDS = TEST_TIMEOUT_SECONDS / 2; + private final TestDirectory dir = TestDirectory.testDirectory(); @Rule - public final RuleChain ruleChain = RuleChain.outerRule( Timeout.seconds( 120 ) ).around( dir ); + public final RuleChain ruleChain = RuleChain.outerRule( Timeout.seconds( TEST_TIMEOUT_SECONDS ) ).around( dir ); private GraphDatabaseService db; private Driver driver; @@ -205,7 +211,7 @@ public void boltServerLogsRealErrorWhenDriverIsClosedWithRunningTransactions() t awaitNumberOfActiveQueriesToBe( 0 ); // verify that closing of the driver resulted in transaction termination on the server and correct log message - internalLogProvider.assertAtLeastOnce( inLog( BoltMessagingProtocolV1Handler.class ).warn( + awaitLogToContainMessage( internalLogProvider, inLog( BoltMessagingProtocolV1Handler.class ).warn( startsWith( "Unable to send error back to the client" ), instanceOf( TransactionTerminatedException.class ) ) ); } @@ -291,11 +297,17 @@ private GraphDatabaseService startDbWithBolt( GraphDatabaseFactory dbFactory ) private void awaitNumberOfActiveQueriesToBe( int value ) throws TimeoutException { - Predicates.await( () -> + await( () -> { Result listQueriesResult = db.execute( "CALL dbms.listQueries()" ); return count( listQueriesResult ) == value + 1; // procedure call itself is also listed - }, 1, MINUTES ); + } ); + } + + private void awaitLogToContainMessage( AssertableLogProvider logProvider, LogMatcher matcher ) + throws TimeoutException + { + await( () -> logProvider.containsMatchingLogCall( matcher ) ); } private Future updateAllNodesAsync( Driver driver ) @@ -342,6 +354,11 @@ private static Monitors newMonitorsSpy( ThrowingSessionMonitor sessionMonitor ) return monitors; } + private static void await( Supplier condition ) throws TimeoutException + { + Predicates.await( condition, PREDICATE_AWAIT_TIMEOUT_SECONDS, SECONDS ); + } + private static class BoltKernelExtensionWithWorkerFactory extends BoltKernelExtension { final WorkerFactory workerFactory;