Add more logging for flaky tests on CI (#393)

Author: natemcmaster

test/dotnet-watch.FunctionalTests/AwaitableProcess.cs

@@ -6,6 +6,7 @@
 using System.Diagnostics;
 using System.Threading.Tasks;
 using System.Threading.Tasks.Dataflow;
+using Microsoft.AspNetCore.Testing;
 using Microsoft.Extensions.Internal;
 using Microsoft.Extensions.CommandLineUtils;
 using Xunit.Abstractions;
@@ -61,10 +62,19 @@ public void Start()
             _logger.WriteLine($"{DateTime.Now}: process start: '{_process.StartInfo.FileName} {_process.StartInfo.Arguments}'");
         }
 
-        public Task<string> GetOutputLineAsync(string message)
-            => GetOutputLineAsync(m => message == m);
+        public async Task<string> GetOutputLineAsync(string message, TimeSpan timeout)
+        {
+            _logger.WriteLine($"Waiting for output line [msg == '{message}']. Will wait for {timeout.TotalSeconds} sec.");
+            return await GetOutputLineAsync(m => message == m).TimeoutAfter(timeout);
+        }
+
+        public async Task<string> GetOutputLineStartsWithAsync(string message, TimeSpan timeout)
+        {
+            _logger.WriteLine($"Waiting for output line [msg.StartsWith('{message}')]. Will wait for {timeout.TotalSeconds} sec.");
+            return await GetOutputLineAsync(m => m.StartsWith(message)).TimeoutAfter(timeout);
+        }
 
-        public async Task<string> GetOutputLineAsync(Predicate<string> predicate)
+        private async Task<string> GetOutputLineAsync(Predicate<string> predicate)
         {
             while (!_source.Completion.IsCompleted)
             {

test/dotnet-watch.FunctionalTests/DotNetWatcherTests.cs

@@ -25,7 +25,7 @@ public async Task RunsWithDotnetWatchEnvVariable()
 
             await _app.StartWatcherAsync();
             const string messagePrefix = "DOTNET_WATCH = ";
-            var message = await _app.Process.GetOutputLineAsync(m => m.StartsWith(messagePrefix));
+            var message = await _app.Process.GetOutputLineStartsWithAsync(messagePrefix, TimeSpan.FromMinutes(2));
             var envValue = message.Substring(messagePrefix.Length);
             Assert.Equal("1", envValue);
         }

test/dotnet-watch.FunctionalTests/GlobbingAppTests.cs

@@ -5,7 +5,6 @@
 using System.IO;
 using System.Linq;
 using System.Threading.Tasks;
-using Microsoft.AspNetCore.Testing;
 using Microsoft.DotNet.Watcher.Tools.Tests;
 using Xunit;
 using Xunit.Abstractions;
@@ -129,7 +128,7 @@ public GlobbingApp(ITestOutputHelper logger)
 
             public async Task<int> GetCompiledAppDefinedTypes()
             {
-                var definedTypesMessage = await Process.GetOutputLineAsync(m => m.StartsWith("Defined types = ")).TimeoutAfter(TimeSpan.FromSeconds(30));
+                var definedTypesMessage = await Process.GetOutputLineStartsWithAsync("Defined types = ", TimeSpan.FromSeconds(30));
                 return int.Parse(definedTypesMessage.Split('=').Last());
             }
         }

test/dotnet-watch.FunctionalTests/Scenario/WatchableApp.cs

@@ -7,7 +7,6 @@
 using System.Linq;
 using System.Runtime.CompilerServices;
 using System.Threading.Tasks;
-using Microsoft.AspNetCore.Testing;
 using Microsoft.Extensions.CommandLineUtils;
 using Xunit.Abstractions;
 
@@ -41,16 +40,16 @@ public WatchableApp(string appName, ITestOutputHelper logger)
         public string SourceDirectory { get; }
 
         public Task HasRestarted()
-            => Process.GetOutputLineAsync(StartedMessage).TimeoutAfter(DefaultMessageTimeOut);
+            => Process.GetOutputLineAsync(StartedMessage, DefaultMessageTimeOut);
 
         public Task HasExited()
-            => Process.GetOutputLineAsync(ExitingMessage).TimeoutAfter(DefaultMessageTimeOut);
+            => Process.GetOutputLineAsync(ExitingMessage, DefaultMessageTimeOut);
 
         public bool UsePollingWatcher { get; set; }
 
         public async Task<int> GetProcessId()
         {
-            var line = await Process.GetOutputLineAsync(l => l.StartsWith("PID =")).TimeoutAfter(DefaultMessageTimeOut);
+            var line = await Process.GetOutputLineStartsWithAsync("PID =", DefaultMessageTimeOut);
             var pid = line.Split('=').Last();
             return int.Parse(pid);
         }
@@ -106,7 +105,7 @@ public async Task StartWatcherAsync(string[] arguments, [CallerMemberName] strin
 
             // Make this timeout long because it depends much on the MSBuild compilation speed.
             // Slow machines may take a bit to compile and boot test apps
-            await Process.GetOutputLineAsync(StartedMessage).TimeoutAfter(TimeSpan.FromMinutes(2));
+            await Process.GetOutputLineAsync(StartedMessage, TimeSpan.FromMinutes(2));
         }
 
         public virtual void Dispose()