Add client disconnect logs (#1521)

pakrym · web-flow · commit 8f99140f308f · 2018-10-16T15:30:19.000-07:00
diff --git 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.Threading;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Connections;
+using Microsoft.AspNetCore.Http.Features;
 
 namespace Microsoft.AspNetCore.Server.IIS.Core
 {
@@ -121,6 +122,7 @@ private async Task ReadBody()
             catch (Exception ex)
             {
                 error = ex;
+                Log.UnexpectedError(_logger, nameof(IISHttpContext), ex);
             }
             finally
             {
@@ -174,6 +176,7 @@ private async Task WriteBody(bool flush = false)
             catch (Exception ex)
             {
                 error = ex;
+                Log.UnexpectedError(_logger, nameof(IISHttpContext), ex);
             }
             finally
             {
@@ -199,9 +202,9 @@ private void AbortIO()
                     {
                         cts.Cancel();
                     }
-                    catch (Exception)
+                    catch (Exception ex)
                     {
-                        // ignore
+                        Log.ApplicationError(_logger, ((IHttpConnectionFeature)this).ConnectionId, TraceIdentifier, ex);
                     }
                 });
             }
@@ -219,6 +222,7 @@ public void Abort(Exception reason)
         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
@@ -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<ILogger, string, Exception> _connectionDisconnect =
+                LoggerMessage.Define<string>(LogLevel.Debug, new EventId(1, "ConnectionDisconnect"), @"Connection ID ""{ConnectionId}"" disconnecting.");
+
+            private static readonly Action<ILogger, string, string, Exception> _applicationError =
+                LoggerMessage.Define<string, string>(LogLevel.Error, new EventId(2, "ApplicationError"), @"Connection ID ""{ConnectionId}"", Request ID ""{TraceIdentifier}"": An unhandled exception was thrown by the application.");
+
+            private static readonly Action<ILogger, string, string, Exception> _unexpectedError =
+                LoggerMessage.Define<string, string>(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
@@ -17,9 +17,11 @@
 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 @@ internal abstract partial class IISHttpContext : NativeRequestContext, IDisposab
         private readonly MemoryPool<byte> _memoryPool;
         private readonly IISHttpServer _server;
 
+        private readonly ILogger _logger;
+
         private GCHandle _thisHandle;
         protected Task _readBodyTask;
         protected Task _writeBodyTask;
@@ -69,13 +73,15 @@ internal unsafe IISHttpContext(
             MemoryPool<byte> 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 @@ protected void ReportApplicationError(Exception ex)
             {
                 _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
@@ -7,15 +7,16 @@
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Builder;
 using Microsoft.AspNetCore.Hosting.Server;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Server.IIS.Core
 {
     internal class IISHttpContextOfT<TContext> : IISHttpContext
     {
         private readonly IHttpApplication<TContext> _application;
 
-        public IISHttpContextOfT(MemoryPool<byte> memoryPool, IHttpApplication<TContext> application, IntPtr pInProcessHandler, IISServerOptions options, IISHttpServer server)
-            : base(memoryPool, pInProcessHandler, options, server)
+        public IISHttpContextOfT(MemoryPool<byte> memoryPool, IHttpApplication<TContext> 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
@@ -82,7 +82,7 @@ public Task StartAsync<TContext>(IHttpApplication<TContext> application, Cancell
         {
             _httpServerHandle = GCHandle.Alloc(this);
 
-            _iisContextFactory = new IISContextFactory<TContext>(_memoryPool, application, _options, this);
+            _iisContextFactory = new IISContextFactory<TContext>(_memoryPool, application, _options, this, _logger);
             _nativeApplication.RegisterCallbacks(_requestHandler, _shutdownHandler, _onDisconnect, _onAsyncCompletion, (IntPtr)_httpServerHandle, (IntPtr)_httpServerHandle);
             return Task.CompletedTask;
         }
@@ -260,18 +260,20 @@ private class IISContextFactory<T> : IISContextFactory
             private readonly MemoryPool<byte> _memoryPool;
             private readonly IISServerOptions _options;
             private readonly IISHttpServer _server;
+            private readonly ILogger _logger;
 
-            public IISContextFactory(MemoryPool<byte> memoryPool, IHttpApplication<T> application, IISServerOptions options, IISHttpServer server)
+            public IISContextFactory(MemoryPool<byte> memoryPool, IHttpApplication<T> 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<T>(_memoryPool, _application, pInProcessHandler, _options, _server);
+                return new IISHttpContextOfT<T>(_memoryPool, _application, pInProcessHandler, _options, _server, _logger);
             }
         }
     }
diff --git 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 @@ public async Task WritesSucceedAfterClientDisconnect()
 
                 await requestCompletedCompletionSource.Task.DefaultTimeout();
             }
+
+            AssertConnectionDisconnectLog();
         }
 
         [ConditionalFact]
@@ -88,6 +89,8 @@ public async Task WritesCancelledWhenUsingAbortedToken()
 
                 Assert.IsType<OperationCanceledException>(exception);
             }
+
+            AssertConnectionDisconnectLog();
         }
 
         [ConditionalFact]
@@ -125,6 +128,8 @@ public async Task ReadThrowsAfterClientDisconnect()
 
             Assert.IsType<ConnectionResetException>(exception);
             Assert.Equal("The client has disconnected", exception.Message);
+
+            AssertConnectionDisconnectLog();
         }
 
         [ConditionalFact]
@@ -202,6 +207,8 @@ public async Task ReaderThrowsCancelledException()
                 }
                 Assert.IsType<OperationCanceledException>(exception);
             }
+
+            AssertConnectionDisconnectLog();
         }
 
         [ConditionalFact]
@@ -253,6 +260,7 @@ await connection.Receive(
 
             Assert.IsType<ConnectionResetException>(exception);
             Assert.Equal("The client has disconnected", exception.Message);
+            AssertConnectionDisconnectLog();
         }
 
         [ConditionalFact]
@@ -275,7 +283,15 @@ public async Task RequestAbortedIsTrippedWithoutIO()
                 }
                 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(

Original file line number	Diff line number	Diff line change
`@@ -6,6 +6,7 @@`
`6`	`6`	`using System.Threading;`
`7`	`7`	`using System.Threading.Tasks;`
`8`	`8`	`using Microsoft.AspNetCore.Connections;`
	`9`	`+using Microsoft.AspNetCore.Http.Features;`
`9`	`10`
`10`	`11`	`namespace Microsoft.AspNetCore.Server.IIS.Core`
`11`	`12`	`{`
`@@ -121,6 +122,7 @@ private async Task ReadBody()`
`121`	`122`	`catch (Exception ex)`
`122`	`123`	`{`
`123`	`124`	`error = ex;`
	`125`	`+ Log.UnexpectedError(_logger, nameof(IISHttpContext), ex);`
`124`	`126`	`}`
`125`	`127`	`finally`
`126`	`128`	`{`
`@@ -174,6 +176,7 @@ private async Task WriteBody(bool flush = false)`
`174`	`176`	`catch (Exception ex)`
`175`	`177`	`{`
`176`	`178`	`error = ex;`
	`179`	`+ Log.UnexpectedError(_logger, nameof(IISHttpContext), ex);`
`177`	`180`	`}`
`178`	`181`	`finally`
`179`	`182`	`{`
`@@ -199,9 +202,9 @@ private void AbortIO()`
`199`	`202`	`{`
`200`	`203`	`cts.Cancel();`
`201`	`204`	`}`
`202`		`- catch (Exception)`
	`205`	`+ catch (Exception ex)`
`203`	`206`	`{`
`204`		`- // ignore`
	`207`	`+ Log.ApplicationError(_logger, ((IHttpConnectionFeature)this).ConnectionId, TraceIdentifier, ex);`
`205`	`208`	`}`
`206`	`209`	`});`
`207`	`210`	`}`
`@@ -219,6 +222,7 @@ public void Abort(Exception reason)`
`219`	`222`	`internal void ConnectionReset()`
`220`	`223`	`{`
`221`	`224`	`AbortIO();`
	`225`	`+ Log.ConnectionDisconnect(_logger, ((IHttpConnectionFeature)this).ConnectionId);`
`222`	`226`	`}`
`223`	`227`	`}`
`224`	`228`	`}`
Original file line number	Diff line number	Diff line change
`@@ -7,15 +7,16 @@`
`7`	`7`	`using System.Threading.Tasks;`
`8`	`8`	`using Microsoft.AspNetCore.Builder;`
`9`	`9`	`using Microsoft.AspNetCore.Hosting.Server;`
	`10`	`+using Microsoft.Extensions.Logging;`
`10`	`11`
`11`	`12`	`namespace Microsoft.AspNetCore.Server.IIS.Core`
`12`	`13`	`{`
`13`	`14`	`internal class IISHttpContextOfT<TContext> : IISHttpContext`
`14`	`15`	`{`
`15`	`16`	`private readonly IHttpApplication<TContext> _application;`
`16`	`17`
`17`		`- public IISHttpContextOfT(MemoryPool<byte> memoryPool, IHttpApplication<TContext> application, IntPtr pInProcessHandler, IISServerOptions options, IISHttpServer server)`
`18`		`- : base(memoryPool, pInProcessHandler, options, server)`
	`18`	`+ public IISHttpContextOfT(MemoryPool<byte> memoryPool, IHttpApplication<TContext> application, IntPtr pInProcessHandler, IISServerOptions options, IISHttpServer server, ILogger logger)`
	`19`	`+ : base(memoryPool, pInProcessHandler, options, server, logger)`
`19`	`20`	`{`
`20`	`21`	`_application = application;`
`21`	`22`	`}`
Original file line number	Diff line number	Diff line change
`@@ -82,7 +82,7 @@ public Task StartAsync<TContext>(IHttpApplication<TContext> application, Cancell`
`82`	`82`	`{`
`83`	`83`	`_httpServerHandle = GCHandle.Alloc(this);`
`84`	`84`
`85`		`- _iisContextFactory = new IISContextFactory<TContext>(_memoryPool, application, _options, this);`
	`85`	`+ _iisContextFactory = new IISContextFactory<TContext>(_memoryPool, application, _options, this, _logger);`
`86`	`86`	`_nativeApplication.RegisterCallbacks(_requestHandler, _shutdownHandler, _onDisconnect, _onAsyncCompletion, (IntPtr)_httpServerHandle, (IntPtr)_httpServerHandle);`
`87`	`87`	`return Task.CompletedTask;`
`88`	`88`	`}`
`@@ -260,18 +260,20 @@ private class IISContextFactory<T> : IISContextFactory`
`260`	`260`	`private readonly MemoryPool<byte> _memoryPool;`
`261`	`261`	`private readonly IISServerOptions _options;`
`262`	`262`	`private readonly IISHttpServer _server;`
	`263`	`+ private readonly ILogger _logger;`
`263`	`264`
`264`		`- public IISContextFactory(MemoryPool<byte> memoryPool, IHttpApplication<T> application, IISServerOptions options, IISHttpServer server)`
	`265`	`+ public IISContextFactory(MemoryPool<byte> memoryPool, IHttpApplication<T> application, IISServerOptions options, IISHttpServer server, ILogger logger)`
`265`	`266`	`{`
`266`	`267`	`_application = application;`
`267`	`268`	`_memoryPool = memoryPool;`
`268`	`269`	`_options = options;`
`269`	`270`	`_server = server;`
	`271`	`+ _logger = logger;`
`270`	`272`	`}`
`271`	`273`
`272`	`274`	`public IISHttpContext CreateHttpContext(IntPtr pInProcessHandler)`
`273`	`275`	`{`
`274`		`- return new IISHttpContextOfT<T>(_memoryPool, _application, pInProcessHandler, _options, _server);`
	`276`	`+ return new IISHttpContextOfT<T>(_memoryPool, _application, pInProcessHandler, _options, _server, _logger);`
`275`	`277`	`}`
`276`	`278`	`}`
`277`	`279`	`}`
Original file line number	Diff line number	Diff line change
`@@ -17,7 +17,6 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests`
`17`	`17`	`[OSSkipCondition(OperatingSystems.Windows, WindowsVersions.Win7, "https://github.com/aspnet/IISIntegration/issues/866")]`
`18`	`18`	`public class ClientDisconnectTests : StrictTestServerTests`
`19`	`19`	`{`
`20`		`-`
`21`	`20`	`[ConditionalFact]`
`22`	`21`	`public async Task WritesSucceedAfterClientDisconnect()`
`23`	`22`	`{`
`@@ -48,6 +47,8 @@ public async Task WritesSucceedAfterClientDisconnect()`
`48`	`47`
`49`	`48`	`await requestCompletedCompletionSource.Task.DefaultTimeout();`
`50`	`49`	`}`
	`50`	`+`
	`51`	`+ AssertConnectionDisconnectLog();`
`51`	`52`	`}`
`52`	`53`
`53`	`54`	`[ConditionalFact]`
`@@ -88,6 +89,8 @@ public async Task WritesCancelledWhenUsingAbortedToken()`
`88`	`89`
`89`	`90`	`Assert.IsType<OperationCanceledException>(exception);`
`90`	`91`	`}`
	`92`	`+`
	`93`	`+ AssertConnectionDisconnectLog();`
`91`	`94`	`}`
`92`	`95`
`93`	`96`	`[ConditionalFact]`
`@@ -125,6 +128,8 @@ public async Task ReadThrowsAfterClientDisconnect()`
`125`	`128`
`126`	`129`	`Assert.IsType<ConnectionResetException>(exception);`
`127`	`130`	`Assert.Equal("The client has disconnected", exception.Message);`
	`131`	`+`
	`132`	`+ AssertConnectionDisconnectLog();`
`128`	`133`	`}`
`129`	`134`
`130`	`135`	`[ConditionalFact]`
`@@ -202,6 +207,8 @@ public async Task ReaderThrowsCancelledException()`
`202`	`207`	`}`
`203`	`208`	`Assert.IsType<OperationCanceledException>(exception);`
`204`	`209`	`}`
	`210`	`+`
	`211`	`+ AssertConnectionDisconnectLog();`
`205`	`212`	`}`
`206`	`213`
`207`	`214`	`[ConditionalFact]`
`@@ -253,6 +260,7 @@ await connection.Receive(`
`253`	`260`
`254`	`261`	`Assert.IsType<ConnectionResetException>(exception);`
`255`	`262`	`Assert.Equal("The client has disconnected", exception.Message);`
	`263`	`+ AssertConnectionDisconnectLog();`
`256`	`264`	`}`
`257`	`265`
`258`	`266`	`[ConditionalFact]`
`@@ -275,7 +283,15 @@ public async Task RequestAbortedIsTrippedWithoutIO()`
`275`	`283`	`}`
`276`	`284`	`await requestAborted.Task;`
`277`	`285`	`}`
	`286`	`+`
	`287`	`+ AssertConnectionDisconnectLog();`
`278`	`288`	`}`
	`289`	`+`
	`290`	`+ private void AssertConnectionDisconnectLog()`
	`291`	`+ {`
	`292`	`+ Assert.Contains(TestSink.Writes, w => w.EventId.Name == "ConnectionDisconnect");`
	`293`	`+ }`
	`294`	`+`
`279`	`295`	`private static async Task SendContentLength1Post(TestConnection connection)`
`280`	`296`	`{`
`281`	`297`	`await connection.Send(`