improve assertions by showing the last result on a timeout (#13119)

Author: zeitlinger

testing-common/src/main/java/io/opentelemetry/instrumentation/testing/InstrumentationTestRunner.java

@@ -18,6 +18,7 @@
 import io.opentelemetry.sdk.testing.assertj.TraceAssert;
 import io.opentelemetry.sdk.testing.assertj.TracesAssert;
 import io.opentelemetry.sdk.trace.data.SpanData;
+import java.time.Duration;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Collection;
@@ -29,6 +30,7 @@
 import java.util.stream.Collectors;
 import javax.annotation.Nullable;
 import org.assertj.core.api.ListAssert;
+import org.awaitility.core.ConditionFactory;
 import org.awaitility.core.ConditionTimeoutException;
 
 /**
@@ -118,25 +120,7 @@ private <T extends Consumer<TraceAssert>> void waitAndAssertTraces(
     List<T> assertionsList = new ArrayList<>();
     assertions.forEach(assertionsList::add);
 
-    try {
-      await()
-          .untilAsserted(() -> doAssertTraces(traceComparator, assertionsList, verifyScopeVersion));
-    } catch (Throwable t) {
-      // awaitility is doing a jmx call that is not implemented in GraalVM:
-      // call:
-      // https://github.com/awaitility/awaitility/blob/fbe16add874b4260dd240108304d5c0be84eabc8/awaitility/src/main/java/org/awaitility/core/ConditionAwaiter.java#L157
-      // see https://github.com/oracle/graal/issues/6101 (spring boot graal native image)
-      if (t.getClass().getName().equals("com.oracle.svm.core.jdk.UnsupportedFeatureError")
-          || t instanceof ConditionTimeoutException) {
-        // Don't throw this failure since the stack is the awaitility thread, causing confusion.
-        // Instead, just assert one more time on the test thread, which will fail with a better
-        // stack trace.
-        // TODO: There is probably a better way to do this.
-        doAssertTraces(traceComparator, assertionsList, verifyScopeVersion);
-      } else {
-        throw t;
-      }
-    }
+    awaitUntilAsserted(() -> doAssertTraces(traceComparator, assertionsList, verifyScopeVersion));
   }
 
   private <T extends Consumer<TraceAssert>> void doAssertTraces(
@@ -159,31 +143,42 @@ private <T extends Consumer<TraceAssert>> void doAssertTraces(
    */
   public final void waitAndAssertMetrics(
       String instrumentationName, String metricName, Consumer<ListAssert<MetricData>> assertion) {
-    await()
-        .untilAsserted(
-            () ->
-                assertion.accept(
-                    assertThat(getExportedMetrics())
-                        .filteredOn(
-                            data ->
-                                data.getInstrumentationScopeInfo()
-                                        .getName()
-                                        .equals(instrumentationName)
-                                    && data.getName().equals(metricName))));
+
+    awaitUntilAsserted(
+        () ->
+            assertion.accept(
+                assertThat(getExportedMetrics())
+                    .describedAs(
+                        "Metrics for instrumentation %s and metric name %s",
+                        instrumentationName, metricName)
+                    .filteredOn(
+                        data ->
+                            data.getInstrumentationScopeInfo().getName().equals(instrumentationName)
+                                && data.getName().equals(metricName))));
   }
 
   @SafeVarargs
   public final void waitAndAssertMetrics(
       String instrumentationName, Consumer<MetricAssert>... assertions) {
-    await()
-        .untilAsserted(
-            () -> {
-              Collection<MetricData> metrics = instrumentationMetrics(instrumentationName);
-              assertThat(metrics).isNotEmpty();
-              for (Consumer<MetricAssert> assertion : assertions) {
-                assertThat(metrics).anySatisfy(metric -> assertion.accept(assertThat(metric)));
-              }
-            });
+    awaitUntilAsserted(
+        () -> {
+          Collection<MetricData> metrics = instrumentationMetrics(instrumentationName);
+          assertThat(metrics).isNotEmpty();
+          for (int i = 0; i < assertions.length; i++) {
+            int index = i;
+            assertThat(metrics)
+                .describedAs(
+                    "Metrics for instrumentation %s and assertion %d", instrumentationName, index)
+                .anySatisfy(metric -> assertions[index].accept(assertThat(metric)));
+          }
+        });
+  }
+
+  public final List<LogRecordData> waitForLogRecords(int numberOfLogRecords) {
+    awaitUntilAsserted(
+        () -> assertThat(getExportedLogRecords().size()).isEqualTo(numberOfLogRecords),
+        await().timeout(Duration.ofSeconds(20)));
+    return getExportedLogRecords();
   }
 
   private List<MetricData> instrumentationMetrics(String instrumentationName) {
@@ -265,4 +260,29 @@ public final <T, E extends Throwable> T runWithNonRecordingSpan(ThrowingSupplier
       throws E {
     return testInstrumenters.runWithNonRecordingSpan(callback);
   }
+
+  private static void awaitUntilAsserted(Runnable runnable) {
+    awaitUntilAsserted(runnable, await());
+  }
+
+  private static void awaitUntilAsserted(Runnable runnable, ConditionFactory conditionFactory) {
+    try {
+      conditionFactory.untilAsserted(runnable::run);
+    } catch (Throwable t) {
+      // awaitility is doing a jmx call that is not implemented in GraalVM:
+      // call:
+      // https://github.com/awaitility/awaitility/blob/fbe16add874b4260dd240108304d5c0be84eabc8/awaitility/src/main/java/org/awaitility/core/ConditionAwaiter.java#L157
+      // see https://github.com/oracle/graal/issues/6101 (spring boot graal native image)
+      if (t.getClass().getName().equals("com.oracle.svm.core.jdk.UnsupportedFeatureError")
+          || t instanceof ConditionTimeoutException) {
+        // Don't throw this failure since the stack is the awaitility thread, causing confusion.
+        // Instead, just assert one more time on the test thread, which will fail with a better
+        // stack trace - that is on the same thread as the test.
+        // TODO: There is probably a better way to do this.
+        runnable.run();
+      } else {
+        throw t;
+      }
+    }
+  }
 }

testing-common/src/main/java/io/opentelemetry/instrumentation/testing/junit/InstrumentationExtension.java

@@ -6,7 +6,6 @@
 package io.opentelemetry.instrumentation.testing.junit;
 
 import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat;
-import static org.awaitility.Awaitility.await;
 
 import io.opentelemetry.api.OpenTelemetry;
 import io.opentelemetry.context.ContextStorage;
@@ -22,7 +21,6 @@
 import io.opentelemetry.sdk.testing.assertj.MetricAssert;
 import io.opentelemetry.sdk.testing.assertj.TraceAssert;
 import io.opentelemetry.sdk.trace.data.SpanData;
-import java.time.Duration;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Comparator;
@@ -125,13 +123,7 @@ public List<List<SpanData>> waitForTraces(int numberOfTraces) {
    * This waits up to 20 seconds, then times out.
    */
   public List<LogRecordData> waitForLogRecords(int numberOfLogRecords) {
-    await()
-        .timeout(Duration.ofSeconds(20))
-        .untilAsserted(
-            () ->
-                assertThat(testRunner.getExportedLogRecords().size())
-                    .isEqualTo(numberOfLogRecords));
-    return testRunner.getExportedLogRecords();
+    return testRunner.waitForLogRecords(numberOfLogRecords);
   }
 
   @SafeVarargs