Skip to content

Added notes about Log Scope usage to README #182

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Jan 8, 2021
Merged
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
63 changes: 63 additions & 0 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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>(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>(TState state)` method. If you provide any `IEnumerable<KeyValuePair<string, object>>` 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<string, object> {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Did you try

var scopeProps = new { TransactionId = 12345, ResponseJson = jsonString };

?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ooh no I did not, good idea. Unfortunately, looks like anonymous types still generate a Scope property:

... Scope=["{ TransactionId = 12345, ResponseJson = "{\"Key1\":\"Value1\", \"Key2\":\"Value2\"}" }"]

{ "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).