Added retries on internal channel acquire errors.

Changed internal channel acquire to do internal retries on acquire errors.
Fixed error logging messages and exception messages on timeout errors to
give more information and correct cause.

Co-authored-by: John Connelly <john.connelly@oracle.com>

Author: gmfeinberg

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

@@ -401,9 +401,12 @@ public Result execute(Request kvRequest) {
         kvRequest.setStartTimeMs(startTime);
         final String requestClass = kvRequest.getClass().getSimpleName();
 
+        String requestId = "";
+        int thisIterationTimeoutMs = 0;
+
         do {
             long thisTime = System.currentTimeMillis();
-            int thisIterationTimeoutMs = timeoutMs - (int)(thisTime - startTime);
+            thisIterationTimeoutMs = timeoutMs - (int)(thisTime - startTime);
 
             /*
              * Check rate limiters before executing the request.
@@ -462,7 +465,7 @@ public Result execute(Request kvRequest) {
                  * operations in the loop.
                  */
                 Channel channel = httpClient.getChannel(thisIterationTimeoutMs);
-                String requestId = Long.toString(nextRequestId());
+                requestId = Long.toString(nextRequestId());
                 responseHandler =
                     new ResponseHandler(httpClient, logger, channel, requestId);
 
@@ -521,7 +524,7 @@ public Result execute(Request kvRequest) {
                     responseHandler.await(thisIterationTimeoutMs);
                 if (isTimeout) {
                     throw new TimeoutException("Request timed out after " +
-                        timeoutMs + " milliseconds");
+                        timeoutMs + " milliseconds: requestId=" + requestId);
                 }
 
                 if (isLoggable(logger, Level.FINE)) {
@@ -687,6 +690,7 @@ public Result execute(Request kvRequest) {
                 throw new NoSQLException(
                     "Unable to execute request: " + ee.getCause().getMessage());
             } catch (TimeoutException te) {
+                exception = te;
                 logInfo(logger, "Timeout exception: " + te);
                 break; /* fall through to exception below */
             } catch (Throwable t) {
@@ -721,8 +725,9 @@ public Result execute(Request kvRequest) {
         kvRequest.setRateLimitDelayedMs(rateDelayedMs);
         statsControl.observeError(kvRequest);
         throw new RequestTimeoutException(timeoutMs,
-            "Request timed out after " + kvRequest.getNumRetries() +
-            (kvRequest.getNumRetries() == 1 ? " retry. " : " retries. ") +
+            requestClass + " timed out: requestId=" + requestId + " " +
+            " nextRequestId=" + nextRequestId() +
+            " iterationTimeout=" + thisIterationTimeoutMs + "ms " +
             (kvRequest.getRetryStats() != null ?
                 kvRequest.getRetryStats() : ""), exception);
     }

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

@@ -97,6 +97,12 @@ public class HttpClient {
     private final int port;
     private final String name;
 
+    /*
+     * Amount of time to wait for acquiring a channel before timing
+     * out and possibly retrying
+     */
+    private final int acquireRetryIntervalMs;
+
     /*
      * Non-null if using SSL
      */
@@ -225,6 +231,11 @@ public HttpClient(String host,
             connectionPoolSize,
             poolMaxPending,
             true); /* do health check on release */
+
+        /* TODO: eventually add this to Config? */
+        acquireRetryIntervalMs = Integer.getInteger(
+                                    "oracle.nosql.driver.acquire.retryinterval",
+                                    1000);
     }
 
     SslContext getSslContext() {
@@ -304,31 +315,67 @@ public void shutdown() {
     public Channel getChannel(int timeoutMs)
         throws InterruptedException, ExecutionException, TimeoutException {
 
+        long startMs = System.currentTimeMillis();
+        long now = startMs;
+        int retries = 0;
+
         while (true) {
+            long msDiff = now - startMs;
+
+            /* retry loop with at most (retryInterval) ms timeouts */
+            long thisTimeoutMs = (timeoutMs - msDiff);
+            if (thisTimeoutMs <= 0) {
+                String msg = "Timed out after " + msDiff +
+                             "ms (" + retries + " retries) trying " +
+                             "to acquire channel";
+                logInfo(logger, "HttpClient " + name + " " + msg);
+                throw new TimeoutException(msg);
+            }
+            if (thisTimeoutMs > acquireRetryIntervalMs) {
+                thisTimeoutMs = acquireRetryIntervalMs;
+            }
             Future<Channel> fut = pool.acquire();
-            Channel retChan = fut.get(timeoutMs, TimeUnit.MILLISECONDS);
+            Channel retChan = null;
+            try {
+                retChan = fut.get(thisTimeoutMs, TimeUnit.MILLISECONDS);
+            } catch (TimeoutException e) {
+                if (retries == 0) {
+                    logInfo(logger, "Timed out after " + msDiff +
+                             "ms trying to acquire channel: retrying");
+                }
+                /* fall through */
+            }
+
             /*
-             * Ensure that the channel is in good shape
+             * Ensure that the channel is in good shape. retChan is null
+             * on a timeout exception from above; that path will retry.
              */
-            if (fut.isSuccess() && retChan.isActive()) {
-                /*
-                 * Clear out any previous state. The channel should not
-                 * have any state associated with it, but this code is here
-                 * just in case it does.
-                 */
-                if (retChan.attr(STATE_KEY).get() != null) {
-                    if (isFineEnabled(logger)) {
-                        logFine(logger, "HttpClient acquired a channel with " +
-                                "a still-active state: clearing.");
+            if (retChan != null) {
+                if (fut.isSuccess() && retChan.isActive()) {
+                    /*
+                     * Clear out any previous state. The channel should not
+                     * have any state associated with it, but this code is here
+                     * just in case it does.
+                     */
+                    if (retChan.attr(STATE_KEY).get() != null) {
+                        if (isFineEnabled(logger)) {
+                            logFine(logger,
+                                    "HttpClient acquired a channel with " +
+                                    "a still-active state: clearing.");
+                        }
+                        retChan.attr(STATE_KEY).set(null);
                     }
-                    retChan.attr(STATE_KEY).set(null);
+                    return retChan;
                 }
-                return retChan;
+                logFine(logger,
+                        "HttpClient " + name + ", acquired an inactive " +
+                        "channel, releasing it and retrying, reason: " +
+                        fut.cause());
+                releaseChannel(retChan);
             }
-            logInfo(logger,
-                    "HttpClient " + name + ", acquired an inactive channel, " +
-                    "releasing it and retrying, reason: " + fut.cause());
-            releaseChannel(retChan);
+            /* reset "now" and increment retries */
+            now = System.currentTimeMillis();
+            retries++;
         }
     }