[Merge-on-Red] - Implement XML log fixer for Helix

src/tests/Common/XUnitLogChecker/XUnitLogChecker.cs

@@ -0,0 +1,293 @@
+using System;
+using System.Collections.Generic;
+using System.IO;
+using System.Linq;
+using System.Text.RegularExpressions;
+using System.Xml;
+
+public class XUnitLogChecker
+{
+ private static class Patterns
+ {
+ public const string OpenTag = @"(\B<\w+)|(\B<!\[CDATA\[)";
+ public const string CloseTag = @"(\B</\w+>)|(\]\]>)";
+ }
+
+ private readonly struct TagResult
+ {
+ public TagResult(string matchValue, TagCategory matchCategory)
+ {
+ Value = matchValue;
+ Category = matchCategory;
+ }
+
+ public string Value { get; init; }
+ public TagCategory Category { get; init; }
+ }
+
+ private enum TagCategory { OPENING, CLOSING }
+
+ private const int SUCCESS = 0;
+ private const int MISSING_ARGS = -1;
+ private const int SOMETHING_VERY_WRONG = -2;
+
+ static int Main(string[] args)
+ {
+ // Maybe add a '--help' flag that also gets triggered in this case.
+ if (args.Length < 2)
+ {
+ Console.WriteLine("[XUnitLogChecker]: The path to the log file and"
+ + " the name of the wrapper are required for an"
+ + " accurate check and fixing.");
+ return MISSING_ARGS;
+ }
+
+ // Creating variables for code clarity and ease of understanding.
+
+ string resultsDir = args[0];
+ string wrapperName = args[1];
+
+ // Browser-Wasm tests follow a different test files layout in Helix.
+ // Everything is located in a root folder, rather than the usual path
+ // with the wrapper name other platforms follow.
+
+ string tempLogName = string.IsNullOrEmpty(wrapperName)
+ ? "tempLog.xml"
+ : $"{wrapperName}.tempLog.xml";
+
+ string finalLogName = string.IsNullOrEmpty(wrapperName)
+ ? "testResults.xml"
+ : $"{wrapperName}.testResults.xml";
+
+ string statsCsvName = string.IsNullOrEmpty(wrapperName)
+ ? "testStats.csv"
+ : $"{wrapperName}.testStats.csv";
+
+ string tempLogPath = Path.Combine(resultsDir, tempLogName);
+ string finalLogPath = Path.Combine(resultsDir, finalLogName);
+ string statsCsvPath = Path.Combine(resultsDir, statsCsvName);
+
+ // If there is not even the temp log, then something went very badly with
+ // the work item in question. It will need a developer/engineer to look
+ // at it urgently.
+
+ if (!File.Exists(tempLogPath))
+ {
+ Console.WriteLine("[XUnitLogChecker]: No logs were found. Something"
+ + " went very wrong with this item...");
+ Console.WriteLine($"[XUnitLogChecker]: Expected log name: '{tempLogName}'");
+
+ return SOMETHING_VERY_WRONG;
+ }
+
+ // Read the stats csv file.
+ IEnumerable<string> workItemStats = File.ReadLines(statsCsvPath);
+
+ // The first value at the top of the csv represents the amount of tests
+ // that were expected to be run.
+ //
+ // NOTE: We know for certain the csv only includes numbers. Therefore,
+ // we're fine in using Int32.Parse() directly.
+
+ int numExpectedTests = Int32.Parse(workItemStats.First().Split(',').First());
+
+ // The last line of the csv represents the status when the work item
+ // finished, successfully or not. It has the following format:
+ // (Tests Run, Tests Passed, Tests Failed, Tests Skipped)
+
+ int[] workItemEndStatus = workItemStats.Last()
+ .Split(',')
+ .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);
+ PrintWorkItemSummary(numExpectedTests, workItemEndStatus);
+
+ // Rename the temp log to the final log, so that Helix can use it without
+ // knowing what transpired here.
+ File.Move(tempLogPath, finalLogPath);
+ return SUCCESS;
+ }
+
+ static void PrintWorkItemSummary(int numExpectedTests, int[] workItemEndStatus)
+ {
+ Console.WriteLine($"\n{workItemEndStatus[0]}/{numExpectedTests} tests run.");
+ Console.WriteLine($"* {workItemEndStatus[1]} tests passed.");
+ Console.WriteLine($"* {workItemEndStatus[2]} tests failed.");
+ Console.WriteLine($"* {workItemEndStatus[3]} tests skipped.\n");
+ }
+
+ static void FixTheXml(string xFile)
+ {
+ var tags = new Stack<string>();
+ string tagText = string.Empty;
+
+ // 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))
+ {
+ // Get all XML tags found in the current line and sort them in order
+ // of appearance.
+ Match[] opens = Regex.Matches(line, Patterns.OpenTag).ToArray();
+ Match[] closes = Regex.Matches(line, Patterns.CloseTag).ToArray();
+ TagResult[] allTags = GetOrderedTagMatches(opens, closes);
+
+ foreach (TagResult tr in allTags)
+ {
+ // Found an opening tag. Push into the stack and move on to the next one.
+ if (tr.Category == TagCategory.OPENING)
+ {
+ // Get the name of the next tag. We need solely the text, so we
+ // ask LINQ to lend us a hand in removing the symbols from the string.
+ tagText = new String(tr.Value.Where(c => char.IsLetter(c)).ToArray());
+
+ // We are beginning to process a test's output. Set the flag to
+ // treat everything as such, until we get the closing output tag.
+ if (tagText.Equals("output") && !inOutput && !inCData)
+ inOutput = true;
+ else if (tagText.Equals("CDATA") && !inCData)
+ inCData = true;
+
+ tags.Push(tagText);
+ continue;
+ }
+
+ // Found a closing tag. If we're currently in an output state, then
+ // check whether it's the output closing tag. Otherwise, ignore it.
+ // This is because in that case, it's just part of the output's text,
+ // rather than an actual XML log tag.
+ if (tr.Category == TagCategory.CLOSING)
+ {
+ // As opposed to the usual XML tags we can find in the logs,
+ // the CDATA closing one doesn't have letters, so we treat it
+ // as a special case.
+ tagText = tr.Value.Equals("]]>")
+ ? "CDATA"
+ : new String(tr.Value
+ .Where(c => char.IsLetter(c))
+ .ToArray());
+
+ if (inCData)
+ {
+ if (tagText.Equals("CDATA"))
+ {
+ tags.Pop();
+ inCData = false;
+ }
+ else continue;
+ }
+
+ if (inOutput)
+ {
+ if (tagText.Equals("output"))
+ {
+ tags.Pop();
+ inOutput = false;
+ }
+ else continue;
+ }
+
+ if (tagText.Equals(tags.Peek()))
+ {
+ tags.Pop();
+ }
+ }
+ }
+ }
+
+ if (tags.Count == 0)
+ {
+ Console.WriteLine($"[XUnitLogChecker]: XUnit log file '{xFile}' was A-OK!");
+ }
+
+ // Write the missing closings for all the opened tags we found.
+ using (StreamWriter xsw = File.AppendText(xFile))
+ while (tags.Count > 0)
+ {
+ string tag = tags.Pop();
+ if (tag.Equals("CDATA"))
+ xsw.WriteLine("]]>");
+ else
+ xsw.WriteLine($"</{tag}>");
+ }
+
+ Console.WriteLine("[XUnitLogChecker]: XUnit log file has been fixed!");
+ }
+
+ static TagResult[] GetOrderedTagMatches(Match[] openingTags, Match[] closingTags)
+ {
+ var result = new TagResult[openingTags.Length + closingTags.Length];
+ int resIndex = 0;
+ int opIndex = 0;
+ int clIndex = 0;
+
+ // Fill up the result array with the tags found, in order of appearance
+ // in the original log file line.
+ //
+ // As long as the result array hasn't been filled, then we know for certain
+ // that there's at least one unprocessed tag.
+
+ while (resIndex < result.Length)
+ {
+ if (opIndex < openingTags.Length)
+ {
+ // We still have pending tags on both lists, opening and closing.
+ // So, we add the one that appears first in the given log line.
+ if (clIndex < closingTags.Length)
+ {
+ if (openingTags[opIndex].Index < closingTags[clIndex].Index)
+ {
+ result[resIndex++] = new TagResult(openingTags[opIndex].Value,
+ TagCategory.OPENING);
+ opIndex++;
+ }
+ else
+ {
+ result[resIndex++] = new TagResult(closingTags[clIndex].Value,
+ TagCategory.CLOSING);
+ clIndex++;
+ }
+ }
+
+ // Only opening tags remaining, so just add them.
+ else
+ {
+ result[resIndex++] = new TagResult(openingTags[opIndex].Value,
+ TagCategory.OPENING);
+ opIndex++;
+ }
+ }
+
+ // Only closing tags remaining, so just add them.
+ else
+ {
+ result[resIndex++] = new TagResult(closingTags[clIndex].Value,
+ TagCategory.CLOSING);
+ clIndex++;
+ }
+ }
+ return result;
+ }
+}
+

src/tests/Common/XUnitLogChecker/XUnitLogChecker.csproj

@@ -0,0 +1,13 @@
+<Project Sdk="Microsoft.NET.Sdk">
+
+ <PropertyGroup>
+ <OutputType>Exe</OutputType>
+ <TargetFramework>$(NetCoreAppToolCurrent)</TargetFramework>
+ <GenerateRuntimeConfigurationFiles>true</GenerateRuntimeConfigurationFiles>
+ </PropertyGroup>
+
+ <ItemGroup>
+ <Compile Include="XUnitLogChecker.cs" />
+ </ItemGroup>
+
+</Project>

src/tests/Common/XUnitWrapperGenerator/ITestInfo.cs

@@ -333,19 +333,26 @@ public WrapperLibraryTestSummaryReporting(string summaryLocalIdentifier, string
  public string WrapTestExecutionWithReporting(string testExecutionExpression, ITestInfo test)
  {
  StringBuilder builder = new();
- builder.AppendLine($"if ({_filterLocalIdentifier} is null || {_filterLocalIdentifier}.ShouldRunTest(@\"{test.ContainingType}.{test.Method}\", {test.TestNameExpression}))");
+ builder.AppendLine($"if ({_filterLocalIdentifier} is null || {_filterLocalIdentifier}.ShouldRunTest(@\"{test.ContainingType}.{test.Method}\","
+ + $" {test.TestNameExpression}))");
  builder.AppendLine("{");
 
  builder.AppendLine($"System.TimeSpan testStart = stopwatch.Elapsed;");
  builder.AppendLine("try {");
  builder.AppendLine($"System.Console.WriteLine(\"{{0:HH:mm:ss.fff}} Running test: {{1}}\", System.DateTime.Now, {test.TestNameExpression});");
  builder.AppendLine($"{_outputRecorderIdentifier}.ResetTestOutput();");
  builder.AppendLine(testExecutionExpression);
- builder.AppendLine($"{_summaryLocalIdentifier}.ReportPassedTest({test.TestNameExpression}, \"{test.ContainingType}\", @\"{test.Method}\", stopwatch.Elapsed - testStart, {_outputRecorderIdentifier}.GetTestOutput());");
+
+ builder.AppendLine($"{_summaryLocalIdentifier}.ReportPassedTest({test.TestNameExpression}, \"{test.ContainingType}\", @\"{test.Method}\","
+ + $" stopwatch.Elapsed - testStart, {_outputRecorderIdentifier}.GetTestOutput(), tempLogSw, statsCsvSw);");
+
  builder.AppendLine($"System.Console.WriteLine(\"{{0:HH:mm:ss.fff}} Passed test: {{1}}\", System.DateTime.Now, {test.TestNameExpression});");
  builder.AppendLine("}");
  builder.AppendLine("catch (System.Exception ex) {");
- builder.AppendLine($"{_summaryLocalIdentifier}.ReportFailedTest({test.TestNameExpression}, \"{test.ContainingType}\", @\"{test.Method}\", stopwatch.Elapsed - testStart, ex, {_outputRecorderIdentifier}.GetTestOutput());");
+
+ builder.AppendLine($"{_summaryLocalIdentifier}.ReportFailedTest({test.TestNameExpression}, \"{test.ContainingType}\", @\"{test.Method}\","
+ + $" stopwatch.Elapsed - testStart, ex, {_outputRecorderIdentifier}.GetTestOutput(), tempLogSw, statsCsvSw);");
+
  builder.AppendLine($"System.Console.WriteLine(\"{{0:HH:mm:ss.fff}} Failed test: {{1}}\", System.DateTime.Now, {test.TestNameExpression});");
  builder.AppendLine("}");
 
@@ -359,6 +366,7 @@ public string WrapTestExecutionWithReporting(string testExecutionExpression, ITe
 
  public string GenerateSkippedTestReporting(ITestInfo skippedTest)
  {
- return $"{_summaryLocalIdentifier}.ReportSkippedTest({skippedTest.TestNameExpression}, \"{skippedTest.ContainingType}\", @\"{skippedTest.Method}\", System.TimeSpan.Zero, string.Empty);";
+ return $"{_summaryLocalIdentifier}.ReportSkippedTest({skippedTest.TestNameExpression}, \"{skippedTest.ContainingType}\", @\"{skippedTest.Method}\","
+ + $" System.TimeSpan.Zero, string.Empty, tempLogSw, statsCsvSw);";
  }
 }