Fix extractAndParseVersionOutput time out issue and add more logging … (

#614)

…during the initialization

<!-- Please provide brief information about the PR, what it contains &
its purpose, new behaviors after the change. And let us know here if you
need any help: https://github.com/microsoft/HydraLab/issues/new -->

## Description

<!-- A few words to explain your changes -->
This is targeted to fix the initialization getting stack bug, the
process may get stuck in:

![image](https://github.com/microsoft/HydraLab/assets/8344245/5ac28049-9351-4fb0-a472-baee10d8b7dd)

### Linked GitHub issue ID: #  

## Pull Request Checklist
<!-- Put an x in the boxes that apply. This is simply a reminder of what
we are going to look for before merging your code. -->

- [ ] Tests for the changes have been added (for bug fixes / features)
- [x] Code compiles correctly with all tests are passed.
- [x] I've read the [contributing
guide](https://github.com/microsoft/HydraLab/blob/main/CONTRIBUTING.md#making-changes-to-the-code)
and followed the recommended practices.
- [ ] [Wikis](https://github.com/microsoft/HydraLab/wiki) or
[README](https://github.com/microsoft/HydraLab/blob/main/README.md) have
been reviewed and added / updated if needed (for bug fixes / features)

### Does this introduce a breaking change?
*If this introduces a breaking change for Hydra Lab users, please
describe the impact and migration path.*

- [ ] Yes
- [x] No

## How you tested it
*Please make sure the change is tested, you can test it by adding UTs,
do local test and share the screenshots, etc.*


Please check the type of change your PR introduces:
- [ ] Bugfix
- [ ] Feature
- [ ] Technical design
- [ ] Build related changes
- [ ] Refactoring (no functional changes, no api changes)
- [ ] Code style update (formatting, renaming) or Documentation content
changes
- [ ] Other (please describe): 

### Feature UI screenshots or Technical design diagrams
*If this is a relatively large or complex change, kick it off by drawing
the tech design with PlantUML and explaining why you chose the solution
you did and what alternatives you considered, etc...*

agent/src/main/java/com/microsoft/hydralab/agent/config/AppConfiguration.java

@@ -85,27 +85,33 @@ public EnvCapabilityDiscoveryService envCapabilityDiscoveryService() throws IOEx
         EnvCapabilityDiscoveryService envCapabilityDiscoveryService = new EnvCapabilityDiscoveryService();
         envCapabilityDiscoveryService.setEnableScan(true);
         envCapabilityDiscoveryService.discover();
+        logger.info("envCapabilityDiscoveryService discover is completed");
         return envCapabilityDiscoveryService;
     }
 
     @Bean
     public AgentManagementService agentManagementService(StorageServiceClientProxy storageServiceClientProxy,
                                                          DeviceStatusListenerManager deviceStatusListenerManager,
                                                          EnvCapabilityDiscoveryService envCapabilityDiscoveryService) {
+        logger.info("start agentManagementService instantiation");
         AgentManagementService agentManagementService = new AgentManagementService();
         File testBaseDir = new File(appOptions.getTestCaseResultLocation());
         if (!testBaseDir.exists()) {
             if (!testBaseDir.mkdirs()) {
                 throw new RuntimeException("agentManager dir.mkdirs() failed: " + testBaseDir);
             }
         }
+        logger.info("testBaseDir is created in {}", testBaseDir.getAbsolutePath());
+
         agentManagementService.setTestBaseDir(testBaseDir);
         File preAppDir = new File(appOptions.getPreAppStorageLocation());
         if (!preAppDir.exists()) {
             if (!preAppDir.mkdirs()) {
                 throw new RuntimeException("agentManager dir.mkdirs() failed: " + preAppDir);
             }
         }
+        logger.info("preAppDir is created in {}", preAppDir.getAbsolutePath());
+
         agentManagementService.setPreAppDir(preAppDir);
         agentManagementService.setPreInstallFailurePolicy(
                 shutdownIfFail ? Const.PreInstallFailurePolicy.SHUTDOWN : Const.PreInstallFailurePolicy.IGNORE);
@@ -127,6 +133,7 @@ public AgentManagementService agentManagementService(StorageServiceClientProxy s
         agentManagementService.setEnvInfo(envCapabilityDiscoveryService.getEnvInfo());
         agentManagementService.setRegistryServer(registryServer);
 
+        logger.info("done with agentManagementService instantiation");
         return agentManagementService;
     }
 

agent/src/main/java/com/microsoft/hydralab/agent/environment/EnvCapabilityDiscoveryService.java

@@ -2,6 +2,7 @@
 
 import com.microsoft.hydralab.common.entity.agent.EnvCapability;
 import com.microsoft.hydralab.common.entity.agent.EnvInfo;
+import lombok.Getter;
 import org.slf4j.Logger;
 
 import java.io.IOException;
@@ -11,7 +12,9 @@
 
 public class EnvCapabilityDiscoveryService {
     Logger logger = org.slf4j.LoggerFactory.getLogger(EnvCapabilityDiscoveryService.class);
+    @Getter
     private final EnvInfo envInfo = new EnvInfo();
+    @Getter
     private EnvCapabilityScanner scanner;
 
     private boolean enableScan = false;
@@ -61,7 +64,4 @@ private void determineEnvironmentComponents(String osName) {
         }
     }
 
-    public EnvInfo getEnvInfo() {
-        return envInfo;
-    }
 }

agent/src/main/java/com/microsoft/hydralab/agent/environment/EnvCapabilityScanner.java

@@ -1,29 +1,38 @@
 package com.microsoft.hydralab.agent.environment;
 
+import com.google.common.annotations.VisibleForTesting;
 import com.microsoft.hydralab.common.entity.agent.EnvCapability;
-import org.apache.commons.io.IOUtils;
 import org.apache.commons.lang3.StringUtils;
 import org.jetbrains.annotations.NotNull;
 import org.slf4j.Logger;
 
 import java.io.BufferedReader;
 import java.io.File;
 import java.io.IOException;
+import java.io.InputStream;
 import java.io.InputStreamReader;
 import java.nio.charset.StandardCharsets;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.HashMap;
 import java.util.List;
 import java.util.Map;
+import java.util.concurrent.Callable;
+import java.util.concurrent.ExecutionException;
+import java.util.concurrent.ExecutorService;
+import java.util.concurrent.Executors;
+import java.util.concurrent.FutureTask;
 import java.util.concurrent.TimeUnit;
+import java.util.concurrent.TimeoutException;
 import java.util.regex.Matcher;
 import java.util.regex.Pattern;
 
 public abstract class EnvCapabilityScanner {
-    Logger logger = org.slf4j.LoggerFactory.getLogger(EnvCapabilityScanner.class);
+    static final Logger LOGGER = org.slf4j.LoggerFactory.getLogger(EnvCapabilityScanner.class);
     protected Map<String, String> systemEnv = System.getenv();
     static Pattern versionPattern = Pattern.compile("([0-9]+\\.[0-9]+\\.[0-9]+)");
+    static final ExecutorService EXECUTOR_SERVICE = Executors.newSingleThreadExecutor();
+    private static final long MAX_WAIT_TIME_SECONDS_GET_VERSION = 15;
 
     @SuppressWarnings("checkstyle:InterfaceIsType")
     public interface VariableNames {
@@ -41,10 +50,12 @@ public List<EnvCapability> scan() throws IOException {
             if (!systemEnv.containsKey(scanVariable)) {
                 continue;
             }
-            logger.info("Scan system variable {} with value {}", scanVariable, systemEnv.get(scanVariable));
+            LOGGER.info("Scan system variable {} with value {}", scanVariable, systemEnv.get(scanVariable));
         }
 
+        LOGGER.info("start scanning capabilities");
         ArrayList<File> files = scanPathExecutables(getPathVariableName());
+        LOGGER.info("Completed scanning capabilities, {}", files);
         List<EnvCapability> capabilities = createCapabilities(files);
         scanCapabilityVersion(capabilities);
         return capabilities;
@@ -69,33 +80,77 @@ private void scanCapabilityVersion(List<EnvCapability> capabilities) throws IOEx
         }
     }
 
-    private void extractAndParseVersionOutput(EnvCapability capability) throws IOException {
+    @VisibleForTesting
+    void extractAndParseVersionOutput(EnvCapability capability) throws IOException {
+        LOGGER.info("Will extractAndParseVersionOutput for {}, {}, {}", capability, capability.getFile().getAbsolutePath(), capability.getKeyword().getFetchVersionParam());
         Process process = Runtime.getRuntime().exec(new String[]{capability.getFile().getAbsolutePath(), capability.getKeyword().getFetchVersionParam()});
-        try (BufferedReader reader = new BufferedReader(new InputStreamReader(process.getInputStream(), StandardCharsets.UTF_8));
-             BufferedReader error = new BufferedReader(new InputStreamReader(process.getErrorStream(), StandardCharsets.UTF_8))) {
+        try (InputStream stdStream = process.getInputStream();
+             InputStream errorStream = process.getErrorStream()) {
             // combine this in case that some output is provided through stdout and some through stderr
+            String stdIO = null;
+            try {
+                stdIO = readInputStreamWithTimeout(stdStream, MAX_WAIT_TIME_SECONDS_GET_VERSION, TimeUnit.SECONDS);
+            } catch (ExecutionException e) {
+                LOGGER.warn("extractAndParseVersionOutput Exception when getting stdIO of " + capability.getKeyword().name(), e);
+            }
+            String stdError = null;
+            try {
+                stdError = readInputStreamWithTimeout(errorStream, MAX_WAIT_TIME_SECONDS_GET_VERSION, TimeUnit.SECONDS);
+            } catch (ExecutionException e) {
+                LOGGER.warn("extractAndParseVersionOutput Exception when getting stdError of " + capability.getKeyword().name());
+            }
+
             String versionOutput = String.format("Standard Output: %s\nError Output: %s",
-                    StringUtils.trim(IOUtils.toString(reader)),
-                    StringUtils.trim(IOUtils.toString(error)));
+                    StringUtils.trim(stdIO),
+                    StringUtils.trim(stdError));
+
+            LOGGER.info("extractAndParseVersionOutput versionOutput: {}", versionOutput);
+
             boolean exited = process.waitFor(5, TimeUnit.SECONDS);
             if (!exited) {
-                logger.warn("Failed to get version of " + capability.getKeyword().name());
+                LOGGER.warn("Failed to get version of " + capability.getKeyword().name());
             }
             capability.getKeyword().setVersionOutput(versionOutput);
 
             Matcher matcher = versionPattern.matcher(versionOutput);
             if (matcher.find()) {
                 capability.setVersion(matcher.group());
             } else {
-                logger.warn("Failed to get version of " + capability.getKeyword().name() + " in " + versionOutput);
+                LOGGER.warn("Failed to get version of " + capability.getKeyword().name() + " in " + versionOutput);
             }
         } catch (InterruptedException e) {
-            logger.error("Failed to get version of " + capability.getKeyword().name() + " at " + capability.getFile().getAbsolutePath(), e);
+            LOGGER.error("Failed to get version of " + capability.getKeyword().name() + " at " + capability.getFile().getAbsolutePath(), e);
         } finally {
             process.destroy();
         }
     }
 
+    static String readInputStreamWithTimeout(InputStream is, long timeout, TimeUnit unit) throws ExecutionException, InterruptedException {
+        StringBuilder result = new StringBuilder();
+        Callable<String> readTask = () -> {
+            try (BufferedReader reader = new BufferedReader(new InputStreamReader(is, StandardCharsets.UTF_8))) {
+                String line;
+                while ((line = reader.readLine()) != null) {
+                    result.append(line).append("\n");
+                }
+                return result.toString();
+            }
+        };
+
+        FutureTask<String> futureTask = new FutureTask<>(readTask);
+        EXECUTOR_SERVICE.execute(futureTask);
+
+        try {
+            return futureTask.get(timeout, unit);
+        } catch (TimeoutException e) {
+            String resultString = result.toString();
+            LOGGER.warn("TimeoutException when getting resultString: " + resultString, e);
+            return resultString;
+        } finally {
+            futureTask.cancel(true);
+        }
+    }
+
     protected abstract String getPathVariableName();
 
     public List<File> listExecutableFiles(String path) {
@@ -104,6 +159,7 @@ public List<File> listExecutableFiles(String path) {
         if (listOfFiles == null) {
             return null;
         }
+        LOGGER.info("Scanning path {} with a count of {}", path, listOfFiles.length);
         ArrayList<File> files = new ArrayList<>();
         for (File file : listOfFiles) {
             if (isExecutable(file)) {
@@ -134,6 +190,7 @@ protected ArrayList<File> scanPathExecutables(String pathVarName) {
         }
         String[] paths = path.split(getPathVariableSeparator());
         // System.out.println(JSON.toJSONString(Arrays.asList(paths)));
+        LOGGER.info("Scanning paths with a count of {}: {}", paths.length, Arrays.asList(paths));
         ArrayList<File> files = new ArrayList<>();
         for (String p : paths) {
             List<File> executableFiles = listExecutableFiles(p);

agent/src/test/java/com/microsoft/hydralab/agent/environment/EnvCapabilityDiscoveryServiceTest.java

@@ -66,4 +66,5 @@ public void testFunctionAvailability() {
                 envCapabilityRequirements);
         Assertions.assertFalse(agentManagementService.getFunctionAvailabilities().get(1).isAvailable());
     }
+
 }