Merge pull request #94 from serilog/request-completion-middleware

nblumhardt · web-flow · commit 81af9a71e162 · 2019-06-25T11:30:16.000+10:00
UseSerilogRequestLogging()
diff --git a/samples/EarlyInitializationSample/Controllers/HomeController.cs b/samples/EarlyInitializationSample/Controllers/HomeController.cs
@@ -1,29 +1,38 @@
 ﻿using System;
 using System.Diagnostics;
+using System.Threading;
 using Microsoft.AspNetCore.Mvc;
 using EarlyInitializationSample.Models;
 using Microsoft.Extensions.Logging;
+using Serilog;
 
 namespace EarlyInitializationSample.Controllers
 {
     public class HomeController : Controller
     {
+        static int _callCount;
+
         readonly ILogger<HomeController> _logger;
+        readonly IDiagnosticContext _diagnosticContext;
 
-        public HomeController(ILogger<HomeController> logger)
+        public HomeController(ILogger<HomeController> logger, IDiagnosticContext diagnosticContext)
         {
             _logger = logger ?? throw new ArgumentNullException(nameof(logger));
+            _diagnosticContext = diagnosticContext ?? throw new ArgumentNullException(nameof(diagnosticContext));
         }
 
         public IActionResult Index()
         {
             _logger.LogInformation("Hello, world!");
+
+            _diagnosticContext.Add("IndexCallCount", Interlocked.Increment(ref _callCount));
+
             return View();
         }
 
         public IActionResult Privacy()
         {
-            return View();
+            throw new InvalidOperationException("Something went wrong.");
         }
 
         [ResponseCache(Duration = 0, Location = ResponseCacheLocation.None, NoStore = true)]
diff --git a/samples/EarlyInitializationSample/Program.cs b/samples/EarlyInitializationSample/Program.cs
@@ -21,7 +21,10 @@ public static int Main(string[] args)
             Log.Logger = new LoggerConfiguration()
                 .ReadFrom.Configuration(Configuration)
                 .Enrich.FromLogContext()
-                .WriteTo.Console()
+                .WriteTo.Console(
+                    // {Properties:j} added:
+                    outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} " +
+                                    "{Properties:j}{NewLine}{Exception}")
                 .CreateLogger();
 
             try
diff --git a/samples/EarlyInitializationSample/Startup.cs b/samples/EarlyInitializationSample/Startup.cs
@@ -8,6 +8,7 @@
 using Microsoft.AspNetCore.Mvc;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.DependencyInjection;
+using Serilog;
 
 namespace EarlyInitializationSample
 {
@@ -46,6 +47,11 @@ public void Configure(IApplicationBuilder app, IHostingEnvironment env)
                 app.UseExceptionHandler("/Home/Error");
             }
 
+            // Write streamlined request completion events, instead of the more verbose ones from the framework.
+            // To use the default framework request logging instead, remove this line and set the "Microsoft"
+            // level in appsettings.json to "Information".
+            app.UseSerilogRequestLogging();
+
             app.UseStaticFiles();
             app.UseCookiePolicy();
 
diff --git a/samples/EarlyInitializationSample/appsettings.json b/samples/EarlyInitializationSample/appsettings.json
@@ -3,7 +3,7 @@
     "MinimumLevel": {
       "Default": "Information",
       "Override": {
-        "Microsoft": "Information",
+        "Microsoft": "Warning",
         "System": "Warning"
       }
     }
diff --git a/samples/InlineInitializationSample/Controllers/HomeController.cs b/samples/InlineInitializationSample/Controllers/HomeController.cs
@@ -1,29 +1,38 @@
 ﻿using System;
 using System.Diagnostics;
+using System.Threading;
 using Microsoft.AspNetCore.Mvc;
 using InlineInitializationSample.Models;
 using Microsoft.Extensions.Logging;
+using Serilog;
 
 namespace InlineInitializationSample.Controllers
 {
     public class HomeController : Controller
     {
+        static int _callCount;
+
         readonly ILogger<HomeController> _logger;
+        readonly IDiagnosticContext _diagnosticContext;
 
-        public HomeController(ILogger<HomeController> logger)
+        public HomeController(ILogger<HomeController> logger, IDiagnosticContext diagnosticContext)
         {
             _logger = logger ?? throw new ArgumentNullException(nameof(logger));
+            _diagnosticContext = diagnosticContext ?? throw new ArgumentNullException(nameof(diagnosticContext));
         }
 
         public IActionResult Index()
         {
             _logger.LogInformation("Hello, world!");
+
+            _diagnosticContext.Add("IndexCallCount", Interlocked.Increment(ref _callCount));
+
             return View();
         }
 
         public IActionResult Privacy()
         {
-            return View();
+            throw new InvalidOperationException("Something went wrong.");
         }
 
         [ResponseCache(Duration = 0, Location = ResponseCacheLocation.None, NoStore = true)]
diff --git a/samples/InlineInitializationSample/Program.cs b/samples/InlineInitializationSample/Program.cs
@@ -17,6 +17,9 @@ public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
                 .UseSerilog((hostingContext, loggerConfiguration) => loggerConfiguration
                     .ReadFrom.Configuration(hostingContext.Configuration)
                     .Enrich.FromLogContext()
-                    .WriteTo.Console());
+                    .WriteTo.Console(
+                        // {Properties:j} added:
+                        outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} " +
+                                        "{Properties:j}{NewLine}{Exception}"));
     }
 }
diff --git a/samples/InlineInitializationSample/Startup.cs b/samples/InlineInitializationSample/Startup.cs
@@ -8,6 +8,7 @@
 using Microsoft.AspNetCore.Mvc;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.DependencyInjection;
+using Serilog;
 
 namespace InlineInitializationSample
 {
@@ -46,6 +47,11 @@ public void Configure(IApplicationBuilder app, IHostingEnvironment env)
                 app.UseExceptionHandler("/Home/Error");
             }
 
+            // Write streamlined request completion events, instead of the more verbose ones from the framework.
+            // To use the default framework request logging instead, remove this line and set the "Microsoft"
+            // level in appsettings.json to "Information".
+            app.UseSerilogRequestLogging();
+
             app.UseStaticFiles();
             app.UseCookiePolicy();
 
diff --git a/samples/InlineInitializationSample/appsettings.json b/samples/InlineInitializationSample/appsettings.json
@@ -3,7 +3,7 @@
     "MinimumLevel": {
       "Default": "Information",
       "Override": {
-        "Microsoft": "Information",
+        "Microsoft": "Warning",
         "System": "Warning"
       }
     }
diff --git a/src/Serilog.AspNetCore/AspNetCore/RequestCompletionMiddleware.cs b/src/Serilog.AspNetCore/AspNetCore/RequestCompletionMiddleware.cs
@@ -0,0 +1,104 @@
+﻿// Copyright 2019 Serilog Contributors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+using System;
+using System.Collections.Generic;
+using System.Diagnostics;
+using System.Linq;
+using System.Threading.Tasks;
+using Microsoft.AspNetCore.Http;
+using Microsoft.AspNetCore.Http.Features;
+using Serilog.Events;
+using Serilog.Extensions.Hosting;
+using Serilog.Parsing;
+
+namespace Serilog.AspNetCore
+{
+    class RequestLoggingMiddleware
+    {
+        readonly RequestDelegate _next;
+        readonly DiagnosticContext _diagnosticContext;
+        readonly MessageTemplate _messageTemplate;
+        readonly int _messageTemplatePlaceholderCount;
+
+        public RequestLoggingMiddleware(RequestDelegate next, DiagnosticContext diagnosticContext, RequestLoggingOptions options)
+        {
+            if (options == null) throw new ArgumentNullException(nameof(options));
+            _next = next ?? throw new ArgumentNullException(nameof(next));
+            _diagnosticContext = diagnosticContext ?? throw new ArgumentNullException(nameof(diagnosticContext));
+
+            _messageTemplate = new MessageTemplateParser().Parse(options.MessageTemplate);
+            _messageTemplatePlaceholderCount = _messageTemplate.Tokens.OfType<PropertyToken>().Count();
+        }
+
+        // ReSharper disable once UnusedMember.Global
+        public async Task Invoke(HttpContext httpContext)
+        {
+            if (httpContext == null) throw new ArgumentNullException(nameof(httpContext));
+
+            var start = Stopwatch.GetTimestamp();
+
+            var collector = _diagnosticContext.BeginCollection();
+            try
+            {
+                await _next(httpContext);
+                var elapsedMs = GetElapsedMilliseconds(start, Stopwatch.GetTimestamp());
+                var statusCode = httpContext.Response.StatusCode;
+                LogCompletion(httpContext, collector, statusCode, elapsedMs, null);
+            }
+            catch (Exception ex)
+                // Never caught, because `LogCompletion()` returns false. This ensures e.g. the developer exception page is still
+                // shown, although it does also mean we see a duplicate "unhandled exception" event from ASP.NET Core.
+                when (LogCompletion(httpContext, collector, 500, GetElapsedMilliseconds(start, Stopwatch.GetTimestamp()), ex))
+            {
+            }
+            finally
+            {
+                collector.Dispose();
+            }
+        }
+
+        bool LogCompletion(HttpContext httpContext, DiagnosticContextCollector collector, int statusCode, double elapsedMs, Exception ex)
+        {
+            var level = statusCode > 499 ? LogEventLevel.Error : LogEventLevel.Information;
+
+            if (!Log.IsEnabled(level)) return false;
+            
+            if (!collector.TryComplete(out var properties))
+                properties = new List<LogEventProperty>();
+
+            properties.Capacity = properties.Count + _messageTemplatePlaceholderCount;
+
+            // Last-in (rightly) wins...
+            properties.Add(new LogEventProperty("RequestMethod", new ScalarValue(httpContext.Request.Method)));
+            properties.Add(new LogEventProperty("RequestPath", new ScalarValue(GetPath(httpContext))));
+            properties.Add(new LogEventProperty("StatusCode", new ScalarValue(statusCode)));
+            properties.Add(new LogEventProperty("Elapsed", new ScalarValue(elapsedMs)));
+            var evt = new LogEvent(DateTimeOffset.Now, level, ex, _messageTemplate, properties);
+            Log.Write(evt);
+
+            return false;
+        }
+
+        static double GetElapsedMilliseconds(long start, long stop)
+        {
+            return (stop - start) * 1000 / (double)Stopwatch.Frequency;
+        }
+        
+        static string GetPath(HttpContext httpContext)
+        {
+            return httpContext.Features.Get<IHttpRequestFeature>()?.RawTarget ?? httpContext.Request.Path.ToString();
+        }
+    }
+}
diff --git a/src/Serilog.AspNetCore/AspNetCore/SerilogLoggerFactory.cs b/src/Serilog.AspNetCore/AspNetCore/SerilogLoggerFactory.cs
@@ -13,6 +13,7 @@
 // limitations under the License.
 
 using System;
+using System.ComponentModel;
 using Microsoft.Extensions.Logging;
 using Serilog.Debugging;
 using Serilog.Extensions.Logging;
@@ -23,6 +24,7 @@ namespace Serilog.AspNetCore
     /// Implements <see cref="ILoggerFactory"/> so that we can inject Serilog Logger.
     /// </summary>
     [Obsolete("Replaced with Serilog.Extensions.Logging.SerilogLoggerFactory")]
+    [EditorBrowsable(EditorBrowsableState.Never)]
     public class SerilogLoggerFactory : ILoggerFactory
     {
         private readonly SerilogLoggerProvider _provider;
diff --git a/src/Serilog.AspNetCore/RequestLoggingOptions.cs b/src/Serilog.AspNetCore/RequestLoggingOptions.cs
@@ -0,0 +1,28 @@
+﻿// Copyright 2019 Serilog Contributors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+using System;
+
+namespace Serilog
+{
+    class RequestLoggingOptions
+    {
+        public string MessageTemplate { get; }
+
+        public RequestLoggingOptions(string messageTemplate)
+        {
+            MessageTemplate = messageTemplate ?? throw new ArgumentNullException(nameof(messageTemplate));
+        }
+    }
+}
diff --git a/src/Serilog.AspNetCore/Serilog.AspNetCore.csproj b/src/Serilog.AspNetCore/Serilog.AspNetCore.csproj
@@ -24,6 +24,7 @@
 
   <ItemGroup>
     <PackageReference Include="Serilog" Version="2.8.0" />
+    <PackageReference Include="Serilog.Extensions.Hosting" Version="3.0.0-*" />
     <PackageReference Include="Serilog.Extensions.Logging" Version="3.0.0-*" />
     <PackageReference Include="Microsoft.AspNetCore.Hosting.Abstractions" Version="2.0.0" />
     <PackageReference Include="Microsoft.Extensions.DependencyInjection" Version="2.0.0" />
diff --git a/src/Serilog.AspNetCore/SerilogApplicationBuilderExtensions.cs b/src/Serilog.AspNetCore/SerilogApplicationBuilderExtensions.cs
@@ -0,0 +1,53 @@
+﻿// Copyright 2019 Serilog Contributors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+using System;
+using Microsoft.AspNetCore.Builder;
+using Serilog.AspNetCore;
+
+namespace Serilog
+{
+    /// <summary>
+    /// Extends <see cref="IApplicationBuilder"/> with methods for configuring Serilog features.
+    /// </summary>
+    public static class SerilogApplicationBuilderExtensions
+    {
+        const string DefaultRequestCompletionMessageTemplate =
+            "HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms";
+
+        /// <summary>
+        /// Adds middleware for streamlined request logging. Instead of writing HTTP request information
+        /// like method, path, timing, status code and exception details
+        /// in several events, this middleware collects information during the request (including from
+        /// <see cref="IDiagnosticContext"/>), and writes a single event at request completion. Add this
+        /// in <c>Startup.cs</c> before any handlers whose activities should be logged.
+        /// </summary>
+        /// <param name="app">The application builder.</param>
+        /// <param name="messageTemplate">The message template to use when logging request completion
+        /// events. The default is
+        /// <c>"HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms"</c>. The
+        /// template can contain any of the placeholders from the default template, names of properties
+        /// added by ASP.NET Core, and names of properties added to the <see cref="IDiagnosticContext"/>.
+        /// </param>
+        /// <returns>The application builder.</returns>
+        public static IApplicationBuilder UseSerilogRequestLogging(
+            this IApplicationBuilder app,
+            string messageTemplate = DefaultRequestCompletionMessageTemplate)
+        {
+            if (app == null) throw new ArgumentNullException(nameof(app));
+            if (messageTemplate == null) throw new ArgumentNullException(nameof(messageTemplate));
+            return app.UseMiddleware<RequestLoggingMiddleware>(new RequestLoggingOptions(messageTemplate));
+        }
+    }
+}
diff --git a/src/Serilog.AspNetCore/SerilogWebHostBuilderExtensions.cs b/src/Serilog.AspNetCore/SerilogWebHostBuilderExtensions.cs

Original file line number	Diff line number	Diff line change
`@@ -1,29 +1,38 @@`
`1`	`1`	`using System;`
`2`	`2`	`using System.Diagnostics;`
	`3`	`+using System.Threading;`
`3`	`4`	`using Microsoft.AspNetCore.Mvc;`
`4`	`5`	`using EarlyInitializationSample.Models;`
`5`	`6`	`using Microsoft.Extensions.Logging;`
	`7`	`+using Serilog;`
`6`	`8`
`7`	`9`	`namespace EarlyInitializationSample.Controllers`
`8`	`10`	`{`
`9`	`11`	`public class HomeController : Controller`
`10`	`12`	`{`
	`13`	`+ static int _callCount;`
	`14`	`+`
`11`	`15`	`readonly ILogger<HomeController> _logger;`
	`16`	`+ readonly IDiagnosticContext _diagnosticContext;`
`12`	`17`
`13`		`- public HomeController(ILogger<HomeController> logger)`
	`18`	`+ public HomeController(ILogger<HomeController> logger, IDiagnosticContext diagnosticContext)`
`14`	`19`	`{`
`15`	`20`	`_logger = logger ?? throw new ArgumentNullException(nameof(logger));`
	`21`	`+ _diagnosticContext = diagnosticContext ?? throw new ArgumentNullException(nameof(diagnosticContext));`
`16`	`22`	`}`
`17`	`23`
`18`	`24`	`public IActionResult Index()`
`19`	`25`	`{`
`20`	`26`	`_logger.LogInformation("Hello, world!");`
	`27`	`+`
	`28`	`+ _diagnosticContext.Add("IndexCallCount", Interlocked.Increment(ref _callCount));`
	`29`	`+`
`21`	`30`	`return View();`
`22`	`31`	`}`
`23`	`32`
`24`	`33`	`public IActionResult Privacy()`
`25`	`34`	`{`
`26`		`- return View();`
	`35`	`+ throw new InvalidOperationException("Something went wrong.");`
`27`	`36`	`}`
`28`	`37`
`29`	`38`	`[ResponseCache(Duration = 0, Location = ResponseCacheLocation.None, NoStore = true)]`
Original file line number	Diff line number	Diff line change
`@@ -3,7 +3,7 @@`
`3`	`3`	`"MinimumLevel": {`
`4`	`4`	`"Default": "Information",`
`5`	`5`	`"Override": {`
`6`		`- "Microsoft": "Information",`
	`6`	`+ "Microsoft": "Warning",`
`7`	`7`	`"System": "Warning"`
`8`	`8`	`}`
`9`	`9`	`}`
Original file line number	Diff line number	Diff line change
`@@ -17,6 +17,9 @@ public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>`
`17`	`17`	`.UseSerilog((hostingContext, loggerConfiguration) => loggerConfiguration`
`18`	`18`	`.ReadFrom.Configuration(hostingContext.Configuration)`
`19`	`19`	`.Enrich.FromLogContext()`
`20`		`- .WriteTo.Console());`
	`20`	`+ .WriteTo.Console(`
	`21`	`+ // {Properties:j} added:`
	`22`	`+ outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} " +`
	`23`	`+ "{Properties:j}{NewLine}{Exception}"));`
`21`	`24`	`}`
`22`	`25`	`}`