[3.x] Various metrics test improvements to avoid intermittent failures (

#5621)

config/testing/src/main/java/io/helidon/config/testing/MatcherWithRetry.java

@@ -22,6 +22,8 @@
 import org.hamcrest.Matcher;
 import org.hamcrest.StringDescription;
 
+import static org.junit.jupiter.api.Assertions.fail;
+
 /**
  * Hamcrest matcher capable of configured retries before failing the assertion, plus more generic retry processing.
  */
@@ -41,18 +43,20 @@ private MatcherWithRetry() {
      * @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 {
+    public static <T> T assertThatWithRetry(String reason, Supplier<T> actualSupplier, Matcher<? super T> matcher) {
 
         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);
+            try {
+                Thread.sleep(RETRY_DELAY_MS);
+            } catch (InterruptedException e) {
+                fail("Error sleeping during assertThatWithRetry", e);
+            }
         }
 
         Description description = new StringDescription();

integrations/micrometer/cdi/pom.xml

@@ -115,6 +115,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>

integrations/micrometer/cdi/src/test/java/io/helidon/integrations/micrometer/cdi/HelloWorldTest.java

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2018, 2021 Oracle and/or its affiliates.
+ * Copyright (c) 2018, 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.
@@ -31,6 +31,8 @@
 import jakarta.ws.rs.core.MediaType;
 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.is;
 import static org.hamcrest.Matchers.notNullValue;
@@ -95,7 +97,7 @@ public void testSlowTimer() {
         assertThat("Returned from HTTP request", result.get(), is(HelloWorldResource.SLOW_RESPONSE));
         Timer slowTimer = registry.timer(HelloWorldResource.SLOW_MESSAGE_TIMER);
         assertThat("Slow message timer", slowTimer, is(notNullValue()));
-        assertThat("Slow message timer count", slowTimer.count(), is((long) exp));
+        assertThatWithRetry("Slow message timer count", slowTimer::count, is((long) exp));
     }
 
     @Test
@@ -116,7 +118,7 @@ public void testFastFailCounter() {
 
         Counter counter = registry.counter(HelloWorldResource.FAST_MESSAGE_COUNTER);
         assertThat("Failed message counter", counter, is(notNullValue()));
-        assertThat("Failed message counter count", counter.count(), is((double) exp / 2));
+        assertThatWithRetry("Failed message counter count", counter::count, is((double) exp / 2));
     }
 
     @Test
@@ -151,7 +153,7 @@ public void testSlowFailCounter() {
 
         Counter counter = registry.counter(HelloWorldResource.SLOW_MESSAGE_FAIL_COUNTER);
         assertThat("Failed message counter", counter, is(notNullValue()));
-        assertThat("Failed message counter count", counter.count(), is((double) 3));
+        assertThatWithRetry("Failed message counter count", counter::count, is((double) 3));
     }
 
     void checkMicrometerURL(int iterations) {

integrations/micrometer/cdi/src/test/java/io/helidon/integrations/micrometer/cdi/MeteredBeanTest.java

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2021 Oracle and/or its affiliates.
+ * Copyright (c) 2021, 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.
@@ -24,6 +24,8 @@
 import jakarta.inject.Inject;
 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.is;
 import static org.junit.jupiter.api.Assertions.assertThrows;
@@ -42,22 +44,26 @@ public class MeteredBeanTest {
     public void testSimpleCounted() {
         int exp = 3;
         IntStream.range(0, exp).forEach(i -> meteredBean.count());
-        assertThat("Value from simple counted meter", registry.counter(MeteredBean.COUNTED).count(), is((double) exp));
+        assertThatWithRetry("Value from simple counted meter", () -> registry.counter(MeteredBean.COUNTED).count(),
+                            is((double) exp));
     }
 
     @Test
     public void testSinglyTimed() {
         int exp = 4;
         IntStream.range(0, exp).forEach(i -> meteredBean.timed());
-        assertThat("Count from singly-timed meter", registry.timer(MeteredBean.TIMED_1).count(), is((long) exp));
+        assertThatWithRetry("Count from singly-timed meter", () -> registry.timer(MeteredBean.TIMED_1).count(),
+                            is((long) exp));
     }
 
     @Test
     public void testDoublyTimed() {
         int exp = 5;
         IntStream.range(0, exp).forEach(i -> meteredBean.timedA());
-        assertThat("Count from doubly-timed meter (A)", registry.timer(MeteredBean.TIMED_A).count(), is((long) exp));
-        assertThat("Count from doubly-timed meter (B)", registry.timer(MeteredBean.TIMED_B).count(), is((long) exp));
+        assertThatWithRetry("Count from doubly-timed meter (A)", () -> registry.timer(MeteredBean.TIMED_A).count(),
+                            is((long) exp));
+        assertThatWithRetry("Count from doubly-timed meter (B)", () -> registry.timer(MeteredBean.TIMED_B).count(),
+                            is((long) exp));
     }
 
     @Test

metrics/metrics/src/test/java/io/helidon/metrics/TestPeriodicExecutor.java

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2021 Oracle and/or its affiliates.
+ * Copyright (c) 2021, 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.
@@ -18,6 +18,8 @@
 import java.time.Duration;
 import java.util.ArrayList;
 import java.util.List;
+import java.util.concurrent.CountDownLatch;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicInteger;
 import java.util.logging.Handler;
 import java.util.logging.Level;
@@ -33,20 +35,20 @@
 import static org.hamcrest.Matchers.containsString;
 import static org.hamcrest.Matchers.equalTo;
 import static org.hamcrest.Matchers.greaterThan;
+import static org.hamcrest.Matchers.greaterThanOrEqualTo;
 import static org.hamcrest.Matchers.is;
+import static org.junit.jupiter.api.Assertions.fail;
 
 class TestPeriodicExecutor {
 
-    private static final int SLEEP_TIME_MS = 1500;
-    private static final int SLEEP_TIME_NO_DATA_MS = 100;
+    private static final int APPROX_TEST_DURATION_MS = 1500;
+    private static final int MAX_TEST_WAIT_TIME_MS = APPROX_TEST_DURATION_MS * 15 / 10; // 1.5 * approx test duration
 
     private static final int FAST_INTERVAL = 250;
     private static final int SLOW_INTERVAL = 400;
 
-    private static final double SLOWDOWN_FACTOR = 0.80; // for slow pipelines!
-
-    private static final double MIN_FAST_COUNT = 1500 / FAST_INTERVAL * SLOWDOWN_FACTOR;
-    private static final double MIN_SLOW_COUNT = 1500 / SLOW_INTERVAL * SLOWDOWN_FACTOR;
+    private static final int MIN_FAST_COUNT = APPROX_TEST_DURATION_MS / FAST_INTERVAL;
+    private static final int MIN_SLOW_COUNT = APPROX_TEST_DURATION_MS / SLOW_INTERVAL;
 
     private static final Logger PERIODIC_EXECUTOR_LOGGER = Logger.getLogger(PeriodicExecutor.class.getName());
 
@@ -59,13 +61,28 @@ void testWithNoDeferrals() throws InterruptedException {
             AtomicInteger countA = new AtomicInteger();
             AtomicInteger countB = new AtomicInteger();
 
-            exec.enrollRunner(() -> countA.incrementAndGet(), Duration.ofMillis(FAST_INTERVAL));
-            exec.enrollRunner(() -> countB.incrementAndGet(), Duration.ofMillis(SLOW_INTERVAL));
+            CountDownLatch latchA = new CountDownLatch(MIN_FAST_COUNT);
+            CountDownLatch latchB = new CountDownLatch(MIN_SLOW_COUNT);
+
+            long startTime = System.nanoTime();
+            exec.enrollRunner(() -> {
+                countA.incrementAndGet();
+                latchA.countDown();
+            }, Duration.ofMillis(FAST_INTERVAL));
+
+            exec.enrollRunner(() -> {
+                countB.incrementAndGet();
+                latchB.countDown();
+            }, Duration.ofMillis(SLOW_INTERVAL));
 
-            Thread.sleep(SLEEP_TIME_MS);
+            assertThat("Wait latch for fast interval", latchA.await(MAX_TEST_WAIT_TIME_MS, TimeUnit.MILLISECONDS), is(true));
+            assertThat("Wait latch for slow interval", latchB.await(MAX_TEST_WAIT_TIME_MS, TimeUnit.MILLISECONDS), is(true));
 
-            assertThat("CountA", (double) countA.get(), is(greaterThan(MIN_FAST_COUNT)));
-            assertThat("CountB", (double) countB.get(), is(greaterThan(MIN_SLOW_COUNT)));
+            Duration elapsedTime = Duration.ofNanos(System.nanoTime() - startTime);
+
+            assertThat("CountA", countA.get(), is(greaterThanOrEqualTo(MIN_FAST_COUNT)));
+            assertThat("CountB", countB.get(), is(greaterThanOrEqualTo(MIN_SLOW_COUNT)));
+            assertThat("Wait duration", elapsedTime, greaterThanOrEqualTo(Duration.ofMillis(1500)));
         } finally {
             if (exec.executorState() == PeriodicExecutor.State.STARTED) {
                 exec.stopExecutor();
@@ -80,16 +97,23 @@ void testWithDeferredEnrollments() throws InterruptedException {
             AtomicInteger countA = new AtomicInteger();
             AtomicInteger countB = new AtomicInteger();
 
-            exec.enrollRunner(() -> countA.incrementAndGet(), Duration.ofMillis(FAST_INTERVAL));
+            CountDownLatch latchA = new CountDownLatch(MIN_FAST_COUNT);
+            CountDownLatch latchB = new CountDownLatch(MIN_SLOW_COUNT);
 
-            exec.startExecutor();
+            exec.enrollRunner(() -> {
+                countA.incrementAndGet();
+                latchA.countDown();
+            }, Duration.ofMillis(FAST_INTERVAL));
 
-            exec.enrollRunner(() -> countB.incrementAndGet(), Duration.ofMillis(SLOW_INTERVAL));
+            exec.startExecutor();
 
-            Thread.sleep(SLEEP_TIME_MS);
+            exec.enrollRunner(() -> {
+                countB.incrementAndGet();
+                latchB.countDown();
+            }, Duration.ofMillis(SLOW_INTERVAL));
 
-            assertThat("CountA", (double) countA.get(), is(greaterThan(MIN_FAST_COUNT)));
-            assertThat("CountB", (double) countB.get(), is(greaterThan(MIN_SLOW_COUNT)));
+            assertThat("Wait latch for fast interval", latchA.await(MAX_TEST_WAIT_TIME_MS, TimeUnit.MILLISECONDS), is(true));
+            assertThat("Wait latch for slow interval", latchB.await(MAX_TEST_WAIT_TIME_MS, TimeUnit.MILLISECONDS), is(true));
         } finally {
             if (exec.executorState() == PeriodicExecutor.State.STARTED) {
                 exec.stopExecutor();
@@ -104,17 +128,25 @@ void testWithLateEnrollment() throws InterruptedException {
             AtomicInteger countA = new AtomicInteger();
             AtomicInteger countB = new AtomicInteger();
 
-            exec.enrollRunner(() -> countA.incrementAndGet(), Duration.ofMillis(FAST_INTERVAL));
+            CountDownLatch latchA = new CountDownLatch(MIN_FAST_COUNT);
+
+            exec.enrollRunner(() -> {
+                countA.incrementAndGet();
+                latchA.countDown();
+            }, Duration.ofMillis(FAST_INTERVAL));
 
             exec.startExecutor();
-            Thread.sleep(SLEEP_TIME_MS);
+            assertThat("Wait latch", latchA.await(MAX_TEST_WAIT_TIME_MS, TimeUnit.MILLISECONDS), is(true));
 
             exec.stopExecutor();
 
             exec.enrollRunner(() -> countB.incrementAndGet(), Duration.ofMillis(SLOW_INTERVAL));
 
-            assertThat("CountA", (double) countA.get(), is(greaterThan(MIN_FAST_COUNT))); // should be 8
-            assertThat("CountB", (double) countB.get(), is(0.0));
+            // The executor is no longer running, so we cannot use a countdown latch to know when to check countB. Use time.
+            Thread.sleep(MAX_TEST_WAIT_TIME_MS);
+
+            assertThat("CountA", countA.get(), is(greaterThanOrEqualTo(MIN_FAST_COUNT))); // should be 8
+            assertThat("CountB", countB.get(), is(0));
         } finally {
             if (exec.executorState() == PeriodicExecutor.State.STARTED) {
                 exec.stopExecutor();
@@ -130,7 +162,8 @@ void testNoWarningOnStopWhenStopped() throws InterruptedException {
         try {
             PeriodicExecutor executor = PeriodicExecutor.create();
             executor.stopExecutor();
-            Thread.sleep(SLEEP_TIME_NO_DATA_MS);
+
+            waitForExecutorState(executor, PeriodicExecutor.State.STOPPED);
             handler.clear();
 
             executor.stopExecutor();
@@ -152,7 +185,7 @@ void testFineMessageOnStopWhenStopped() throws InterruptedException {
             PERIODIC_EXECUTOR_LOGGER.setLevel(Level.FINE);
             PeriodicExecutor executor = PeriodicExecutor.create();
             executor.stopExecutor();
-            Thread.sleep(SLEEP_TIME_NO_DATA_MS);
+            waitForExecutorState(executor, PeriodicExecutor.State.STOPPED);
 
             executor.stopExecutor();
             handler.clear();
@@ -184,7 +217,7 @@ void testFineLoggingOnExpectedStop(PeriodicExecutor.State testState) throws Inte
 
             if (testState == PeriodicExecutor.State.STARTED) {
                 executor.startExecutor();
-                Thread.sleep(SLEEP_TIME_NO_DATA_MS);
+                waitForExecutorState(executor, PeriodicExecutor.State.STARTED);
             }
 
             handler.clear();
@@ -205,6 +238,15 @@ void testFineLoggingOnExpectedStop(PeriodicExecutor.State testState) throws Inte
         }
     }
 
+    private void waitForExecutorState(PeriodicExecutor executor, PeriodicExecutor.State expectedState) {
+        for (int i = MAX_TEST_WAIT_TIME_MS; i > 0; i -= 500) {
+            if (executor.executorState() == expectedState) {
+                return;
+            }
+        }
+        fail("Timed out waiting for executor in state " + executor.executorState() + " to enter state " + expectedState.name());
+    }
+
     private static class MyHandler extends Handler {
 
         private List<LogRecord> logRecords = new ArrayList<>();

microprofile/metrics/src/test/java/io/helidon/microprofile/metrics/HelloWorldAsyncResponseTest.java

@@ -133,7 +133,7 @@ public void test() throws Exception {
     }
 
     @Test
-    public void testAsyncWithArg() throws InterruptedException {
+    public void testAsyncWithArg() {
         LongStream.range(0, 3).forEach(
                 i -> webTarget
                         .path("helloworld/slowWithArg/Johan")

microprofile/metrics/src/test/java/io/helidon/microprofile/metrics/HelloWorldAsyncResponseWithRestRequestTest.java

@@ -88,28 +88,23 @@ void checkForAsyncMethodRESTRequestMetric() throws NoSuchMethodException {
 
         AtomicReference<JsonObject> nextRestRequest = new AtomicReference<>();
 
-        try {
-            // With async endpoints, metrics updates can occur after the server sends the response.
-            // Retry as needed (including fetching the metrics again) for a little while for the count to change.
-            assertThatWithRetry("getAsync count value after invocation",
-                                () -> JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(
-                                                // Set the reference using fresh metrics and get that newly-set JSON object, then
-                                                // extract the 'count' field cast as a number.
-                                                nextRestRequest.updateAndGet(old -> getRESTRequestJSON()),
-                                                "count",
-                                                false))
-                                        .longValue(),
-                                is(1L));
-
-            // Reuse (no need to update the atomic reference again) the freshly-fetched metrics JSON.
-             getAsyncTime = JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(nextRestRequest.get(),
-                                                                                      "elapsedTime",
-                                                                                      false));
-            assertThat("getAsync elapsedTime value after invocation", getAsyncTime.longValue(), is(greaterThan(0L)));
-        } catch (Exception e) {
-            throw new RuntimeException("Dump of REST.request metrics due to following assertion failure\n"
-                                               + restRequest, e);
-        }
+        // With async endpoints, metrics updates can occur after the server sends the response.
+        // Retry as needed (including fetching the metrics again) for a little while for the count to change.
+        assertThatWithRetry("getAsync count value after invocation",
+                            () -> JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(
+                                            // Set the reference using fresh metrics and get that newly-set JSON object, then
+                                            // extract the 'count' field cast as a number.
+                                            nextRestRequest.updateAndGet(old -> getRESTRequestJSON()),
+                                            "count",
+                                            false))
+                                    .longValue(),
+                            is(1L));
+
+        // Reuse (no need to update the atomic reference again) the freshly-fetched metrics JSON.
+         getAsyncTime = JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(nextRestRequest.get(),
+                                                                                  "elapsedTime",
+                                                                                  false));
+        assertThat("getAsync elapsedTime value after invocation", getAsyncTime.longValue(), is(greaterThan(0L)));
     }
 
     private JsonObject getRESTRequestJSON() {