UseSerilogRequestLogging()

Author: nblumhardt

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,23 +1,32 @@
 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 = 0;
+
         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();
         }
 

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,93 @@
+// 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.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
+    {
+        // 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;
+
+        public RequestLoggingMiddleware(RequestDelegate next, DiagnosticContext diagnosticContext)
+        {
+            _next = next ?? throw new ArgumentNullException(nameof(next));
+            _diagnosticContext = diagnosticContext ?? throw new ArgumentNullException(nameof(diagnosticContext));
+        }
+
+        // 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);
+            }
+            // Never caught, because `LogCompletion()` returns false.
+            catch (Exception ex) when (LogCompletion(httpContext, collector, 500, GetElapsedMilliseconds(start, Stopwatch.GetTimestamp()), ex)) { }
+        }
+
+        static 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/Serilog.AspNetCore.csproj

@@ -28,6 +28,7 @@
     <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

@@ -0,0 +1,41 @@
+// Copyright 2017-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
+    {
+        /// <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>
+        /// <returns>The application builder.</returns>
+        public static IApplicationBuilder UseSerilogRequestLogging(this IApplicationBuilder app)
+        {
+            if (app == null) throw new ArgumentNullException(nameof(app));
+            return app.UseMiddleware<RequestLoggingMiddleware>();
+        }
+    }
+}

src/Serilog.AspNetCore/SerilogWebHostBuilderExtensions.cs

@@ -1,4 +1,4 @@
-// Copyright 2017 Serilog Contributors
+// Copyright 2017-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.
@@ -17,6 +17,7 @@
 using Microsoft.Extensions.Logging;
 using Serilog.Extensions.Logging;
 using Microsoft.Extensions.DependencyInjection;
+using Serilog.Extensions.Hosting;
 
 namespace Serilog
 {
@@ -63,6 +64,8 @@ public static IWebHostBuilder UseSerilog(
                 {
                     collection.AddSingleton<ILoggerFactory>(services => new SerilogLoggerFactory(logger, dispose));
                 }
+
+                ConfigureServices(collection, logger);
             });
 
             return builder;
@@ -127,8 +130,30 @@ public static IWebHostBuilder UseSerilog(
 
                     return factory;
                 });
+
+                ConfigureServices(collection, logger);
             });
             return builder;
         }
+        
+        static void ConfigureServices(IServiceCollection collection, ILogger logger)
+        {
+            if (collection == null) throw new ArgumentNullException(nameof(collection));
+
+            if (logger != null)
+            {
+                // This won't (and shouldn't) take ownership of the logger. 
+                collection.AddSingleton(logger);
+            }
+
+            // Registered to provide two services...
+            var diagnosticContext = new DiagnosticContext(logger);
+
+            // Consumed by e.g. middleware
+            collection.AddSingleton(diagnosticContext);
+
+            // Consumed by user code
+            collection.AddSingleton<IDiagnosticContext>(diagnosticContext);
+        }
     }
 }