Add robustness to some of the timing-susceptible metrics tests; add util matcher with retry (helidon-io#5047)

tjquinno · web-flow · commit d0059b98afe0 · 2022-10-04T01:20:31.000-04:00
Signed-off-by: tim.quinn@oracle.com &lt;tim.quinn@oracle.com&gt;

Signed-off-by: tim.quinn@oracle.com &lt;tim.quinn@oracle.com&gt;
diff --git a/config/testing/src/main/java/io/helidon/config/testing/MatcherWithRetry.java b/config/testing/src/main/java/io/helidon/config/testing/MatcherWithRetry.java
@@ -0,0 +1,82 @@
+/*
+ * Copyright (c) 2022 Oracle and/or its affiliates.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package io.helidon.config.testing;
+
+import java.util.concurrent.Callable;
+import java.util.function.Supplier;
+
+import org.hamcrest.Description;
+import org.hamcrest.Matcher;
+import org.hamcrest.StringDescription;
+
+/**
+ * Hamcrest matcher capable of configured retries before failing the assertion, plus more generic retry processing.
+ */
+public class MatcherWithRetry {
+
+    private static final int RETRY_COUNT = Integer.getInteger("io.helidon.test.retryCount", 10);
+    private static final int RETRY_DELAY_MS = Integer.getInteger("io.helidon.test.retryDelayMs", 500);
+
+    private MatcherWithRetry() {
+    }
+
+    /**
+     * Checks the matcher, possibly multiple times after configured delays, invoking the supplier of the matched value each time,
+     * until either the matcher passes or the maximum retry expires.
+     * @param reason explanation of the assertion
+     * @param actualSupplier {@code Supplier} that furnishes the value to submit to the matcher
+     * @param matcher Hamcrest matcher which evaluates the supplied value
+     * @return the supplied value
+     * @param <T> type of the supplied value
+     * @throws InterruptedException if the sleep is interrupted
+     */
+    public static <T> T assertThatWithRetry(String reason, Supplier<T> actualSupplier, Matcher<? super T> matcher)
+            throws InterruptedException {
+
+        T actual = null;
+        for (int i = 0; i < RETRY_COUNT; i++) {
+            actual = actualSupplier.get();
+            if (matcher.matches(actual)) {
+                return actual;
+            }
+            Thread.sleep(RETRY_DELAY_MS);
+        }
+
+        Description description = new StringDescription();
+        description.appendText(reason)
+                .appendText("\nExpected: ")
+                .appendDescriptionOf(matcher)
+                .appendText("\n     but: ");
+        matcher.describeMismatch(actual, description);
+
+        throw new AssertionError(description.toString());
+    }
+
+    /**
+     * Retries the specified work until successful or retry limit is exceeded.
+     *
+     * @param work the work to perform; returned boolean indicates if the work was successful
+     * @throws Exception exception from the work or from the sleep being interrupted
+     */
+    public static void retry(Callable<Boolean> work) throws Exception {
+        for (int i = 0; i < RETRY_COUNT; i++) {
+            if (work.call()) {
+                return;
+            }
+            Thread.sleep(RETRY_DELAY_MS);
+        }
+    }
+}
diff --git a/metrics/metrics/pom.xml b/metrics/metrics/pom.xml
@@ -87,6 +87,11 @@
             <artifactId>helidon-webclient</artifactId>
             <scope>test</scope>
         </dependency>
+        <dependency>
+            <groupId>io.helidon.config</groupId>
+            <artifactId>helidon-config-testing</artifactId>
+            <scope>test</scope>
+        </dependency>
         <dependency>
             <groupId>org.junit.jupiter</groupId>
             <artifactId>junit-jupiter-api</artifactId>
diff --git a/metrics/metrics/src/test/java/io/helidon/metrics/TestServer.java b/metrics/metrics/src/test/java/io/helidon/metrics/TestServer.java
@@ -28,6 +28,7 @@
 
 import io.helidon.common.http.Http;
 import io.helidon.common.http.MediaType;
+import io.helidon.config.testing.MatcherWithRetry;
 import io.helidon.media.jsonp.JsonpSupport;
 import io.helidon.webclient.WebClient;
 import io.helidon.webclient.WebClientRequestBuilder;
@@ -187,7 +188,7 @@ void checkKPIDisabledByDefault() {
     }
 
     @Test
-    void checkMetricsForExecutorService() {
+    void checkMetricsForExecutorService() throws Exception {
 
         String jsonKeyForCompleteTaskCountInThreadPool =
                 "executor-service.completed-task-count;poolIndex=0;supplierCategory=my-thread-thread-pool-1;supplierIndex=0";
@@ -223,22 +224,25 @@ void checkMetricsForExecutorService() {
 
         assertThat("Slow greet access response status", slowGreetResponse.status().code(), is(200));
 
-        WebClientResponse secondMetricsResponse = metricsRequestBuilder
-                .submit()
-                .await(CLIENT_TIMEOUT);
+        MatcherWithRetry.retry(() -> {
 
-        assertThat("Second access to metrics", secondMetricsResponse.status().code(), is(200));
+            WebClientResponse secondMetricsResponse = metricsRequestBuilder
+                    .submit()
+                    .await(CLIENT_TIMEOUT);
 
-        JsonObject secondMetrics = secondMetricsResponse.content().as(JsonObject.class).await(CLIENT_TIMEOUT);
+            assertThat("Second access to metrics", secondMetricsResponse.status().code(), is(200));
 
-        assertThat("JSON metrics results after accessing slow endpoint",
-                   secondMetrics,
-                   hasKey(jsonKeyForCompleteTaskCountInThreadPool));
+            JsonObject secondMetrics = secondMetricsResponse.content().as(JsonObject.class).await(CLIENT_TIMEOUT);
 
+            assertThat("JSON metrics results after accessing slow endpoint",
+                       secondMetrics,
+                       hasKey(jsonKeyForCompleteTaskCountInThreadPool));
 
-        int secondCompletedTaskCount = secondMetrics.getInt(jsonKeyForCompleteTaskCountInThreadPool);
+            int secondCompletedTaskCount = secondMetrics.getInt(jsonKeyForCompleteTaskCountInThreadPool);
 
-        assertThat("Completed task count after accessing slow endpoint", secondCompletedTaskCount, is(1));
+            assertThat("Completed task count after accessing slow endpoint", secondCompletedTaskCount, is(1));
+            return true;
+        });
     }
 
     @ParameterizedTest
diff --git a/microprofile/metrics/pom.xml b/microprofile/metrics/pom.xml
@@ -97,6 +97,11 @@
             <artifactId>helidon-microprofile-tests-junit5</artifactId>
             <scope>test</scope>
         </dependency>
+        <dependency>
+            <groupId>io.helidon.config</groupId>
+            <artifactId>helidon-config-testing</artifactId>
+            <scope>test</scope>
+        </dependency>
     </dependencies>
 
     <build>
diff --git a/microprofile/metrics/src/test/java/io/helidon/microprofile/metrics/HelloWorldAsyncResponseTest.java b/microprofile/metrics/src/test/java/io/helidon/microprofile/metrics/HelloWorldAsyncResponseTest.java
@@ -38,6 +38,7 @@
 import org.eclipse.microprofile.metrics.annotation.RegistryType;
 import org.junit.jupiter.api.Test;
 
+import static io.helidon.config.testing.MatcherWithRetry.assertThatWithRetry;
 import static io.helidon.metrics.api.KeyPerformanceIndicatorMetricsSettings.Builder.KEY_PERFORMANCE_INDICATORS_CONFIG_KEY;
 import static io.helidon.metrics.api.KeyPerformanceIndicatorMetricsSettings.Builder.KEY_PERFORMANCE_INDICATORS_EXTENDED_CONFIG_KEY;
 import static io.helidon.microprofile.metrics.HelloWorldResource.SLOW_MESSAGE_SIMPLE_TIMER;
@@ -117,9 +118,9 @@ public void test() throws Exception {
 
         Duration minDuration = Duration.ofMillis(HelloWorldResource.SLOW_DELAY_MS);
 
-        assertThat("Change in count for explicit SimpleTimer",
-                explicitSimpleTimer.getCount() - explicitSimpleTimerCountBefore, is(1L));
-        long explicitDiffNanos = explicitSimpleTimer.getElapsedTime().toNanos() - explicitSimpleTimerDurationBefore.toNanos();
+        assertThatWithRetry("Change in count for explicit SimpleTimer",
+                            () -> explicitSimpleTimer.getCount() - explicitSimpleTimerCountBefore,
+                            is(1L));long explicitDiffNanos = explicitSimpleTimer.getElapsedTime().toNanos() - explicitSimpleTimerDurationBefore.toNanos();
         assertThat("Change in elapsed time for explicit SimpleTimer", explicitDiffNanos, is(greaterThan(minDuration.toNanos())));
 
         long syntheticDiffNanos = simpleTimer.getElapsedTime().toNanos() - syntheticaSimpleTimerDurationBefore.toNanos();
diff --git a/microprofile/metrics/src/test/java/io/helidon/microprofile/metrics/HelloWorldAsyncResponseWithRestRequestTest.java b/microprofile/metrics/src/test/java/io/helidon/microprofile/metrics/HelloWorldAsyncResponseWithRestRequestTest.java
@@ -16,7 +16,6 @@
 package io.helidon.microprofile.metrics;
 
 import java.util.Map;
-import java.util.concurrent.TimeUnit;
 
 import io.helidon.microprofile.tests.junit5.AddConfig;
 import io.helidon.microprofile.tests.junit5.HelidonTest;
@@ -31,6 +30,7 @@
 import jakarta.ws.rs.core.Response;
 import org.junit.jupiter.api.Test;
 
+import static io.helidon.config.testing.MatcherWithRetry.assertThatWithRetry;
 import static org.hamcrest.MatcherAssert.assertThat;
 import static org.hamcrest.Matchers.containsString;
 import static org.hamcrest.Matchers.greaterThan;
@@ -53,10 +53,11 @@ void checkForAsyncMethodRESTRequestMetric() throws NoSuchMethodException {
         JsonObject restRequest = getRESTRequestJSON();
 
         // Make sure count is 0 before invoking.
-        JsonNumber getAsyncCount = JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(restRequest,
-                                                                                              "count",
-                                                                                              false));
-        assertThat("getAsync count value before invocation", getAsyncCount.longValue(), is(0L));
+        long getAsyncCount = JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(restRequest,
+                                                                                        "count",
+                                                                                        false))
+                .longValue();
+        assertThat("getAsync count value before invocation", getAsyncCount, is(0L));
 
         JsonNumber getAsyncTime = JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(restRequest,
                                                                                              "elapsedTime",
@@ -85,15 +86,20 @@ void checkForAsyncMethodRESTRequestMetric() throws NoSuchMethodException {
         // Retrieve metrics again and make sure we see an additional count and added time. Don't bother checking the min and
         // max because we'd have to wait up to a minute for those values to change.
 
-        restRequest = getRESTRequestJSON();
+        JsonObject nextRestRequest = getRESTRequestJSON();
 
         try {
-            getAsyncCount = JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(restRequest,
-                                                                                       "count",
-                                                                                       false));
-            assertThat("getAsync count value after invocation", getAsyncCount.longValue(), is(1L));
+            // With async endpoints, metrics updates can occur after the server sends the response.
+            // Retry as needed for a little while for the count to change.
+            assertThatWithRetry("getAsync count value after invocation",
+                                () -> JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(nextRestRequest,
+                                                                                                 "count",
+                                                                                                 false))
+                                        .longValue(),
+                                is(1L));
 
-            getAsyncTime = JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(restRequest,
+
+            getAsyncTime = JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(nextRestRequest,
                                                                                       "elapsedTime",
                                                                                       false));
             assertThat("getAsync elapsedTime value after invocation", getAsyncTime.longValue(), is(greaterThan(0L)));
@@ -124,20 +130,24 @@ private JsonObject getRESTRequestJSON() {
 
     private JsonValue getRESTRequestValueForGetAsyncMethod(JsonObject restRequestJson,
                                                            String valueName,
-                                                           boolean nullOK) throws NoSuchMethodException {
+                                                           boolean nullOK) {
         JsonValue getAsyncValue = null;
 
         for (Map.Entry<String, JsonValue> entry : restRequestJson.entrySet()) {
             // Conceivably there could be multiple tags in the metric ID besides the class and method ones, so do not assume
             // the key value in the JSON object has only the class and method tags and only in that order.
-            if (entry.getKey().startsWith(valueName + ";")
-                    && entry.getKey().contains("class=" + HelloWorldResource.class.getName())
-                    && entry.getKey().contains(
-                    "method="
-                            + HelloWorldResource.class.getMethod("getAsync", AsyncResponse.class).getName()
-                            + "_" + AsyncResponse.class.getName())) {
-                getAsyncValue = entry.getValue();
-                break;
+            try {
+                if (entry.getKey().startsWith(valueName + ";")
+                        && entry.getKey().contains("class=" + HelloWorldResource.class.getName())
+                        && entry.getKey().contains(
+                        "method="
+                                + HelloWorldResource.class.getMethod("getAsync", AsyncResponse.class).getName()
+                                + "_" + AsyncResponse.class.getName())) {
+                    getAsyncValue = entry.getValue();
+                    break;
+                }
+            } catch (NoSuchMethodException e) {
+                throw new RuntimeException(e);
             }
         }
 
diff --git a/microprofile/metrics/src/test/java/io/helidon/microprofile/metrics/HelloWorldTest.java b/microprofile/metrics/src/test/java/io/helidon/microprofile/metrics/HelloWorldTest.java
@@ -41,6 +41,7 @@
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
 
+import static io.helidon.config.testing.MatcherWithRetry.assertThatWithRetry;
 import static io.helidon.microprofile.metrics.HelloWorldResource.MESSAGE_SIMPLE_TIMER;
 import static org.hamcrest.MatcherAssert.assertThat;
 import static org.hamcrest.Matchers.is;
@@ -151,7 +152,9 @@ public void testMappedException() throws Exception {
         );
 
         assertThat("Response code from mapped exception endpoint", response.getStatus(), is(500));
-        assertThat("Change in successful count", simpleTimer.getCount() - successfulBeforeRequest, is(1L));
+        assertThatWithRetry("Change in successful count",
+                            () -> simpleTimer.getCount() - successfulBeforeRequest,
+                            is(1L));
         assertThat("Change in unsuccessful count", counter.getCount() - unsuccessfulBeforeRequest, is(0L));
     }
 
@@ -172,7 +175,9 @@ void testUnmappedException() throws Exception {
         );
 
         assertThat("Response code from unmapped exception endpoint", response.getStatus(), is(500));
-        assertThat("Change in successful count", simpleTimer.getCount() - successfulBeforeRequest, is(0L));
+        assertThatWithRetry("Change in successful count",
+                            () -> simpleTimer.getCount() - successfulBeforeRequest,
+                            is(0L));
         assertThat("Change in unsuccessful count", counter.getCount() - unsuccessfulBeforeRequest, is(1L));
     }
 
