From be446d4bd0ad6a175e0b6603821ce5c1155478a5 Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Wed, 26 Jun 2019 16:10:25 +1000 Subject: [PATCH 1/2] README and dependency updates --- README.md | 86 +++++++++++++++++-- .../Controllers/HomeController.cs | 2 +- .../Controllers/HomeController.cs | 2 +- .../AspNetCore/RequestCompletionMiddleware.cs | 23 ++--- .../Serilog.AspNetCore.csproj | 2 +- 5 files changed, 94 insertions(+), 21 deletions(-) diff --git a/README.md b/README.md index 3aba5fd..165c434 100644 --- a/README.md +++ b/README.md @@ -1,15 +1,16 @@ # Serilog.AspNetCore [![Build status](https://ci.appveyor.com/api/projects/status/4rscdto23ik6vm2r?svg=true)](https://ci.appveyor.com/project/serilog/serilog-aspnetcore) [![NuGet Version](http://img.shields.io/nuget/v/Serilog.AspNetCore.svg?style=flat)](https://www.nuget.org/packages/Serilog.AspNetCore/) +Serilog logging for ASP.NET Core. This package routes ASP.NET Core log messages through Serilog, so you can get information about ASP.NET's internal operations written to the same Serilog sinks as your application events. -Serilog logging for ASP.NET Core. This package routes ASP.NET Core log messages through Serilog, so you can get information about ASP.NET's internal operations logged to the same Serilog sinks as your application events. +With _Serilog.AspNetCore_ installed and configured, you can write log messages directly through Serilog or any `ILogger` interface injected by ASP.NET. All loggers will use the same underlying implementation, levels, and destinations. ### Instructions **First**, install the _Serilog.AspNetCore_ [NuGet package](https://www.nuget.org/packages/Serilog.AspNetCore) into your app. You will need a way to view the log messages - _Serilog.Sinks.Console_ writes these to the console; there are [many more sinks available](https://www.nuget.org/packages?q=Tags%3A%22serilog%22) on NuGet. -```powershell -Install-Package Serilog.AspNetCore -DependencyVersion Highest -Install-Package Serilog.Sinks.Console +```shell +dotnet add package Serilog.AspNetCore +dotnet add package Serilog.Sinks.Console ``` **Next**, in your application's _Program.cs_ file, configure Serilog first. A `try`/`catch` block will ensure any configuration issues are appropriately logged: @@ -82,11 +83,82 @@ Tip: to see Serilog output in the Visual Studio output window when running under A more complete example, showing _appsettings.json_ configuration, can be found in [the sample project here](https://github.com/serilog/serilog-aspnetcore/tree/dev/samples/EarlyInitializationSample). -### Using the package +### Request logging -With _Serilog.AspNetCore_ installed and configured, you can write log messages directly through Serilog or any `ILogger` interface injected by ASP.NET. All loggers will use the same underlying implementation, levels, and destinations. +The package includes middleware for smarter HTTP request logging. The default request logging implemented by ASP.NET Core is noisy, with multiple events emitted per request. The included middleware condenses these into a single event that carries method, path, status code, and timing information. + +As text, this has a format like: + +``` +[16:05:54 INF] HTTP GET / responded 200 in 227.3253 ms +``` + +Or as [JSON](https://github.com/serilog/serilog-formatting-compact): + +```json +{ + "@t":"2019-06-26T06:05:54.6881162Z", + "@mt":"HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms", + "@r":["224.5185"], + "RequestMethod":"GET", + "RequestPath":"/", + "StatusCode":200, + "Elapsed":224.5185, + "RequestId":"0HLNPVG1HI42T:00000001", + "CorrelationId":null, + "ConnectionId":"0HLNPVG1HI42T" +} +``` + +To enable the middleware, first change the minimum level for `Microsoft` to `Warning` in your logger configuration or _appsettings.json_ file: + +```csharp + .MinimumLevel.Override("Microsoft", LogEventLevel.Warning) +``` + +Then, in your application's _Startup.cs_, add the middleware with `UseSerilogRequestLogging()`: + +```csharp + public void Configure(IApplicationBuilder app, IHostingEnvironment env) + { + if (env.IsDevelopment()) + { + app.UseDeveloperExceptionPage(); + } + else + { + app.UseExceptionHandler("/Home/Error"); + } + + app.UseSerilogRequestLogging(); // <-- Add this line + + // Other app configuration +``` + +It's important that the `UseSerilogRequestLogging()` call appears _before_ handlers such as MVC. The middleware will not time or log components that appear before it in the pipeline. (This can be utilized to exclude noisy handlers from logging, such as `UseStaticFiles()`, by placing `UseSerilogRequestLogging()` after them.) + +During request processing, additional properties can be attached to the completion event using `IDiagnosticContext.Set()`: + +```csharp + public class HomeController : Controller + { + readonly IDiagnosticContext _diagnosticContext; + + public HomeController(IDiagnosticContext diagnosticContext) + { + _diagnosticContext = diagnosticContext ?? throw new ArgumentNullException(nameof(diagnosticContext)); + } + + public IActionResult Index() + { + // The request completion event will carry this property + _diagnosticContext.Set("CatalogLoadTime", 1423); + + return View(); + } +``` -**Tip:** change the minimum level for `Microsoft` to `Warning` and plug in this [custom logging middleware](https://github.com/datalust/serilog-middleware-example/blob/master/src/Datalust.SerilogMiddlewareExample/Diagnostics/SerilogMiddleware.cs) to clean up request logging output and record more context around errors and exceptions. +This pattern has the advantage of reducing the number of log events that need to be constructed, transmitted, and stored per HTTP request. Having many properties on the same event can also make correlation of request details and other data easier. ### Inline initialization diff --git a/samples/EarlyInitializationSample/Controllers/HomeController.cs b/samples/EarlyInitializationSample/Controllers/HomeController.cs index c7eb1ef..46c32ab 100644 --- a/samples/EarlyInitializationSample/Controllers/HomeController.cs +++ b/samples/EarlyInitializationSample/Controllers/HomeController.cs @@ -25,7 +25,7 @@ public IActionResult Index() { _logger.LogInformation("Hello, world!"); - _diagnosticContext.Add("IndexCallCount", Interlocked.Increment(ref _callCount)); + _diagnosticContext.Set("IndexCallCount", Interlocked.Increment(ref _callCount)); return View(); } diff --git a/samples/InlineInitializationSample/Controllers/HomeController.cs b/samples/InlineInitializationSample/Controllers/HomeController.cs index 3c0412f..565294f 100644 --- a/samples/InlineInitializationSample/Controllers/HomeController.cs +++ b/samples/InlineInitializationSample/Controllers/HomeController.cs @@ -25,7 +25,7 @@ public IActionResult Index() { _logger.LogInformation("Hello, world!"); - _diagnosticContext.Add("IndexCallCount", Interlocked.Increment(ref _callCount)); + _diagnosticContext.Set("IndexCallCount", Interlocked.Increment(ref _callCount)); return View(); } diff --git a/src/Serilog.AspNetCore/AspNetCore/RequestCompletionMiddleware.cs b/src/Serilog.AspNetCore/AspNetCore/RequestCompletionMiddleware.cs index 61f837b..797d896 100644 --- a/src/Serilog.AspNetCore/AspNetCore/RequestCompletionMiddleware.cs +++ b/src/Serilog.AspNetCore/AspNetCore/RequestCompletionMiddleware.cs @@ -13,7 +13,6 @@ // limitations under the License. using System; -using System.Collections.Generic; using System.Diagnostics; using System.Linq; using System.Threading.Tasks; @@ -30,7 +29,8 @@ class RequestLoggingMiddleware readonly RequestDelegate _next; readonly DiagnosticContext _diagnosticContext; readonly MessageTemplate _messageTemplate; - readonly int _messageTemplatePlaceholderCount; + + static readonly LogEventProperty[] NoProperties = new LogEventProperty[0]; public RequestLoggingMiddleware(RequestDelegate next, DiagnosticContext diagnosticContext, RequestLoggingOptions options) { @@ -39,7 +39,6 @@ public RequestLoggingMiddleware(RequestDelegate next, DiagnosticContext diagnost _diagnosticContext = diagnosticContext ?? throw new ArgumentNullException(nameof(diagnosticContext)); _messageTemplate = new MessageTemplateParser().Parse(options.MessageTemplate); - _messageTemplatePlaceholderCount = _messageTemplate.Tokens.OfType().Count(); } // ReSharper disable once UnusedMember.Global @@ -75,16 +74,18 @@ bool LogCompletion(HttpContext httpContext, DiagnosticContextCollector collector if (!Log.IsEnabled(level)) return false; - if (!collector.TryComplete(out var properties)) - properties = new List(); + if (!collector.TryComplete(out var collectedProperties)) + collectedProperties = NoProperties; - properties.Capacity = properties.Count + _messageTemplatePlaceholderCount; + // Last-in (correctly) wins... + var properties = collectedProperties.Concat(new[] + { + new LogEventProperty("RequestMethod", new ScalarValue(httpContext.Request.Method)), + new LogEventProperty("RequestPath", new ScalarValue(GetPath(httpContext))), + new LogEventProperty("StatusCode", new ScalarValue(statusCode)), + new LogEventProperty("Elapsed", new ScalarValue(elapsedMs)) + }); - // 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); diff --git a/src/Serilog.AspNetCore/Serilog.AspNetCore.csproj b/src/Serilog.AspNetCore/Serilog.AspNetCore.csproj index ca7aee0..83af8dc 100644 --- a/src/Serilog.AspNetCore/Serilog.AspNetCore.csproj +++ b/src/Serilog.AspNetCore/Serilog.AspNetCore.csproj @@ -24,7 +24,7 @@ - + From fff098414a0de07cb8319a956124535db262e872 Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Wed, 26 Jun 2019 16:13:03 +1000 Subject: [PATCH 2/2] Larger clickable link --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index 165c434..a37e18c 100644 --- a/README.md +++ b/README.md @@ -93,7 +93,7 @@ As text, this has a format like: [16:05:54 INF] HTTP GET / responded 200 in 227.3253 ms ``` -Or as [JSON](https://github.com/serilog/serilog-formatting-compact): +Or [as JSON](https://github.com/serilog/serilog-formatting-compact): ```json {