Enhanced control and logging of SSL handshake process

Fixed a possible unexpected Cloud service latency path

Author: gmfeinberg

CHANGELOG.md

@@ -2,6 +2,17 @@
 All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](http://keepachangelog.com/).
 
+## [Unpublished]
+
+### Added
+- Added new methods in NoSQLHandleConfig to control the SSL handshake timeout,
+default 3000 milliseconds.
+  - get/setSslHandshakeTimeout
+
+### Fixed
+- Cloud only: Fixed an issue that a request may have unexpected latency when
+authenticated with instance/resource principal due to security token refresh.
+
 ## [5.3.1] 2022-02-17
 
 See also sections on 5.2.30 and 5.2.31 as they were not released publicly. The last public release was 5.2.29.

driver/.classpath

@@ -5,17 +5,17 @@
   <classpathentry kind="output" path="target/classes"/>
   <classpathentry kind="con" path="org.eclipse.jdt.launching.JRE_CONTAINER/org.eclipse.jdt.internal.debug.ui.launcher.StandardVMType/JavaSE-1.8"/>
   <classpathentry kind="var" path="M2_REPO/com/fasterxml/jackson/core/jackson-core/2.12.1/jackson-core-2.12.1.jar"/>
-  <classpathentry kind="var" path="M2_REPO/io/netty/netty-buffer/4.1.52.Final/netty-buffer-4.1.52.Final.jar"/>
-  <classpathentry kind="var" path="M2_REPO/io/netty/netty-common/4.1.52.Final/netty-common-4.1.52.Final.jar"/>
-  <classpathentry kind="var" path="M2_REPO/io/netty/netty-codec-http/4.1.52.Final/netty-codec-http-4.1.52.Final.jar"/>
-  <classpathentry kind="var" path="M2_REPO/io/netty/netty-transport/4.1.52.Final/netty-transport-4.1.52.Final.jar"/>
-  <classpathentry kind="var" path="M2_REPO/io/netty/netty-resolver/4.1.52.Final/netty-resolver-4.1.52.Final.jar"/>
-  <classpathentry kind="var" path="M2_REPO/io/netty/netty-codec/4.1.52.Final/netty-codec-4.1.52.Final.jar"/>
-  <classpathentry kind="var" path="M2_REPO/io/netty/netty-handler/4.1.52.Final/netty-handler-4.1.52.Final.jar"/>
-  <classpathentry kind="var" path="M2_REPO/io/netty/netty-handler-proxy/4.1.52.Final/netty-handler-proxy-4.1.52.Final.jar"/>
-  <classpathentry kind="var" path="M2_REPO/io/netty/netty-codec-socks/4.1.52.Final/netty-codec-socks-4.1.52.Final.jar"/>
+  <classpathentry kind="var" path="M2_REPO/io/netty/netty-buffer/4.1.71.Final/netty-buffer-4.1.71.Final.jar"/>
+  <classpathentry kind="var" path="M2_REPO/io/netty/netty-common/4.1.71.Final/netty-common-4.1.71.Final.jar"/>
+  <classpathentry kind="var" path="M2_REPO/io/netty/netty-codec-http/4.1.71.Final/netty-codec-http-4.1.71.Final.jar"/>
+  <classpathentry kind="var" path="M2_REPO/io/netty/netty-transport/4.1.71.Final/netty-transport-4.1.71.Final.jar"/>
+  <classpathentry kind="var" path="M2_REPO/io/netty/netty-resolver/4.1.71.Final/netty-resolver-4.1.71.Final.jar"/>
+  <classpathentry kind="var" path="M2_REPO/io/netty/netty-codec/4.1.71.Final/netty-codec-4.1.71.Final.jar"/>
+  <classpathentry kind="var" path="M2_REPO/io/netty/netty-handler/4.1.71.Final/netty-handler-4.1.71.Final.jar"/>
+  <classpathentry kind="var" path="M2_REPO/io/netty/netty-handler-proxy/4.1.71.Final/netty-handler-proxy-4.1.71.Final.jar"/>
+  <classpathentry kind="var" path="M2_REPO/io/netty/netty-codec-socks/4.1.71.Final/netty-codec-socks-4.1.71.Final.jar"/>
   <classpathentry kind="var" path="M2_REPO/org/bouncycastle/bcprov-jdk15on/1.68/bcprov-jdk15on-1.68.jar"/>
   <classpathentry kind="var" path="M2_REPO/org/bouncycastle/bcpkix-jdk15on/1.68/bcpkix-jdk15on-1.68.jar"/>
-  <classpathentry kind="var" path="M2_REPO/junit/junit/4.12/junit-4.12.jar"/>
+  <classpathentry kind="var" path="M2_REPO/junit/junit/4.13.1/junit-4.13.1.jar"/>
   <classpathentry kind="var" path="M2_REPO/org/hamcrest/hamcrest-core/1.3/hamcrest-core-1.3.jar"/>
 </classpath>

driver/src/main/java/oracle/nosql/driver/DefaultRetryHandler.java

@@ -46,20 +46,23 @@ public int getNumRetries() {
      * Decide whether to retry or not.
      * Default behavior is to *not* retry OperationThrottlingException
      * because the retry time is likely much longer than normal because
-     * they are DDL operations. In addition, *not* retry any requests that
-     * should not be retried: TableRequest, ListTablesRequest,
-     * GetTableRequest, TableUsageRequest, GetIndexesRequest.
+     * they are DDL operations. Read and Write throttling exceptions are
+     * always retryable. Otherwise check the request itself to see if
+     * it should not be retried.
      */
     @Override
     public boolean doRetry(Request request,
                            int numRetries,
                            RetryableException re) {
         if (re instanceof OperationThrottlingException) {
             return false;
-        } else if (!request.shouldRetry()) {
-            return false;
         }
-        return (numRetries < maxRetries);
+        if (re instanceof ReadThrottlingException ||
+            re instanceof WriteThrottlingException ||
+            request.shouldRetry()) {
+            return (numRetries < maxRetries);
+        }
+        return false;
     }
 
     /**
@@ -100,15 +103,17 @@ public static int computeBackoffDelay(Request request, int fixedDelayMs) {
 
         int delayMs = fixedDelayMs;
         if (delayMs == 0) {
-            // add 200ms plus a small random amount
+            /* add 200ms plus a small random amount */
             int mSecToAdd = 200 + (int)(Math.random() * 50);
 
             delayMs = request.getRetryDelayMs();
             delayMs += mSecToAdd;
         }
 
-        // if the delay would put us over the timeout, reduce it to just before
-        // the timeout would occur.
+        /*
+         * if the delay would put us over the timeout, reduce it to just before
+         * the timeout would occur.
+         */
         long nowMs = System.currentTimeMillis();
         long msLeft = (startTimeMs + (long)timeoutMs) - nowMs;
         if ((int)msLeft < delayMs) {

driver/src/main/java/oracle/nosql/driver/NoSQLHandleConfig.java

@@ -167,6 +167,12 @@ public class NoSQLHandleConfig implements Cloneable {
      */
     private int sslSessionTimeout = 0;
 
+    /**
+     * The timeout limit of SSH handshake, or 0 if not configured by
+     * the user.
+     */
+    private int sslHandshakeTimeoutMs = 0;
+
     /**
      * Cloud service only.
      *
@@ -1022,6 +1028,16 @@ public int getSSLSessionCacheSize() {
         return sslSessionCacheSize;
     }
 
+    /**
+     * Returns the configured SSL handshake timeout, in milliseconds.
+     *
+     * @return the timeout, in milliseconds, or 0 if it has not been set
+     * @since 5.3.2
+     */
+    public int getSSLHandshakeTimeout() {
+        return sslHandshakeTimeoutMs;
+    }
+
     /**
      * Set SSL cipher suites to enable, in the order of preference. null to
      * use default cipher suites.
@@ -1081,7 +1097,7 @@ public NoSQLHandleConfig setSSLSessionCacheSize(int cacheSize) {
     }
 
     /**
-     * Set the timeout for the cached SSL session objects, in seconds. 0 to
+     * Sets the timeout for the cached SSL session objects, in seconds. 0 to
      * use the default value, no limit. When the timeout limit is exceeded for
      * a session, the SSLSession object is invalidated and future connections
      * cannot resume or rejoin the session.
@@ -1100,6 +1116,27 @@ public NoSQLHandleConfig setSSLSessionTimeout(int timeout) {
         return this;
     }
 
+    /**
+     * Sets the timeout for the SSL handshake, in milliseconds. 0 to use the
+     * default value, 3000 milliseconds. In general the default works. This
+     * value can be set to help debug suspected SSL issues and force
+     * retries within the request timeout period.
+     *
+     * @param timeout the SSL handshake timeout
+     *
+     * @return this
+     * @since 5.3.2
+     */
+    public NoSQLHandleConfig setSSLHandshakeTimeout(int timeout) {
+        if (timeout < 0) {
+            throw new IllegalArgumentException(
+                "NoSQLHandleConfig.setSSLHandshakeTimeout: timeout must " +
+                "be a positive value or zero");
+        }
+        this.sslHandshakeTimeoutMs = timeout;
+        return this;
+    }
+
     /**
      * Sets an HTTP proxy host to be used for the session. If a proxy host
      * is specified a proxy port must also be specified, using

driver/src/main/java/oracle/nosql/driver/http/Client.java

@@ -215,6 +215,7 @@ public Client(Logger logger,
                                     httpConfig.getMaxContentLength(),
                                     httpConfig.getMaxChunkSize(),
                                     sslCtx,
+                                    config.getSSLHandshakeTimeout(),
                                     "NoSQL Driver",
                                     logger);
         if (httpConfig.getProxyHost() != null) {
@@ -501,8 +502,8 @@ public Result execute(Request kvRequest) {
                 Channel channel = httpClient.getChannel(thisIterationTimeoutMs);
                 requestId = Long.toString(nextRequestId());
                 responseHandler =
-                    new ResponseHandler(httpClient, logger, channel, requestId);
-
+                    new ResponseHandler(httpClient, logger, channel,
+                                        requestId, kvRequest.shouldRetry());
                 buffer = channel.alloc().directBuffer();
                 buffer.retain();
 

driver/src/main/java/oracle/nosql/driver/http/NoSQLHandleImpl.java

@@ -144,14 +144,16 @@ private void configAuthProvider(Logger logger, NoSQLHandleConfig config) {
                     endpoint = endpoint.substring(0, endpoint.length() - 1);
                 }
                 stProvider.setEndpoint(endpoint)
-                          .setSslContext(config.getSslContext());
+                          .setSslContext(config.getSslContext())
+                          .setSslHandshakeTimeout(
+                              config.getSSLHandshakeTimeout());
             }
         } else if (ap instanceof SignatureProvider) {
             SignatureProvider sigProvider = (SignatureProvider) ap;
-            sigProvider.prepare(config);
             if (sigProvider.getLogger() == null) {
                 sigProvider.setLogger(logger);
             }
+            sigProvider.prepare(config);
         }
     }
 

driver/src/main/java/oracle/nosql/driver/httpclient/HttpClient.java

@@ -78,6 +78,7 @@ public class HttpClient {
     static final int DEFAULT_MAX_PENDING = 3;
     static final int DEFAULT_MAX_CONTENT_LENGTH = 32 * 1024 * 1024; // 32MB
     static final int DEFAULT_MAX_CHUNK_SIZE = 65536;
+    static final int DEFAULT_HANDSHAKE_TIMEOUT_MS = 3000;
     /*
      * timeout for acquiring a Netty channel in ms. If exceeded a new
      * connection is created
@@ -107,6 +108,7 @@ public class HttpClient {
      * Non-null if using SSL
      */
     private final SslContext sslCtx;
+    private final int handshakeTimeoutMs;
 
     private final Logger logger;
 
@@ -136,6 +138,7 @@ public class HttpClient {
      * @param connectionPoolSize the max number of HTTP connections to use
      * for concurrent requests. If 0, a default value is used (2)
      * @param sslCtx if non-null, SSL context to use for connections.
+     * @param handshakeTimeoutMs if not zero, timeout to use for SSL handshake
      * @param name A name to use in logging messages for this client.
      * @param logger A logger to use for logging messages.
      */
@@ -145,11 +148,12 @@ public HttpClient(String host,
                       int connectionPoolSize,
                       int poolMaxPending,
                       SslContext sslCtx,
+                      int handshakeTimeoutMs,
                       String name,
                       Logger logger) {
         this(host, port, numThreads, connectionPoolSize, poolMaxPending,
             DEFAULT_MAX_CONTENT_LENGTH, DEFAULT_MAX_CHUNK_SIZE,
-            sslCtx, name, logger);
+            sslCtx, handshakeTimeoutMs, name, logger);
     }
 
     /**
@@ -169,6 +173,7 @@ public HttpClient(String host,
      * @param maxChunkSize maximum size in bytes of chunked response messages.
      * If 0, a default value is used (64KB).
      * @param sslCtx if non-null, SSL context to use for connections.
+     * @param handshakeTimeoutMs if not zero, timeout to use for SSL handshake
      * @param name A name to use in logging messages for this client.
      * @param logger A logger to use for logging messages.
      */
@@ -180,6 +185,7 @@ public HttpClient(String host,
                       int maxContentLength,
                       int maxChunkSize,
                       SslContext sslCtx,
+                      int handshakeTimeoutMs,
                       String name,
                       Logger logger) {
 
@@ -190,12 +196,15 @@ public HttpClient(String host,
         this.name = name;
 
         poolMaxPending = (poolMaxPending == 0 ?
-                              DEFAULT_MAX_PENDING : poolMaxPending);
+            DEFAULT_MAX_PENDING : poolMaxPending);
 
         this.maxContentLength = (maxContentLength == 0 ?
-                              DEFAULT_MAX_CONTENT_LENGTH : maxContentLength);
+            DEFAULT_MAX_CONTENT_LENGTH : maxContentLength);
         this.maxChunkSize = (maxChunkSize == 0 ?
-                              DEFAULT_MAX_CHUNK_SIZE : maxChunkSize);
+            DEFAULT_MAX_CHUNK_SIZE : maxChunkSize);
+
+        this.handshakeTimeoutMs = (handshakeTimeoutMs == 0 ?
+            DEFAULT_HANDSHAKE_TIMEOUT_MS : handshakeTimeoutMs);
 
         int cores = Runtime.getRuntime().availableProcessors();
 
@@ -258,6 +267,10 @@ Logger getLogger() {
         return logger;
     }
 
+    int getHandshakeTimeoutMs() {
+        return handshakeTimeoutMs;
+    }
+
     public int getMaxContentLength() {
         return maxContentLength;
     }
@@ -340,8 +353,9 @@ public Channel getChannel(int timeoutMs)
                 retChan = fut.get(thisTimeoutMs, TimeUnit.MILLISECONDS);
             } catch (TimeoutException e) {
                 if (retries == 0) {
-                    logInfo(logger, "Timed out after " + msDiff +
-                             "ms trying to acquire channel: retrying");
+                    logInfo(logger, "Timed out after " +
+                            (System.currentTimeMillis() - startMs) +
+                            "ms trying to acquire channel: retrying");
                 }
                 /* fall through */
             }

driver/src/main/java/oracle/nosql/driver/httpclient/HttpClientChannelPoolHandler.java

@@ -8,14 +8,15 @@
 package oracle.nosql.driver.httpclient;
 
 import static oracle.nosql.driver.util.LogUtil.logFine;
-import static oracle.nosql.driver.util.LogUtil.logInfo;
-import java.net.InetSocketAddress;
 
+import java.net.InetSocketAddress;
 import javax.net.ssl.SSLEngine;
 import javax.net.ssl.SSLParameters;
 
 import io.netty.channel.Channel;
 import io.netty.channel.ChannelHandler.Sharable;
+import io.netty.channel.ChannelHandlerContext;
+import io.netty.channel.ChannelInboundHandlerAdapter;
 import io.netty.channel.ChannelPipeline;
 import io.netty.channel.EventLoop;
 import io.netty.channel.pool.ChannelHealthChecker;
@@ -24,6 +25,7 @@
 import io.netty.handler.codec.http.HttpObjectAggregator;
 import io.netty.handler.proxy.HttpProxyHandler;
 import io.netty.handler.ssl.SslHandler;
+import io.netty.handler.ssl.SslHandshakeCompletionEvent;
 import io.netty.util.concurrent.Future;
 
 /**
@@ -74,7 +76,10 @@ public void channelCreated(Channel ch) {
             final SSLParameters sslParameters = sslEngine.getSSLParameters();
             sslParameters.setEndpointIdentificationAlgorithm("HTTPS");
             sslEngine.setSSLParameters(sslParameters);
+            sslHandler.setHandshakeTimeoutMillis(client.getHandshakeTimeoutMs());
+
             p.addLast(sslHandler);
+            p.addLast(new ChannelLoggingHandler(client));
         }
         p.addLast(CODEC_HANDLER_NAME, new HttpClientCodec
                               (4096, // initial line
@@ -125,4 +130,46 @@ public Future<Boolean> isHealthy(Channel channel) {
         return val? loop.newSucceededFuture(Boolean.TRUE) :
             loop.newSucceededFuture(Boolean.FALSE);
     }
+
+    private static class ChannelLoggingHandler
+        extends ChannelInboundHandlerAdapter {
+
+        private HttpClient client;
+
+        ChannelLoggingHandler(HttpClient client) {
+            this.client = client;
+        }
+
+        @Override
+        public void channelActive(ChannelHandlerContext ctx) {
+            logFine(client.getLogger(),
+                    "HttpClient " + client.getName() +
+                    ", channel " + ctx.channel() + " connected");
+            ctx.fireChannelActive();
+        }
+
+        @Override
+        public void channelInactive(ChannelHandlerContext ctx) {
+            logFine(client.getLogger(),
+                    "HttpClient " + client.getName() +
+                    ", channel " + ctx.channel() + " inactive");
+            ctx.fireChannelInactive();
+        }
+
+        @Override
+        public void userEventTriggered(ChannelHandlerContext ctx,
+                                       Object evt)
+            throws Exception {
+
+            if (evt instanceof SslHandshakeCompletionEvent) {
+                if (!((SslHandshakeCompletionEvent) evt).isSuccess()) {
+                    logFine(client.getLogger(),
+                            "HttpClient " + client.getName() +
+                            ", channel: " + ctx.channel() +
+                            " handshake failed: " + evt);
+                }
+            }
+            ctx.fireUserEventTriggered(evt);
+        }
+    }
 }