diff --git a/samples/EarlyInitializationSample/Controllers/HomeController.cs b/samples/EarlyInitializationSample/Controllers/HomeController.cs index d6e42c5..c7eb1ef 100644 --- 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 _logger; + readonly IDiagnosticContext _diagnosticContext; - public HomeController(ILogger logger) + public HomeController(ILogger 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 index 66b92d0..e8fda83 100644 --- 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 index 01b6b3a..418f352 100644 --- 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 index bae2d8b..69e5005 100644 --- 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 index 0e49af9..3c0412f 100644 --- 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 _logger; + readonly IDiagnosticContext _diagnosticContext; - public HomeController(ILogger logger) + public HomeController(ILogger 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 index 3863117..47f76a0 100644 --- 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 index 73df1bf..adcf024 100644 --- 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 index bae2d8b..69e5005 100644 --- 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 new file mode 100644 index 0000000..61f837b --- /dev/null +++ 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().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(); + + 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()?.RawTarget ?? httpContext.Request.Path.ToString(); + } + } +} diff --git a/src/Serilog.AspNetCore/AspNetCore/SerilogLoggerFactory.cs b/src/Serilog.AspNetCore/AspNetCore/SerilogLoggerFactory.cs index 1640356..b468dea 100644 --- 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 so that we can inject Serilog Logger. /// [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 new file mode 100644 index 0000000..f68cf43 --- /dev/null +++ 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 index c698358..ca7aee0 100644 --- a/src/Serilog.AspNetCore/Serilog.AspNetCore.csproj +++ b/src/Serilog.AspNetCore/Serilog.AspNetCore.csproj @@ -24,6 +24,7 @@ + diff --git a/src/Serilog.AspNetCore/SerilogApplicationBuilderExtensions.cs b/src/Serilog.AspNetCore/SerilogApplicationBuilderExtensions.cs new file mode 100644 index 0000000..91c7106 --- /dev/null +++ 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 +{ + /// + /// Extends with methods for configuring Serilog features. + /// + public static class SerilogApplicationBuilderExtensions + { + const string DefaultRequestCompletionMessageTemplate = + "HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms"; + + /// + /// 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 + /// ), and writes a single event at request completion. Add this + /// in Startup.cs before any handlers whose activities should be logged. + /// + /// The application builder. + /// The message template to use when logging request completion + /// events. The default is + /// "HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms". 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 . + /// + /// The application builder. + 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(new RequestLoggingOptions(messageTemplate)); + } + } +} diff --git a/src/Serilog.AspNetCore/SerilogWebHostBuilderExtensions.cs b/src/Serilog.AspNetCore/SerilogWebHostBuilderExtensions.cs index 6d22578..f27a8fb 100644 --- a/src/Serilog.AspNetCore/SerilogWebHostBuilderExtensions.cs +++ b/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(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(diagnosticContext); + } } }