Logging of client reconnects and transient errors

nicktorwald · nicktorwald · commit 20faf42618f0 · 2019-09-17T18:51:27.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,9 +1,18 @@
 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 void log(Level level, Throwable error, Supplier<String> message) {
+        if (!isLoggable(level)) {
+            return;
+        }
+        log(level, message.get(), error);
+    }
+
     public abstract boolean isLoggable(Level level);
 
     @Override
@@ -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
@@ -1,5 +1,7 @@
 package org.tarantool.logging;
 
+import java.util.function.Supplier;
+
 /**
  * Minimal logger contract to perform internal
  * logging.
@@ -26,6 +28,8 @@ enum Level {
 
     void error(final String message, Throwable throwable);
 
+    void error(final Supplier<String> message, Throwable throwable);
+
     boolean isWarnEnabled();
 
     void warn(final String message);
@@ -34,6 +38,8 @@ enum Level {
 
     void warn(final String message, Throwable throwable);
 
+    void warn(final Supplier<String> message, Throwable throwable);
+
     boolean isInfoEnabled();
 
     void info(final String message);
@@ -42,6 +48,8 @@ enum Level {
 
     void info(final String message, Throwable throwable);
 
+    void info(final Supplier<String> message, Throwable throwable);
+
     boolean isDebugEnabled();
 
     void debug(final String message);
@@ -50,6 +58,8 @@ enum Level {
 
     void debug(final String message, Throwable throwable);
 
+    void debug(final Supplier<String> message, Throwable throwable);
+
     boolean isTraceEnabled();
 
     void trace(final String message);
@@ -58,4 +68,6 @@ enum Level {
 
     void trace(final String message, Throwable throwable);
 
+    void trace(final Supplier<String> message, Throwable throwable);
+
 }
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`	`}`