From a7c57d13495fd61c3c4c11fb309c1d1358f9d018 Mon Sep 17 00:00:00 2001 From: Dan Vicarel Date: Mon, 9 Nov 2020 13:14:51 -0500 Subject: [PATCH 1/2] Added notes about Log Scope usage to README The ability to pass any `IEnumerable>` to `ILogger.BeginScope` is an _extremely_ useful feature, but unfortunately it doesn't seem to be officially documented anywhere. I only discovered it while digging through this repo's source code! I assume this repo is the correct location for this information, as it only applies when one is using both Serilog and the _Microsoft.Extensions.Logging_ library, but I could see where it might be better off in the Serilog wiki. Looking forward to your feedback! --- README.md | 63 +++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 63 insertions(+) diff --git a/README.md b/README.md index 2dbb39d..de78765 100644 --- a/README.md +++ b/README.md @@ -80,6 +80,69 @@ That's it! With the level bumped up a little you should see log output like: [22:14:45.741 DBG] Handled. Status code: 304 File: /css/site.css ``` +### Notes on Log Scopes + +_Microsoft.Extensions.Logging_ provides the `BeginScope` API, which can be used to add arbitrary properties to log events within a certain region of code. The API comes in two forms: + +1. The method: `IDisposable BeginScope(TState state)` +2. The extension method: `IDisposable BeginScope(this ILogger logger, string messageFormat, params object[] args)` + +Using the extension method will add a `Scope` property to your log events. This is most useful for adding simple "scope strings" to your events, as in the following code: + +```cs +using (_logger.BeginScope("Transaction")) { + _logger.LogInformation("Beginning..."); + _logger.LogInformation("Completed in {DurationMs}ms...", 30); +} +// Example JSON output: +// {"@t":"2020-10-29T19:05:56.4126822Z","@m":"Beginning...","@i":"f6a328e9","SourceContext":"SomeNamespace.SomeService","Scope":["Transaction"]} +// {"@t":"2020-10-29T19:05:56.4176816Z","@m":"Completed in 30ms...","@i":"51812baa","DurationMs":30,"SourceContext":"SomeNamespace.SomeService","Scope":["Transaction"]} +``` + +If you simply want to add a "bag" of additional properties to your log events, however, this extension method approach can be overly verbose. For example, to add `TransactionId` and `ResponseJson` properties to your log events, you would have to do something like the following: + +```cs +// WRONG! Prefer the dictionary approach below instead +using (_logger.BeginScope("TransactionId: {TransactionId}, ResponseJson: {ResponseJson}", 12345, jsonString)) { + _logger.LogInformation("Completed in {DurationMs}ms...", 30); +} +// Example JSON output: +// { +// "@t":"2020-10-29T19:05:56.4176816Z", +// "@m":"Completed in 30ms...", +// "@i":"51812baa", +// "DurationMs":30, +// "SourceContext":"SomeNamespace.SomeService", +// "TransactionId": 12345, +// "ResponseJson": "{ \"Key1\": \"Value1\", \"Key2\": \"Value2\" }", +// "Scope":["TransactionId: 12345, ResponseJson: { \"Key1\": \"Value1\", \"Key2\": \"Value2\" }"] +// } +``` + +Not only does this add the unnecessary `Scope` property to your event, but it also duplicates serialized values between `Scope` and the intended properties, as you can see here with `ResponseJson`. If this were "real" JSON like an API response, then a potentially very large block of text would be duplicated within your log event! Moreover, the template string within `BeginScope` is rather arbitrary when all you want to do is add a bag of properties, and you start mixing enriching concerns with formatting concerns. + +A far better alternative is to use the `BeginScope(TState state)` method. If you provide any `IEnumerable>` to this method, then we will output the key/value pairs as structured properties _without_ the `Scope` property, as in this example: + +```cs +var scopeProps = new Dictionary { + { "TransactionId", 12345 }, + { "ResponseJson", jsonString }, +}; +using (_logger.BeginScope(scopeProps) { + _logger.LogInformation("Transaction completed in {DurationMs}ms...", 30); +} +// Example JSON output: +// { +// "@t":"2020-10-29T19:05:56.4176816Z", +// "@m":"Completed in 30ms...", +// "@i":"51812baa", +// "DurationMs":30, +// "SourceContext":"SomeNamespace.SomeService", +// "TransactionId": 12345, +// "ResponseJson": "{ \"Key1\": \"Value1\", \"Key2\": \"Value2\" }" +// } +``` + ### Credits This package evolved from an earlier package _Microsoft.Framework.Logging.Serilog_ [provided by the ASP.NET team](https://github.com/aspnet/Logging/pull/182). From 792e72376e45df312e9a8bc8f9d7a9802af1167f Mon Sep 17 00:00:00 2001 From: Dan Vicarel Date: Mon, 9 Nov 2020 16:51:18 -0500 Subject: [PATCH 2/2] Tweaked some wording in the Log Scope notes, per review --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index de78765..905fc55 100644 --- a/README.md +++ b/README.md @@ -121,7 +121,7 @@ using (_logger.BeginScope("TransactionId: {TransactionId}, ResponseJson: {Respon Not only does this add the unnecessary `Scope` property to your event, but it also duplicates serialized values between `Scope` and the intended properties, as you can see here with `ResponseJson`. If this were "real" JSON like an API response, then a potentially very large block of text would be duplicated within your log event! Moreover, the template string within `BeginScope` is rather arbitrary when all you want to do is add a bag of properties, and you start mixing enriching concerns with formatting concerns. -A far better alternative is to use the `BeginScope(TState state)` method. If you provide any `IEnumerable>` to this method, then we will output the key/value pairs as structured properties _without_ the `Scope` property, as in this example: +A far better alternative is to use the `BeginScope(TState state)` method. If you provide any `IEnumerable>` to this method, then Serilog will output the key/value pairs as structured properties _without_ the `Scope` property, as in this example: ```cs var scopeProps = new Dictionary {