Skip to content

Commit

Permalink
Improve log assertion in BoltFailuresIT
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
lutovich committed Sep 7, 2017
1 parent 618db39 commit 5269eae
Show file tree
Hide file tree
Showing 2 changed files with 51 additions and 28 deletions.
Expand Up @@ -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;
Expand All @@ -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;
Expand Down Expand Up @@ -601,20 +602,10 @@ public void assertContainsThrowablesMatching( int logSkipCount, Throwable... th
*/
public void assertAtLeastOnce( LogMatcher... expected )
{
Set<LogMatcher> expectedMatchers = new HashSet<>( Arrays.asList( expected ) );
Set<LogMatcher> 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 )
{
Expand All @@ -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()
) );
}
}

Expand All @@ -663,7 +649,7 @@ public void assertContainsLogCallContaining( String partOfMessage )
}
}

boolean containsLogCallContaining( String partOfMessage )
private boolean containsLogCallContaining( String partOfMessage )
{
synchronized ( logCalls )
{
Expand All @@ -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 )
Expand Down
25 changes: 21 additions & 4 deletions integrationtests/src/test/java/org/neo4j/bolt/BoltFailuresIT.java
Expand Up @@ -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;
Expand All @@ -52,13 +53,15 @@
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;
import org.neo4j.test.rule.TestDirectory;

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;
Expand All @@ -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;
Expand Down Expand Up @@ -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 ) ) );
}
Expand Down Expand Up @@ -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 )
Expand Down Expand Up @@ -342,6 +354,11 @@ private static Monitors newMonitorsSpy( ThrowingSessionMonitor sessionMonitor )
return monitors;
}

private static void await( Supplier<Boolean> condition ) throws TimeoutException
{
Predicates.await( condition, PREDICATE_AWAIT_TIMEOUT_SECONDS, SECONDS );
}

private static class BoltKernelExtensionWithWorkerFactory extends BoltKernelExtension
{
final WorkerFactory workerFactory;
Expand Down

0 comments on commit 5269eae

Please sign in to comment.