Updates to azure-core-test (Azure#37140)

Updates to azure-core-test

Author: alzimmermsft

eng/code-quality-reports/src/main/resources/checkstyle/checkstyle-suppressions.xml

@@ -509,7 +509,7 @@ the main ServiceBusClientBuilder. -->
  <suppress checks="ThrowFromClientLogger" files="com.azure.security.attestation.implementation.models.*\.java"/>
 
   <suppress checks="com.azure.tools.checkstyle.checks.GoodLoggingCheck"
-            files="com.azure.core.test.(AzureTestWatcher|ThreadDumper).java"/>
+            files="com.azure.core.test.(AzureTestWatcher|TestBase|ThreadDumper).java"/>
 
   <!-- This policy is purely an implementation detail and should not be used by customers -->
   <suppress checks="com.azure.tools.checkstyle.checks.HttpPipelinePolicyCheck"

sdk/core/azure-core-test/src/main/java/com/azure/core/test/AzureTestWatcher.java

@@ -3,73 +3,62 @@
 
 package com.azure.core.test;
 
-import com.azure.core.test.implementation.TestRunMetrics;
-import com.azure.core.util.Configuration;
 import org.junit.jupiter.api.extension.AfterTestExecutionCallback;
 import org.junit.jupiter.api.extension.BeforeTestExecutionCallback;
 import org.junit.jupiter.api.extension.ExtensionContext;
 
-import java.lang.reflect.Method;
-import java.util.Objects;
-import java.util.function.Supplier;
+import static com.azure.core.test.TestBase.getTestName;
+import static com.azure.core.test.TestBase.shouldLogExecutionStatus;
 
 /**
  * JUnit 5 extension class which reports on testing running and simple metrics about the test such as run time.
  */
 public class AzureTestWatcher implements BeforeTestExecutionCallback, AfterTestExecutionCallback {
-    private static final String AZURE_TEST_DEBUG = "AZURE_TEST_DEBUG";
-
-    private static final Supplier<Boolean> SHOULD_LOG_EXECUTION_STATUS = () ->
-        Boolean.parseBoolean(Configuration.getGlobalConfiguration().get(AZURE_TEST_DEBUG));
-
     /**
      * Creates an instance of {@link AzureTestWatcher}.
      */
     public AzureTestWatcher() {
     }
 
     @Override
-    public void beforeTestExecution(ExtensionContext extensionContext) {
-        if (!SHOULD_LOG_EXECUTION_STATUS.get()) {
+    public void beforeTestExecution(ExtensionContext context) {
+        // If the test class is an instance of TestBase or is a subtype of TestBase, then we don't need to track
+        // anything here as TestBase handles this logic in it's Before and After test methods.
+        Class<?> clazz = context.getTestClass().orElse(null);
+        if (clazz != null && TestBase.class.isAssignableFrom(clazz)) {
             return;
         }
 
-        String displayName = extensionContext.getDisplayName();
-
-        String testName = "";
-        String fullyQualifiedTestName = "";
-        if (extensionContext.getTestMethod().isPresent()) {
-            Method method = extensionContext.getTestMethod().get();
-            testName = method.getName();
-            fullyQualifiedTestName = method.getDeclaringClass().getName() + "." + testName;
-        }
-
-        StringBuilder logPrefixBuilder = new StringBuilder("Starting test ")
-            .append(fullyQualifiedTestName);
-
-        if (!Objects.equals(displayName, testName)) {
-            logPrefixBuilder.append("(")
-                .append(displayName)
-                .append(")");
+        // Check if test debugging is enabled to determine whether logging should happen.
+        if (!shouldLogExecutionStatus()) {
+            return;
         }
 
-        logPrefixBuilder.append(",");
+        String testName = getTestName(context.getTestMethod(), context.getDisplayName());
+        System.out.println("Starting test " + testName + ".");
 
-        getStore(extensionContext).put(extensionContext.getRequiredTestMethod(),
-            new TestRunMetrics(logPrefixBuilder.toString(), System.currentTimeMillis()));
+        getStore(context).put(context.getRequiredTestMethod(), System.currentTimeMillis());
     }
 
     @Override
     public void afterTestExecution(ExtensionContext context) {
-        if (!SHOULD_LOG_EXECUTION_STATUS.get()) {
+        // If the test class is an instance of TestBase or is a subtype of TestBase, then we don't need to track
+        // anything here as TestBase handles this logic in it's Before and After test methods.
+        Class<?> clazz = context.getTestClass().orElse(null);
+        if (clazz != null && TestBase.class.isAssignableFrom(clazz)) {
+            return;
+        }
+
+        // Check if test debugging is enabled to determine whether logging should happen.
+        if (!shouldLogExecutionStatus()) {
             return;
         }
 
-        TestRunMetrics testInformation = getStore(context)
-            .remove(context.getRequiredTestMethod(), TestRunMetrics.class);
-        long duration = System.currentTimeMillis() - testInformation.getStartMillis();
+        long startMillis = getStore(context).remove(context.getRequiredTestMethod(), long.class);
+        long duration = System.currentTimeMillis() - startMillis;
 
-        System.out.printf("%s completed in %d ms.%n", testInformation.getLogPrefix(), duration);
+        String testName = getTestName(context.getTestMethod(), context.getDisplayName());
+        System.out.println("Finished test " + testName + " in " + duration + " ms.");
     }
 
     private static ExtensionContext.Store getStore(ExtensionContext context) {

sdk/core/azure-core-test/src/main/java/com/azure/core/test/InterceptorManager.java

@@ -543,4 +543,24 @@ public void setProxyRecordingOptions(TestProxyRecordingOptions testProxyRecordin
             throw new RuntimeException("Recording must have been started before setting recording options.");
         }
     }
+
+    /**
+     * Gets the name of the running test.
+     *
+     * @return Name of the running test.
+     */
+    public String getTestName() {
+        return testName;
+    }
+
+    /**
+     * Gets the name of the playback record.
+     * <p>
+     * The playback record name is equivalent to {@code <testClass>.<testMethod>[<testIteration>]}.
+     *
+     * @return Name of the playback record.
+     */
+    public String getPlaybackRecordName() {
+        return playbackRecordName;
+    }
 }

sdk/core/azure-core-test/src/main/java/com/azure/core/test/TestBase.java

@@ -8,6 +8,7 @@
 import com.azure.core.test.http.PlaybackClient;
 import com.azure.core.test.implementation.TestIterationContext;
 import com.azure.core.test.implementation.TestingHelpers;
+import com.azure.core.test.utils.HttpURLConnectionHttpClient;
 import com.azure.core.test.utils.TestResourceNamer;
 import com.azure.core.util.Configuration;
 import com.azure.core.util.CoreUtils;
@@ -32,7 +33,10 @@
 import java.util.ArrayList;
 import java.util.List;
 import java.util.Locale;
+import java.util.Objects;
+import java.util.Optional;
 import java.util.ServiceLoader;
+import java.util.concurrent.atomic.AtomicReference;
 import java.util.stream.Stream;
 
 import static com.azure.core.test.utils.TestUtils.toURI;
@@ -41,6 +45,8 @@
  * Base class for running live and playback tests using {@link InterceptorManager}.
  */
 public abstract class TestBase implements BeforeEachCallback {
+    private static final String AZURE_TEST_DEBUG = "AZURE_TEST_DEBUG";
+
     // Environment variable name used to determine the TestMode.
     private static final String AZURE_TEST_HTTP_CLIENTS = "AZURE_TEST_HTTP_CLIENTS";
 
@@ -70,6 +76,8 @@ public abstract class TestBase implements BeforeEachCallback {
     private static final boolean DEFAULT_TO_NETTY = CoreUtils.isNullOrEmpty(CONFIGURED_HTTP_CLIENTS_TO_TEST);
     private static final List<String> CONFIGURED_HTTP_CLIENTS;
 
+    private static final AtomicReference<HttpClient> TEST_PROXY_HTTP_CLIENT = new AtomicReference<>();
+
     static {
         CONFIGURED_HTTP_CLIENTS = new ArrayList<>();
 
@@ -115,6 +123,8 @@ public abstract class TestBase implements BeforeEachCallback {
 
     private URL proxyUrl;
 
+    private long testStartTimeMillis;
+
     /**
      * Creates a new instance of {@link TestBase}.
      */
@@ -152,6 +162,8 @@ public void setupTest(TestInfo testInfo) {
         } else if (testInfo.getTags().contains("Live")) {
             localTestMode = TestMode.LIVE;
         }
+
+        String testName = getTestName(testInfo.getTestMethod(), testInfo.getDisplayName());
         Path testClassPath = Paths.get(toURI(testInfo.getTestClass().get().getResource(testInfo.getTestClass().get().getSimpleName() + ".class")));
         this.testContextManager =
             new TestContextManager(testInfo.getTestMethod().get(),
@@ -160,7 +172,13 @@ public void setupTest(TestInfo testInfo) {
                 testInfo.getTestClass().get().getAnnotation(RecordWithoutRequestBody.class) != null,
                 testClassPath);
         testContextManager.setTestIteration(testIterationContext.getTestIteration());
-        logger.info("Test Mode: {}, Name: {}", localTestMode, testContextManager.getTestName());
+        ThreadDumper.addRunningTest(testName);
+        logger.info("Test Mode: {}, Name: {}", localTestMode, testName);
+
+        if (shouldLogExecutionStatus()) {
+            System.out.println("Starting test " + testName + ".");
+            testStartTimeMillis = System.currentTimeMillis();
+        }
 
         try {
             interceptorManager = new InterceptorManager(testContextManager);
@@ -170,7 +188,7 @@ public void setupTest(TestInfo testInfo) {
         }
 
         if (isTestProxyEnabled()) {
-            interceptorManager.setHttpClient(getHttpClients().findFirst().orElse(null));
+            interceptorManager.setHttpClient(getTestProxyHttpClient());
             // The supplier/consumer are used to retrieve/store variables over the wire.
             testResourceNamer = new TestResourceNamer(testContextManager,
                 interceptorManager.getProxyVariableConsumer(),
@@ -196,9 +214,24 @@ public void setupTest(TestInfo testInfo) {
      */
     @AfterEach
     public void teardownTest(TestInfo testInfo) {
-        if (testContextManager != null && testContextManager.didTestRun()) {
-            afterTest();
-            interceptorManager.close();
+        if (shouldLogExecutionStatus()) {
+            String testName = getTestName(testInfo.getTestMethod(), testInfo.getDisplayName());
+
+            if (testStartTimeMillis > 0) {
+                long duration = System.currentTimeMillis() - testStartTimeMillis;
+                System.out.println("Finished test " + testName + " in " + duration + " ms.");
+            } else {
+                System.out.println("Finished test " + testName + ", duration unknown.");
+            }
+        }
+
+        if (testContextManager != null) {
+            ThreadDumper.removeRunningTest(testContextManager.getTestPlaybackRecordingName());
+
+            if (testContextManager.didTestRun()) {
+                afterTest();
+                interceptorManager.close();
+            }
         }
     }
 
@@ -396,4 +429,28 @@ protected <T, U> PollerFlux<T, U> setPlaybackPollerFluxPollInterval(PollerFlux<T
     protected HttpClient getHttpClientOrUsePlayback(HttpClient httpClient) {
         return (testMode == TestMode.PLAYBACK) ? interceptorManager.getPlaybackClient() : httpClient;
     }
+
+    private static HttpClient getTestProxyHttpClient() {
+        return TEST_PROXY_HTTP_CLIENT.updateAndGet(httpClient -> httpClient == null
+            ? getHttpClients().findFirst().orElse(new HttpURLConnectionHttpClient())
+            : httpClient);
+    }
+
+    static String getTestName(Optional<Method> testMethod, String displayName) {
+        String testName = "";
+        String fullyQualifiedTestName = "";
+        if (testMethod.isPresent()) {
+            Method method = testMethod.get();
+            testName = method.getName();
+            fullyQualifiedTestName = method.getDeclaringClass().getName() + "." + testName;
+        }
+
+        return Objects.equals(displayName, testName)
+            ? fullyQualifiedTestName
+            : fullyQualifiedTestName + "(" + displayName + ")";
+    }
+
+    static boolean shouldLogExecutionStatus() {
+        return Configuration.getGlobalConfiguration().get(AZURE_TEST_DEBUG, false);
+    }
 }

sdk/core/azure-core-test/src/main/java/com/azure/core/test/ThreadDumper.java

@@ -124,14 +124,36 @@ public void beforeAll(ExtensionContext context) {
 
     @Override
     public void beforeEach(ExtensionContext context) {
+        // If the test class is an instance of TestBase or is a subtype of TestBase, then we don't need to track
+        // anything here as TestBase handles this logic in it's Before and After test methods.
+        Class<?> clazz = context.getTestClass().orElse(null);
+        if (clazz != null && TestBase.class.isAssignableFrom(clazz)) {
+            return;
+        }
+        
         RUNNING_TEST_TIMES.put(getFullTestName(context), System.currentTimeMillis());
     }
 
+    static void addRunningTest(String testName) {
+        RUNNING_TEST_TIMES.put(testName, System.currentTimeMillis());
+    }
+
     @Override
     public void afterEach(ExtensionContext context) {
+        // If the test class is an instance of TestBase or is a subtype of TestBase, then we don't need to track
+        // anything here as TestBase handles this logic in it's Before and After test methods.
+        Class<?> clazz = context.getTestClass().orElse(null);
+        if (clazz != null && TestBase.class.isAssignableFrom(clazz)) {
+            return;
+        }
+
         RUNNING_TEST_TIMES.remove(getFullTestName(context));
     }
 
+    static void removeRunningTest(String testName) {
+        RUNNING_TEST_TIMES.remove(testName);
+    }
+
     private static String getFullTestName(ExtensionContext context) {
         String displayName = context.getDisplayName();
 

sdk/core/azure-core-test/src/main/java/com/azure/core/test/implementation/TestRunMetrics.java

@@ -83,6 +83,9 @@ public void startRecording(File recordFile, Path testClassPath) {
 
             try (HttpResponse response = client.sendSync(request, Context.NONE)) {
                 checkForTestProxyErrors(response);
+                if (response.getStatusCode() != 200) {
+                    throw new RuntimeException(response.getBodyAsBinaryData().toString());
+                }
 
                 this.xRecordingId = response.getHeaderValue(X_RECORDING_ID);
             }
@@ -111,11 +114,10 @@ public void stopRecording(Queue<String> variables) {
             .setHeader(HttpHeaderName.CONTENT_TYPE, "application/json")
             .setHeader(X_RECORDING_ID, xRecordingId)
             .setBody(serializeVariables(variables));
-        
+
         try (HttpResponse response = client.sendSync(request, Context.NONE)) {
             checkForTestProxyErrors(response);
-
-            if (response.getStatusCode() == 400) {
+            if (response.getStatusCode() != 200) {
                 throw new RuntimeException(response.getBodyAsBinaryData().toString());
             }
         }

sdk/core/azure-core-test/src/main/java/com/azure/core/test/policy/TestProxyRecordPolicy.java

@@ -63,7 +63,8 @@ public static synchronized void startProxy() {
                 }
 
                 ProcessBuilder builder = new ProcessBuilder(commandLine, "--storage-location", repoRoot.toString())
-                    .redirectOutput(repoRootTarget.resolve("test-proxy.log").toFile());
+                    .redirectOutput(repoRootTarget.resolve("test-proxy.log").toFile())
+                    .redirectError(repoRootTarget.resolve("test-proxy-error.log").toFile());
                 Map<String, String> environment = builder.environment();
                 environment.put("LOGGING__LOGLEVEL", "Debug");
                 environment.put("LOGGING__LOGLEVEL__MICROSOFT", "Debug");