Fix race conditions between CTRL+C and RunAsync in dotnet-watch

Increase timeouts in testing dotnet-run and improve verbosity of test logging

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.

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())
+            using (var program = new Program(PhysicalConsole.Singleton, Directory.GetCurrentDirectory()))
-                .RunAsync(args)
+            {
-                .GetAwaiter()
+                return program
-                .GetResult();
+                    .RunAsync(args)
+                    .GetAwaiter()
+                    .GetResult();
+            }
         }
 
         public async Task<int> RunAsync(string[] args)
@@ -44,8 +52,7 @@ namespace Microsoft.DotNet.Watcher
             }
             catch (CommandParsingException ex)
             {
-                CreateReporter(verbose: true, quiet: false, console: _console)
+                _reporter.Error(ex.Message);
-                    .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<int> 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();
+        }
     }
 }

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()

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);

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();
+            await _app.HasRestarted();
-            types = await _app.GetCompiledAppDefinedTypes().OrTimeout();
+            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();
+            await _app.HasRestarted();
-            types = await _app.GetCompiledAppDefinedTypes().OrTimeout();
+            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();
+            await _app.HasRestarted();
-            types = await _app.GetCompiledAppDefinedTypes().OrTimeout();
+            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();
+            await _app.HasRestarted();
-            types = await _app.GetCompiledAppDefinedTypes().OrTimeout();
+            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, "");

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();
+            await _app.StartWatcherAsync(new[] { "--no-exit" });
-            var pid = await _app.GetProcessId().OrTimeout();
+            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();
+            await _app.HasRestarted();
-            var pid2 = await _app.GetProcessId().OrTimeout();
+            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();
+            await _app.StartWatcherAsync();
-            var pid = await _app.GetProcessId().OrTimeout();
+            var pid = await _app.GetProcessId().TimeoutAfter(DefaultTimeout);
-            await _app.HasExited().OrTimeout(); // process should exit after run
+            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();
+            await _app.HasRestarted();
-            var pid2 = await _app.GetProcessId().OrTimeout();
+            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()

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();
         }

test/Microsoft.DotNet.Watcher.Tools.Tests/Microsoft.DotNet.Watcher.Tools.Tests.csproj

@@ -15,6 +15,10 @@
 
   <ItemGroup>
     <ProjectReference Include="..\..\src\Microsoft.DotNet.Watcher.Tools\Microsoft.DotNet.Watcher.Tools.csproj" />
+  </ItemGroup>
+
+  <ItemGroup>
+    <PackageReference Include="Microsoft.AspNetCore.Testing" Version="$(AspNetCoreVersion)" />
     <PackageReference Include="Microsoft.NET.Test.Sdk" Version="$(TestSdkVersion)" />
     <PackageReference Include="xunit" Version="$(XunitVersion)" />
     <PackageReference Include="xunit.runner.visualstudio" Version="$(XunitVersion)" />

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();
         }
     }
-}
+}

test/Microsoft.DotNet.Watcher.Tools.Tests/Utilities/TaskExtensions.cs

@@ -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<T> OrTimeout<T>(this Task<T> 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}");
-            }
-        }
-    }
-}

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<bool> _cancelKeySubscribed = new TaskCompletionSource<bool>();
+
         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;
         }