JVMCBC-1664 ArrayIndexOutOfBoundsException when request takes more than 1 hour

Motivation
----------
When a request takes more than ~1 hour* (like a long-running
Analytics query), AggregatingValueRecorder.recordValue()
throws ArrayIndexOutOfBoundsException. This exception
can mask an underlying cause, like request timeout
or cancellation.

* The actual threshold is closer to 1 hour, 13 minutes, 18 seconds.

Modifications
-------------
If the recorder throws an exception, log a warning
instead of recording a value.

Rejected Alternatives
---------------------
Could initialize AggregatingValueRecorder.recorderStats
with a `highestTrackableLatency` of several hours,
but that would require allocating hundreds more histogram buckets,
with an unknown impact on performance / resource usage.

Change-Id: I7da205baa9b34cc06d4b3b797c8d8ae0471ab0ec
Reviewed-on: https://review.couchbase.org/c/couchbase-jvm-clients/+/229979
Tested-by: Build Bot <[email protected]>
Reviewed-by: Michael Reiche <[email protected]>

Author: dnault

core-io/src/main/java/com/couchbase/client/core/msg/RequestContext.java

@@ -28,6 +28,8 @@
 import com.couchbase.client.core.retry.RetryReason;
 import com.couchbase.client.core.topology.NodeIdentifier;
 import com.couchbase.client.core.util.HostAndPort;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import reactor.util.annotation.Nullable;
 
 import java.time.Duration;
@@ -51,6 +53,7 @@
  * @since 2.0.0
  */
 public class RequestContext extends CoreContext {
+  private static final Logger log = LoggerFactory.getLogger(RequestContext.class);
 
   /**
    * Holds the last dispatch latency if set already (or at all).
@@ -239,7 +242,11 @@ public RequestContext logicallyComplete(@Nullable Throwable err) {
     if (!(environment().meter() instanceof NoopMeter)) {
       long latency = logicalRequestLatency();
       if (latency > 0) {
-        core().responseMetric(request, err).recordValue(latency);
+        try {
+          core().responseMetric(request, err).recordValue(latency);
+        } catch (Exception e) {
+          log.warn("Failed to record request latency ({}). {}", Duration.ofNanos(latency), this, e);
+        }
       }
     }
 

core-io/src/main/java/com/couchbase/client/core/protostellar/ProtostellarRequest.java

@@ -31,10 +31,11 @@
 import com.couchbase.client.core.retry.RetryReason;
 import com.couchbase.client.core.retry.RetryStrategy;
 import com.couchbase.client.core.service.ServiceType;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import reactor.util.annotation.Nullable;
 
 import java.time.Duration;
-import java.util.Collections;
 import java.util.HashMap;
 import java.util.HashSet;
 import java.util.Map;
@@ -49,6 +50,8 @@
  */
 @Stability.Internal
 public class ProtostellarRequest<TGrpcRequest> {
+  private static final Logger log = LoggerFactory.getLogger(ProtostellarRequest.class);
+
   private final CoreProtostellar core;
   private final @Nullable RequestSpan span;
   private final long absoluteTimeout;
@@ -151,7 +154,11 @@ public void raisedResponseToUser(@Nullable Throwable err) {
       long latency = logicalRequestLatency();
       if (latency > 0) {
         Core.ResponseMetricIdentifier rmi = new Core.ResponseMetricIdentifier(serviceType.id(), requestName);
-        core.responseMetric(rmi).recordValue(latency);
+        try {
+          core.responseMetric(rmi).recordValue(latency);
+        } catch (Exception e) {
+          log.warn("Failed to record request latency ({}). {}", Duration.ofNanos(latency), context(), e);
+        }
       }
     }
   }