extend timeout and more logging (#183)

test/AutobahnTestApp/Program.cs

@@ -1,6 +1,7 @@
-using System;
+using System;
 using System.IO;
 using System.Net;
+using System.Runtime.Loader;
 using Microsoft.AspNetCore.Hosting;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.Logging;
@@ -11,6 +12,7 @@ namespace AutobahnTestApp
     {
         public static void Main(string[] args)
         {
+            var scenarioName = "Unknown";
             var config = new ConfigurationBuilder()
                 .AddCommandLine(args)
                 .Build();
@@ -24,6 +26,7 @@ namespace AutobahnTestApp
 
             if (string.Equals(builder.GetSetting("server"), "Microsoft.AspNetCore.Server.HttpSys", System.StringComparison.Ordinal))
             {
+                scenarioName = "HttpSysServer";
                 Console.WriteLine("Using HttpSys server");
                 builder.UseHttpSys();
             }
@@ -31,6 +34,7 @@ namespace AutobahnTestApp
             {
                 // ANCM is hosting the process.
                 // The port will not yet be configured at this point, but will also not require HTTPS.
+                scenarioName = "AspNetCoreModule";
                 Console.WriteLine("Detected ANCM, using Kestrel");
                 builder.UseKestrel();
             }
@@ -55,15 +59,27 @@ namespace AutobahnTestApp
                     {
                         if (uri.Scheme.Equals("https", StringComparison.OrdinalIgnoreCase))
                         {
+                            scenarioName = "Kestrel(SSL)";
                             var certPath = Path.Combine(AppContext.BaseDirectory, "TestResources", "testCert.pfx");
                             Console.WriteLine($"Using SSL with certificate: {certPath}");
                             listenOptions.UseHttps(certPath, "testPassword");
                         }
+                        else
+                        {
+                            scenarioName = "Kestrel(NonSSL)";
+                        }
                     });
                 });
             }
 
             var host = builder.Build();
+
+            AppDomain.CurrentDomain.UnhandledException += (_, a) =>
+            {
+                Console.WriteLine($"Unhandled exception (Scenario: {scenarioName}): {a.ExceptionObject.ToString()}");
+            };
+
+            Console.WriteLine($"Starting Server for Scenario: {scenarioName}");
             host.Run();
         }
     }

test/AutobahnTestApp/Startup.cs

@@ -1,4 +1,4 @@
-using System;
+using System;
 using System.Net.WebSockets;
 using System.Threading;
 using System.Threading.Tasks;
@@ -22,8 +22,10 @@ namespace AutobahnTestApp
                 if (context.WebSockets.IsWebSocketRequest)
                 {
                     logger.LogInformation("Received WebSocket request");
-                    var webSocket = await context.WebSockets.AcceptWebSocketAsync();
+                    using (var webSocket = await context.WebSockets.AcceptWebSocketAsync())
-                    await Echo(webSocket);
+                    {
+                        await Echo(webSocket, context.RequestAborted);
+                    }
                 }
                 else
                 {
@@ -35,16 +37,16 @@ namespace AutobahnTestApp
 
         }
 
-        private async Task Echo(WebSocket webSocket)
+        private async Task Echo(WebSocket webSocket, CancellationToken cancellationToken)
         {
             var buffer = new byte[1024 * 4];
-            var result = await webSocket.ReceiveAsync(new ArraySegment<byte>(buffer), CancellationToken.None);
+            var result = await webSocket.ReceiveAsync(new ArraySegment<byte>(buffer), cancellationToken);
             while (!result.CloseStatus.HasValue)
             {
-                await webSocket.SendAsync(new ArraySegment<byte>(buffer, 0, result.Count), result.MessageType, result.EndOfMessage, CancellationToken.None);
+                await webSocket.SendAsync(new ArraySegment<byte>(buffer, 0, result.Count), result.MessageType, result.EndOfMessage, cancellationToken);
-                result = await webSocket.ReceiveAsync(new ArraySegment<byte>(buffer), CancellationToken.None);
+                result = await webSocket.ReceiveAsync(new ArraySegment<byte>(buffer), cancellationToken);
             }
-            await webSocket.CloseAsync(result.CloseStatus.Value, result.CloseStatusDescription, CancellationToken.None);
+            await webSocket.CloseAsync(result.CloseStatus.Value, result.CloseStatusDescription, cancellationToken);
         }
     }
 }

test/Microsoft.AspNetCore.WebSockets.ConformanceTest/Autobahn/AutobahnTester.cs

@@ -1,4 +1,4 @@
-using System;
+using System;
 using System.Collections.Generic;
 using System.IO;
 using System.Linq;
@@ -16,6 +16,7 @@ namespace Microsoft.AspNetCore.WebSockets.ConformanceTest.Autobahn
     public class AutobahnTester : IDisposable
     {
         private readonly List<IApplicationDeployer> _deployers = new List<IApplicationDeployer>();
+        private readonly List<DeploymentResult> _deployments = new List<DeploymentResult>();
         private readonly List<AutobahnExpectations> _expectations = new List<AutobahnExpectations>();
         private readonly ILoggerFactory _loggerFactory;
         private readonly ILogger _logger;
@@ -35,6 +36,10 @@ namespace Microsoft.AspNetCore.WebSockets.ConformanceTest.Autobahn
             var specFile = Path.GetTempFileName();
             try
             {
+                // Start pinging the servers to see that they're still running
+                var pingCts = new CancellationTokenSource();
+                var pinger = new Timer(state => Pinger((CancellationToken)state), pingCts.Token, TimeSpan.FromSeconds(10), TimeSpan.FromSeconds(10));
+
                 Spec.WriteJson(specFile);
 
                 // Run the test (write something to the console so people know this will take a while...)
@@ -44,6 +49,8 @@ namespace Microsoft.AspNetCore.WebSockets.ConformanceTest.Autobahn
                 {
                     throw new Exception("wstest failed");
                 }
+
+                pingCts.Cancel();
             }
             finally
             {
@@ -63,6 +70,42 @@ namespace Microsoft.AspNetCore.WebSockets.ConformanceTest.Autobahn
             }
         }
 
+        // Async void! It's OK here because we are running in a timer. We're just using async void to chain continuations.
+        // There's nobody to await this, hence async void.
+        private async void Pinger(CancellationToken token)
+        {
+            try
+            {
+                while (!token.IsCancellationRequested)
+                {
+                    try
+                    {
+                        foreach (var deployment in _deployments)
+                        {
+                            if (token.IsCancellationRequested)
+                            {
+                                return;
+                            }
+
+                            var resp = await deployment.HttpClient.GetAsync("/ping", token);
+                            if (!resp.IsSuccessStatusCode)
+                            {
+                                _logger.LogWarning("Non-successful response when pinging {url}: {statusCode} {reasonPhrase}", deployment.ApplicationBaseUri, resp.StatusCode, resp.ReasonPhrase);
+                            }
+                        }
+                    }
+                    catch (OperationCanceledException)
+                    {
+                        // We don't want to throw when the token fires, just stop.
+                    }
+                }
+            }
+            catch (Exception ex)
+            {
+                _logger.LogError(ex, "Error while pinging servers");
+            }
+        }
+
         public void Verify(AutobahnResult result)
         {
             var failures = new StringBuilder();
@@ -104,6 +147,7 @@ namespace Microsoft.AspNetCore.WebSockets.ConformanceTest.Autobahn
             var deployer = ApplicationDeployerFactory.Create(parameters, _loggerFactory);
             var result = await deployer.DeployAsync();
             _deployers.Add(deployer);
+            _deployments.Add(result);
             cancellationToken.ThrowIfCancellationRequested();
 
             var handler = new HttpClientHandler();
@@ -114,7 +158,7 @@ namespace Microsoft.AspNetCore.WebSockets.ConformanceTest.Autobahn
                 // See https://github.com/dotnet/corefx/issues/9728
                 handler.ServerCertificateCustomValidationCallback = (_, __, ___, ____) => true;
             }
-            var client = new HttpClient(handler);
+            var client = result.CreateHttpClient(handler);
 
             // Make sure the server works
             var resp = await RetryHelper.RetryRequest(() =>

test/Microsoft.AspNetCore.WebSockets.ConformanceTest/AutobahnTests.cs

@@ -1,4 +1,4 @@
-using System;
+using System;
 using System.Diagnostics;
 using System.IO;
 using System.Runtime.InteropServices;
@@ -7,6 +7,7 @@ using System.Threading.Tasks;
 using Microsoft.AspNetCore.Server.IntegrationTesting;
 using Microsoft.AspNetCore.Testing.xunit;
 using Microsoft.AspNetCore.WebSockets.ConformanceTest.Autobahn;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Logging.Testing;
 using Xunit.Abstractions;
 
@@ -14,6 +15,8 @@ namespace Microsoft.AspNetCore.WebSockets.ConformanceTest
 {
     public class AutobahnTests : LoggedTest
     {
+        private static readonly TimeSpan TestTimeout = TimeSpan.FromMinutes(3);
+
         public AutobahnTests(ITestOutputHelper output) : base(output)
         {
         }
@@ -26,6 +29,7 @@ namespace Microsoft.AspNetCore.WebSockets.ConformanceTest
         {
             using (StartLog(out var loggerFactory))
             {
+                var logger = loggerFactory.CreateLogger<AutobahnTests>();
                 var reportDir = Environment.GetEnvironmentVariable("AUTOBAHN_SUITES_REPORT_DIR");
                 var outDir = !string.IsNullOrEmpty(reportDir) ?
                     reportDir :
@@ -44,28 +48,31 @@ namespace Microsoft.AspNetCore.WebSockets.ConformanceTest
                     .ExcludeCase("9.*", "12.*", "13.*");
 
                 var cts = new CancellationTokenSource();
-                cts.CancelAfter(TimeSpan.FromMinutes(5)); // These tests generally complete in just over 1 minute.
+                cts.CancelAfter(TestTimeout); // These tests generally complete in just over 1 minute.
 
-                AutobahnResult result;
+                using (cts.Token.Register(() => logger.LogError("Test run is taking longer than maximum duration of {timeoutMinutes:0.00} minutes. Aborting...", TestTimeout.TotalMinutes)))
-                using (var tester = new AutobahnTester(loggerFactory, spec))
                 {
-                    await tester.DeployTestAndAddToSpec(ServerType.Kestrel, ssl: false, environment: "ManagedSockets", cancellationToken: cts.Token);
+                    AutobahnResult result;
-
+                    using (var tester = new AutobahnTester(loggerFactory, spec))
-                    // Windows-only WebListener tests, and Kestrel SSL tests (due to: https://github.com/aspnet/WebSockets/issues/102)
-                    if (RuntimeInformation.IsOSPlatform(OSPlatform.Windows))
                     {
-                        await tester.DeployTestAndAddToSpec(ServerType.Kestrel, ssl: true, environment: "ManagedSockets", cancellationToken: cts.Token);
+                        await tester.DeployTestAndAddToSpec(ServerType.Kestrel, ssl: false, environment: "ManagedSockets", cancellationToken: cts.Token);
 
-                        if (IsWindows8OrHigher())
+                        // Windows-only WebListener tests, and Kestrel SSL tests (due to: https://github.com/aspnet/WebSockets/issues/102)
+                        if (RuntimeInformation.IsOSPlatform(OSPlatform.Windows))
                         {
-                            // WebListener occasionally gives a non-strict response on 3.2. IIS Express seems to have the same behavior. Wonder if it's related to HttpSys?
+                            await tester.DeployTestAndAddToSpec(ServerType.Kestrel, ssl: true, environment: "ManagedSockets", cancellationToken: cts.Token);
-                            // For now, just allow the non-strict response, it's not a failure.
-                            await tester.DeployTestAndAddToSpec(ServerType.WebListener, ssl: false, environment: "ManagedSockets", cancellationToken: cts.Token);
-                        }
-                    }
 
-                    result = await tester.Run(cts.Token);
+                            if (IsWindows8OrHigher())
-                    tester.Verify(result);
+                            {
+                                // WebListener occasionally gives a non-strict response on 3.2. IIS Express seems to have the same behavior. Wonder if it's related to HttpSys?
+                                // For now, just allow the non-strict response, it's not a failure.
+                                await tester.DeployTestAndAddToSpec(ServerType.WebListener, ssl: false, environment: "ManagedSockets", cancellationToken: cts.Token);
+                            }
+                        }
+
+                        result = await tester.Run(cts.Token);
+                        tester.Verify(result);
+                    }
                 }
 
                 // If it hasn't been cancelled yet, cancel the token just to be sure