Allow configuration of the completion message template

Author: nblumhardt

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)]

samples/InlineInitializationSample/Controllers/HomeController.cs

@@ -10,7 +10,7 @@ namespace InlineInitializationSample.Controllers
 {
     public class HomeController : Controller
     {
-        static int _callCount = 0;
+        static int _callCount;
 
         readonly ILogger<HomeController> _logger;
         readonly IDiagnosticContext _diagnosticContext;
@@ -32,7 +32,7 @@ public IActionResult Index()
 
         public IActionResult Privacy()
         {
-            return View();
+            throw new InvalidOperationException("Something went wrong.");
         }
 
         [ResponseCache(Duration = 0, Location = ResponseCacheLocation.None, NoStore = true)]

src/Serilog.AspNetCore/AspNetCore/RequestCompletionMiddleware.cs

@@ -15,6 +15,7 @@
 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;
@@ -26,18 +27,19 @@ namespace Serilog.AspNetCore
 {
     class RequestLoggingMiddleware
     {
-        // We may, at some future point, wish to allow customization of the template used in completion events.
-        const int MessageTemplatePlaceholderCount = 4;
-        static readonly MessageTemplate MessageTemplate =
-            new MessageTemplateParser().Parse("HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms");
-
         readonly RequestDelegate _next;
         readonly DiagnosticContext _diagnosticContext;
+        readonly MessageTemplate _messageTemplate;
+        readonly int _messageTemplatePlaceholderCount;
 
-        public RequestLoggingMiddleware(RequestDelegate next, DiagnosticContext diagnosticContext)
+        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
@@ -46,19 +48,28 @@ 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;
+                var statusCode = httpContext.Response.StatusCode;
                 LogCompletion(httpContext, collector, statusCode, elapsedMs, null);
             }
-            // Never caught, because `LogCompletion()` returns false.
-            catch (Exception ex) when (LogCompletion(httpContext, collector, 500, GetElapsedMilliseconds(start, Stopwatch.GetTimestamp()), ex)) { }
+            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();
+            }
         }
 
-        static bool LogCompletion(HttpContext httpContext, DiagnosticContextCollector collector, int? statusCode, double elapsedMs, Exception ex)
+        bool LogCompletion(HttpContext httpContext, DiagnosticContextCollector collector, int statusCode, double elapsedMs, Exception ex)
         {
             var level = statusCode > 499 ? LogEventLevel.Error : LogEventLevel.Information;
 
@@ -67,14 +78,14 @@ static bool LogCompletion(HttpContext httpContext, DiagnosticContextCollector co
             if (!collector.TryComplete(out var properties))
                 properties = new List<LogEventProperty>();
 
-            properties.Capacity = properties.Count + MessageTemplatePlaceholderCount;
+            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);
+            var evt = new LogEvent(DateTimeOffset.Now, level, ex, _messageTemplate, properties);
             Log.Write(evt);
 
             return false;

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

src/Serilog.AspNetCore/Serilog.AspNetCore.csproj

@@ -24,11 +24,11 @@
 
   <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" />
     <PackageReference Include="Microsoft.Extensions.Logging" Version="2.0.0" />
-    <ProjectReference Include="..\..\..\serilog-extensions-hosting\src\Serilog.Extensions.Hosting\Serilog.Extensions.Hosting.csproj" />
   </ItemGroup>
 
 </Project>

src/Serilog.AspNetCore/SerilogApplicationBuilderExtensions.cs

@@ -1,4 +1,4 @@
-// Copyright 2017-2019 Serilog Contributors
+// 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.
@@ -23,6 +23,9 @@ namespace Serilog
     /// </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
@@ -31,11 +34,20 @@ public static class SerilogApplicationBuilderExtensions
         /// 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)
+        public static IApplicationBuilder UseSerilogRequestLogging(
+            this IApplicationBuilder app,
+            string messageTemplate = DefaultRequestCompletionMessageTemplate)
         {
             if (app == null) throw new ArgumentNullException(nameof(app));
-            return app.UseMiddleware<RequestLoggingMiddleware>();
+            if (messageTemplate == null) throw new ArgumentNullException(nameof(messageTemplate));
+            return app.UseMiddleware<RequestLoggingMiddleware>(new RequestLoggingOptions(messageTemplate));
         }
     }
 }