Merge pull request #287 from lutovich/1.1-logging-around-routing-table

nigelsmall · web-flow · commit c6ec3c276d43 · 2016-12-05T15:16:08.000Z
Additional logging around refresh of the routing table
diff --git a/driver/src/main/java/org/neo4j/driver/internal/cluster/ClusterComposition.java b/driver/src/main/java/org/neo4j/driver/internal/cluster/ClusterComposition.java
@@ -19,12 +19,14 @@
 package org.neo4j.driver.internal.cluster;
 
 import java.util.HashSet;
+import java.util.List;
 import java.util.Set;
 
 import org.neo4j.driver.internal.NetworkSession;
 import org.neo4j.driver.internal.net.BoltServerAddress;
 import org.neo4j.driver.internal.spi.Connection;
 import org.neo4j.driver.internal.util.Clock;
+import org.neo4j.driver.v1.Logger;
 import org.neo4j.driver.v1.Record;
 import org.neo4j.driver.v1.Statement;
 import org.neo4j.driver.v1.StatementResult;
@@ -45,29 +47,29 @@ final class Default implements Provider
         {
             private static final Statement GET_SERVER = new Statement( Provider.GET_SERVERS );
             private final Clock clock;
+            private final Logger log;
 
-            Default( Clock clock )
+            Default( Clock clock, Logger log )
             {
                 this.clock = clock;
+                this.log = log;
             }
 
             @Override
             public ClusterComposition getClusterComposition( Connection connection ) throws ServiceUnavailableException
             {
                 StatementResult cursor = getServers( connection );
+                List<Record> records = cursor.list();
+                log.info( "Got getServers response: %s", records );
                 long now = clock.millis();
                 try
                 {
-                    if ( !cursor.hasNext() )
+                    if ( records.size() != 1 )
                     {
-                        return null; // server returned too few rows, this is a contract violation, treat as incapable
+                        // server returned too few or too many rows, this is a contract violation, treat as incapable
+                        return null;
                     }
-                    Record record = cursor.next();
-                    if ( cursor.hasNext() )
-                    {
-                        return null; // server returned too many rows, this is a contract violation, treat as incapable
-                    }
-                    return read( record, now );
+                    return read( records.get( 0 ), now );
                 }
                 finally
                 {
diff --git a/driver/src/main/java/org/neo4j/driver/internal/cluster/LoadBalancer.java b/driver/src/main/java/org/neo4j/driver/internal/cluster/LoadBalancer.java
@@ -51,7 +51,8 @@ public LoadBalancer(
             ConnectionPool connections,
             BoltServerAddress... routingAddresses ) throws ServiceUnavailableException
     {
-        this( settings, clock, log, connections, new ClusterComposition.Provider.Default( clock ), routingAddresses );
+        this( settings, clock, log, connections, new ClusterComposition.Provider.Default( clock, log ),
+                routingAddresses );
     }
 
     LoadBalancer(
@@ -118,6 +119,9 @@ private Connection acquireConnection( RoundRobinAddressSet servers ) throws Serv
                 }
                 catch ( ServiceUnavailableException e )
                 {
+                    log.error( String.format( "Failed to refresh routing information using routing address %s",
+                            address ), e );
+
                     forget( address );
                 }
             }
@@ -129,6 +133,8 @@ private synchronized void ensureRouting() throws ServiceUnavailableException
     {
         if ( stale() )
         {
+            log.info( "Routing information is stale. Ttl %s, currentTime %s, routers %s, writers %s, readers %s",
+                    expirationTimeout, clock.millis(), routers, writers, readers );
             try
             {
                 // get a new routing table
@@ -143,6 +149,9 @@ private synchronized void ensureRouting() throws ServiceUnavailableException
                 {
                     connections.purge( address );
                 }
+
+                log.info( "Refreshed routing information. Ttl %s, routers %s, writers %s, readers %s",
+                        expirationTimeout, routers, writers, readers );
             }
             catch ( InterruptedException e )
             {
@@ -177,6 +186,7 @@ private ClusterComposition lookupRoutingTable() throws InterruptedException, Ser
                 try ( Connection connection = connections.acquire( address ) )
                 {
                     cluster = provider.getClusterComposition( connection );
+                    log.info( "Got cluster composition %s", cluster );
                 }
                 catch ( Exception e )
                 {
diff --git a/driver/src/main/java/org/neo4j/driver/internal/cluster/RoundRobinAddressSet.java b/driver/src/main/java/org/neo4j/driver/internal/cluster/RoundRobinAddressSet.java
@@ -18,6 +18,7 @@
  */
 package org.neo4j.driver.internal.cluster;
 
+import java.util.Arrays;
 import java.util.Set;
 import java.util.concurrent.atomic.AtomicInteger;
 
@@ -128,6 +129,12 @@ public synchronized void remove( BoltServerAddress address )
         }
     }
 
+    @Override
+    public String toString()
+    {
+        return "RoundRobinAddressSet=" + Arrays.toString( addresses );
+    }
+
     /** breaking encapsulation in order to perform white-box testing of boundary case */
     void setOffset( int target )
     {
diff --git a/driver/src/test/java/org/neo4j/driver/internal/cluster/ClusterCompositionProviderTest.java b/driver/src/test/java/org/neo4j/driver/internal/cluster/ClusterCompositionProviderTest.java
@@ -18,22 +18,23 @@
  */
 package org.neo4j.driver.internal.cluster;
 
+import org.junit.Test;
+import org.mockito.invocation.InvocationOnMock;
+import org.mockito.stubbing.Answer;
+import org.mockito.stubbing.Stubber;
+
 import java.util.Collections;
 import java.util.HashMap;
 import java.util.HashSet;
 import java.util.Map;
 import java.util.Set;
 
-import org.junit.Test;
-import org.mockito.invocation.InvocationOnMock;
-import org.mockito.stubbing.Answer;
-import org.mockito.stubbing.Stubber;
-
 import org.neo4j.driver.internal.EventHandler;
 import org.neo4j.driver.internal.net.BoltServerAddress;
 import org.neo4j.driver.internal.spi.Collector;
 import org.neo4j.driver.internal.spi.Connection;
 import org.neo4j.driver.internal.util.FakeClock;
+import org.neo4j.driver.v1.Logger;
 import org.neo4j.driver.v1.Value;
 import org.neo4j.driver.v1.exceptions.ServiceUnavailableException;
 
@@ -148,7 +149,8 @@ public void shouldPropagateConnectionFailureExceptions() throws Exception
 
     private ClusterComposition getClusterComposition()
     {
-        return new ClusterComposition.Provider.Default( clock ).getClusterComposition( connection );
+        return new ClusterComposition.Provider.Default( clock, mock( Logger.class ) )
+                .getClusterComposition( connection );
     }
 
     private void keys( final String... keys )

Original file line number	Diff line number	Diff line change
`@@ -19,12 +19,14 @@`
`19`	`19`	`package org.neo4j.driver.internal.cluster;`
`20`	`20`
`21`	`21`	`import java.util.HashSet;`
	`22`	`+import java.util.List;`
`22`	`23`	`import java.util.Set;`
`23`	`24`
`24`	`25`	`import org.neo4j.driver.internal.NetworkSession;`
`25`	`26`	`import org.neo4j.driver.internal.net.BoltServerAddress;`
`26`	`27`	`import org.neo4j.driver.internal.spi.Connection;`
`27`	`28`	`import org.neo4j.driver.internal.util.Clock;`
	`29`	`+import org.neo4j.driver.v1.Logger;`
`28`	`30`	`import org.neo4j.driver.v1.Record;`
`29`	`31`	`import org.neo4j.driver.v1.Statement;`
`30`	`32`	`import org.neo4j.driver.v1.StatementResult;`
`@@ -45,29 +47,29 @@ final class Default implements Provider`
`45`	`47`	`{`
`46`	`48`	`private static final Statement GET_SERVER = new Statement( Provider.GET_SERVERS );`
`47`	`49`	`private final Clock clock;`
	`50`	`+ private final Logger log;`
`48`	`51`
`49`		`- Default( Clock clock )`
	`52`	`+ Default( Clock clock, Logger log )`
`50`	`53`	`{`
`51`	`54`	`this.clock = clock;`
	`55`	`+ this.log = log;`
`52`	`56`	`}`
`53`	`57`
`54`	`58`	`@Override`
`55`	`59`	`public ClusterComposition getClusterComposition( Connection connection ) throws ServiceUnavailableException`
`56`	`60`	`{`
`57`	`61`	`StatementResult cursor = getServers( connection );`
	`62`	`+ List<Record> records = cursor.list();`
	`63`	`+ log.info( "Got getServers response: %s", records );`
`58`	`64`	`long now = clock.millis();`
`59`	`65`	`try`
`60`	`66`	`{`
`61`		`- if ( !cursor.hasNext() )`
	`67`	`+ if ( records.size() != 1 )`
`62`	`68`	`{`
`63`		`- return null; // server returned too few rows, this is a contract violation, treat as incapable`
	`69`	`+ // server returned too few or too many rows, this is a contract violation, treat as incapable`
	`70`	`+ return null;`
`64`	`71`	`}`
`65`		`- Record record = cursor.next();`
`66`		`- if ( cursor.hasNext() )`
`67`		`- {`
`68`		`- return null; // server returned too many rows, this is a contract violation, treat as incapable`
`69`		`- }`
`70`		`- return read( record, now );`
	`72`	`+ return read( records.get( 0 ), now );`
`71`	`73`	`}`
`72`	`74`	`finally`
`73`	`75`	`{`
Original file line number	Diff line number	Diff line change
`@@ -51,7 +51,8 @@ public LoadBalancer(`
`51`	`51`	`ConnectionPool connections,`
`52`	`52`	`BoltServerAddress... routingAddresses ) throws ServiceUnavailableException`
`53`	`53`	`{`
`54`		`- this( settings, clock, log, connections, new ClusterComposition.Provider.Default( clock ), routingAddresses );`
	`54`	`+ this( settings, clock, log, connections, new ClusterComposition.Provider.Default( clock, log ),`
	`55`	`+ routingAddresses );`
`55`	`56`	`}`
`56`	`57`
`57`	`58`	`LoadBalancer(`
`@@ -118,6 +119,9 @@ private Connection acquireConnection( RoundRobinAddressSet servers ) throws Serv`
`118`	`119`	`}`
`119`	`120`	`catch ( ServiceUnavailableException e )`
`120`	`121`	`{`
	`122`	`+ log.error( String.format( "Failed to refresh routing information using routing address %s",`
	`123`	`+ address ), e );`
	`124`	`+`
`121`	`125`	`forget( address );`
`122`	`126`	`}`
`123`	`127`	`}`
`@@ -129,6 +133,8 @@ private synchronized void ensureRouting() throws ServiceUnavailableException`
`129`	`133`	`{`
`130`	`134`	`if ( stale() )`
`131`	`135`	`{`
	`136`	`+ log.info( "Routing information is stale. Ttl %s, currentTime %s, routers %s, writers %s, readers %s",`
	`137`	`+ expirationTimeout, clock.millis(), routers, writers, readers );`
`132`	`138`	`try`
`133`	`139`	`{`
`134`	`140`	`// get a new routing table`
`@@ -143,6 +149,9 @@ private synchronized void ensureRouting() throws ServiceUnavailableException`
`143`	`149`	`{`
`144`	`150`	`connections.purge( address );`
`145`	`151`	`}`
	`152`	`+`
	`153`	`+ log.info( "Refreshed routing information. Ttl %s, routers %s, writers %s, readers %s",`
	`154`	`+ expirationTimeout, routers, writers, readers );`
`146`	`155`	`}`
`147`	`156`	`catch ( InterruptedException e )`
`148`	`157`	`{`
`@@ -177,6 +186,7 @@ private ClusterComposition lookupRoutingTable() throws InterruptedException, Ser`
`177`	`186`	`try ( Connection connection = connections.acquire( address ) )`
`178`	`187`	`{`
`179`	`188`	`cluster = provider.getClusterComposition( connection );`
	`189`	`+ log.info( "Got cluster composition %s", cluster );`
`180`	`190`	`}`
`181`	`191`	`catch ( Exception e )`
`182`	`192`	`{`
Original file line number	Diff line number	Diff line change
`@@ -18,6 +18,7 @@`
`18`	`18`	`*/`
`19`	`19`	`package org.neo4j.driver.internal.cluster;`
`20`	`20`
	`21`	`+import java.util.Arrays;`
`21`	`22`	`import java.util.Set;`
`22`	`23`	`import java.util.concurrent.atomic.AtomicInteger;`
`23`	`24`
`@@ -128,6 +129,12 @@ public synchronized void remove( BoltServerAddress address )`
`128`	`129`	`}`
`129`	`130`	`}`
`130`	`131`
	`132`	`+ @Override`
	`133`	`+ public String toString()`
	`134`	`+ {`
	`135`	`+ return "RoundRobinAddressSet=" + Arrays.toString( addresses );`
	`136`	`+ }`
	`137`	`+`
`131`	`138`	`/** breaking encapsulation in order to perform white-box testing of boundary case */`
`132`	`139`	`void setOffset( int target )`
`133`	`140`	`{`