While working on another post about implementing your own custom ILogger implementation, I came across a method on the ILogger interface that I had never actually used before. It looks something like _logger.BeginScope(“Message Here”); , Or correction, it didn’t just take a string, it could take any type and use this for a “scope”. It intrigued me, so I got playing.
The Basics Of Scopes In ILogger
I’m not really sure on the use of “scope” as Microsoft has used it here. Scope when talking about logging seems to imply either the logging level, or more likely which classes can use a particular logger. But scope as Microsoft has defined it in ILogger is actually to do with adding extra messaging onto a log entry. It’s somewhat metadata-ish, but it tends to lend itself more like a stacktrace from within a single method.
To turn on scopes, first you need to actually be using a logger that implements them – not all do. And secondly you need to know if that particular logger has a setting to then turn them on if they are not already on by default. I know popular loggers like NLog and Serilog do use scopes, but for now we are just going to use the Console logger provided by Microsoft. To turn it on, when configuring our logger we just use the “IncludeScopes” flag.
loggerFactory.AddConsole(includeScopes: true);
First I’ll give a bit of code to look at as it’s probably easier than me rambling on trying to explain.
[HttpGet]
public IActionResult Get()
{
using (_logger.BeginScope("Within the first loop"))
{
for(int i=0; i < 10; i++)
{
//Do something potentially bad here that could cause logs.
using (_logger.BeginScope("Within the second loop"))
{
for(int j=0; j < 10; j++)
{
_logger.LogError("Let's log an error message");
}
}
}
}
return new StatusCodeResult((int)HttpStatusCode.OK);
}
Now when we run this, we end up with a log like so :
=> RequestId:0HLCSQKHT9VQN:00000001 RequestPath:/api/values => RequestId:0HLCSQKHT9VQN:00000001 RequestPath:/api/values => CustomLoggerExample.Controllers.ValuesController.Get (CustomLoggerExample) => CustomLoggerExample.Controllers.ValuesController.Get (CustomLoggerExample) => Within the first loop => Within the first loop => Within the second loop => Within the second loop Let's log an error message
So for this particular logger, what it does is it appends it before the logs. But it’s important to note that the scope messages are stored separately, it just so happens that this loggers only way of reporting is to push it all into text. You can see the actual code for the Console logger by Microsoft here : https://github.com/aspnet/Logging/blob/dev/src/Microsoft.Extensions.Logging.Console/ConsoleLogScope.cs. So we can see it basically appends it in a hierarchical fashion and doesn’t actually turn it into a string message until we actually log a message.
If for example you were using a Logger that wrote to a database, you could have a separate column for scope data rather than just appending it to the log message. Same thing if you were using a logging provider that allowed some sort of metadata field etc.
Note : I know that the scope message is doubled up. This is because of the way the ConsoleLogger holds these messages. It actually holds them as a key value pair of string and object. The way it gets the key is by calling “ToString()” on the message… which basically calls ToString() on a string. It then writes out the Key followed by the Value, hence the doubling up.
So It’s Basically Additional Metadata?
Yes and no. The most important thing about scopes is it’s hierarchy. Every library I’ve looked at that implements scopes implements them in a way that there is a very clear hierarchy to the messages. Plenty of libraries allow you to add additional information with an exception/error message, but through scopes we can determine where the general area of our code got up to and the data around it without having to define private variables to hold this information.
Using Non String Values
The interesting thing is that BeginScope actually accepts any object as a scope, but it’s up to the actual Logger to decide how these logs are written. So for example, if I pass a Dictionary of values to a BeginScope statement, some libraries may just ToString() anything that’s given to them, others may check the type and decide that it’s better represented in a different format.
If we take a look at something like NLog. We can see how they handle scopes here : https://github.com/NLog/NLog.Extensions.Logging/blob/master/src/NLog.Extensions.Logging/Logging/NLogLogger.cs#L269. Or if I take the code and paste it up :
public IDisposable BeginScope<TState>(TState state)
{
if (state == null)
{
throw new ArgumentNullException(nameof(state));
}
if (_options.CaptureMessageProperties && state is IEnumerable<KeyValuePair<string, object>> messageProperties)
{
return ScopeProperties.CreateFromState(state, messageProperties);
}
return NestedDiagnosticsLogicalContext.Push(state);
}
We can see it checks if the state message is a type of IEnumerable<KeyValuePair<string, object>> and then throws it off to another method (Which basically splits open the list and creates a nicer looking message). If it’s anything else (Likely a string), we just push the message as is. There isn’t really any defined way provided by Microsoft on how different types should be handled, it’s purely up to the library author.
How About XYZ Logging Library
Because logging scopes are pretty loosely defined within the ASP.NET Core framework, it pays to always test how scopes are handled within the particular logging library you are using. There is no way for certain to say that scopes are even supported, or that they will be output in a way that makes any sense. It’s also important to look at the library code or documentation, and see if there is any special handling for scope types that you can take advantage of.
