Logging of client reconnects and transient errors

nicktorwald · nicktorwald · commit 58bbc196ff60 · 2019-09-17T18:38:46.000+07:00
Add logging waring messages when client tries establishing connection to Tarantool instance. All the request that cannot be processed because of some transient errors are also traced. Disable JUL logging for test classes by default. Follows on: #194
diff --git a/pom.xml b/pom.xml
@@ -1,4 +1,5 @@
-<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
+<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
     <modelVersion>4.0.0</modelVersion>
 
     <groupId>org.tarantool</groupId>
@@ -12,6 +13,7 @@
         <mockito.version>1.10.19</mockito.version>
         <!-- logger dependency versions -->
         <sfl4j.version>1.7.26</sfl4j.version>
+        <project.testResources>${project.basedir}/src/test/resources</project.testResources>
     </properties>
     <name>Tarantool Connector for Java</name>
     <url>https://github.com/tarantool/tarantool-java</url>
@@ -73,17 +75,24 @@
                 <artifactId>templating-maven-plugin</artifactId>
                 <version>1.0.0</version>
                 <executions>
-                  <execution>
-                    <id>filter-src</id>
-                    <goals>
-                      <goal>filter-sources</goal>
-                    </goals>
-                  </execution>
+                    <execution>
+                        <id>filter-src</id>
+                        <goals>
+                            <goal>filter-sources</goal>
+                        </goals>
+                    </execution>
                 </executions>
             </plugin>
             <plugin>
                 <artifactId>maven-surefire-plugin</artifactId>
                 <version>3.0.0-M3</version>
+                <configuration>
+                    <systemPropertyVariables>
+                        <java.util.logging.config.file>
+                            ${project.testResources}/jul-silent.properties
+                        </java.util.logging.config.file>
+                    </systemPropertyVariables>
+                </configuration>
             </plugin>
             <plugin>
                 <groupId>org.apache.maven.plugins</groupId>
@@ -99,6 +108,12 @@
                 </executions>
                 <configuration>
                     <trimStackTrace>false</trimStackTrace>
+                    <systemPropertyVariables>
+                        <java.util.logging.config.file>
+                            ${project.testResources}/jul-silent.properties
+                        </java.util.logging.config.file>
+                    </systemPropertyVariables>
+
                 </configuration>
             </plugin>
             <plugin>
diff --git a/src/main/java/org/tarantool/RoundRobinSocketProviderImpl.java b/src/main/java/org/tarantool/RoundRobinSocketProviderImpl.java
@@ -13,6 +13,7 @@
 import java.util.concurrent.locks.Lock;
 import java.util.concurrent.locks.ReadWriteLock;
 import java.util.concurrent.locks.ReentrantReadWriteLock;
+import java.util.function.Supplier;
 import java.util.stream.Collectors;
 
 /**
@@ -93,13 +94,7 @@ private void updateAddressList(Collection<String> addresses) {
      * @return socket addresses
      */
     public List<SocketAddress> getAddresses() {
-        Lock readLock = addressListLock.readLock();
-        readLock.lock();
-        try {
-            return Collections.unmodifiableList(this.socketAddresses);
-        } finally {
-            readLock.unlock();
-        }
+        return readGuard(() -> Collections.unmodifiableList(this.socketAddresses));
     }
 
     /**
@@ -109,14 +104,10 @@ public List<SocketAddress> getAddresses() {
      *     if {@link #currentPosition} has {@link #UNSET_POSITION} value
      */
     protected InetSocketAddress getLastObtainedAddress() {
-        Lock readLock = addressListLock.readLock();
-        readLock.lock();
-        try {
+        return readGuard(() -> {
             int index = currentPosition.get();
             return index != UNSET_POSITION ? socketAddresses.get(index) : null;
-        } finally {
-            readLock.unlock();
-        }
+        });
     }
 
     /**
@@ -176,13 +167,7 @@ public void setRetriesLimit(int retriesLimit) {
      * @return Number of configured addresses.
      */
     protected int getAddressCount() {
-        Lock readLock = addressListLock.readLock();
-        readLock.lock();
-        try {
-            return socketAddresses.size();
-        } finally {
-            readLock.unlock();
-        }
+        return readGuard(socketAddresses::size);
     }
 
     /**
@@ -191,11 +176,25 @@ protected int getAddressCount() {
      * @return Socket address to use for the next reconnection attempt
      */
     protected InetSocketAddress getNextSocketAddress() {
+        return readGuard(() -> {
+            int position = currentPosition.updateAndGet(i -> (i + 1) % socketAddresses.size());
+            return socketAddresses.get(position);
+        });
+    }
+
+    @Override
+    public SocketAddress getAddress() {
+        return readGuard(() -> {
+            int position = currentPosition.get() + 1 % socketAddresses.size();
+            return socketAddresses.get(position);
+        });
+    }
+
+    private <R> R readGuard(Supplier<R> supplier) {
         Lock readLock = addressListLock.readLock();
         readLock.lock();
         try {
-            int position = currentPosition.updateAndGet(i -> (i + 1) % socketAddresses.size());
-            return socketAddresses.get(position);
+            return supplier.get();
         } finally {
             readLock.unlock();
         }
diff --git a/src/main/java/org/tarantool/SingleSocketChannelProviderImpl.java b/src/main/java/org/tarantool/SingleSocketChannelProviderImpl.java
@@ -24,6 +24,7 @@ public SingleSocketChannelProviderImpl(String address) {
         setAddress(address);
     }
 
+    @Override
     public SocketAddress getAddress() {
         return address;
     }
diff --git a/src/main/java/org/tarantool/SocketChannelProvider.java b/src/main/java/org/tarantool/SocketChannelProvider.java
@@ -19,4 +19,15 @@ public interface SocketChannelProvider {
      */
     SocketChannel get(int retryNumber, Throwable lastError);
 
+    /**
+     * Gets an address that will be used when
+     * {@link #get(int, Throwable)} is invoked.
+     *
+     * @return effective address or {@literal null}
+     *     if it cannot be calculated in advance.
+     */
+    default SocketAddress getAddress() {
+        return null;
+    }
+
 }
diff --git a/src/main/java/org/tarantool/TarantoolClientImpl.java b/src/main/java/org/tarantool/TarantoolClientImpl.java
@@ -1,13 +1,17 @@
 package org.tarantool;
 
+import org.tarantool.logging.Logger;
+import org.tarantool.logging.LoggerFactory;
 import org.tarantool.protocol.ProtoUtils;
 import org.tarantool.protocol.ReadableViaSelectorChannel;
 import org.tarantool.protocol.TarantoolGreeting;
 import org.tarantool.protocol.TarantoolPacket;
+import org.tarantool.util.StringUtils;
 
 import java.io.IOException;
 import java.nio.ByteBuffer;
 import java.nio.channels.SocketChannel;
+import java.util.Arrays;
 import java.util.Iterator;
 import java.util.List;
 import java.util.Map;
@@ -28,6 +32,8 @@
 
 public class TarantoolClientImpl extends TarantoolBase<Future<?>> implements TarantoolClient {
 
+    private static final Logger LOGGER = LoggerFactory.getLogger(TarantoolClientImpl.class);
+
     public static final CommunicationException NOT_INIT_EXCEPTION
         = new CommunicationException("Not connected, initializing connection");
 
@@ -147,6 +153,12 @@ protected void reconnect(Throwable lastError) {
         int retryNumber = 0;
         while (!Thread.currentThread().isInterrupted()) {
             try {
+                if (lastError != NOT_INIT_EXCEPTION) {
+                    LOGGER.warn(() -> "Attempt to (re-)connect to Tarantool instance " +
+                        (StringUtils.isBlank(config.username) ? "" : config.username + ":*****@") +
+                        socketProvider.getAddress().toString(), lastError
+                    );
+                }
                 channel = socketProvider.get(retryNumber++, lastError == NOT_INIT_EXCEPTION ? null : lastError);
             } catch (Exception e) {
                 closeChannel(channel);
@@ -714,6 +726,15 @@ public Object[] getArgs() {
             return args;
         }
 
+        @Override
+        public String toString() {
+            return "TarantoolOp{" +
+                "id=" + id +
+                ", code=" + code +
+                ", args=" + Arrays.toString(args) +
+                '}';
+        }
+
         /**
          * Missed in jdk8 CompletableFuture operator to limit execution
          * by time.
diff --git a/src/main/java/org/tarantool/TarantoolClusterClient.java b/src/main/java/org/tarantool/TarantoolClusterClient.java
@@ -2,6 +2,8 @@
 
 import org.tarantool.cluster.TarantoolClusterDiscoverer;
 import org.tarantool.cluster.TarantoolClusterStoredFunctionDiscoverer;
+import org.tarantool.logging.Logger;
+import org.tarantool.logging.LoggerFactory;
 import org.tarantool.protocol.TarantoolPacket;
 import org.tarantool.util.StringUtils;
 
@@ -27,6 +29,8 @@
  */
 public class TarantoolClusterClient extends TarantoolClientImpl {
 
+    private static final Logger LOGGER = LoggerFactory.getLogger(TarantoolClusterClient.class);
+
     /**
      * Need some execution context to retry writes.
      */
@@ -153,6 +157,7 @@ protected boolean checkFail(TarantoolOp<?> future, Exception e) {
         } else {
             assert retries != null;
             retries.put(future.getId(), future);
+            LOGGER.trace("Request {0} was delayed because of {1}", future, e);
             return false;
         }
     }
@@ -194,13 +199,18 @@ protected void onReconnect() {
             // First call is before the constructor finished. Skip it.
             return;
         }
-        Collection<TarantoolOp<?>> futuresToRetry = new ArrayList<>(retries.values());
+        Collection<TarantoolOp<?>> delayed = new ArrayList<>(retries.values());
+        Collection<TarantoolOp<?>> reissued = new ArrayList<>(retries.size());
         retries.clear();
-        for (final TarantoolOp<?> future : futuresToRetry) {
+        for (final TarantoolOp<?> future : delayed) {
             if (!future.isDone()) {
                 executor.execute(() -> registerOperation(future));
+                reissued.add(future);
             }
         }
+        for (final TarantoolOp<?> future : reissued) {
+            LOGGER.trace("{0} was re-issued after reconnection", future);
+        }
     }
 
     @Override
diff --git a/src/main/java/org/tarantool/logging/BaseLogger.java b/src/main/java/org/tarantool/logging/BaseLogger.java
@@ -1,11 +1,20 @@
 package org.tarantool.logging;
 
+import java.util.function.Supplier;
+
 abstract class BaseLogger implements Logger {
 
     public abstract void log(Level level, String text, Throwable error, Object... parameters);
 
     public abstract boolean isLoggable(Level level);
 
+    public void log(Level level, Throwable error, Supplier<String> message) {
+        if (!isLoggable(level)) {
+            return;
+        }
+        log(level, message.get(), error);
+    }
+
     @Override
     public void debug(String message) {
         log(Level.DEBUG, message, null);
@@ -21,6 +30,11 @@ public void debug(String message, Throwable throwable) {
         log(Level.DEBUG, message, throwable);
     }
 
+    @Override
+    public void debug(Supplier<String> message, Throwable throwable) {
+        log(Level.DEBUG, throwable, message);
+    }
+
     @Override
     public void error(String message) {
         log(Level.ERROR, message, null);
@@ -36,6 +50,11 @@ public void error(String message, Throwable throwable) {
         log(Level.ERROR, message, throwable);
     }
 
+    @Override
+    public void error(Supplier<String> message, Throwable throwable) {
+        log(Level.ERROR, throwable, message);
+    }
+
     @Override
     public void info(String message) {
         log(Level.INFO, message, null);
@@ -51,6 +70,11 @@ public void info(String message, Throwable throwable) {
         log(Level.INFO, message, throwable);
     }
 
+    @Override
+    public void info(Supplier<String> message, Throwable throwable) {
+        log(Level.INFO, throwable, message);
+    }
+
     @Override
     public void trace(String message) {
         log(Level.TRACE, message, null);
@@ -66,6 +90,11 @@ public void trace(String message, Throwable throwable) {
         log(Level.TRACE, message, throwable);
     }
 
+    @Override
+    public void trace(Supplier<String> message, Throwable throwable) {
+        log(Level.TRACE, throwable, message);
+    }
+
     @Override
     public void warn(String message) {
         log(Level.WARN, message, null);
@@ -81,6 +110,11 @@ public void warn(String message, Throwable throwable) {
         log(Level.WARN, message, throwable);
     }
 
+    @Override
+    public void warn(Supplier<String> message, Throwable throwable) {
+        log(Level.TRACE, throwable, message);
+    }
+
     @Override
     public boolean isDebugEnabled() {
         return isLoggable(Level.DEBUG);
diff --git a/src/main/java/org/tarantool/logging/Logger.java b/src/main/java/org/tarantool/logging/Logger.java
diff --git a/src/test/java/org/tarantool/ClientReconnectClusterIT.java b/src/test/java/org/tarantool/ClientReconnectClusterIT.java
diff --git a/src/test/resources/jul-silent.properties b/src/test/resources/jul-silent.properties

Original file line number	Diff line number	Diff line change
`@@ -24,6 +24,7 @@ public SingleSocketChannelProviderImpl(String address) {`
`24`	`24`	`setAddress(address);`
`25`	`25`	`}`
`26`	`26`
	`27`	`+ @Override`
`27`	`28`	`public SocketAddress getAddress() {`
`28`	`29`	`return address;`
`29`	`30`	`}`