Logging of client reconnects and transient errors

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

Author: nicktorwald

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>

src/main/java/org/tarantool/TarantoolClientImpl.java

@@ -1,5 +1,7 @@
 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;
@@ -8,6 +10,7 @@
 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 +31,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 +152,9 @@ 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", lastError);
+                }
                 channel = socketProvider.get(retryNumber++, lastError == NOT_INIT_EXCEPTION ? null : lastError);
             } catch (Exception e) {
                 closeChannel(channel);
@@ -714,6 +722,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.

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

src/test/resources/jul-silent.properties

@@ -0,0 +1,8 @@
+# This configurations defines a standard console output
+# and disables all messages for it by default
+
+handlers = java.util.logging.ConsoleHandler
+.level = INFO
+java.util.logging.ConsoleHandler.level = OFF
+java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
+java.util.logging.SimpleFormatter.format = [%1$tF %1$tT] [%4$-7s] %5$s %n