From d51a6951c7e40a0dc6a8eb8f2a47f2517a1cb275 Mon Sep 17 00:00:00 2001 From: Nate McMaster Date: Mon, 12 Feb 2018 12:29:13 -0800 Subject: [PATCH] Add more logging for flaky tests on CI (#393) --- .../AwaitableProcess.cs | 16 +++++++++++++--- .../DotNetWatcherTests.cs | 2 +- .../GlobbingAppTests.cs | 3 +-- .../Scenario/WatchableApp.cs | 9 ++++----- 4 files changed, 19 insertions(+), 11 deletions(-) diff --git a/test/dotnet-watch.FunctionalTests/AwaitableProcess.cs b/test/dotnet-watch.FunctionalTests/AwaitableProcess.cs index 1700845d5e..25a0189315 100644 --- a/test/dotnet-watch.FunctionalTests/AwaitableProcess.cs +++ b/test/dotnet-watch.FunctionalTests/AwaitableProcess.cs @@ -6,6 +6,7 @@ using System.Collections.Generic; 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 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests _logger.WriteLine($"{DateTime.Now}: process start: '{_process.StartInfo.FileName} {_process.StartInfo.Arguments}'"); } - public Task GetOutputLineAsync(string message) - => GetOutputLineAsync(m => message == m); + public async Task 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 GetOutputLineAsync(Predicate predicate) + public async Task 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); + } + + private async Task GetOutputLineAsync(Predicate predicate) { while (!_source.Completion.IsCompleted) { diff --git a/test/dotnet-watch.FunctionalTests/DotNetWatcherTests.cs b/test/dotnet-watch.FunctionalTests/DotNetWatcherTests.cs index 368c55a202..d0dc735247 100644 --- a/test/dotnet-watch.FunctionalTests/DotNetWatcherTests.cs +++ b/test/dotnet-watch.FunctionalTests/DotNetWatcherTests.cs @@ -25,7 +25,7 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests 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); } diff --git a/test/dotnet-watch.FunctionalTests/GlobbingAppTests.cs b/test/dotnet-watch.FunctionalTests/GlobbingAppTests.cs index 4e958f71f5..71b5d068bf 100644 --- a/test/dotnet-watch.FunctionalTests/GlobbingAppTests.cs +++ b/test/dotnet-watch.FunctionalTests/GlobbingAppTests.cs @@ -5,7 +5,6 @@ using System; 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 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests public async Task 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()); } } diff --git a/test/dotnet-watch.FunctionalTests/Scenario/WatchableApp.cs b/test/dotnet-watch.FunctionalTests/Scenario/WatchableApp.cs index 88c322b382..7725812bd6 100644 --- a/test/dotnet-watch.FunctionalTests/Scenario/WatchableApp.cs +++ b/test/dotnet-watch.FunctionalTests/Scenario/WatchableApp.cs @@ -7,7 +7,6 @@ using System.IO; 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 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests 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 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 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests // 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()