Fix Test Watcher Timeouts and Log Checker File Reading Issues

src/native/watchdog/watchdog.cpp

@@ -35,8 +35,8 @@ int main(const int argc, const char *argv[])
         return EXIT_FAILURE;
     }
 
-    const long timeout_sec = strtol(argv[1], nullptr, 10);
-    int exit_code = run_timed_process(timeout_sec * 1000L, argc-2, &argv[2]);
+    const long timeout_ms = strtol(argv[1], nullptr, 10);
+    int exit_code = run_timed_process(timeout_ms, argc-2, &argv[2]);
 
     printf("App Exit Code: %d\n", exit_code);
     return exit_code;

src/tests/Common/CLRTest.Execute.Bash.targets

@@ -290,7 +290,7 @@ fi
       </PropertyGroup>
       <PropertyGroup>
       <CLRTestRunFile Condition="'$(CLRTestIsHosted)'=='true'">"$CORE_ROOT/corerun" $(CoreRunArgs)  ${__DotEnvArg}</CLRTestRunFile>
-      <WatcherRunFile>"$CORE_ROOT/watchdog" 300</WatcherRunFile>
+      <WatcherRunFile>"$CORE_ROOT/watchdog" $_WatcherTimeoutMilliseconds</WatcherRunFile>
 
       <!-- Note that this overwrites CLRTestBashPreCommands rather than adding to it. -->
       <CLRTestBashPreCommands Condition="'$(CLRTestKind)' == 'BuildAndRun' and '$(TargetArchitecture)' == 'wasm'"><![CDATA[
@@ -549,6 +549,11 @@ ReleaseLock()
 cd "$%28dirname "${BASH_SOURCE[0]}")"
 LockFile="lock"
 _RunWithWatcher=0
+_WatcherTimeoutMilliseconds=600000
+
+if [[ ! -z "$__TestTimeout" ]]%3B then
+    _WatcherTimeoutMilliseconds=$__TestTimeout
+fi
 
 
 # The __TestEnv variable may be used to specify a script to source before the test.

src/tests/Common/CLRTest.Execute.Batch.targets

@@ -298,7 +298,7 @@ if defined DoLink (
       </PropertyGroup>
       <PropertyGroup>
       <CLRTestRunFile Condition="'$(CLRTestIsHosted)'=='true'">"%CORE_ROOT%\corerun.exe" $(CoreRunArgs) %__DotEnvArg%</CLRTestRunFile>
-      <WatcherRunFile>"%CORE_ROOT%\watchdog.exe" 300</WatcherRunFile>
+      <WatcherRunFile>"%CORE_ROOT%\watchdog.exe" %_WatcherTimeoutMilliseconds%</WatcherRunFile>
 
       <BatchCopyCoreShimLocalCmds Condition="'$(CLRTestScriptLocalCoreShim)' == 'true'"><![CDATA[
 REM Local CoreShim requested - see MSBuild property 'CLRTestScriptLocalCoreShim'
@@ -439,6 +439,11 @@ set "lockFolder=%~dp0\lock"
 pushd %~dp0
 set "scriptPath=%~dp0"
 set /A _RunWithWatcher=0
+set _WatcherTimeoutMilliseconds=600000
+
+IF NOT "%__TestTimeout%"=="" (
+    set _WatcherTimeoutMilliseconds=%__TestTimeout%
+)
 
 $(BatchCLRTestArgPrep)
 $(BatchCLRTestExitCodePrep)

src/tests/Common/XUnitLogChecker/XUnitLogChecker.cs

@@ -1,8 +1,10 @@
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.IO;
 using System.Linq;
 using System.Text.RegularExpressions;
+using System.Threading;
 using System.Xml;
 
 public class XUnitLogChecker
@@ -29,6 +31,7 @@ private enum TagCategory { OPENING, CLOSING }
 
     private const int SUCCESS = 0;
     private const int MISSING_ARGS = -1;
+    private const int FAILURE = -2;
 
     static int Main(string[] args)
     {
@@ -73,8 +76,41 @@ static int Main(string[] args)
             return SUCCESS;
         }
 
-        // Read the stats csv file.
-        IEnumerable<string> workItemStats = File.ReadLines(statsCsvPath);
+        // If the final results log file is present, then we can assume everything
+        // went fine, and it's ready to go without any further processing. We just
+        // check the stats csv file to know how many tests were run, and display a
+        // brief summary of the work item.
+
+        if (File.Exists(finalLogPath))
+        {
+            Console.WriteLine($"[XUnitLogChecker]: Item '{wrapperName}' did"
+                              + " complete successfully!");
+            return SUCCESS;
+        }
+
+        // If we're here, then that means we've got something to fix.
+        // First, read the stats csv file. If it doesn't exist, then we can
+        // assume something went very badly and will likely cause more issues
+        // later on, so we exit now.
+
+        if (!File.Exists(statsCsvPath))
+        {
+            Console.WriteLine("[XUnitLogChecker]: An error occurred. No stats csv"
+                            + $" was found. The expected name would be '{statsCsvPath}'.");
+            return FAILURE;
+        }
+
+        // Declaring the enumerable to contain the log lines first because we
+        // might not be able to read on the first try due to locked resources
+        // on Windows. We will retry for up to one minute when this case happens.
+        IEnumerable<string>? workItemStats = TryReadFile(statsCsvPath);
+
+        if (workItemStats is null)
+        {
+            Console.WriteLine("[XUnitLogChecker]: Timed out trying to read the"
+                            + $" stats file '{statsCsvPath}'.");
+            return FAILURE;
+        }
 
         // The first value at the top of the csv represents the amount of tests
         // that were expected to be run.
@@ -93,25 +129,17 @@ static int Main(string[] args)
                                                .Select(x => Int32.Parse(x))
                                                .ToArray();
 
-        // If the final results log file is present, then we can assume everything
-        // went fine, and it's ready to go without any further processing. We just
-        // check the stats csv file to know how many tests were run, and display a
-        // brief summary of the work item.
-
-        if (File.Exists(finalLogPath))
-        {
-            Console.WriteLine($"[XUnitLogChecker]: Item '{wrapperName}' did"
-                              + " complete successfully!");
-
-            PrintWorkItemSummary(numExpectedTests, workItemEndStatus);
-            return SUCCESS;
-        }
-
         // Here goes the main core of the XUnit Log Checker :)
         Console.WriteLine($"[XUnitLogChecker]: Item '{wrapperName}' did not"
                         + " finish running. Checking and fixing the log...");
 
-        FixTheXml(tempLogPath);
+        bool success = FixTheXml(tempLogPath);
+        if (!success)
+        {
+            Console.WriteLine("[XUnitLogChecker]: Fixing the log failed.");
+            return FAILURE;
+        }
+
         PrintWorkItemSummary(numExpectedTests, workItemEndStatus);
 
         // Rename the temp log to the final log, so that Helix can use it without
@@ -120,6 +148,33 @@ static int Main(string[] args)
         return SUCCESS;
     }
 
+    static IEnumerable<string> TryReadFile(string filePath)
+    {
+        IEnumerable<string>? fileContents = null;
+        Stopwatch fileReadStopwatch = Stopwatch.StartNew();
+
+        while (fileReadStopwatch.ElapsedMilliseconds < 60000)
+        {
+            // We were able to read the file, so we can finish this loop.
+            if (fileContents is not null)
+                break;
+
+            try
+            {
+                fileContents = File.ReadLines(filePath);
+            }
+            catch (IOException ioEx)
+            {
+                Console.WriteLine("[XUnitLogChecker]: Could not read the"
+                                + $" file {filePath}. Retrying...");
+
+                // Give it a couple seconds before trying again.
+                Thread.Sleep(2000);
+            }
+        }
+        return fileContents;
+    }
+
     static void PrintWorkItemSummary(int numExpectedTests, int[] workItemEndStatus)
     {
         Console.WriteLine($"\n{workItemEndStatus[0]}/{numExpectedTests} tests run.");
@@ -128,17 +183,25 @@ static void PrintWorkItemSummary(int numExpectedTests, int[] workItemEndStatus)
         Console.WriteLine($"* {workItemEndStatus[3]} tests skipped.\n");
     }
 
-    static void FixTheXml(string xFile)
+    static bool FixTheXml(string xFile)
     {
         var tags = new Stack<string>();
         string tagText = string.Empty;
+        IEnumerable<string>? logLines = TryReadFile(xFile);
+
+        if (logLines is null)
+        {
+            Console.WriteLine("[XUnitLogChecker]: Timed out trying to read the"
+                            + $" log file '{xFile}'.");
+            return false;
+        }
 
         // Flag to ensure we don't process tag-like-looking things while reading through
         // a test's output.
         bool inOutput = false;
         bool inCData = false;
 
-        foreach (string line in File.ReadLines(xFile))
+        foreach (string line in logLines)
         {
             // Get all XML tags found in the current line and sort them in order
             // of appearance.
@@ -212,6 +275,7 @@ static void FixTheXml(string xFile)
         if (tags.Count == 0)
         {
             Console.WriteLine($"[XUnitLogChecker]: XUnit log file '{xFile}' was A-OK!");
+            return true;
         }
 
         // Write the missing closings for all the opened tags we found.
@@ -226,6 +290,7 @@ static void FixTheXml(string xFile)
         }
 
         Console.WriteLine("[XUnitLogChecker]: XUnit log file has been fixed!");
+        return true;
     }
 
     static TagResult[] GetOrderedTagMatches(Match[] openingTags, Match[] closingTags)