From 8f99140f308fa2cef5f49360694fb924f87d2cfb Mon Sep 17 00:00:00 2001 From: Pavel Krymets Date: Tue, 16 Oct 2018 15:30:19 -0700 Subject: [PATCH] Add client disconnect logs (#1521) --- .../Core/IISHttpContext.IO.cs | 8 +++- .../Core/IISHttpContext.Log.cs | 39 +++++++++++++++++++ .../Core/IISHttpContext.cs | 10 ++++- .../Core/IISHttpContextOfT.cs | 5 ++- .../Core/IISHttpServer.cs | 8 ++-- test/IIS.Tests/ClientDisconnectTests.cs | 18 ++++++++- 6 files changed, 79 insertions(+), 9 deletions(-) create mode 100644 src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContext.Log.cs diff --git a/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContext.IO.cs b/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContext.IO.cs index 724d2e55e1..bfe44d634c 100644 --- a/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContext.IO.cs +++ b/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContext.IO.cs @@ -6,6 +6,7 @@ using System.Buffers; using System.Threading; using System.Threading.Tasks; using Microsoft.AspNetCore.Connections; +using Microsoft.AspNetCore.Http.Features; namespace Microsoft.AspNetCore.Server.IIS.Core { @@ -121,6 +122,7 @@ namespace Microsoft.AspNetCore.Server.IIS.Core catch (Exception ex) { error = ex; + Log.UnexpectedError(_logger, nameof(IISHttpContext), ex); } finally { @@ -174,6 +176,7 @@ namespace Microsoft.AspNetCore.Server.IIS.Core catch (Exception ex) { error = ex; + Log.UnexpectedError(_logger, nameof(IISHttpContext), ex); } finally { @@ -199,9 +202,9 @@ namespace Microsoft.AspNetCore.Server.IIS.Core { cts.Cancel(); } - catch (Exception) + catch (Exception ex) { - // ignore + Log.ApplicationError(_logger, ((IHttpConnectionFeature)this).ConnectionId, TraceIdentifier, ex); } }); } @@ -219,6 +222,7 @@ namespace Microsoft.AspNetCore.Server.IIS.Core internal void ConnectionReset() { AbortIO(); + Log.ConnectionDisconnect(_logger, ((IHttpConnectionFeature)this).ConnectionId); } } } diff --git a/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContext.Log.cs b/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContext.Log.cs new file mode 100644 index 0000000000..1056ac1479 --- /dev/null +++ b/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContext.Log.cs @@ -0,0 +1,39 @@ +// 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.Runtime.CompilerServices; +using Microsoft.Extensions.Logging; + +namespace Microsoft.AspNetCore.Server.IIS.Core +{ + internal abstract partial class IISHttpContext + { + private static class Log + { + private static readonly Action _connectionDisconnect = + LoggerMessage.Define(LogLevel.Debug, new EventId(1, "ConnectionDisconnect"), @"Connection ID ""{ConnectionId}"" disconnecting."); + + private static readonly Action _applicationError = + LoggerMessage.Define(LogLevel.Error, new EventId(2, "ApplicationError"), @"Connection ID ""{ConnectionId}"", Request ID ""{TraceIdentifier}"": An unhandled exception was thrown by the application."); + + private static readonly Action _unexpectedError = + LoggerMessage.Define(LogLevel.Error, new EventId(3, "UnexpectedError"), @"Unexpected exception in ""{ClassName}.{MethodName}""."); + + public static void ConnectionDisconnect(ILogger logger, string connectionId) + { + _connectionDisconnect(logger, connectionId, null); + } + + public static void ApplicationError(ILogger logger, string connectionId, string traceIdentifier, Exception ex) + { + _applicationError(logger, connectionId, traceIdentifier, ex); + } + + public static void UnexpectedError(ILogger logger, string className, Exception ex, [CallerMemberName] string methodName = null) + { + _unexpectedError(logger, className, methodName, ex); + } + } + } +} diff --git a/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContext.cs b/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContext.cs index 01aeeebec6..09e478a989 100644 --- a/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContext.cs +++ b/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContext.cs @@ -17,9 +17,11 @@ using System.Threading.Tasks; using Microsoft.AspNetCore.Builder; using Microsoft.AspNetCore.Connections; using Microsoft.AspNetCore.Http; +using Microsoft.AspNetCore.Http.Features; using Microsoft.AspNetCore.HttpSys.Internal; using Microsoft.AspNetCore.Server.IIS.Core.IO; using Microsoft.AspNetCore.WebUtilities; +using Microsoft.Extensions.Logging; namespace Microsoft.AspNetCore.Server.IIS.Core { @@ -50,6 +52,8 @@ namespace Microsoft.AspNetCore.Server.IIS.Core private readonly MemoryPool _memoryPool; private readonly IISHttpServer _server; + private readonly ILogger _logger; + private GCHandle _thisHandle; protected Task _readBodyTask; protected Task _writeBodyTask; @@ -69,13 +73,15 @@ namespace Microsoft.AspNetCore.Server.IIS.Core MemoryPool memoryPool, IntPtr pInProcessHandler, IISServerOptions options, - IISHttpServer server) + IISHttpServer server, + ILogger logger) : base((HttpApiTypes.HTTP_REQUEST*)NativeMethods.HttpGetRawRequest(pInProcessHandler)) { _memoryPool = memoryPool; _pInProcessHandler = pInProcessHandler; _options = options; _server = server; + _logger = logger; } public Version HttpVersion { get; set; } @@ -450,6 +456,8 @@ namespace Microsoft.AspNetCore.Server.IIS.Core { _applicationException = new AggregateException(_applicationException, ex); } + + Log.ApplicationError(_logger, ((IHttpConnectionFeature)this).ConnectionId, TraceIdentifier, ex); } public void PostCompletion(NativeMethods.REQUEST_NOTIFICATION_STATUS requestNotificationStatus) diff --git a/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContextOfT.cs b/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContextOfT.cs index ec3fc006b2..bb104f5ac1 100644 --- a/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContextOfT.cs +++ b/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpContextOfT.cs @@ -7,6 +7,7 @@ using System.Threading; using System.Threading.Tasks; using Microsoft.AspNetCore.Builder; using Microsoft.AspNetCore.Hosting.Server; +using Microsoft.Extensions.Logging; namespace Microsoft.AspNetCore.Server.IIS.Core { @@ -14,8 +15,8 @@ namespace Microsoft.AspNetCore.Server.IIS.Core { private readonly IHttpApplication _application; - public IISHttpContextOfT(MemoryPool memoryPool, IHttpApplication application, IntPtr pInProcessHandler, IISServerOptions options, IISHttpServer server) - : base(memoryPool, pInProcessHandler, options, server) + public IISHttpContextOfT(MemoryPool memoryPool, IHttpApplication application, IntPtr pInProcessHandler, IISServerOptions options, IISHttpServer server, ILogger logger) + : base(memoryPool, pInProcessHandler, options, server, logger) { _application = application; } diff --git a/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpServer.cs b/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpServer.cs index 7cde852570..bfabf61bd7 100644 --- a/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpServer.cs +++ b/src/Microsoft.AspNetCore.Server.IIS/Core/IISHttpServer.cs @@ -82,7 +82,7 @@ namespace Microsoft.AspNetCore.Server.IIS.Core { _httpServerHandle = GCHandle.Alloc(this); - _iisContextFactory = new IISContextFactory(_memoryPool, application, _options, this); + _iisContextFactory = new IISContextFactory(_memoryPool, application, _options, this, _logger); _nativeApplication.RegisterCallbacks(_requestHandler, _shutdownHandler, _onDisconnect, _onAsyncCompletion, (IntPtr)_httpServerHandle, (IntPtr)_httpServerHandle); return Task.CompletedTask; } @@ -260,18 +260,20 @@ namespace Microsoft.AspNetCore.Server.IIS.Core private readonly MemoryPool _memoryPool; private readonly IISServerOptions _options; private readonly IISHttpServer _server; + private readonly ILogger _logger; - public IISContextFactory(MemoryPool memoryPool, IHttpApplication application, IISServerOptions options, IISHttpServer server) + public IISContextFactory(MemoryPool memoryPool, IHttpApplication application, IISServerOptions options, IISHttpServer server, ILogger logger) { _application = application; _memoryPool = memoryPool; _options = options; _server = server; + _logger = logger; } public IISHttpContext CreateHttpContext(IntPtr pInProcessHandler) { - return new IISHttpContextOfT(_memoryPool, _application, pInProcessHandler, _options, _server); + return new IISHttpContextOfT(_memoryPool, _application, pInProcessHandler, _options, _server, _logger); } } } diff --git a/test/IIS.Tests/ClientDisconnectTests.cs b/test/IIS.Tests/ClientDisconnectTests.cs index 2731c5665e..d8c7d4ef89 100644 --- a/test/IIS.Tests/ClientDisconnectTests.cs +++ b/test/IIS.Tests/ClientDisconnectTests.cs @@ -17,7 +17,6 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests [OSSkipCondition(OperatingSystems.Windows, WindowsVersions.Win7, "https://github.com/aspnet/IISIntegration/issues/866")] public class ClientDisconnectTests : StrictTestServerTests { - [ConditionalFact] public async Task WritesSucceedAfterClientDisconnect() { @@ -48,6 +47,8 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests await requestCompletedCompletionSource.Task.DefaultTimeout(); } + + AssertConnectionDisconnectLog(); } [ConditionalFact] @@ -88,6 +89,8 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests Assert.IsType(exception); } + + AssertConnectionDisconnectLog(); } [ConditionalFact] @@ -125,6 +128,8 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests Assert.IsType(exception); Assert.Equal("The client has disconnected", exception.Message); + + AssertConnectionDisconnectLog(); } [ConditionalFact] @@ -202,6 +207,8 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests } Assert.IsType(exception); } + + AssertConnectionDisconnectLog(); } [ConditionalFact] @@ -253,6 +260,7 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests Assert.IsType(exception); Assert.Equal("The client has disconnected", exception.Message); + AssertConnectionDisconnectLog(); } [ConditionalFact] @@ -275,7 +283,15 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests } await requestAborted.Task; } + + AssertConnectionDisconnectLog(); } + + private void AssertConnectionDisconnectLog() + { + Assert.Contains(TestSink.Writes, w => w.EventId.Name == "ConnectionDisconnect"); + } + private static async Task SendContentLength1Post(TestConnection connection) { await connection.Send(