Improve msbuild logger for testing workloads

src/Framework/Logging/AnsiCodes.cs

@@ -1,6 +1,8 @@
 // Licensed to the .NET Foundation under one or more agreements.
 // The .NET Foundation licenses this file to you under the MIT license.
 
+using System.Text.RegularExpressions;
+
 namespace Microsoft.Build.Logging.TerminalLogger;
 
 /// <summary>

src/MSBuild.UnitTests/NodeStatus_Tests.cs → src/MSBuild.UnitTests/NodeStatus_SizeChange_Tests.cs

@@ -3,8 +3,10 @@
 
 using System;
 using System.Collections.Generic;
+using System.IO;
 using System.Linq;
 using System.Text;
+using System.Text.RegularExpressions;
 using System.Threading.Tasks;
 
 using Microsoft.Build.Logging.TerminalLogger;
@@ -19,11 +21,11 @@
 namespace Microsoft.Build.CommandLine.UnitTests;
 
 [UsesVerify]
-public class NodeStatus_Tests
+public class NodeStatus_SizeChange_Tests
 {
     private readonly NodeStatus _status = new("Namespace.Project", "TargetFramework", "Target", new MockStopwatch());
 
-    public NodeStatus_Tests()
+    public NodeStatus_SizeChange_Tests()
     {
         UseProjectRelativeDirectory("Snapshots");
     }

src/MSBuild.UnitTests/NodeStatus_Transition_Tests.cs

@@ -0,0 +1,180 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+using System;
+using System.Collections.Generic;
+using System.IO;
+using System.Linq;
+using System.Text;
+using System.Text.RegularExpressions;
+using System.Threading.Tasks;
+
+using Microsoft.Build.Logging.TerminalLogger;
+using Shouldly;
+using VerifyTests;
+using VerifyXunit;
+using Xunit;
+
+using static VerifyXunit.Verifier;
+
+
+namespace Microsoft.Build.CommandLine.UnitTests;
+
+[UsesVerify]
+public class NodeStatus_Transition_Tests
+{
+    public NodeStatus_Transition_Tests()
+    {
+        UseProjectRelativeDirectory("Snapshots");
+    }
+
+    [Fact]
+    public void NodeStatusTargetThrowsForInputWithAnsi()
+    {
+#if DEBUG
+        Func<NodeStatus> newNodeStatus = () => new NodeStatus("project", "tfm", AnsiCodes.Colorize("colorized target", TerminalColor.Green), new MockStopwatch());
+        newNodeStatus.ShouldThrow<Exception>().Message.ShouldContain("Target should not contain any escape codes, if you want to colorize target use the other constructor.");
+#endif
+    }
+
+    [Fact]
+    public async Task NodeTargetChanges()
+    {
+        var rendered = Animate(
+            [
+                new("Namespace.Project", "TargetFramework", "Build", new MockStopwatch())
+            ],
+            [
+               new("Namespace.Project", "TargetFramework", "Testing", new MockStopwatch())
+            ]);
+
+        await VerifyReplay(rendered);
+    }
+
+    [Fact]
+    public async Task NodeTargetUpdatesTime()
+    {
+        // This test look like there is no change between the frames, but we ask the stopwatch for time they will increase the number.
+        // We need this because animations check that NodeStatus reference is the same.
+        // And we cannot use MockStopwatch because we don't know when to call Tick on them, and if we do it right away, the time will update in "both" nodes.
+        NodeStatus node = new("Namespace.Project", "TargetFramework", "Build", new TickingStopwatch());
+        var rendered = Animate(
+            [
+                node,
+            ],
+            [
+               node,
+            ]);
+
+        await VerifyReplay(rendered);
+    }
+
+    [Fact]
+    public async Task NodeTargetChangesToColoredTarget()
+    {
+        var rendered = Animate(
+            [
+                new("Namespace.Project", "TargetFramework", "Testing", new MockStopwatch())
+            ],
+            [
+               new("Namespace.Project", "TargetFramework", TerminalColor.Red, "failed", "MyTestName1", new MockStopwatch())
+            ]);
+
+        await VerifyReplay(rendered);
+    }
+
+    [Fact]
+    public async Task NodeWithColoredTargetUpdatesTime()
+    {
+        // This test look like there is no change between the frames, but we ask the stopwatch for time they will increase the number.
+        // We need this because animations check that NodeStatus reference is the same.
+        // And we cannot use MockStopwatch because we don't know when to call Tick on them, and if we do it right away, the time will update in "both" nodes.
+        NodeStatus node = new("Namespace.Project", "TargetFramework", TerminalColor.Green, "passed", "MyTestName1", new TickingStopwatch());
+        var rendered = Animate(
+            [
+                node,
+            ],
+            [
+               node
+            ]);
+
+        await VerifyReplay(rendered);
+    }
+
+    /// <summary>
+    /// Chains and renders node status updates and outputs replay able string of all the transitions.
+    /// </summary>
+    /// <param name="nodeStatusesUpdates">Takes array of arrays. The inner array is collection of nodes that are currently running. The outer array is how they update over time.</param>
+    /// <returns></returns>
+    private string Animate(params NodeStatus[][] nodeStatusesUpdates)
+    {
+        var width = 80;
+        var height = 1;
+
+        NodesFrame previousFrame = new(Array.Empty<NodeStatus>(), 0, 0);
+        StringBuilder result = new StringBuilder();
+        foreach (var nodeStatuses in nodeStatusesUpdates)
+        {
+            NodesFrame currentFrame = new NodesFrame(nodeStatuses, width, height);
+            result.Append(currentFrame.Render(previousFrame));
+            previousFrame = currentFrame;
+        }
+
+        return result.ToString();
+    }
+
+    private async Task VerifyReplay(string rendered)
+    {
+        try
+        {
+            await Verify(rendered);
+        }
+        catch (Exception ex)
+        {
+            if (ex.GetType().Name != "VerifyException")
+            {
+                throw;
+            }
+
+            if (!ex.Message.StartsWith("Directory:"))
+            {
+                throw;
+            }
+
+            string? directory = null;
+            string? received = null;
+            string? verified = null;
+            foreach (var line in ex.Message.Split('\n'))
+            {
+                var trimmed = line.TrimStart(' ', '-');
+                Extract(trimmed, "Directory", ref directory);
+                Extract(trimmed, "Received", ref received);
+                Extract(trimmed, "Verified", ref verified);
+            }
+
+            if (directory == null || received == null || verified == null)
+            {
+                throw;
+            }
+
+            var pipeline = $$""" | % { "`n`n" } { $_ -split "(?=`e)" | % { Write-Host -NoNewline $_; Start-Sleep 0.5 }; Write-Host }""";
+            throw new Exception($$"""
+                {{ex.Message.TrimEnd('\n')}}
+
+                Received replay:
+                    Get-Content {{Path.Combine(directory, received)}} {{pipeline}}
+
+                Verified replay:
+                    Get-Content {{Path.Combine(directory, verified)}} {{pipeline}}
+                """);
+        }
+
+        void Extract(string line, string prefix, ref string? output)
+        {
+            if (line.StartsWith($"{prefix}: "))
+            {
+                output = line.Substring(prefix.Length + 2);
+            }
+        }
+    }
+}

src/MSBuild.UnitTests/Snapshots/NodeStatus_Transition_Tests.NodeTargetChanges.verified.txt

@@ -0,0 +1,4 @@
+
+  Namespace.Project TargetFramework Build (0.0s)
+
+  Namespace.Project TargetFramework Testing (0.0s)

src/MSBuild.UnitTests/Snapshots/NodeStatus_Transition_Tests.NodeTargetChangesToColoredTarget.verified.txt

@@ -0,0 +1,4 @@
+
+  Namespace.Project TargetFramework Testing (0.0s)
+
+  Namespace.Project TargetFramework failed MyTestName1 (0.0s)

src/MSBuild.UnitTests/Snapshots/NodeStatus_Transition_Tests.NodeTargetUpdatesTime.verified.txt

@@ -0,0 +1,4 @@
+
+  Namespace.Project TargetFramework Build (0.0s)
+
+(0.2s)

src/MSBuild.UnitTests/Snapshots/NodeStatus_Transition_Tests.NodeWithColoredTargetUpdatesTime.verified.txt

@@ -0,0 +1,4 @@
+
+  Namespace.Project TargetFramework passed MyTestName1 (0.0s)
+
+(0.2s)

src/MSBuild.UnitTests/StaticStopwatch.cs

@@ -0,0 +1,23 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+using System.Net.Http.Headers;
+using Microsoft.Build.Logging.TerminalLogger;
+
+namespace Microsoft.Build.CommandLine.UnitTests;
+
+/// <summary>
+/// Stopwatch that always show the time provided in constructor.
+/// </summary>
+internal sealed class StaticStopwatch : StopwatchAbstraction
+{
+    public StaticStopwatch(double elapsedSeconds)
+    {
+        ElapsedSeconds = elapsedSeconds;
+    }
+
+    public override double ElapsedSeconds { get; }
+
+    public override void Start() => throw new System.NotImplementedException();
+    public override void Stop() => throw new System.NotImplementedException();
+}

src/MSBuild.UnitTests/TickingStopwatch.cs

@@ -0,0 +1,32 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+using Microsoft.Build.Logging.TerminalLogger;
+
+namespace Microsoft.Build.CommandLine.UnitTests;
+
+/// <summary>
+/// Stopwatch that will increase by 0.1, every time you ask them for time. Useful for animations, because they check that NodeStatus
+/// reference stays the same, and also for ensuring we are grabbing the time only once per frame.
+/// </summary>
+internal sealed class TickingStopwatch : StopwatchAbstraction
+{
+    private double _elapsedSeconds;
+
+    public TickingStopwatch(double elapsedSeconds = 0.0)
+    {
+        _elapsedSeconds = elapsedSeconds;
+    }
+
+    public override double ElapsedSeconds
+    {
+        get
+        {
+            var elapsed = _elapsedSeconds;
+            _elapsedSeconds += 0.1;
+            return elapsed;
+        }
+    }
+    public override void Start() => throw new System.NotImplementedException();
+    public override void Stop() => throw new System.NotImplementedException();
+}