diff --git a/src/Microsoft.AspNetCore.Server.Kestrel/Infrastructure/IKestrelTrace.cs b/src/Microsoft.AspNetCore.Server.Kestrel/Infrastructure/IKestrelTrace.cs index 1b61c3acc9..4dd0beb17d 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel/Infrastructure/IKestrelTrace.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel/Infrastructure/IKestrelTrace.cs @@ -38,8 +38,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Infrastructure void NotAllConnectionsClosedGracefully(); - void ApplicationError(Exception ex); - void ApplicationError(string connectionId, Exception ex); } } \ No newline at end of file diff --git a/src/Microsoft.AspNetCore.Server.Kestrel/Infrastructure/KestrelTrace.cs b/src/Microsoft.AspNetCore.Server.Kestrel/Infrastructure/KestrelTrace.cs index 9562b202b5..6dae29ed37 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel/Infrastructure/KestrelTrace.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel/Infrastructure/KestrelTrace.cs @@ -22,8 +22,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel private static readonly Action _connectionWroteFin; private static readonly Action _connectionKeepAlive; private static readonly Action _connectionDisconnect; - private static readonly Action _applicationError; - private static readonly Action _applicationErrorWithId; + private static readonly Action _applicationError; private static readonly Action _connectionError; private static readonly Action _connectionDisconnectedWrite; private static readonly Action _notAllConnectionsClosedGracefully; @@ -45,8 +44,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel _connectionDisconnect = LoggerMessage.Define(LogLevel.Debug, 10, @"Connection id ""{ConnectionId}"" disconnecting."); // ConnectionWrite: Reserved: 11 // ConnectionWriteCallback: Reserved: 12 - _applicationError = LoggerMessage.Define(LogLevel.Error, 13, "An unhandled exception thrown by the application."); - _applicationErrorWithId = LoggerMessage.Define(LogLevel.Error, 13, @"Connection id ""{ConnectionId}"" unhandled exception thrown by the application."); + _applicationError = LoggerMessage.Define(LogLevel.Error, 13, @"Connection id ""{ConnectionId}"": An unhandled exception was thrown by the application."); _connectionError = LoggerMessage.Define(LogLevel.Information, 14, @"Connection id ""{ConnectionId}"" communication error"); _connectionDisconnectedWrite = LoggerMessage.Define(LogLevel.Debug, 15, @"Connection id ""{ConnectionId}"" write of ""{count}"" bytes to disconnected client."); _notAllConnectionsClosedGracefully = LoggerMessage.Define(LogLevel.Debug, 16, "Some connections failed to close gracefully during server shutdown."); @@ -121,14 +119,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel // Reserved: Event ID 12 } - public virtual void ApplicationError(Exception ex) - { - _applicationError(_logger, ex); - } - public virtual void ApplicationError(string connectionId, Exception ex) { - _applicationErrorWithId(_logger, connectionId, ex); + _applicationError(_logger, connectionId, ex); } public virtual void ConnectionError(string connectionId, Exception ex) diff --git a/src/Microsoft.AspNetCore.Server.Kestrel/Infrastructure/LoggingThreadPool.cs b/src/Microsoft.AspNetCore.Server.Kestrel/Infrastructure/LoggingThreadPool.cs index a5f41987d4..e9625cffec 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel/Infrastructure/LoggingThreadPool.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel/Infrastructure/LoggingThreadPool.cs @@ -4,6 +4,7 @@ using System; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; namespace Microsoft.AspNetCore.Server.Kestrel.Infrastructure { @@ -28,7 +29,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Infrastructure } catch (Exception e) { - _log.ApplicationError(e); + _log.LogError(0, e, "LoggingThreadPool.Run"); } }; @@ -40,7 +41,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Infrastructure } catch (Exception e) { - _log.ApplicationError(e); + _log.LogError(0, e, "LoggingThreadPool.Complete"); } }; @@ -52,7 +53,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Infrastructure } catch (Exception e) { - _log.ApplicationError(e); + _log.LogError(0, e, "LoggingThreadPool.Cancel"); } }; } @@ -74,7 +75,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Infrastructure public void Error(TaskCompletionSource tcs, Exception ex) { - // ex ang _log are closure captured + // ex and _log are closure captured ThreadPool.QueueUserWorkItem((o) => { try @@ -83,7 +84,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Infrastructure } catch (Exception e) { - _log.ApplicationError(e); + _log.LogError(0, e, "LoggingThreadPool.Error"); } }, tcs); } diff --git a/test/Microsoft.AspNetCore.Server.KestrelTests/KestrelServerTests.cs b/test/Microsoft.AspNetCore.Server.KestrelTests/KestrelServerTests.cs index d54202dc9d..8c4e8c1490 100644 --- a/test/Microsoft.AspNetCore.Server.KestrelTests/KestrelServerTests.cs +++ b/test/Microsoft.AspNetCore.Server.KestrelTests/KestrelServerTests.cs @@ -69,7 +69,7 @@ namespace Microsoft.AspNetCore.Server.KestrelTests features.Set(information); var lifetime = new LifetimeNotImplemented(); - var logger = new TestKestrelTrace.TestLogger(); + var logger = new TestApplicationErrorLogger(); return new KestrelServer(features, lifetime, logger); } diff --git a/test/Microsoft.AspNetCore.Server.KestrelTests/LoggingThreadPoolTests.cs b/test/Microsoft.AspNetCore.Server.KestrelTests/LoggingThreadPoolTests.cs new file mode 100644 index 0000000000..92b8c2c94f --- /dev/null +++ b/test/Microsoft.AspNetCore.Server.KestrelTests/LoggingThreadPoolTests.cs @@ -0,0 +1,49 @@ +// 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; +using System.Collections.Generic; +using System.Linq; +using System.Threading.Tasks; +using Microsoft.AspNetCore.Server.Kestrel.Infrastructure; +using Xunit; + +namespace Microsoft.AspNetCore.Server.KestrelTests +{ + public class LoggingThreadPoolTests + { + [Fact] + public void TcsContinuationErrorsDontGetLoggedAsGeneralErrors() + { + var testLogger = new TestApplicationErrorLogger(); + var testKestrelTrace = new TestKestrelTrace(testLogger); + var threadPool = new LoggingThreadPool(testKestrelTrace); + + var completeTcs = new TaskCompletionSource(); + ThrowSynchronously(completeTcs.Task); + threadPool.Complete(completeTcs); + + var errorTcs = new TaskCompletionSource(); + ThrowSynchronously(errorTcs.Task); + threadPool.Error(errorTcs, new Exception()); + + var cancelTcs = new TaskCompletionSource(); + ThrowSynchronously(cancelTcs.Task); + threadPool.Cancel(cancelTcs); + + Assert.Throws(() => + Task.WhenAll(completeTcs.Task, errorTcs.Task, cancelTcs.Task).Wait()); + + Assert.Equal(0, testLogger.TotalErrorsLogged); + } + + private void ThrowSynchronously(Task task) + { + task.ContinueWith(_ => + { + throw new Exception(); + }, TaskContinuationOptions.ExecuteSynchronously); + } + } +} diff --git a/test/Microsoft.AspNetCore.Server.KestrelTests/TestHelpers/TestApplicationErrorLogger.cs b/test/Microsoft.AspNetCore.Server.KestrelTests/TestHelpers/TestApplicationErrorLogger.cs index f6e7f04169..eb48a70890 100644 --- a/test/Microsoft.AspNetCore.Server.KestrelTests/TestHelpers/TestApplicationErrorLogger.cs +++ b/test/Microsoft.AspNetCore.Server.KestrelTests/TestHelpers/TestApplicationErrorLogger.cs @@ -12,6 +12,8 @@ namespace Microsoft.AspNetCore.Server.KestrelTests // Application errors are logged using 13 as the eventId. private const int ApplicationErrorEventId = 13; + public int TotalErrorsLogged { get; set; } + public int ApplicationErrorsLogged { get; set; } public IDisposable BeginScopeImpl(object state) @@ -26,6 +28,12 @@ namespace Microsoft.AspNetCore.Server.KestrelTests 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}"); +#endif + + TotalErrorsLogged++; + if (eventId.Id == ApplicationErrorEventId) { ApplicationErrorsLogged++; diff --git a/test/Microsoft.AspNetCore.Server.KestrelTests/TestLogger.cs b/test/Microsoft.AspNetCore.Server.KestrelTests/TestHelpers/TestKestrelTrace.cs similarity index 57% rename from test/Microsoft.AspNetCore.Server.KestrelTests/TestLogger.cs rename to test/Microsoft.AspNetCore.Server.KestrelTests/TestHelpers/TestKestrelTrace.cs index 11076560bc..5d811063b1 100644 --- a/test/Microsoft.AspNetCore.Server.KestrelTests/TestLogger.cs +++ b/test/Microsoft.AspNetCore.Server.KestrelTests/TestHelpers/TestKestrelTrace.cs @@ -6,9 +6,12 @@ namespace Microsoft.AspNetCore.Server.KestrelTests { public class TestKestrelTrace : KestrelTrace { - public TestKestrelTrace() : base(new TestLogger()) + public TestKestrelTrace() : this(new TestApplicationErrorLogger()) { + } + public TestKestrelTrace(ILogger testLogger) : base(testLogger) + { } public override void ConnectionRead(string connectionId, int count) @@ -25,25 +28,5 @@ namespace Microsoft.AspNetCore.Server.KestrelTests { //_logger.LogDebug(1, @"Connection id ""{ConnectionId}"" send finished with status {status}.", connectionId, status); } - - public class TestLogger : ILogger - { - 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}"); -#endif - } - - public bool IsEnabled(LogLevel logLevel) - { - return true; - } - - public IDisposable BeginScopeImpl(object state) - { - return new Disposable(() => { }); - } - } } } \ No newline at end of file