Remove IKestrelTrace.ApplicationError overload without connection id

Add test verifying that exceptions thrown from application tcs continuations
run by the LoggingThreadPool don't get logged as general exceptions.
This commit is contained in:
Stephen Halter 2016-03-30 11:13:13 -07:00
parent a8e5c0ce30
commit f0e438f65f
7 changed files with 71 additions and 39 deletions

View File

@ -38,8 +38,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Infrastructure
void NotAllConnectionsClosedGracefully();
void ApplicationError(Exception ex);
void ApplicationError(string connectionId, Exception ex);
}
}

View File

@ -22,8 +22,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel
private static readonly Action<ILogger, string, int, Exception> _connectionWroteFin;
private static readonly Action<ILogger, string, Exception> _connectionKeepAlive;
private static readonly Action<ILogger, string, Exception> _connectionDisconnect;
private static readonly Action<ILogger, Exception> _applicationError;
private static readonly Action<ILogger, string, Exception> _applicationErrorWithId;
private static readonly Action<ILogger, string, Exception> _applicationError;
private static readonly Action<ILogger, string, Exception> _connectionError;
private static readonly Action<ILogger, string, int, Exception> _connectionDisconnectedWrite;
private static readonly Action<ILogger, Exception> _notAllConnectionsClosedGracefully;
@ -45,8 +44,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel
_connectionDisconnect = LoggerMessage.Define<string>(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<string>(LogLevel.Error, 13, @"Connection id ""{ConnectionId}"" unhandled exception thrown by the application.");
_applicationError = LoggerMessage.Define<string>(LogLevel.Error, 13, @"Connection id ""{ConnectionId}"": An unhandled exception was thrown by the application.");
_connectionError = LoggerMessage.Define<string>(LogLevel.Information, 14, @"Connection id ""{ConnectionId}"" communication error");
_connectionDisconnectedWrite = LoggerMessage.Define<string, int>(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)

View File

@ -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<object> 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);
}

View File

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

View File

@ -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<object>();
ThrowSynchronously(completeTcs.Task);
threadPool.Complete(completeTcs);
var errorTcs = new TaskCompletionSource<object>();
ThrowSynchronously(errorTcs.Task);
threadPool.Error(errorTcs, new Exception());
var cancelTcs = new TaskCompletionSource<object>();
ThrowSynchronously(cancelTcs.Task);
threadPool.Cancel(cancelTcs);
Assert.Throws<AggregateException>(() =>
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);
}
}
}

View File

@ -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<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
#if false
Console.WriteLine($"Log {logLevel}[{eventId}]: {formatter(state, exception)} {exception?.Message}");
#endif
TotalErrorsLogged++;
if (eventId.Id == ApplicationErrorEventId)
{
ApplicationErrorsLogged++;

View File

@ -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<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> 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(() => { });
}
}
}
}