test: massive test speedup (#1542)

.github/workflows/maven.yml

@@ -16,6 +16,7 @@ jobs:
     strategy:
       matrix:
         os: [ubuntu-20.04, windows-latest]
+      fail-fast: false
     name: Build on ${{ matrix.os }}
     steps:
       - uses: actions/checkout@v2

src/integrationtests/java/com/aws/greengrass/integrationtests/BaseITCase.java

@@ -11,12 +11,19 @@
 import com.aws.greengrass.deployment.DeviceConfiguration;
 import com.aws.greengrass.lifecyclemanager.Kernel;
 import com.aws.greengrass.lifecyclemanager.KernelAlternatives;
+import com.aws.greengrass.logging.api.Logger;
+import com.aws.greengrass.logging.impl.LogManager;
 import com.aws.greengrass.logging.impl.config.LogConfig;
 import com.aws.greengrass.testcommons.testutilities.GGExtension;
 import com.aws.greengrass.testcommons.testutilities.UniqueRootPathExtension;
 import com.aws.greengrass.testing.TestFeatureParameterInterface;
 import com.aws.greengrass.testing.TestFeatureParameters;
 import com.aws.greengrass.util.Utils;
+import com.aws.greengrass.util.platforms.windows.UserEnv;
+import com.sun.jna.platform.win32.Advapi32;
+import com.sun.jna.platform.win32.Kernel32;
+import com.sun.jna.platform.win32.Kernel32Util;
+import com.sun.jna.platform.win32.WinNT;
 import org.apache.commons.io.FileUtils;
 import org.junit.jupiter.api.AfterAll;
 import org.junit.jupiter.api.AfterEach;
@@ -54,6 +61,7 @@
  */
 @ExtendWith({GGExtension.class, UniqueRootPathExtension.class, MockitoExtension.class})
 public class BaseITCase {
+    protected static final Logger LOGGER = LogManager.getLogger(BaseITCase.class);
     protected static final String WINDOWS_TEST_UESRNAME = "integ-tester";
     protected static final String WINDOWS_TEST_UESRNAME_2 = "integ-tester-2";
     public static final String WINDOWS_TEST_PASSWORD = "hunter2HUNTER@";
@@ -111,8 +119,6 @@ static void cleanup() throws IOException, InterruptedException {
         if (!PlatformResolver.isWindows) {
             return;
         }
-        deleteWindowsTestUser(WINDOWS_TEST_UESRNAME);
-        deleteWindowsTestUser(WINDOWS_TEST_UESRNAME_2);
         WindowsCredUtils.delete(WINDOWS_TEST_UESRNAME);
         WindowsCredUtils.delete(WINDOWS_TEST_UESRNAME_2);
         testContext.close();
@@ -132,10 +138,35 @@ public static void createWindowsTestUser(String username, String password)
         }
         if (p.exitValue() != 0) {
             String error = Utils.inputStreamToString(p.getErrorStream());
-            if (!error.contains("The account already exists")) {
+            if (error.contains("The account already exists")) {
+                // The account already exists, no need to load profile again
+                return;
+            } else {
                 fail("Failed to create user: " + username + ". " + error);
             }
         }
+
+        // Login and load the user's profile. This can take 1+ minutes (which is crazy I know). LoadUserProfile
+        // sometimes blocks for a minute for some reason....
+        // anyway, do the blocking here before we enter the test where timeouts are going to apply
+        LOGGER.atInfo().log("Loading user profile for {}", username);
+        WinNT.HANDLEByReference userTokenHandle = new WinNT.HANDLEByReference();
+        int[] logonTypes =
+                {Kernel32.LOGON32_LOGON_INTERACTIVE, Kernel32.LOGON32_LOGON_SERVICE, Kernel32.LOGON32_LOGON_BATCH};
+        for (int logonType : logonTypes) {
+            if (Advapi32.INSTANCE.LogonUser(username, null, password, logonType,
+                    Kernel32.LOGON32_PROVIDER_DEFAULT, userTokenHandle)) {
+                break;
+            }
+        }
+
+        final UserEnv.PROFILEINFO profileInfo = new UserEnv.PROFILEINFO();
+        profileInfo.lpUserName = username;
+        profileInfo.dwSize = profileInfo.size();
+        profileInfo.write();
+        UserEnv.INSTANCE.LoadUserProfile(userTokenHandle.getValue(), profileInfo);
+        Kernel32Util.closeHandleRefs(userTokenHandle);
+        LOGGER.atInfo().log("Done loading user profile for {}", username);
     }
 
     public static void deleteWindowsTestUser(String username) throws IOException, InterruptedException {

src/integrationtests/java/com/aws/greengrass/integrationtests/deployment/DeploymentConfigMergingTest.java

@@ -37,6 +37,7 @@
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.api.extension.ExtendWith;
+import org.slf4j.event.Level;
 import software.amazon.awssdk.aws.greengrass.GreengrassCoreIPCClient;
 import software.amazon.awssdk.aws.greengrass.model.ComponentUpdatePolicyEvents;
 import software.amazon.awssdk.aws.greengrass.model.DeferComponentUpdateRequest;
@@ -118,6 +119,7 @@ void after() {
         if (kernel != null) {
             kernel.shutdown();
         }
+        LogManager.getRootLogConfiguration().setLevel(Level.INFO);
     }
 
     @AfterAll
@@ -174,10 +176,10 @@ void GIVEN_kernel_running_single_service_WHEN_merge_changes_service_THEN_service
 
         // GIVEN
         ConfigPlatformResolver.initKernelWithMultiPlatformConfig(kernel, getClass().getResource("single_service.yaml"));
-        CountDownLatch mainRunning = new CountDownLatch(1);
+        CountDownLatch mainFinished = new CountDownLatch(1);
         kernel.getContext().addGlobalStateChangeListener((service, oldState, newState) -> {
-            if (service.getName().equals("main") && newState.equals(State.RUNNING)) {
-                mainRunning.countDown();
+            if (service.getName().equals("main") && newState.equals(State.FINISHED)) {
+                mainFinished.countDown();
             }
         });
 
@@ -189,7 +191,7 @@ void GIVEN_kernel_running_single_service_WHEN_merge_changes_service_THEN_service
         };
         try (AutoCloseable l = createCloseableLogListener(listener)) {
             kernel.launch();
-            assertTrue(mainRunning.await(5, TimeUnit.SECONDS));
+            assertTrue(mainFinished.await(5, TimeUnit.SECONDS));
 
             // WHEN
             CountDownLatch mainRestarted = new CountDownLatch(1);
@@ -223,14 +225,14 @@ void GIVEN_kernel_running_single_service_WHEN_merge_change_adding_dependency_THE
         // GIVEN
         ConfigPlatformResolver.initKernelWithMultiPlatformConfig(kernel, getClass().getResource("single_service.yaml"));
 
-        CountDownLatch mainRunning = new CountDownLatch(1);
+        CountDownLatch mainFinished = new CountDownLatch(1);
         kernel.getContext().addGlobalStateChangeListener((service, oldState, newState) -> {
-            if (service.getName().equals("main") && newState.equals(State.RUNNING)) {
-                mainRunning.countDown();
+            if (service.getName().equals("main") && newState.equals(State.FINISHED)) {
+                mainFinished.countDown();
             }
         });
         kernel.launch();
-        assertTrue(mainRunning.await(5, TimeUnit.SECONDS));
+        assertTrue(mainFinished.await(5, TimeUnit.SECONDS));
 
         // WHEN
         AtomicBoolean mainRestarted = new AtomicBoolean(false);
@@ -281,14 +283,14 @@ void GIVEN_kernel_running_single_service_WHEN_merge_change_adding_nested_depende
         // GIVEN
         ConfigPlatformResolver.initKernelWithMultiPlatformConfig(kernel, getClass().getResource("single_service.yaml"));
 
-        CountDownLatch mainRunning = new CountDownLatch(1);
+        CountDownLatch mainFinished = new CountDownLatch(1);
         kernel.getContext().addGlobalStateChangeListener((service, oldState, newState) -> {
-            if (service.getName().equals("main") && newState.equals(State.RUNNING)) {
-                mainRunning.countDown();
+            if (service.getName().equals("main") && newState.equals(State.FINISHED)) {
+                mainFinished.countDown();
             }
         });
         kernel.launch();
-        assertTrue(mainRunning.await(5, TimeUnit.SECONDS));
+        assertTrue(mainFinished.await(5, TimeUnit.SECONDS));
 
         // WHEN
         CountDownLatch mainRestarted = new CountDownLatch(1);
@@ -354,15 +356,15 @@ void GIVEN_kernel_running_single_service_WHEN_merge_same_doc_happens_twice_THEN_
         ConfigPlatformResolver.initKernelWithMultiPlatformConfig(kernel, getClass().getResource("single_service.yaml"));
 
         // launch Nucleus
-        CountDownLatch mainRunning = new CountDownLatch(1);
+        CountDownLatch mainFinished = new CountDownLatch(1);
         kernel.getContext().addGlobalStateChangeListener((service, oldState, newState) -> {
-            if (service.getName().equals("main") && newState.equals(State.RUNNING)) {
-                mainRunning.countDown();
+            if (service.getName().equals("main") && newState.equals(State.FINISHED)) {
+                mainFinished.countDown();
             }
         });
         kernel.launch();
 
-        assertTrue(mainRunning.await(5, TimeUnit.SECONDS));
+        assertTrue(mainFinished.await(5, TimeUnit.SECONDS));
 
         Map<String, Object> nucleusConfig = getNucleusConfig();
         HashMap<String, Object> newConfig = new HashMap<String, Object>() {{
@@ -449,23 +451,23 @@ void GIVEN_kernel_running_single_service_WHEN_merge_same_doc_happens_twice_THEN_
 
     @Test
     void GIVEN_kernel_running_services_WHEN_merge_removes_service_THEN_removed_service_is_closed() throws Throwable {
+        LogManager.getRootLogConfiguration().setLevel(Level.TRACE);
         // GIVEN
         ConfigPlatformResolver.initKernelWithMultiPlatformConfig(kernel,
                 getClass().getResource("long_running_services.yaml"));
-        kernel.launch();
-
         CountDownLatch mainDone = new CountDownLatch(1);
         kernel.getContext().addGlobalStateChangeListener((service, oldState, newState) -> {
             if (kernel.getMain().equals(service) && State.FINISHED == newState) {
                 mainDone.countDown();
             }
         });
 
-        //wait for main to run
-        assertTrue(mainDone.await(60, TimeUnit.SECONDS), "main done");
+        kernel.launch();
 
-        Map<String, Object> currentConfig = new HashMap<>(kernel.getConfig().toPOJO());
+        // wait for main to run
+        assertTrue(mainDone.await(15, TimeUnit.SECONDS), "main done");
 
+        Map<String, Object> currentConfig = new HashMap<>(kernel.getConfig().toPOJO());
         Map<String, Map> servicesConfig = (Map<String, Map>) currentConfig.get(SERVICES_NAMESPACE_TOPIC);
 
         //removing all services in the current Nucleus config except sleeperB, main, and nucleus
@@ -607,7 +609,7 @@ void GIVEN_kernel_running_single_service_WHEN_deployment_with_skip_safety_check_
 
         // GIVEN
         ConfigPlatformResolver.initKernelWithMultiPlatformConfig(kernel, getClass().getResource("single_service.yaml"));
-        Runnable mainRunning = createServiceStateChangeWaiter(kernel, "main",5, State.RUNNING);
+        Runnable mainRunning = createServiceStateChangeWaiter(kernel, "main",5, State.FINISHED);
         kernel.launch();
         mainRunning.run();
 

src/integrationtests/java/com/aws/greengrass/integrationtests/deployment/DeploymentServiceIntegrationTest.java

@@ -171,9 +171,8 @@ void GIVEN_device_deployment_not_started_WHEN_new_deployment_THEN_first_deployme
 
             CountDownLatch nonDisruptableServiceServiceLatch = new CountDownLatch(1);
             kernel.getContext().addGlobalStateChangeListener((service, oldState, newState) -> {
-                if (service.getName().equals("NonDisruptableService") && newState.equals(State.RUNNING)) {
+                if (service.getName().equals("NonDisruptableService") && newState.equals(State.FINISHED)) {
                     nonDisruptableServiceServiceLatch.countDown();
-
                 }
             });
             assertTrue(nonDisruptableServiceServiceLatch.await(30, TimeUnit.SECONDS));
@@ -236,9 +235,8 @@ void GIVEN_a_cloud_deployment_WHEN_receives_deployment_THEN_service_runs_and_dep
 
             CountDownLatch redSignalServiceLatch = new CountDownLatch(1);
             kernel.getContext().addGlobalStateChangeListener((service, oldState, newState) -> {
-                if (service.getName().equals("RedSignal") && newState.equals(State.RUNNING)) {
+                if (service.getName().equals("RedSignal") && newState.equals(State.FINISHED)) {
                     redSignalServiceLatch.countDown();
-
                 }
             });
 
@@ -341,9 +339,8 @@ void GIVEN_deployment_with_system_resource_WHEN_receives_deployment_THEN_deploym
         try (AutoCloseable l = TestUtils.createCloseableLogListener(listener)) {
             CountDownLatch componentRunning = new CountDownLatch(1);
             kernel.getContext().addGlobalStateChangeListener((service, oldState, newState) -> {
-                if (service.getName().equals("RedSignal") && newState.equals(State.RUNNING)) {
+                if (service.getName().equals("RedSignal") && newState.equals(State.FINISHED)) {
                     componentRunning.countDown();
-
                 }
             });
 

src/integrationtests/java/com/aws/greengrass/integrationtests/deployment/DeploymentTaskIntegrationTest.java

@@ -57,6 +57,7 @@
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.api.TestMethodOrder;
 import org.junit.jupiter.api.extension.ExtensionContext;
+import org.slf4j.event.Level;
 import software.amazon.awssdk.aws.greengrass.GreengrassCoreIPCClient;
 import software.amazon.awssdk.aws.greengrass.model.ComponentUpdatePolicyEvents;
 import software.amazon.awssdk.aws.greengrass.model.DeferComponentUpdateRequest;
@@ -266,6 +267,7 @@ void beforeEach(ExtensionContext context) throws Exception {
     @AfterEach
     void afterEach() {
         executorService.shutdownNow();
+        LogManager.getRootLogConfiguration().setLevel(Level.INFO);
     }
 
     /**
@@ -433,6 +435,7 @@ void GIVEN_sample_deployment_doc_WHEN_submitted_to_deployment_task_THEN_services
     @Order(4)
     void GIVEN_multiple_deployments_with_config_update_WHEN_submitted_to_deployment_task_THEN_configs_are_updated()
             throws Exception {
+        LogManager.getRootLogConfiguration().setLevel(Level.TRACE);
 
         // Two things are verified in this test
         // 1. The component's configurations are updated correctly in the kernel's config store
@@ -628,7 +631,7 @@ private void verifyDefaultValueIsApplied(List<String> stdouts, Map<String, Objec
                 IsMapContaining.hasEntry("leafKey", "default value of /path/leafKey"));
 
         // verify interpolation result
-        assertThat("The stdout should be captured within seconds.", countDownLatch.await(STDOUT_TIMEOUT, TimeUnit.SECONDS));
+        assertThat("The stdout should be captured within seconds.", countDownLatch.await(120, TimeUnit.SECONDS));
         String stdout = stdouts.get(0);
 
         assertThat(stdout, containsString("Value for /singleLevelKey: default value of singleLevelKey."));

src/integrationtests/java/com/aws/greengrass/integrationtests/ipc/IPCPubSubTest.java

@@ -394,7 +394,7 @@ public void onStreamClosed() {
             assertTrue(subscriptionLatch.await(10, TimeUnit.SECONDS));
 
             publishToTopicOverIpcAsBinaryMessage(greengrassCoreIPCClient, "/topic/1/2", "ABCDEFG");
-            assertFalse(cdl.await(20, TimeUnit.SECONDS));
+            assertFalse(cdl.await(5, TimeUnit.SECONDS));
         }
     }
 

src/integrationtests/java/com/aws/greengrass/integrationtests/ipc/IPCServicesTest.java

@@ -158,8 +158,7 @@ void GIVEN_ConfigStoreClient_WHEN_subscribe_THEN_key_sent_when_changed(Extension
         Topics configuration = kernel.findServiceTopic("ServiceName").createInteriorChild(CONFIGURATION_CONFIG_KEY);
         configuration.createLeafChild("abc").withValue("pqr");
         configuration.createLeafChild("DDF").withValue("xyz");
-        kernel.getContext().runOnPublishQueueAndWait(() -> {
-        });
+        kernel.getContext().waitForPublishQueueToClear();
 
         Pair<CompletableFuture<Void>, Consumer<ConfigurationUpdateEvents>> pAbcNew = asyncAssertOnConsumer((a) -> {
             assertThat(a.getConfigurationUpdateEvent().getKeyPath(), is(Collections.singletonList("abc")));

src/integrationtests/java/com/aws/greengrass/integrationtests/lifecyclemanager/KernelTest.java

@@ -316,7 +316,7 @@ void GIVEN_expected_state_transitions_WHEN_services_error_out_THEN_all_expectati
         ConfigPlatformResolver.initKernelWithMultiPlatformConfig(kernel,
                 this.getClass().getResource("config_broken.yaml"));
         kernel.launch();
-        if (!assertionLatch.await(120, TimeUnit.SECONDS) && !expectedStateTransitionList.isEmpty()) {
+        if (!assertionLatch.await(60, TimeUnit.SECONDS) && !expectedStateTransitionList.isEmpty()) {
             expectedStateTransitionList.stream().filter(x -> !x.seen).forEach(e -> System.err.println(
                     String.format("Fail to see state event for service %s: %s=> %s", e.serviceName, e.was, e.current)));
 

src/integrationtests/java/com/aws/greengrass/integrationtests/lifecyclemanager/ServiceDependencyLifecycleTest.java

@@ -408,7 +408,7 @@ void WHEN_dependency_type_changes_with_no_other_updates_THEN_customer_app_should
         when(doc2.getDeploymentId()).thenReturn("typeSoftToHard");
         when(doc2.getFailureHandlingPolicy()).thenReturn(FailureHandlingPolicy.DO_NOTHING);
 
-        testRoutine(TEST_ROUTINE_MEDIUM_TIMEOUT, kernel,
+        testRoutine(5, kernel,
                 () -> configMerger.mergeInNewConfig(createMockDeployment(doc2), depTypeSoftToHard).get(10, TimeUnit.SECONDS),
                 "dependency type changes from soft to hard", new LinkedList<>(), new HashSet<>(stateTransitions));
 
@@ -422,7 +422,7 @@ void WHEN_dependency_type_changes_with_no_other_updates_THEN_customer_app_should
         when(doc1.getDeploymentId()).thenReturn("typeHardToSoft");
         when(doc1.getFailureHandlingPolicy()).thenReturn(FailureHandlingPolicy.DO_NOTHING);
 
-        testRoutine(TEST_ROUTINE_MEDIUM_TIMEOUT, kernel,
+        testRoutine(5, kernel,
                 () -> configMerger.mergeInNewConfig(createMockDeployment(doc1), depTypeHardToSoft).get(10, TimeUnit.SECONDS),
                 "dependency type changes from hard to soft", new LinkedList<>(), new HashSet<>(stateTransitions));
     }