UseSerilogRequestLogging()

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/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

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();
 

samples/EarlyInitializationSample/appsettings.json

@@ -3,7 +3,7 @@
     "MinimumLevel": {
       "Default": "Information",
       "Override": {
-        "Microsoft": "Information",
+        "Microsoft": "Warning",
         "System": "Warning"
       }
     }

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

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

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();
 

samples/InlineInitializationSample/appsettings.json

@@ -3,7 +3,7 @@
     "MinimumLevel": {
       "Default": "Information",
       "Override": {
-        "Microsoft": "Information",
+        "Microsoft": "Warning",
         "System": "Warning"
       }
     }

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

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;

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,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" />

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