From 5124adf450969acc46ab7705463072ffccabd3f7 Mon Sep 17 00:00:00 2001 From: Stephen Halter Date: Thu, 2 Feb 2017 17:07:14 -0800 Subject: [PATCH] Better report Kestrel crashing errors --- .../Internal/Infrastructure/KestrelThread.cs | 7 +++---- .../Internal/KestrelEngine.cs | 17 ++++++++++++++++- .../KestrelServerTests.cs | 6 +++--- test/shared/TestApplicationErrorLogger.cs | 14 ++++++++++++-- 4 files changed, 34 insertions(+), 10 deletions(-) diff --git a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/KestrelThread.cs b/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/KestrelThread.cs index 117efc08fc..383f804cfa 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/KestrelThread.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/KestrelThread.cs @@ -142,17 +142,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal Post(t => t.OnStopImmediate()); if (!await WaitAsync(_threadTcs.Task, stepTimeout).ConfigureAwait(false)) { - _log.LogError(0, null, "KestrelThread.StopAsync failed to terminate libuv thread."); + _log.LogCritical("KestrelThread.StopAsync failed to terminate libuv thread."); } } } catch (ObjectDisposedException) { - // REVIEW: Should we log something here? // Until we rework this logic, ODEs are bound to happen sometimes. if (!await WaitAsync(_threadTcs.Task, stepTimeout).ConfigureAwait(false)) { - _log.LogError(0, null, "KestrelThread.StopAsync failed to terminate libuv thread."); + _log.LogCritical("KestrelThread.StopAsync failed to terminate libuv thread."); } } } @@ -343,8 +342,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal } finally { - thisHandle.Free(); _threadTcs.SetResult(null); + thisHandle.Free(); } } diff --git a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/KestrelEngine.cs b/src/Microsoft.AspNetCore.Server.Kestrel/Internal/KestrelEngine.cs index b7a7b5a63e..6f21130f6f 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/KestrelEngine.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel/Internal/KestrelEngine.cs @@ -51,7 +51,22 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal public void Dispose() { - Task.WaitAll(Threads.Select(thread => thread.StopAsync(TimeSpan.FromSeconds(2.5))).ToArray()); + try + { + Task.WaitAll(Threads.Select(thread => thread.StopAsync(TimeSpan.FromSeconds(2.5))).ToArray()); + } + catch (AggregateException aggEx) + { + // An uncaught exception was likely thrown from the libuv event loop. + // The original error that crashed one loop may have caused secondary errors in others. + // Make sure that the stack trace of the original error is logged. + foreach (var ex in aggEx.InnerExceptions) + { + Log.LogCritical("Failed to gracefully close Kestrel.", ex); + } + + throw; + } Threads.Clear(); #if DEBUG diff --git a/test/Microsoft.AspNetCore.Server.KestrelTests/KestrelServerTests.cs b/test/Microsoft.AspNetCore.Server.KestrelTests/KestrelServerTests.cs index bb82eac55f..5225e5a16d 100644 --- a/test/Microsoft.AspNetCore.Server.KestrelTests/KestrelServerTests.cs +++ b/test/Microsoft.AspNetCore.Server.KestrelTests/KestrelServerTests.cs @@ -23,7 +23,7 @@ namespace Microsoft.AspNetCore.Server.KestrelTests [InlineData(-1337)] public void StartWithNonPositiveThreadCountThrows(int threadCount) { - var testLogger = new TestApplicationErrorLogger(); + var testLogger = new TestApplicationErrorLogger { ThrowOnCriticalErrors = false }; var server = CreateServer(new KestrelServerOptions() { ThreadCount = threadCount }, testLogger); var exception = Assert.Throws(() => StartDummyApplication(server)); @@ -35,7 +35,7 @@ namespace Microsoft.AspNetCore.Server.KestrelTests [Fact] public void StartWithInvalidAddressThrows() { - var testLogger = new TestApplicationErrorLogger(); + var testLogger = new TestApplicationErrorLogger { ThrowOnCriticalErrors = false }; var server = CreateServer(new KestrelServerOptions(), testLogger); server.Features.Get().Addresses.Add("http:/asdf"); @@ -72,7 +72,7 @@ namespace Microsoft.AspNetCore.Server.KestrelTests [InlineData(int.MaxValue - 1, int.MaxValue)] public void StartWithMaxRequestBufferSizeLessThanMaxRequestLineSizeThrows(long maxRequestBufferSize, int maxRequestLineSize) { - var testLogger = new TestApplicationErrorLogger(); + var testLogger = new TestApplicationErrorLogger { ThrowOnCriticalErrors = false }; var options = new KestrelServerOptions(); options.Limits.MaxRequestBufferSize = maxRequestBufferSize; options.Limits.MaxRequestLineSize = maxRequestLineSize; diff --git a/test/shared/TestApplicationErrorLogger.cs b/test/shared/TestApplicationErrorLogger.cs index 057e8435fb..76ee249a36 100644 --- a/test/shared/TestApplicationErrorLogger.cs +++ b/test/shared/TestApplicationErrorLogger.cs @@ -14,6 +14,8 @@ namespace Microsoft.AspNetCore.Testing // Application errors are logged using 13 as the eventId. private const int ApplicationErrorEventId = 13; + public bool ThrowOnCriticalErrors { get; set; } = true; + public ConcurrentBag Messages { get; } = new ConcurrentBag(); public int TotalErrorsLogged => Messages.Count(message => message.LogLevel == LogLevel.Error); @@ -34,9 +36,17 @@ namespace Microsoft.AspNetCore.Testing public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { -#if false - Console.WriteLine($"Log {logLevel}[{eventId}]: {formatter(state, exception)} {exception?.Message}"); +#if true + if (logLevel == LogLevel.Critical && ThrowOnCriticalErrors) #endif + { + Console.WriteLine($"Log {logLevel}[{eventId}]: {formatter(state, exception)} {exception?.Message}"); + + if (logLevel == LogLevel.Critical && ThrowOnCriticalErrors) + { + throw new Exception("Unexpected critical error.", exception); + } + } Messages.Add(new LogMessage {