From 88f43ffc1a43b42fb3b360d45841896334747182 Mon Sep 17 00:00:00 2001 From: Nate McMaster Date: Thu, 27 Apr 2017 17:01:55 -0700 Subject: [PATCH] Fix race conditions between CTRL+C and RunAsync in dotnet-watch Increase timeouts in testing dotnet-run and improve verbosity of test logging --- .../CommandLineOptions.cs | 3 + src/Microsoft.DotNet.Watcher.Tools/Program.cs | 112 ++++++++++-------- .../AppWithDepsTests.cs | 5 +- .../DotNetWatcherTests.cs | 2 +- .../GlobbingAppTests.cs | 41 ++++--- .../NoDepsAppTests.cs | 23 ++-- .../Scenario/WatchableApp.cs | 15 ++- ...icrosoft.DotNet.Watcher.Tools.Tests.csproj | 4 + .../ProgramTests.cs | 9 +- .../Utilities/TaskExtensions.cs | 25 ---- test/Shared/TestConsole.cs | 18 ++- 11 files changed, 143 insertions(+), 114 deletions(-) delete mode 100644 test/Microsoft.DotNet.Watcher.Tools.Tests/Utilities/TaskExtensions.cs diff --git a/src/Microsoft.DotNet.Watcher.Tools/CommandLineOptions.cs b/src/Microsoft.DotNet.Watcher.Tools/CommandLineOptions.cs index 8056dff67e..e6a6b90fba 100644 --- a/src/Microsoft.DotNet.Watcher.Tools/CommandLineOptions.cs +++ b/src/Microsoft.DotNet.Watcher.Tools/CommandLineOptions.cs @@ -38,6 +38,9 @@ Environment variables: changes. This is required for some file systems, such as network shares, Docker mounted volumes, and other virtual file systems. + DOTNET_WATCH + dotnet-watch sets this variable to '1' on all child processes launched. + Remarks: The special option '--' is used to delimit the end of the options and the beginning of arguments that will be passed to the child dotnet process. diff --git a/src/Microsoft.DotNet.Watcher.Tools/Program.cs b/src/Microsoft.DotNet.Watcher.Tools/Program.cs index 2f60889657..3b287ed30f 100644 --- a/src/Microsoft.DotNet.Watcher.Tools/Program.cs +++ b/src/Microsoft.DotNet.Watcher.Tools/Program.cs @@ -12,10 +12,12 @@ using Microsoft.Extensions.Tools.Internal; namespace Microsoft.DotNet.Watcher { - public class Program + public class Program : IDisposable { private readonly IConsole _console; private readonly string _workingDir; + private readonly CancellationTokenSource _cts; + private IReporter _reporter; public Program(IConsole console, string workingDir) { @@ -24,15 +26,21 @@ namespace Microsoft.DotNet.Watcher _console = console; _workingDir = workingDir; + _cts = new CancellationTokenSource(); + _console.CancelKeyPress += OnCancelKeyPress; + _reporter = CreateReporter(verbose: true, quiet: false, console: _console); } public static int Main(string[] args) { DebugHelper.HandleDebugSwitch(ref args); - return new Program(PhysicalConsole.Singleton, Directory.GetCurrentDirectory()) - .RunAsync(args) - .GetAwaiter() - .GetResult(); + using (var program = new Program(PhysicalConsole.Singleton, Directory.GetCurrentDirectory())) + { + return program + .RunAsync(args) + .GetAwaiter() + .GetResult(); + } } public async Task RunAsync(string[] args) @@ -44,8 +52,7 @@ namespace Microsoft.DotNet.Watcher } catch (CommandParsingException ex) { - CreateReporter(verbose: true, quiet: false, console: _console) - .Error(ex.Message); + _reporter.Error(ex.Message); return 1; } @@ -60,54 +67,55 @@ namespace Microsoft.DotNet.Watcher return 2; } - var reporter = CreateReporter(options.IsVerbose, options.IsQuiet, _console); + // update reporter as configured by options + _reporter = CreateReporter(options.IsVerbose, options.IsQuiet, _console); - using (CancellationTokenSource ctrlCTokenSource = new CancellationTokenSource()) + try { - _console.CancelKeyPress += (sender, ev) => + if (_cts.IsCancellationRequested) { - if (!ctrlCTokenSource.IsCancellationRequested) - { - reporter.Output("Shutdown requested. Press Ctrl+C again to force exit."); - ev.Cancel = true; - } - else - { - ev.Cancel = false; - } - ctrlCTokenSource.Cancel(); - }; - - try - { - if (options.ListFiles) - { - return await ListFilesAsync(reporter, - options.Project, - ctrlCTokenSource.Token); - } - else - { - - return await MainInternalAsync(reporter, - options.Project, - options.RemainingArguments, - ctrlCTokenSource.Token); - } - } - catch (Exception ex) - { - if (ex is TaskCanceledException || ex is OperationCanceledException) - { - // swallow when only exception is the CTRL+C forced an exit - return 0; - } - - reporter.Error(ex.ToString()); - reporter.Error("An unexpected error occurred"); return 1; } + + if (options.ListFiles) + { + return await ListFilesAsync(_reporter, + options.Project, + _cts.Token); + } + else + { + return await MainInternalAsync(_reporter, + options.Project, + options.RemainingArguments, + _cts.Token); + } } + catch (Exception ex) + { + if (ex is TaskCanceledException || ex is OperationCanceledException) + { + // swallow when only exception is the CTRL+C forced an exit + return 0; + } + + _reporter.Error(ex.ToString()); + _reporter.Error("An unexpected error occurred"); + return 1; + } + } + + private void OnCancelKeyPress(object sender, ConsoleCancelEventArgs args) + { + // suppress CTRL+C on the first press + args.Cancel = !_cts.IsCancellationRequested; + + if (args.Cancel) + { + _reporter.Output("Shutdown requested. Press Ctrl+C again to force exit."); + } + + _cts.Cancel(); } private async Task MainInternalAsync( @@ -181,5 +189,11 @@ namespace Microsoft.DotNet.Watcher private static IReporter CreateReporter(bool verbose, bool quiet, IConsole console) => new PrefixConsoleReporter(console, verbose || CliContext.IsGlobalVerbose(), quiet); + + public void Dispose() + { + _console.CancelKeyPress -= OnCancelKeyPress; + _cts.Dispose(); + } } } diff --git a/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/AppWithDepsTests.cs b/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/AppWithDepsTests.cs index 37bfd618d1..3cbef02868 100644 --- a/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/AppWithDepsTests.cs +++ b/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/AppWithDepsTests.cs @@ -4,6 +4,7 @@ using System; using System.IO; using System.Threading.Tasks; +using Microsoft.AspNetCore.Testing; using Xunit; using Xunit.Abstractions; @@ -22,13 +23,13 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests [Fact] public async Task ChangeFileInDependency() { - await _app.StartWatcherAsync().OrTimeout(); + await _app.StartWatcherAsync(); var fileToChange = Path.Combine(_app.DependencyFolder, "Foo.cs"); var programCs = File.ReadAllText(fileToChange); File.WriteAllText(fileToChange, programCs); - await _app.HasRestarted().OrTimeout(); + await _app.HasRestarted(); } public void Dispose() diff --git a/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/DotNetWatcherTests.cs b/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/DotNetWatcherTests.cs index f9d16972ee..950f765135 100644 --- a/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/DotNetWatcherTests.cs +++ b/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/DotNetWatcherTests.cs @@ -23,7 +23,7 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests { Assert.True(string.IsNullOrEmpty(Environment.GetEnvironmentVariable("DOTNET_WATCH")), "DOTNET_WATCH cannot be set already when this test is running"); - await _app.StartWatcherAsync().OrTimeout(); + await _app.StartWatcherAsync(); const string messagePrefix = "DOTNET_WATCH = "; var message = await _app.Process.GetOutputLineAsync(m => m.StartsWith(messagePrefix)); var envValue = message.Substring(messagePrefix.Length); diff --git a/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/GlobbingAppTests.cs b/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/GlobbingAppTests.cs index f2c37077d5..011d64805a 100644 --- a/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/GlobbingAppTests.cs +++ b/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/GlobbingAppTests.cs @@ -5,6 +5,7 @@ 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; @@ -13,6 +14,8 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests { public class GlobbingAppTests : IDisposable { + private static readonly TimeSpan DefaultTimeout = TimeSpan.FromSeconds(30); + private GlobbingApp _app; public GlobbingAppTests(ITestOutputHelper logger) { @@ -25,84 +28,84 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests [InlineData(false)] public async Task ChangeCompiledFile(bool usePollingWatcher) { - await _app.StartWatcherAsync().OrTimeout(); + await _app.StartWatcherAsync(); - var types = await _app.GetCompiledAppDefinedTypes().OrTimeout(); + var types = await _app.GetCompiledAppDefinedTypes().TimeoutAfter(DefaultTimeout); Assert.Equal(2, types); var fileToChange = Path.Combine(_app.SourceDirectory, "include", "Foo.cs"); var programCs = File.ReadAllText(fileToChange); File.WriteAllText(fileToChange, programCs); - await _app.HasRestarted().OrTimeout(); - types = await _app.GetCompiledAppDefinedTypes().OrTimeout(); + await _app.HasRestarted(); + types = await _app.GetCompiledAppDefinedTypes().TimeoutAfter(DefaultTimeout); Assert.Equal(2, types); } [Fact(Skip = "Broken. See https://github.com/aspnet/DotNetTools/issues/212")] public async Task AddCompiledFile() { - await _app.StartWatcherAsync().OrTimeout(); + await _app.StartWatcherAsync(); - var types = await _app.GetCompiledAppDefinedTypes().OrTimeout(); + var types = await _app.GetCompiledAppDefinedTypes().TimeoutAfter(DefaultTimeout); Assert.Equal(2, types); var fileToChange = Path.Combine(_app.SourceDirectory, "include", "Bar.cs"); File.WriteAllText(fileToChange, "public class Bar {}"); - await _app.HasRestarted().OrTimeout(); - types = await _app.GetCompiledAppDefinedTypes().OrTimeout(); + await _app.HasRestarted(); + types = await _app.GetCompiledAppDefinedTypes().TimeoutAfter(DefaultTimeout); Assert.Equal(3, types); } [Fact] public async Task DeleteCompiledFile() { - await _app.StartWatcherAsync().OrTimeout(); + await _app.StartWatcherAsync(); - var types = await _app.GetCompiledAppDefinedTypes().OrTimeout(); + var types = await _app.GetCompiledAppDefinedTypes().TimeoutAfter(DefaultTimeout); Assert.Equal(2, types); var fileToChange = Path.Combine(_app.SourceDirectory, "include", "Foo.cs"); File.Delete(fileToChange); - await _app.HasRestarted().OrTimeout(); - types = await _app.GetCompiledAppDefinedTypes().OrTimeout(); + await _app.HasRestarted(); + types = await _app.GetCompiledAppDefinedTypes().TimeoutAfter(DefaultTimeout); Assert.Equal(1, types); } [Fact] public async Task DeleteSourceFolder() { - await _app.StartWatcherAsync().OrTimeout(); + await _app.StartWatcherAsync(); - var types = await _app.GetCompiledAppDefinedTypes().OrTimeout(); + var types = await _app.GetCompiledAppDefinedTypes().TimeoutAfter(DefaultTimeout); Assert.Equal(2, types); var folderToDelete = Path.Combine(_app.SourceDirectory, "include"); Directory.Delete(folderToDelete, recursive: true); - await _app.HasRestarted().OrTimeout(); - types = await _app.GetCompiledAppDefinedTypes().OrTimeout(); + await _app.HasRestarted(); + types = await _app.GetCompiledAppDefinedTypes().TimeoutAfter(DefaultTimeout); Assert.Equal(1, types); } [Fact] public async Task RenameCompiledFile() { - await _app.StartWatcherAsync().OrTimeout(); + await _app.StartWatcherAsync(); var oldFile = Path.Combine(_app.SourceDirectory, "include", "Foo.cs"); var newFile = Path.Combine(_app.SourceDirectory, "include", "Foo_new.cs"); File.Move(oldFile, newFile); - await _app.HasRestarted().OrTimeout(); + await _app.HasRestarted(); } [Fact] public async Task ChangeExcludedFile() { - await _app.StartWatcherAsync().OrTimeout(); + await _app.StartWatcherAsync(); var changedFile = Path.Combine(_app.SourceDirectory, "exclude", "Baz.cs"); File.WriteAllText(changedFile, ""); diff --git a/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/NoDepsAppTests.cs b/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/NoDepsAppTests.cs index 6e22a55436..633766d96a 100644 --- a/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/NoDepsAppTests.cs +++ b/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/NoDepsAppTests.cs @@ -5,6 +5,7 @@ using System; using System.Diagnostics; using System.IO; using System.Threading.Tasks; +using Microsoft.AspNetCore.Testing; using Xunit; using Xunit.Abstractions; @@ -12,6 +13,8 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests { public class NoDepsAppTests : IDisposable { + private static readonly TimeSpan DefaultTimeout = TimeSpan.FromSeconds(30); + private readonly WatchableApp _app; public NoDepsAppTests(ITestOutputHelper logger) @@ -23,16 +26,16 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests [Fact] public async Task RestartProcessOnFileChange() { - await _app.StartWatcherAsync(new[] { "--no-exit" }).OrTimeout(); - var pid = await _app.GetProcessId().OrTimeout(); + await _app.StartWatcherAsync(new[] { "--no-exit" }); + var pid = await _app.GetProcessId().TimeoutAfter(DefaultTimeout); // Then wait for it to restart when we change a file var fileToChange = Path.Combine(_app.SourceDirectory, "Program.cs"); var programCs = File.ReadAllText(fileToChange); File.WriteAllText(fileToChange, programCs); - await _app.HasRestarted().OrTimeout(); - var pid2 = await _app.GetProcessId().OrTimeout(); + await _app.HasRestarted(); + var pid2 = await _app.GetProcessId().TimeoutAfter(DefaultTimeout); Assert.NotEqual(pid, pid2); // first app should have shut down @@ -42,18 +45,18 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests [Fact] public async Task RestartProcessThatTerminatesAfterFileChange() { - await _app.StartWatcherAsync().OrTimeout(); - var pid = await _app.GetProcessId().OrTimeout(); - await _app.HasExited().OrTimeout(); // process should exit after run + await _app.StartWatcherAsync(); + var pid = await _app.GetProcessId().TimeoutAfter(DefaultTimeout); + await _app.HasExited().TimeoutAfter(DefaultTimeout); // process should exit after run var fileToChange = Path.Combine(_app.SourceDirectory, "Program.cs"); var programCs = File.ReadAllText(fileToChange); File.WriteAllText(fileToChange, programCs); - await _app.HasRestarted().OrTimeout(); - var pid2 = await _app.GetProcessId().OrTimeout(); + await _app.HasRestarted(); + var pid2 = await _app.GetProcessId().TimeoutAfter(DefaultTimeout); Assert.NotEqual(pid, pid2); - await _app.HasExited().OrTimeout(); // process should exit after run + await _app.HasExited().TimeoutAfter(DefaultTimeout); // process should exit after run } public void Dispose() diff --git a/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/Scenario/WatchableApp.cs b/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/Scenario/WatchableApp.cs index 3fdb1872e3..7be9e65c7c 100644 --- a/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/Scenario/WatchableApp.cs +++ b/test/Microsoft.DotNet.Watcher.Tools.FunctionalTests/Scenario/WatchableApp.cs @@ -7,6 +7,7 @@ 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; @@ -38,7 +39,7 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests public string SourceDirectory { get; } public Task HasRestarted() - => Process.GetOutputLineAsync(StartedMessage); + => Process.GetOutputLineAsync(StartedMessage).TimeoutAfter(TimeSpan.FromMinutes(2)); public Task HasExited() => Process.GetOutputLineAsync(ExitingMessage); @@ -74,7 +75,11 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests { Executable = DotNetMuxer.MuxerPathOrDefault(), Arguments = args, - WorkingDirectory = SourceDirectory + WorkingDirectory = SourceDirectory, + EnvironmentVariables = + { + ["DOTNET_CLI_CONTEXT_VERBOSE"] = bool.TrueString + }, }; Process = new AwaitableProcess(spec, _logger); @@ -88,11 +93,15 @@ namespace Microsoft.DotNet.Watcher.Tools.FunctionalTests { var args = new[] { "run", "--" }.Concat(arguments); Start(args, name); - await Process.GetOutputLineAsync(StartedMessage); + + // 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)); } public virtual void Dispose() { + _logger?.WriteLine("Disposing WatchableApp"); Process?.Dispose(); Scenario.Dispose(); } diff --git a/test/Microsoft.DotNet.Watcher.Tools.Tests/Microsoft.DotNet.Watcher.Tools.Tests.csproj b/test/Microsoft.DotNet.Watcher.Tools.Tests/Microsoft.DotNet.Watcher.Tools.Tests.csproj index bcb78e5e3b..55bc572749 100644 --- a/test/Microsoft.DotNet.Watcher.Tools.Tests/Microsoft.DotNet.Watcher.Tools.Tests.csproj +++ b/test/Microsoft.DotNet.Watcher.Tools.Tests/Microsoft.DotNet.Watcher.Tools.Tests.csproj @@ -15,6 +15,10 @@ + + + + diff --git a/test/Microsoft.DotNet.Watcher.Tools.Tests/ProgramTests.cs b/test/Microsoft.DotNet.Watcher.Tools.Tests/ProgramTests.cs index e00099acfb..8c116b5595 100644 --- a/test/Microsoft.DotNet.Watcher.Tools.Tests/ProgramTests.cs +++ b/test/Microsoft.DotNet.Watcher.Tools.Tests/ProgramTests.cs @@ -5,6 +5,7 @@ using System; using System.IO; using System.Text; using System.Threading.Tasks; +using Microsoft.AspNetCore.Testing; using Microsoft.Extensions.Tools.Internal; using Xunit; using Xunit.Abstractions; @@ -35,18 +36,20 @@ namespace Microsoft.DotNet.Watcher.Tools.Tests var stdout = new StringBuilder(); _console.Out = new StringWriter(stdout); var program = new Program(_console, _tempDir.Root) - .RunAsync(new [] { "run" }); + .RunAsync(new[] { "run" }); + await _console.CancelKeyPressSubscribed.TimeoutAfter(TimeSpan.FromSeconds(30)); _console.ConsoleCancelKey(); - var exitCode = await program.OrTimeout(); + var exitCode = await program.TimeoutAfter(TimeSpan.FromSeconds(30)); Assert.Contains("Shutdown requested. Press Ctrl+C again to force exit.", stdout.ToString()); Assert.Equal(0, exitCode); } + public void Dispose() { _tempDir.Dispose(); } } -} \ No newline at end of file +} diff --git a/test/Microsoft.DotNet.Watcher.Tools.Tests/Utilities/TaskExtensions.cs b/test/Microsoft.DotNet.Watcher.Tools.Tests/Utilities/TaskExtensions.cs deleted file mode 100644 index daaa77918e..0000000000 --- a/test/Microsoft.DotNet.Watcher.Tools.Tests/Utilities/TaskExtensions.cs +++ /dev/null @@ -1,25 +0,0 @@ -// Copyright (c) .NET Foundation. All rights reserved. -// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. - -using System.Runtime.CompilerServices; - -namespace System.Threading.Tasks -{ - public static class TaskExtensions - { - public static async Task OrTimeout(this Task task, int timeout = 30, [CallerFilePath] string file = null, [CallerLineNumber] int line = 0) - { - await OrTimeout((Task)task, timeout, file, line); - return task.Result; - } - - public static async Task OrTimeout(this Task task, int timeout = 30, [CallerFilePath] string file = null, [CallerLineNumber] int line = 0) - { - var finished = await Task.WhenAny(task, Task.Delay(TimeSpan.FromSeconds(timeout))); - if (!ReferenceEquals(finished, task)) - { - throw new TimeoutException($"Task exceeded max running time of {timeout}s at {file}:{line}"); - } - } - } -} \ No newline at end of file diff --git a/test/Shared/TestConsole.cs b/test/Shared/TestConsole.cs index 6804c0265e..b8198238f3 100644 --- a/test/Shared/TestConsole.cs +++ b/test/Shared/TestConsole.cs @@ -5,6 +5,7 @@ using System; using System.IO; using System.Linq; using System.Reflection; +using System.Threading.Tasks; using System.Text; using Xunit.Abstractions; @@ -12,6 +13,9 @@ namespace Microsoft.Extensions.Tools.Internal { public class TestConsole : IConsole { + private event ConsoleCancelEventHandler _cancelKeyPress; + private readonly TaskCompletionSource _cancelKeySubscribed = new TaskCompletionSource(); + public TestConsole(ITestOutputHelper output) { var writer = new TestOutputWriter(output); @@ -19,7 +23,17 @@ namespace Microsoft.Extensions.Tools.Internal Out = writer; } - public event ConsoleCancelEventHandler CancelKeyPress; + public event ConsoleCancelEventHandler CancelKeyPress + { + add + { + _cancelKeyPress += value; + _cancelKeySubscribed.TrySetResult(true); + } + remove => _cancelKeyPress -= value; + } + + public Task CancelKeyPressSubscribed => _cancelKeySubscribed.Task; public TextWriter Error { get; set; } public TextWriter Out { get; set; } @@ -36,7 +50,7 @@ namespace Microsoft.Extensions.Tools.Internal .DeclaredConstructors .Single(c => c.GetParameters().First().ParameterType == typeof(ConsoleSpecialKey)); var args = (ConsoleCancelEventArgs)ctor.Invoke(new object[] { ConsoleSpecialKey.ControlC }); - CancelKeyPress?.Invoke(this, args); + _cancelKeyPress.Invoke(this, args); return args; }