Remove stacktrace from connection acquisition attempts in LoadBalancer (neo4j#944)

This is to reduce the noise in the logs on connection acquisition errors. Complete failures are reported separately.

Author: injectives

driver/src/main/java/org/neo4j/driver/internal/cluster/RediscoveryImpl.java

@@ -57,6 +57,9 @@ public class RediscoveryImpl implements Rediscovery
 {
     private static final String NO_ROUTERS_AVAILABLE = "Could not perform discovery for database '%s'. No routing server available.";
     private static final String RECOVERABLE_ROUTING_ERROR = "Failed to update routing table with server '%s'.";
+    private static final String RECOVERABLE_DISCOVERY_ERROR_WITH_SERVER = "Received a recoverable discovery error with server '%s', " +
+                                                                          "will continue discovery with other routing servers if available. " +
+                                                                          "Complete failure is reported separately from this entry.";
 
     private final BoltServerAddress initialRouter;
     private final RoutingSettings settings;
@@ -258,8 +261,9 @@ private ClusterComposition handleRoutingProcedureError( Throwable error, Routing
         // Retriable error happened during discovery.
         DiscoveryException discoveryError = new DiscoveryException( format( RECOVERABLE_ROUTING_ERROR, routerAddress ), error );
         Futures.combineErrors( baseError, discoveryError ); // we record each failure here
-        logger.warn( format( "Received a recoverable discovery error with server '%s', will continue discovery with other routing servers if available.",
-                routerAddress ), discoveryError );
+        String warningMessage = format( RECOVERABLE_DISCOVERY_ERROR_WITH_SERVER, routerAddress );
+        logger.warn( warningMessage );
+        logger.debug( warningMessage, discoveryError );
         routingTable.forget( routerAddress );
         return null;
     }

driver/src/main/java/org/neo4j/driver/internal/cluster/loadbalancing/LoadBalancer.java

@@ -20,6 +20,7 @@
 
 import io.netty.util.concurrent.EventExecutorGroup;
 
+import java.util.ArrayList;
 import java.util.List;
 import java.util.concurrent.CompletableFuture;
 import java.util.concurrent.CompletionStage;
@@ -60,6 +61,11 @@
 public class LoadBalancer implements ConnectionProvider
 {
     private static final String LOAD_BALANCER_LOG_NAME = "LoadBalancer";
+    private static final String CONNECTION_ACQUISITION_COMPLETION_FAILURE_MESSAGE = "Connection acquisition failed for all available addresses.";
+    private static final String CONNECTION_ACQUISITION_COMPLETION_EXCEPTION_MESSAGE =
+            "Failed to obtain connection towards %s server. Known routing table is: %s";
+    private static final String CONNECTION_ACQUISITION_ATTEMPT_FAILURE_MESSAGE =
+            "Failed to obtain a connection towards address %s, will try other addresses if available. Complete failure is reported separately from this entry.";
     private final ConnectionPool connectionPool;
     private final RoutingTableRegistry routingTables;
     private final LoadBalancingStrategy loadBalancingStrategy;
@@ -177,19 +183,23 @@ private CompletionStage<Connection> acquire( AccessMode mode, RoutingTable routi
     {
         AddressSet addresses = addressSet( mode, routingTable );
         CompletableFuture<Connection> result = new CompletableFuture<>();
-        acquire( mode, routingTable, addresses, result );
+        List<Throwable> attemptExceptions = new ArrayList<>();
+        acquire( mode, routingTable, addresses, result, attemptExceptions );
         return result;
     }
 
-    private void acquire( AccessMode mode, RoutingTable routingTable, AddressSet addresses, CompletableFuture<Connection> result )
+    private void acquire( AccessMode mode, RoutingTable routingTable, AddressSet addresses, CompletableFuture<Connection> result,
+                          List<Throwable> attemptErrors )
     {
         BoltServerAddress address = selectAddress( mode, addresses );
 
         if ( address == null )
         {
-            result.completeExceptionally( new SessionExpiredException(
-                    "Failed to obtain connection towards " + mode + " server. " +
-                    "Known routing table is: " + routingTable ) );
+            SessionExpiredException completionError =
+                    new SessionExpiredException( format( CONNECTION_ACQUISITION_COMPLETION_EXCEPTION_MESSAGE, mode, routingTable ) );
+            attemptErrors.forEach( completionError::addSuppressed );
+            log.error( CONNECTION_ACQUISITION_COMPLETION_FAILURE_MESSAGE, completionError );
+            result.completeExceptionally( completionError );
             return;
         }
 
@@ -200,10 +210,12 @@ private void acquire( AccessMode mode, RoutingTable routingTable, AddressSet add
             {
                 if ( error instanceof ServiceUnavailableException )
                 {
-                    SessionExpiredException errorToLog = new SessionExpiredException( format( "Server at %s is no longer available", address ), error );
-                    log.warn( "Failed to obtain a connection towards address " + address, errorToLog );
+                    String attemptMessage = format( CONNECTION_ACQUISITION_ATTEMPT_FAILURE_MESSAGE, address );
+                    log.warn( attemptMessage );
+                    log.debug( attemptMessage, error );
+                    attemptErrors.add( error );
                     routingTable.forget( address );
-                    eventExecutorGroup.next().execute( () -> acquire( mode, routingTable, addresses, result ) );
+                    eventExecutorGroup.next().execute( () -> acquire( mode, routingTable, addresses, result, attemptErrors ) );
                 }
                 else
                 {

driver/src/test/java/org/neo4j/driver/integration/RoutingDriverBoltKitTest.java

@@ -36,7 +36,6 @@
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicInteger;
-import java.util.function.Function;
 
 import org.neo4j.driver.AccessMode;
 import org.neo4j.driver.AuthToken;
@@ -827,7 +826,7 @@ void shouldRetryWriteTransactionUntilSuccessWithWhenLeaderIsRemoved() throws Exc
             assertEquals( 0, writer.exitStatus() );
         }
         verify( logger, times( 3 ) ).warn( startsWith( "Transaction failed and will be retried in" ), any( SessionExpiredException.class ) );
-        verify( logger ).warn( startsWith( "Failed to obtain a connection towards address 127.0.0.1:9004" ), any( SessionExpiredException.class ) );
+        verify( logger ).warn( startsWith( "Failed to obtain a connection towards address 127.0.0.1:9004" ) );
     }
 
     @Test
@@ -861,7 +860,7 @@ void shouldRetryWriteTransactionUntilSuccessWithWhenLeaderIsRemovedV3() throws E
         }
         verify( logger, times( 1 ) ).warn( startsWith( "Transaction failed and will be retried in" ), any( TransientException.class ) );
         verify( logger, times( 2 ) ).warn( startsWith( "Transaction failed and will be retried in" ), any( SessionExpiredException.class ) );
-        verify( logger ).warn( startsWith( "Failed to obtain a connection towards address 127.0.0.1:9004" ), any( SessionExpiredException.class ) );
+        verify( logger ).warn( startsWith( "Failed to obtain a connection towards address 127.0.0.1:9004" ) );
     }
 
     @Test

driver/src/test/java/org/neo4j/driver/internal/cluster/RediscoveryTest.java

@@ -52,7 +52,6 @@
 import static org.junit.jupiter.api.Assertions.assertNotNull;
 import static org.junit.jupiter.api.Assertions.assertThrows;
 import static org.mockito.ArgumentMatchers.any;
-import static org.mockito.ArgumentMatchers.anyString;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.never;
 import static org.mockito.Mockito.startsWith;
@@ -182,9 +181,14 @@ void shouldFailImmediatelyWhenClusterCompositionProviderReturnsFailure()
         ClusterComposition composition = await( rediscovery.lookupClusterComposition( table, pool, empty() ) );
         assertEquals( validComposition, composition );
 
-        ArgumentCaptor<DiscoveryException> argument = ArgumentCaptor.forClass( DiscoveryException.class );
-        verify( logger ).warn( anyString(), argument.capture() );
-        assertThat( argument.getValue().getCause(), equalTo( protocolError ) );
+        ArgumentCaptor<String> warningMessageCaptor = ArgumentCaptor.forClass( String.class );
+        ArgumentCaptor<String> debugMessageCaptor = ArgumentCaptor.forClass( String.class );
+        ArgumentCaptor<DiscoveryException> debugThrowableCaptor = ArgumentCaptor.forClass( DiscoveryException.class );
+        verify( logger ).warn( warningMessageCaptor.capture() );
+        verify( logger ).debug( debugMessageCaptor.capture(), debugThrowableCaptor.capture() );
+        assertNotNull( warningMessageCaptor.getValue() );
+        assertEquals( warningMessageCaptor.getValue(), debugMessageCaptor.getValue() );
+        assertThat( debugThrowableCaptor.getValue().getCause(), equalTo( protocolError ) );
     }
 
     @Test