Replaced file wait with async log retrieval

Author: JustinGrote

test/PowerShellEditorServices.Test.E2E/DebugAdapterProtocolMessageTests.cs

@@ -30,21 +30,38 @@ public class DebugAdapterProtocolMessageTests(ITestOutputHelper output) : IAsync
         private IDebugAdapterClient client;
 
         private static readonly bool s_isWindows = RuntimeInformation.IsOSPlatform(OSPlatform.Windows);
-        private static readonly string s_testTempPath = Path.Combine(Path.GetTempPath(), Path.GetRandomFileName());
+
+        /// <summary>
+        /// Test scripts output here, where the output can be read to verify script progress against breakpointing
+        /// </summary>
+        private static readonly string testScriptLogPath = Path.Combine(Path.GetTempPath(), Path.GetRandomFileName());
 
         private readonly PsesStdioLanguageServerProcessHost psesHost = new(isDebugAdapter: true);
 
         private readonly TaskCompletionSource<IDebugAdapterClient> initializedLanguageClientTcs = new();
+        /// <summary>
+        /// This task is useful for waiting until the client is initialized (but before Server Initialized is sent)
+        /// </summary>
         private Task<IDebugAdapterClient> initializedLanguageClient => initializedLanguageClientTcs.Task;
 
         /// <summary>
-        /// This TCS is useful for waiting until a breakpoint is hit in a test.
-        /// </summary>
+        /// Is used to read the script log file to verify script progress against breakpointing.
+        private StreamReader scriptLogReader;
+
         private TaskCompletionSource<StoppedEvent> nextStoppedTcs = new();
+        /// <summary>
+        /// This task is useful for waiting until a breakpoint is hit in a test.
+        /// </summary>
         private Task<StoppedEvent> nextStopped => nextStoppedTcs.Task;
 
         public async Task InitializeAsync()
         {
+            // Cleanup testScriptLogPath if it exists due to an interrupted previous run
+            if (File.Exists(testScriptLogPath))
+            {
+                File.Delete(testScriptLogPath);
+            }
+
             (StreamReader stdout, StreamWriter stdin) = await psesHost.Start();
 
             // Splice the streams together and enable debug logging of all messages sent and received
@@ -106,6 +123,12 @@ await client.RequestDisconnect(new DisconnectArguments
             });
             client?.Dispose();
             psesHost.Stop();
+
+            scriptLogReader?.Dispose(); //Also disposes the underlying filestream
+            if (File.Exists(testScriptLogPath))
+            {
+                File.Delete(testScriptLogPath);
+            }
         }
 
         private static string NewTestFile(string script, bool isPester = false)
@@ -117,17 +140,24 @@ private static string NewTestFile(string script, bool isPester = false)
             return filePath;
         }
 
-        private string GenerateScriptFromLoggingStatements(params string[] logStatements)
+        /// <summary>
+        /// Given an array of strings, generate a PowerShell script that writes each string to our test script log path
+        /// so it can be read back later to verify script progress against breakpointing.
+        /// </summary>
+        /// <param name="logStatements">A list of statements that for which a script will be generated to write each statement to a testing log that can be read by <see cref="ReadScriptLogLineAsync" />. The strings are double quoted in Powershell, so variables such as <c>$($PSScriptRoot)</c> etc. can be used</param>
+        /// <returns>A script string that should be written to disk and instructed by PSES to execute</returns>
+        /// <exception cref="ArgumentNullException"></exception>
+        private string GenerateLoggingScript(params string[] logStatements)
         {
             if (logStatements.Length == 0)
             {
                 throw new ArgumentNullException(nameof(logStatements), "Expected at least one argument.");
             }
 
             // Clean up side effects from other test runs.
-            if (File.Exists(s_testTempPath))
+            if (File.Exists(testScriptLogPath))
             {
-                File.Delete(s_testTempPath);
+                File.Delete(testScriptLogPath);
             }
 
             // Have script create file first with `>` (but don't rely on overwriting).
@@ -136,7 +166,7 @@ private string GenerateScriptFromLoggingStatements(params string[] logStatements
                 .Append("Write-Output \"")
                 .Append(logStatements[0])
                 .Append("\" > '")
-                .Append(s_testTempPath)
+                .Append(testScriptLogPath)
                 .AppendLine("'");
 
             for (int i = 1; i < logStatements.Length; i++)
@@ -146,7 +176,7 @@ private string GenerateScriptFromLoggingStatements(params string[] logStatements
                     .Append("Write-Output \"")
                     .Append(logStatements[i])
                     .Append("\" >> '")
-                    .Append(s_testTempPath)
+                    .Append(testScriptLogPath)
                     .AppendLine("'");
             }
 
@@ -155,15 +185,37 @@ private string GenerateScriptFromLoggingStatements(params string[] logStatements
             return builder.ToString();
         }
 
-        private static async Task<string[]> GetLog()
+        /// <summary>
+        /// Reads the next output line from the test script log file. Useful in assertions to verify script progress against breakpointing.
+        /// </summary>
+        private async Task<string> ReadScriptLogLineAsync()
         {
-            for (int i = 0; !File.Exists(s_testTempPath) && i < 60; i++)
+            while (scriptLogReader is null)
             {
-                await Task.Delay(1000);
+                try
+                {
+                    scriptLogReader = new StreamReader(
+                        new FileStream(
+                            testScriptLogPath,
+                            FileMode.OpenOrCreate,
+                            FileAccess.Read, // Because we use append, its OK to create the file ahead of the script
+                            FileShare.ReadWrite
+                        )
+                    );
+                }
+                catch (IOException) //Sadly there does not appear to be a xplat way to wait for file availability, but luckily this does not appear to fire often.
+                {
+                    await Task.Delay(500);
+                }
+            }
+
+            // return valid lines only
+            string nextLine = string.Empty;
+            while (nextLine is null || nextLine.Length == 0)
+            {
+                nextLine = await scriptLogReader.ReadLineAsync(); //Might return null if at EOF because we created it above but the script hasn't written to it yet
             }
-            // Sleep one more time after the file exists so whatever is writing can finish.
-            await Task.Delay(1000);
-            return File.ReadLines(s_testTempPath).ToArray();
+            return nextLine;
         }
 
         [Fact]
@@ -181,36 +233,35 @@ public void CanInitializeWithCorrectServerSettings()
         [Fact]
         public async Task UsesDotSourceOperatorAndQuotesAsync()
         {
-            string filePath = NewTestFile(GenerateScriptFromLoggingStatements("$($MyInvocation.Line)"));
+            string filePath = NewTestFile(GenerateLoggingScript("$($MyInvocation.Line)"));
             await client.LaunchScript(filePath);
             ConfigurationDoneResponse configDoneResponse = await client.RequestConfigurationDone(new ConfigurationDoneArguments());
             Assert.NotNull(configDoneResponse);
-            Assert.Collection(await GetLog(),
-                (i) => Assert.StartsWith(". '", i));
+            string actual = await ReadScriptLogLineAsync();
+            Assert.StartsWith(". '", actual);
         }
 
         [Fact]
         public async Task UsesCallOperatorWithSettingAsync()
         {
-            string filePath = NewTestFile(GenerateScriptFromLoggingStatements("$($MyInvocation.Line)"));
+            string filePath = NewTestFile(GenerateLoggingScript("$($MyInvocation.Line)"));
             await client.LaunchScript(filePath, executeMode: "Call");
             ConfigurationDoneResponse configDoneResponse = await client.RequestConfigurationDone(new ConfigurationDoneArguments());
             Assert.NotNull(configDoneResponse);
-            Assert.Collection(await GetLog(),
-                (i) => Assert.StartsWith("& '", i));
+            string actual = await ReadScriptLogLineAsync();
+            Assert.StartsWith("& '", actual);
         }
 
         [Fact]
         public async Task CanLaunchScriptWithNoBreakpointsAsync()
         {
-            string filePath = NewTestFile(GenerateScriptFromLoggingStatements("works"));
+            string filePath = NewTestFile(GenerateLoggingScript("works"));
 
             await client.LaunchScript(filePath);
 
             ConfigurationDoneResponse configDoneResponse = await client.RequestConfigurationDone(new ConfigurationDoneArguments());
             Assert.NotNull(configDoneResponse);
-            Assert.Collection(await GetLog(),
-                (i) => Assert.Equal("works", i));
+            Assert.Equal("works", await ReadScriptLogLineAsync());
         }
 
         [SkippableFact]
@@ -219,7 +270,7 @@ public async Task CanSetBreakpointsAsync()
             Skip.If(PsesStdioLanguageServerProcessHost.RunningInConstrainedLanguageMode,
                 "Breakpoints can't be set in Constrained Language Mode.");
 
-            string filePath = NewTestFile(GenerateScriptFromLoggingStatements(
+            string filePath = NewTestFile(GenerateLoggingScript(
                 "before breakpoint",
                 "at breakpoint",
                 "after breakpoint"
@@ -243,32 +294,36 @@ public async Task CanSetBreakpointsAsync()
             ConfigurationDoneResponse configDoneResponse = await client.RequestConfigurationDone(new ConfigurationDoneArguments());
             Assert.NotNull(configDoneResponse);
 
+            // Wait until we hit the breakpoint
             StoppedEvent stoppedEvent = await nextStopped;
+            Assert.Equal("breakpoint", stoppedEvent.Reason);
+
+            // The code before the breakpoint should have already run
+            Assert.Equal("before breakpoint", await ReadScriptLogLineAsync());
 
             // Assert that the stopped breakpoint is the one we set
             StackTraceResponse stackTraceResponse = await client.RequestStackTrace(new StackTraceArguments { ThreadId = 1 });
             DapStackFrame stoppedTopFrame = stackTraceResponse.StackFrames.First();
             Assert.Equal(2, stoppedTopFrame.Line);
 
+            _ = await client.RequestContinue(new ContinueArguments { ThreadId = 1 });
 
-            ContinueResponse continueResponse = await client.RequestContinue(
-                new ContinueArguments { ThreadId = 1 });
-
-            Assert.NotNull(continueResponse);
-            Assert.Collection(await GetLog(),
-                (i) => Assert.Equal("at breakpoint", i),
-                (i) => Assert.Equal("after breakpoint", i));
+            Assert.Equal("at breakpoint", await ReadScriptLogLineAsync());
+            Assert.Equal("after breakpoint", await ReadScriptLogLineAsync());
         }
 
         [SkippableFact]
         public async Task FailsIfStacktraceRequestedWhenNotPaused()
         {
             Skip.If(PsesStdioLanguageServerProcessHost.RunningInConstrainedLanguageMode,
                 "Breakpoints can't be set in Constrained Language Mode.");
-            string filePath = NewTestFile(GenerateScriptFromLoggingStatements(
-                "labelTestBreakpoint"
+
+            // We want a long running script that never hits the next breakpoint
+            string filePath = NewTestFile(GenerateLoggingScript(
+                "$(sleep 10)",
+                "Should fail before we get here"
             ));
-            // Set a breakpoint
+
             await client.SetBreakpoints(
                 new SetBreakpointsArguments
                 {
@@ -282,7 +337,7 @@ await client.SetBreakpoints(
             await client.RequestConfigurationDone(new ConfigurationDoneArguments());
             await client.LaunchScript(filePath);
 
-            // Get the stacktrace for the breakpoint
+            // Try to get the stacktrace. If we are not at a breakpoint, this should fail.
             await Assert.ThrowsAsync<JsonRpcException>(() => client.RequestStackTrace(
                 new StackTraceArguments { }
             ));
@@ -293,17 +348,14 @@ public async Task SendsInitialLabelBreakpointForPerformanceReasons()
         {
             Skip.If(PsesStdioLanguageServerProcessHost.RunningInConstrainedLanguageMode,
                 "Breakpoints can't be set in Constrained Language Mode.");
-            string filePath = NewTestFile(GenerateScriptFromLoggingStatements(
+            string filePath = NewTestFile(GenerateLoggingScript(
                 "before breakpoint",
-                "at breakpoint",
-                "after breakpoint"
+                "label breakpoint"
             ));
 
-            //TODO: This is technically wrong per the spec, configDone should be completed BEFORE launching, but this is how the vscode client does it today and we really need to fix that.
+            // Trigger a launch. Note that per DAP spec, launch doesn't actually begin until ConfigDone finishes.
             await client.LaunchScript(filePath);
 
-
-            // {"command":"setBreakpoints","arguments":{"source":{"name":"dfsdfg.ps1","path":"/Users/tyleonha/Code/PowerShell/Misc/foo/dfsdfg.ps1"},"lines":[2],"breakpoints":[{"line":2}],"sourceModified":false},"type":"request","seq":3}
             SetBreakpointsResponse setBreakpointsResponse = await client.SetBreakpoints(new SetBreakpointsArguments
             {
                 Source = new Source { Name = Path.GetFileName(filePath), Path = filePath },
@@ -318,16 +370,20 @@ public async Task SendsInitialLabelBreakpointForPerformanceReasons()
 
             _ = client.RequestConfigurationDone(new ConfigurationDoneArguments());
 
-            // Resume when the next breakpoint hits
+            // Wait for the breakpoint to be hit
             StoppedEvent stoppedEvent = await nextStopped;
-
             Assert.Equal("breakpoint", stoppedEvent.Reason);
 
+            // The code before the breakpoint should have already run
+            Assert.Equal("before breakpoint", await ReadScriptLogLineAsync());
+
             // Get the stacktrace for the breakpoint
             StackTraceResponse stackTraceResponse = await client.RequestStackTrace(
                 new StackTraceArguments { ThreadId = 1 }
             );
             DapStackFrame firstFrame = stackTraceResponse.StackFrames.First();
+
+            // Our synthetic label breakpoint should be present
             Assert.Equal(
                 StackFramePresentationHint.Label,
                 firstFrame.PresentationHint
@@ -391,7 +447,7 @@ public async Task CanStepPastSystemWindowsForms()
         [Fact]
         public async Task CanLaunchScriptWithCommentedLastLineAsync()
         {
-            string script = GenerateScriptFromLoggingStatements("$($MyInvocation.Line)") + "# a comment at the end";
+            string script = GenerateLoggingScript("$($MyInvocation.Line)", "$(1+1)") + "# a comment at the end";
             Assert.EndsWith(Environment.NewLine + "# a comment at the end", script);
 
             // NOTE: This is horribly complicated, but the "script" parameter here is assigned to
@@ -400,15 +456,16 @@ public async Task CanLaunchScriptWithCommentedLastLineAsync()
             // ConfigurationDoneHandler in LaunchScriptAsync.
             await client.LaunchScript(script);
 
-            ConfigurationDoneResponse configDoneResponse = await client.RequestConfigurationDone(new ConfigurationDoneArguments());
-            Assert.NotNull(configDoneResponse);
+            _ = await client.RequestConfigurationDone(new ConfigurationDoneArguments());
+
             // We can check that the script was invoked as expected, which is to dot-source a script
             // block with the contents surrounded by newlines. While we can't check that the last
             // line was a curly brace by itself, we did check that the contents ended with a
             // comment, so if this output exists then the bug did not recur.
-            Assert.Collection(await GetLog(),
-                (i) => Assert.Equal(". {", i),
-                (i) => Assert.Equal("", i));
+            Assert.Equal(". {", await ReadScriptLogLineAsync());
+
+            // Verifies that the script did run and the body was evaluated
+            Assert.Equal("2", await ReadScriptLogLineAsync());
         }
 
         [SkippableFact]
@@ -441,14 +498,14 @@ public async Task CanRunPesterTestFile()
                         { throw 'error' } | Should -Throw
                     }
                     It 'D' {
-                        " + GenerateScriptFromLoggingStatements("pester") + @"
+                        " + GenerateLoggingScript("pester") + @"
                     }
                 }
             }", isPester: true);
 
             await client.LaunchScript($"Invoke-Pester -Script '{pesterTest}'");
             await client.RequestConfigurationDone(new ConfigurationDoneArguments());
-            Assert.Collection(await GetLog(), (i) => Assert.Equal("pester", i));
+            Assert.Equal("pester", await ReadScriptLogLineAsync());
         }
     }
 }