26 Monitoring and troubleshooting errors with logging
This chapter covers
• Understanding the components of a log message
• Writing logs to multiple output locations
• Controlling log verbosity in different environments using filtering
• Using structured logging to make logs searchable
Logging is one of those topics that seems unnecessary, right up until you desperately need it! There’s nothing more frustrating than finding a problem that you can reproduce only in production and then discovering there are no logs to help you debug it.
Logging is the process of recording events or activities in an app, and it often involves writing a record to a console, a file, the Windows Event Log, or some other system. You can record anything in a log message, though there are generally two different types of messages:
• Informational messages—A standard event occurred: a user logged in, a product was placed in a shopping cart, or a new post was created on a blogging app.
• Warnings and errors—An error or unexpected condition occurred: a user had a negative total in the shopping cart, or an exception occurred.
Historically, a common problem with logging in larger applications was that each library and framework would generate logs in a slightly different format, if at all. When an error occurred in your app and you were trying to diagnose it, this inconsistency made it harder to connect the dots in your app to get the full picture and understand the problem.
Luckily, ASP.NET Core includes a new generic logging interface that you can plug into. It’s used throughout the ASP.NET Core framework code itself, as well as by third-party libraries, and you can easily use it to create logs in your own code. With the ASP.NET Core logging framework, you can control the verbosity of logs coming from each part of your code, including the framework and libraries, and you can write the log output to any destination that plugs into the framework.
In this chapter I cover the .NET logging framework ASP.NET Core uses in detail, and I explain how you can use it to record events and diagnose errors in your own apps. In section 26.1 I’ll describe the architecture of the logging framework. You’ll learn how dependency injection (DI) makes it easy for both libraries and apps to create log messages, as well as to write those logs to multiple destinations.
In section 26.2 you’ll learn how to write your own log messages in your apps with the ILogger interface. We’ll break down the anatomy of a typical log record and look at its properties, such as the log level, category, and message.
Writing logs is useful only if you can read them, so in section 26.3 you’ll learn how to add logging providers to your application. Logging providers control where your app writes your log messages, such as to the console, to a file, or even to an external service.
Logging is an important part of any application, but determining how much logging is enough can be a tricky question. On one hand, you want to provide sufficient information to be able to diagnose any problems. On the other hand, you don’t want to fill your logs with data that makes it hard to find the important information when you need it. Even worse, what is sufficient in development might be far too much once you’re running in production.
In section 26.4 I’ll explain how you can filter log messages from various sections of your app, such as the ASP.NET Core infrastructure libraries, so that your logging providers write only the important messages. This lets you keep that balance between extensive logging in development and writing only important logs in production.
In the final section of this chapter I’ll touch on some of the benefits of structured logging, an approach to logging that you can use with some providers for the ASP.NET Core logging framework. Structured logging involves attaching data to log messages as key-value pairs to make it easier to search and query logs. You might attach a unique customer ID to every log message generated by your app, for example. Finding all the log messages associated with a user is much simpler with this approach, compared with recording the customer ID in an inconsistent manner as part of the log message.
We’ll start this chapter by digging into what logging involves and why your future self will thank you for using logging effectively in your application. Then we’ll look at the pieces of the ASP.NET Core logging framework you’ll use directly in your apps and how they fit together.
26.1 Using logging effectively in a production app
Imagine you’ve just deployed a new app to production when a customer calls saying that they’re getting an error message using your app. How would you identify what caused the problem? You could ask the customer what steps they were taking and potentially try to re-create the error yourself, but if that doesn’t work, you’re left trawling through the code, trying to spot errors with nothing else to go on.
Logging can provide the extra context you need to quickly diagnose a problem. Arguably, the most important logs capture the details about the error itself, but the events that led to the error can be equally useful in diagnosing the cause of an error.
There are many reasons for adding logging to an application, but typically, the reasons fall into one of three categories:
• Logging for auditing or analytics reasons, to trace when events have occurred
• Logging errors
• Logging nonerror events to provide a breadcrumb trail of events when an error does occur
The first of these reasons is simple. You may be required to keep a record of every time a user logs in, for example, or you may want to keep track of how many times a particular API method is called. Logging is an easy way to record the behavior of your app by writing a message to the log every time an interesting event occurs.
I find the second reason for logging to be the most common. When an app is working perfectly, logs often go completely untouched. It’s when there’s a problem and a customer comes calling that logs become invaluable. A good set of logs can help you understand the conditions in your app that caused an error, including the context of the error itself, but also the context in previous requests.
TIP Even with extensive logging in place, you may not realize you have a problem in your app unless you look through your logs regularly. For any medium-size to large app, this becomes impractical, so monitoring services such as Sentry (https://sentry.io) can be invaluable for notifying you of problems quickly.
If this sounds like a lot of work, you’re in luck. ASP.NET Core does a ton of the “breadcrumb logging” for you so that you can focus on creating high-quality log messages that provide the most value when diagnosing problems.
26.1.1 Highlighting problems using custom log messages
ASP.NET Core uses logging throughout its libraries. Depending on how you configure your app, you’ll have access to the details of each request and EF Core query, even without adding logging messages to your own code. In figure 26.1 you can see the log messages created when you view a single recipe in the recipe application.
Figure 26.1 The ASP.NET Core Framework libraries use logging throughout. A single request generates multiple log messages that describe the flow of the request through your application.
This gives you a lot of useful information. You can see which URL was requested, the Razor Page and page handler that were invoked (for a Razor Pages app), the Entity Framework Core (EF Core )database command, the action result executed, and the response. This information can be invaluable when you’re trying to isolate a problem, whether it’s a bug in a production app or a feature in development when you’re working locally.
This infrastructure logging can be useful, but log messages that you create yourself can have even greater value. For example, you may be able to spot the cause of the error from the log messages in figure 26.1; we’re attempting to view a recipe with an unknown RecipeId of 5, but it’s far from obvious. If you explicitly add a log message to your app when this happens, as in figure 26.2, the problem is much more apparent.
Figure 26.2 You can write your own logs. These are often more useful for identifying problems and interesting events in your apps.
This custom log message easily stands out and clearly states both the problem (the recipe with the requested ID doesn’t exist) and the parameters/variables that led to it (the ID value of 5). Adding similar log messages to your own applications will make it easier for you to diagnose problems, track important events, and generally know what your app is doing.
I hope you’re now motivated to add logging to your apps, so we’ll dig into the details of what that involves. In section 26.1.2 you’ll see how to create a log message and how to define where the log messages are written. We’ll look in detail at these two aspects in sections 26.2 and 26.3; first, though, we’ll look at where they fit in terms of the ASP.NET Core logging framework as a whole.
26.1.2 The ASP.NET Core logging abstractions
The ASP.NET Core logging framework consists of several abstractions (interfaces, implementations, and helper classes), the most important of which are shown in figure 26.3:
• ILogger—This is the interface you’ll interact with in your code. It has a Log() method, which is used to write a log message.
• ILoggerProvider—This is used to create a custom instance of an ILogger, depending on the provider. A console ILoggerProvider would create an ILogger that writes to the console, whereas a file ILoggerProvider would create an ILogger that writes to a file.
• ILoggerFactory—This is the glue between the ILoggerProvider instances and the ILogger you use in your code. You register ILoggerProvider instances with an ILoggerFactory and call CreateLogger() on the ILoggerFactory when you need an ILogger. The factory creates an ILogger that wraps each of the providers, so when you call the Log() method, the log is written to every provider.
Figure 26.3 The components of the ASP.NET Core logging framework. You register logging providers with an ILoggerFactory, which creates implementations of ILogger. You write logs to the ILogger, which delegates to the ILogger implementations that write logs to the console or a file. You can send logs to multiple locations with this design without having to configure the locations when you create a log message.
The design in figure 26.3 makes it easy to add or change where your application writes the log messages without having to change your application code. The following listing shows all the code required to add an ILoggerProvider that writes logs to the console.
Listing 26.1 Adding a console log provider in Program.cs
WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
builder.Logging.AddConsole() ❶
WebApplication app = builder.Build();
app.MapGet("/", () => "Hello World!");
app.Run();❶ Adds a new provider using the Logging property on WebApplicationBuilder
NOTE The console logger is added by default by WebApplicationBuilder, as you’ll see in section 26.3.
Other than this configuration on WebApplicationBuilder, you don’t interact with ILoggerProvider instances directly. Instead, you write logs using an instance of ILogger, as you’ll see in the next section.
26.2 Adding log messages to your application
In this section we’ll look in detail at how to create log messages in your own application. You’ll learn how to create an instance of ILogger, and how to use it to add logging to an existing application. Finally, we’ll look at the properties that make up a logging record, what they mean, and what you can use them for.
Logging, like almost everything in ASP.NET Core, is available through DI. To add logging to your own services, you need only inject an instance of ILogger
NOTE When you inject ILogger
You can use the injected ILogger instance to create log messages, which it writes to each configured ILoggerProvider. The following listing shows how to inject an ILogger<> instance into the PageModel of the Index.cshtml Razor Page for the recipe application from previous chapters and how to write a log message indicating how many recipes were found.
Listing 26.2 Injecting ILogger into a class and writing a log message
public class IndexModel : PageModel
{
private readonly RecipeService _service;
private readonly ILogger<IndexModel> _log; #A
public ICollection<RecipeSummaryViewModel> Recipes { get; set; }
public IndexModel(
RecipeService service,
ILogger<IndexModel> log) #A
{
_service = service;
_log = log; #A
}
public void OnGet()
{
Recipes = _service.GetRecipes();
_log.LogInformation( #B
"Loaded {RecipeCount} recipes", Recipes.Count); #B
}
}❶ Injects the generic ILogger
❷ Writes an Information-level log. The RecipeCount variable is substituted in the message.
In this example you’re using one of the many extension methods on ILogger to create the log message, LogInformation(). There are many extension methods on ILogger that let you easily specify a LogLevel for the message.
DEFINITION The log level of a log is how important it is and is defined by the LogLevel enum. Every log message has a log level.
You can also see that the message you pass to the LogInformation method has a placeholder indicated by braces, {RecipeCount}, and you pass an additional parameter, Recipes.Count, to the logger. The logger replaces the placeholder with the parameter at runtime. Placeholders are matched with parameters by position, so if you include two placeholders, for example, the second placeholder is matched with the second parameter.
TIP You could have used normal string interpolation to create the log message, as in $"Loaded {Recipes.Count} recipes". But I recommend always using placeholders, as they provide additional information for the logger that can be used for structured logging, as you’ll see in section 26.5.
When the OnGet page handler in the IndexModel executes, ILogger writes a message to any configured logging providers. The exact format of the log message varies from provider to provider, but figure 26.4 shows how the console provider displays the log message from listing 26.2.
Figure 26.4 An example log message as it’s written to the default console provider. The log-level category provides information about how important the message is and where it was generated. The EventId provides a way to identify similar log messages.
The exact presentation of the message will vary depending on where the log is written, but each log record includes up to six common elements:
• Log level—The log level of the log is how important it is and is defined by the LogLevel enum.
• Event category—The category may be any string value, but it’s typically set to the name of the class creating the log. For ILogger
• Message—This is the content of the log message. It can be a static string, or it can contain placeholders for variables, as shown in listing 26.2. Placeholders are indicated by braces, {} and are replaced by the provided parameter values.
• Parameters—If the message contains placeholders, they’re associated with the provided parameters. For the example in listing 26.2, the value of Recipes.Count is assigned to the placeholder called RecipeCount. Some loggers can extract these values and expose them in your logs, as you’ll see in section 26.5.
• Exception—If an exception occurs, you can pass the exception object to the logging function along with the message and other parameters. The logger records the exception in addition to the message itself.
• EventId—This is an optional integer identifier for the error, which can be used to quickly find all similar logs in a series of log messages. You might use an EventId of 1000 when a user attempts to load a non-existent recipe and an EventId of 1001 when a user attempts to access a recipe they don’t have permission to access. If you don’t provide an EventId, the value 0 is used.
High-performance logging with source generators
Source generators are a compiler feature introduced in C# 9. Using this feature, you can automatically generate boilerplate code when your project compiles. .NET 7 includes several built-in source generators, such as the Regex generator I described in chapter 14. There’s also a source generator that works with ILogger, which can help you avoid pitfalls such as accidentally using interpolated strings, and makes more advanced and performant logging patterns easy to use.To use the logging source generator in the OnGet handler from listing 26.2, define a partial method in the IndexModel class, decorate it with a [LoggerMessage] attribute, and invoke the method inside the OnGet handler method:
[LoggerMessage(10, LogLevel.Information, "Loaded {RecipeCount} recipes")]
partial void LogLoadedRecipes(int recipeCount);
public void OnGet()
{
Recipes = _service.GetRecipes();
LogLoadedRecipes(Recipes.Count);
}The [LoggerMessage] attribute defines the event ID, log level, and message the log message uses, and the parameters of the partial method it decorates are substituted into the message at runtime. This pattern also comes with several analyzers to make sure you use it correctly in your code while optimizing the generated code behind the scenes to prevent allocations where possible.
The logging source generator is optional, so it’s up to you whether to use it. You can read more about the source generator, the extra configuration options, and how it works on my blog at http://mng.bz/vn14 and in the documentation at http://mng.bz/4D1j.
Not every log message will have all the possible elements. You won’t always have an Exception or parameters, for example, and it’s common to omit the EventId. There are various overloads to the logging methods that take these elements as additional method parameters. Besides these optional elements, each message has, at very least, a level, category, and message. These are the key features of the log, so we’ll look at each in turn.
26.2.1 Log level: How important is the log message?
Whenever you create a log using ILogger, you must specify the log level. This indicates how serious or important the log message is, and it’s an important factor when it comes to filtering which logs are written by a provider, as well as finding the important log messages after the fact.
You might create an Information level log when a user starts to edit a recipe. This is useful for tracing the application’s flow and behavior, but it’s not important, because everything is normal. But if an exception is thrown when the user attempts to save the recipe, you might create a Warning or Error level log.
The log level is typically set by using one of several extension methods on the ILogger interface, as shown in listing 26.3. This example creates an Information level log when the View method executes and a Warning level error if the requested recipe isn’t found.
Listing 26.3 Specifying the log level using extension methods on ILogger
private readonly ILogger _log; #A
public async IActionResult OnGet(int id)
{
_log.LogInformation( #B
"Loading recipe with id {RecipeId}", id); #B
Recipe = _service.GetRecipeDetail(id);
if (Recipe is null)
{
_log.LogWarning( #C
"Could not find recipe with id {RecipeId}", id); #C
return NotFound();
}
return Page();
}❶ An ILogger instance is injected into the Razor Page using constructor injection.
❷ Writes an Information level log message
❸ Writes a Warning level log message
The LogInformation and LogWarning extension methods create log messages with a log level of Information and Warning, respectively. There are six log levels to choose among, ordered here from most to least serious:
• Critical—For disastrous failures that may leave the app unable to function correctly, such as out-of-memory exceptions or if the hard drive is out of disk space or the server is on fire.
• Error—For errors and exceptions that you can’t handle gracefully, such as exceptions thrown when saving an edited entity in EF Core. The operation failed, but the app can continue to function for other requests and users.
• Warning—For when an unexpected or error condition arises that you can work around. You might log a Warning for handled exceptions or when an entity isn’t found, as in listing 26.3.
• Information—For tracking normal application flow, such as logging when a user signs in or when they view a specific page in your app. Typically these log messages provide context when you need to understand the steps leading up to an error message.
• Debug—For tracking detailed information that’s particularly useful during development. Generally, this level has only short-term usefulness.
• Trace—For tracking extremely detailed information, which may contain sensitive information like passwords or keys. It’s rarely used and not used at all by the framework libraries.
Think of these log levels in terms of a pyramid, as shown in figure 26.5. As you progress down the log levels, the importance of the messages goes down, but the frequency goes up. Typically, you’ll find many Debug level log messages in your application, but (I hope) few Critical- or Error-level messages.
Figure 26.5 The pyramid of log levels. Logs with a level near the base of the pyramid are used more frequently but are less important. Logs with a level near the top should be rare but are important.
This pyramid shape will become more meaningful when we look at filtering in section 26.4. When an app is in production, you typically don’t want to record all the Debug-level messages generated by your application. The sheer volume of messages would be overwhelming to sort through and could end up filling your disk with messages that say “Everything’s OK!” Additionally, Trace messages shouldn’t be enabled in production, as they may leak sensitive data. By filtering out the lower log levels, you can ensure that you generate a sane number of logs in production but have access to all the log levels in development.
In general, higher-level logs are more important than lower-level logs, so a Warning log is more important than an Information log, but there’s another aspect to consider. Where the log came from, or who created the log, is a key piece of information that’s recorded with each log message and is called the category.
26.2.2 Log category: Which component created the log
As well as a log level, every log message also has a category. You set the log level independently for every log message, but the category is set when you create the ILogger instance. Like log levels, the category is particularly useful for filtering, as you’ll see in section 26.4. It’s written to every log message, as shown in figure 26.6.
Figure 26.6 Every log message has an associated category, which is typically the class name of the component creating the log. The default console logging provider outputs the log category for every log.
The category is a string, so you can set it to anything, but the convention is to set it to the fully qualified name of the type that’s using ILogger. In section 26.2 I achieved this by injecting ILogger
Alternatively, you can inject ILoggerFactory into your methods and pass an explicit category when creating an ILogger instance, as shown in the following listing. This lets you change the category to an arbitrary string.
Listing 26.4 Injecting ILoggerFactory to use a custom category
public class RecipeService
{
private readonly ILogger _log;
public RecipeService(ILoggerFactory factory) #A
{
_log = factory.CreateLogger("RecipeApp.RecipeService"); #B
}
}❶ Injects an ILoggerFactory instead of an ILogger directly
❷ Passes a category as a string when calling CreateLogger
There is also an overload of CreateLogger() with a generic parameter that uses the provided class to set the category. If the RecipeService in listing 26.4 were in the RecipeApp namespace, the CreateLogger call could be written equivalently as
_log = factory.CreateLogger<RecipeService>();Similarly, the final ILogger instance created by this call would be the same as if you’d directly injected ILogger
TIP Unless you’re using heavily customized categories for some reason, favor injecting ILogger
The final compulsory part of every log entry is fairly obvious: the log message. At the simplest level, this can be any string, but it’s worth thinking carefully about what information would be useful to record—anything that will help you diagnose problems later on.
26.2.3 Formatting messages and capturing parameter values
Whenever you create a log entry, you must provide a message. This can be any string you like, but as you saw in listing 26.2, you can also include placeholders indicated by braces, {}, in the message string:
_log.LogInformation("Loaded {RecipeCount} recipes", Recipes.Count);Including a placeholder and a parameter value in your log message effectively creates a key-value pair, which some logging providers can store as additional information associated with the log. The previous log message would assign the value of Recipes.Count to a key, RecipeCount, and the log message itself is generated by replacing the placeholder with the parameter value, to give the following (where Recipes.Count=3):
"Loaded 3 recipes"You can include multiple placeholders in a log message, and they’re associated with the additional parameters passed to the log method. The order of the placeholders in the format string must match the order of the parameters you provide.
WARNING You must pass at least as many parameters to the log method as there are placeholders in the message. If you don’t pass enough parameters, you’ll get an exception at runtime.
For example, the log message
_log.LogInformation("User {UserId} loaded recipe {RecipeId}", 123, 456)would create the parameters UserId=123 and RecipeId=456. Structured logging providers could store these values, in addition to the formatted log message "User 123 loaded recipe 456". This makes it easier to search the logs for a particular UserId or RecipeId.
DEFINITION Structured or semantic logging attaches additional structure to log messages to make them more easily searchable and filterable. Rather than storing only text, it stores additional contextual information, typically as key-value pairs. JavaScript Object Notation (JSON) is a common format used for structured log messages.
Not all logging providers use semantic logging. The default console logging provider format doesn’t, for example; the message is formatted to replace the placeholders, but there’s no way of searching the console by key-value.
TIP You can enable JSON output for the console provider by calling WebApplicationBuilder.Logging.AddJsonConsole(). You can further customize the format of the provider, as described in the documentation at http://mng.bz/QP8v.
Even if you’re not using structured logging initially, I recommend writing your log messages as though you are, with explicit placeholders and parameters. That way, if you decide to add a structured logging provider later, you’ll immediately see the benefits. Additionally, I find that thinking about the parameters that you can log in this way prompts you to record more parameter values instead of only a log message. There’s nothing more frustrating than seeing a message like "Cannot insert record due to duplicate key" but not having the key value logged!
TIP Generally speaking, I’m a fan of C#’s interpolated strings, but don’t use them for your log messages when a placeholder and parameter would also make sense. Using placeholders instead of interpolated strings gives you the same output message but also creates key-value pairs that can be searched later.
We’ve looked a lot at how you can create log messages in your app, but we haven’t focused on where those logs are written. In the next section we’ll look at the built-in ASP.NET Core logging providers, how they’re configured, and how you can add a third-party provider.
26.3 Controlling where logs are written using logging providers
In this section you’ll learn how to control where your log messages are written by adding ILoggerProviders to your application. As an example, you’ll see how to add a simple file logger provider that writes your log messages to a file, in addition to the existing console logger provider.
Up to this point, we’ve been writing all our log messages to the console. If you’ve run any ASP.NET Core sample apps locally, you’ll probably have seen the log messages written to the console window.
NOTE If you’re using Visual Studio and debugging by using the Internet Information Services (IIS) Express option, you won’t see the console window (though the log messages are written to the Debug Output window instead).
Writing log messages to the console is great when you’re debugging, but it’s not much use for production. No one’s going to be monitoring a console window on a server, and the logs wouldn’t be saved anywhere or be searchable. Clearly, you’ll need to write your production logs somewhere else.
As you saw in section 26.1, logging providers control the destination of your log messages in ASP.NET Core. They take the messages you create using the ILogger interface and write them to an output location, which varies depending on the provider.
NOTE This name always gets to me: the log provider effectively consumes the log messages you create and outputs them to a destination. You can probably see the origin of the name from figure 26.3, but I still find it somewhat counterintuitive.
Microsoft has written several first-party log providers for ASP.NET Core that are available out of the box in ASP.NET Core. These providers include
• Console provider—Writes messages to the console, as you’ve already seen
• Debug provider—Writes messages to the debug window when you’re debugging an app in Visual Studio or Visual Studio Code, for example
• EventLog provider—Writes messages to the Windows Event Log and outputs log messages only when running in Windows, as it requires Windows-specific APIs
• EventSource provider—Writes messages using Event Tracing for Windows (ETW) or LTTng tracing on Linux
There are also many third-party logging provider implementations, such as an Azure App Service provider, an elmah.io provider, and an Elasticsearch provider. On top of that, there are integrations with other existing logging frameworks like NLog and Serilog. It’s always worth looking to see whether your favorite .NET logging library or service has a provider for ASP.NET Core, as most do.
TIP Serilog (https://serilog.net) is my go-to logging framework. It’s a mature framework with a huge number of supported destinations for writing logs. See Serilog’s ASP.NET Core integration repository for details on how to use Serilog with ASP.NET Core apps: https://github.com/serilog/serilog-aspnetcore.
You configure the logging providers for your app in Program.cs. WebApplicationBuilder configures the console and debug providers for your application automatically, but it’s likely that you’ll want to change or add to these.
In this section I show how to add a simple third-party logging provider that writes to a rolling file so our application writes logs to a new file each day. We’ll continue to log using the console and debug providers as well, because they’re more useful than the file provider when developing locally.
To add a third-party logging provider in ASP.NET Core, follow these steps:
-
Add the logging provider NuGet package to the solution. I’m going to be using a provider called NetEscapades.Extensions.Logging.RollingFile, which is available on NuGet and GitHub. You can add it to your solution using the NuGet Package Manager in Visual Studio or using the .NET command-line interface (CLI) by running
dotnet add package NetEscapades.Extensions.Logging.RollingFilefrom your application’s project folder.
-
Add the logging provider to WebApplicationBuilder.Logging. You can add the file provider by calling AddFile(), as shown in the next listing. AddFile() is an extension method provided by the logging provider package to simplify adding the provider to your app.
NOTE This package is a simple file logging provider, available at http://mng.bz/XN5a. It’s based on the Azure App Service logging provider. If you need a more robust package, consider using Serilog’s file providers instead.
Listing 26.5 Adding a third-party logging provider to WebApplicationBuilder
WebApplicationBuilder builder = WebApplication.CreateBuilder(args); ❶
builder.Logging.AddFile(); ❷
WebApplication app = builder.Build();
app.MapGet("/", () => "Hello world!");
app.Run();❶ The WebApplicationBuilder configures the console and debug providers as normal.
❷ Adds the new file logging provider to the logger factory
NOTE Adding a new provider doesn’t replace existing providers. WebApplicationBuilder automatically adds the console and debug logging providers in listing 26.5. To remove them, call builder.Logging.ClearProviders() before adding the file provider.
With the file logging provider configured, you can run the application and generate logs. Every time your application writes a log using an ILogger instance, ILogger writes the message to all configured providers, as shown in figure 26.7. The console messages are conveniently available, but you also have a persistent record of the logs stored in a file.
Figure 26.7 Logging a message with ILogger writes the log using all the configured providers. This lets you, for example, log a convenient message to the console while also persisting the logs to a file.
TIP By default, the rolling file provider writes logs to a subdirectory of your application. You can specify additional options such as filenames and file size limits using overloads of AddFile(). For production, I recommend using a more established logging provider, such as Serilog.
The key takeaway from listing 26.5 is that the provider system makes it easy to integrate existing logging frameworks and providers with the ASP.NET Core logging abstractions. Whichever logging provider you choose to use in your application, the principles are the same: add a new logging provider to WebApplicationBuilder.Logging using extension methods like AddConsole(), or AddFile() in this case.
Logging your application messages to a file can be useful in some scenarios, and it’s certainly better than logging to a nonexistent console window in production, but it may still not be the best option.
If you discovered a bug in production and needed to look at the logs quickly to see what happened, for example, you’d need to log on to the remote server, find the log files on disk, and trawl through them to find the problem. If you have multiple web servers, you’d have a mammoth job to fetch all the logs before you could even start to tackle the bug—assuming that you even have remote access to the production servers! Not fun. Add to that the possibility of file permission or drive space problems, and file logging seems less attractive.
Instead, it’s often better to send your logs to a centralized location, separate from your application. Exactly where this location may be is up to you; the key is that each instance of your app sends its logs to the same location, separate from the app itself.
If you’re running your app on Microsoft Azure, you get centralized logging for free because you can collect logs using the Azure App Service provider. Alternatively, you could send your logs to a third-party log aggregator service such as elmah.io (https://elmah.io) or Seq (https://getseq.net). You can find ASP.NET Core logging providers for each of these services on NuGet, so adding them is the same process as adding the file provider you’ve seen already.
Whichever providers you add, once you start running your apps in production, you’ll quickly discover a new problem: the sheer number of log messages your app generates! In the next section you’ll learn how to keep this under control without affecting your local development.
26.4 Changing log verbosity with filtering
In this section you’ll see how to reduce the number of log messages written to the logger providers. You’ll learn how to apply a base level filter, filter out messages from specific namespaces, and use logging provider-specific filters.
If you’ve been playing around with the logging samples, you’ll probably have noticed that you get a lot of log messages, even for a single request like the one in figure 26.2: messages from the Kestrel server and messages from EF Core, not to mention your own custom messages. When you’re debugging locally, having access to all that detailed information is extremely useful, but in production you’ll be so swamped by noise that picking out the important messages will be difficult.
ASP.NET Core includes the ability to filter out log messages before they’re written, based on a combination of three things:
• The log level of the message
• The category of the logger (who created the log)
• The logger provider (where the log will be written)
You can create multiple rules using these properties, and for each log that’s created, the most specific rule is applied to determine whether the log should be written to the output. You could create the following three rules:
• The default minimum log level is Information. If no other rules apply, only logs with a log level of Information or above will be written to providers.
• For categories that start with Microsoft, the minimum log level is Warning. Any logger created in a namespace that starts with Microsoft will write only logs that have a log level of Warning or above. This would filter out the noisy framework messages you saw in figure 26.6.
• For the console provider, the minimum log level is Error. Logs written to the console provider must have a minimum log level of Error. Logs with a lower level won’t be written to the console, though they might be written using other providers.
Typically, the goal with log filtering is to reduce the number of logs written to certain providers or from certain namespaces (based on the log category). Figure 26.8 shows a possible set of filtering rules that apply to the console and file logging providers.
Figure 26.8 Applying filtering rules to a log message to determine whether a log should be written. For each provider, the most specific rule is selected. If the log exceeds the rule’s required minimum level, the provider writes the log; otherwise, it discards it.
In this example, the console logger explicitly restricts logs written in the Microsoft namespace to Warning or above, so the console logger ignores the log message shown. Conversely, the file logger doesn’t have a rule that explicitly restricts the Microsoft namespace, so it uses the configured minimum level of Information and writes the log to the output.
TIP Only a single rule is chosen when deciding whether a log message should be written; rules aren’t combined. In figure 26.8, rule 1 is considered to be more specific than rule 5, so the log is written to the file provider, even though technically, both rules could apply.
You typically define your app’s set of logging rules using the layered configuration approach discussed in chapter 10, because this lets you easily have different rules when running in development and production.
TIP As you saw in chapter 11, you can load configuration settings from multiple sources, like JSON files and environment variables, and can load them conditionally based on the IHostingEnvironment. A common practice is to include logging settings for your production environment in appsettings.json and overrides for your local development environment in appsettings.Development.json.
WebApplicationBuilder automatically loads configuration rules from the "Logging" section of the IConfiguration object. This happens automatically, and you rarely need to customize it, but listing 26.6 shows how you could also add configuration rules from the "LoggingRules" section using AddConfiguration().
NOTE WebApplicationBuilder always adds the configuration to load from the "Logging" section; you can’t remove this. For this reason, it’s rarely worth adding configuration yourself; instead, use the default "Logging" configuration section where possible.
Listing 26.6 Loading logging configuration using AddConfiguration()
WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
builder.Logging.AddConfiguration(
builder.Configuration.GetSection("LoggingRules")); ❶
var app = builder.Build();
app.MapGet("/", () => "Hello world!");
app.Run();❶ Loads the log filtering configuration from the LoggingRules section
Assuming that you don’t override the configuration section, your appsettings.json will typically contain a "Logging" section, which defines the configuration rules for your app. Listing 26.8 shows how this might look to define all the rules shown in figure 26.8.
Listing 26.7 The log filtering configuration section of appsettings.json
{
"Logging": {
"LogLevel": { #A
"Default": "Debug", #A
"System": "Warning", #A
"Microsoft": "Warning" #A
},
"File": { #B
"LogLevel": { #B
"Default": "Information" #B
}
},
"Console": { #C
"LogLevel": { #C
"Default": "Debug", #C
"Microsoft": "Warning" #C
}
}
}
}❶ Rules to apply if there are no specific rules for a provider
❷ Rules to apply to the File provider
❸ Rules to apply to the Console provider
When creating your logging rules, the important thing to bear in mind is that if you have any provider-specific rules, these will take precedence over the category-based rules defined in the "LogLevel" section. Therefore, for the configuration defined in listing 26.7, if your app uses only the file or console logging providers, the rules in the "LogLevel" section will effectively never apply.
If you find this confusing, don’t worry; so do I. Whenever I’m setting up logging, I check the algorithm used to determine which rule applies for a given provider and category, which is as follows:
- Select all rules for the given provider. If no rules apply, select all rules that don’t define a provider (the top "LogLevel" section from listing 26.7).
- From the selected rules, select rules with the longest matching category prefix. If no selected rules match the category prefix, select the "Default" if present.
- If multiple rules are selected, use the last one.
- If no rules are selected, use the global minimum level, "LogLevel:Default" (Debug in listing 26.7).
Each of these steps except the last narrows down the applicable rules for a log message until you’re left with a single rule. You saw this in effect for a "Microsoft" category log in figure 26.8. Figure 26.9 shows the process in more detail.
Figure 26.9 Selecting a rule to apply from the available set for the console provider and an Information level log. Each step reduces the number of rules that apply until you’re left with only one.
WARNING Log filtering rules aren’t merged; a single rule is selected. Including provider-specific rules will override global category-specific rules, so I tend to stick to category-specific rules where possible to make the overall set of rules easier to understand.
With some effective filtering in place, your production logs should be much more manageable, as shown in figure 26.10. Generally, I find it’s best to limit the logs from the ASP.NET Core infrastructure and referenced libraries to Warning or above while keeping logs that my app writes to Debug in development and Information in production.
Figure 26.10 Using filtering to reduce the number of logs written. In this example, category filters have been added to the Microsoft and System namespaces, so only logs of Warning and above are recorded. That increases the proportion of logs that are directly relevant to your application.
This is close to the default configuration used in the ASP.NET Core templates. You may find you need to add additional category-specific filters, depending on which NuGet libraries you use and the categories they write to. The best way to find out is generally to run your app and see whether you get flooded with uninteresting log messages.
TIP Most logging providers listen for configuration changes and update their filters dynamically. That means you should be able to modify your appsettings.json or appsettings.Development.json file and check the effect on the log messages, iterating quickly without restarting your app.
Even with your log verbosity under control, if you stick to the default logging providers like the file or console loggers, you’ll probably regret it in the long run. These log providers work perfectly well, but when it comes to finding specific error messages or analyzing your logs, you’ll have your work cut out for you. In the next section you’ll see how structured logging can help you tackle this problem.
26.5 Structured logging: Creating searchable, useful logs
In this section you’ll learn how structured logging makes working with log messages easier. You’ll learn to attach key-value pairs to log messages and how to store and query for key values using the structured logging provider Seq. Finally, you’ll learn how to use scopes to attach key-value pairs to all log messages within a block.
Let’s imagine you’ve rolled out the recipe application we’ve been working on to production. You’ve added logging to the app so that you can keep track of any errors in your application, and you’re storing the logs in a file.
One day, a customer calls and says they can’t view their recipe. Sure enough, when you look through the log messages, you a see a warning:
warn: RecipeApplication.Pages.Recipes.ViewModel [12]
Could not find recipe with id 3245This piques your interest. Why did this happen? Has it happened before for this customer? Has it happened before for this recipe? Has it happened for other recipes? Does it happen regularly?
How would you go about answering these questions? Given that the logs are stored in a text file, you might start doing basic text searches in your editor of choice, looking for the phrase "Could not find recipe with id". Depending on your notepad-fu skills, you could probably get a fair way in answering your questions, but it would likely be a laborious, error-prone, and painful process.
The limiting factor is that the logs are stored as unstructured text, so text processing is the only option available to you. A better approach is to store the logs in a structured format so that you can easily query the logs, filter them, and create analytics. Structured logs could be stored in any format, but these days they’re typically represented as JSON. A structured version of the same recipe warning log might look something like this:
{
"eventLevel": "Warning",
"category": "RecipeApplication.Pages.Recipes.ViewModel",
"eventId": "12",
"messageTemplate": "Could not find recipe with {recipeId}",
"message": "Could not find recipe with id 3245",
"recipeId": "3245"
}This structured log message contains all the same details as the unstructured version, but in a format that would easily let you search for specific log entries. It makes it simple to filter logs by their EventLevel or to show only those logs relating to a specific recipe ID.
NOTE This is only an example of what a structured log could look like. The format used for the logs will vary depending on the logging provider used and could be anything. The main point is that properties of the log are available as key-value pairs.
Adding structured logging to your app requires a logging provider that can create and store structured logs. Elasticsearch is a popular general search and analytics engine that can be used to store and query your logs. One big advantage of using a central store such as Elasticsearch is the ability to aggregate the logs from all your apps in one place and analyze them together. You can add the Elasticsearch.Extensions.Logging provider to your app in the same way as you added the file sink in section 26.3.
NOTE Elasticsearch is a REST-based search engine that’s often used for aggregating logs. You can find out more at https://www.elastic.co/elasticsearch.
Elasticsearch is a powerful production-scale engine for storing your logs, but setting it up and running it in production isn’t easy. Even after you’ve got it up and running, there’s a somewhat steep learning curve associated with the query syntax. If you’re interested in something more user-friendly for your structured logging needs, Seq (https://getseq.net) is a great option. In the next section I’ll show you how adding Seq as a structured logging provider makes analyzing your logs that much easier.
26.5.1 Adding a structured logging provider to your app
To demonstrate the advantages of structured logging, in this section you’ll configure an app to write logs to Seq. You’ll see that the configuration is essentially identical to unstructured providers, but the possibilities afforded by structured logging make considering it a no-brainer.
Seq is installed on a server or your local machine and collects structured log messages over HTTP, providing a web interface for you to view and analyze your logs. It is currently available as a Windows app or a Linux Docker container. You can install a free version for development, which allows you to experiment with structured logging in general.
TIP You can download Seq from https://getseq.net/Download.
From the point of view of your app, the process for adding the Seq provider should be familiar:
-
Install the Seq logging provider using Visual Studio or the .NET CLI with
dotnet add package Seq.Extensions.Logging -
Add the Seq logging provider in Program.cs. To add the Seq provider call AddSeq():
WebApplicationBuilder builder = WebApplication.CreateBuilder(args); builder.Logging.AddSeq();
That’s all you need to add Seq to your app. This will send logs to the default local URL when you have Seq installed in your local environment. The AddSeq() extension method includes additional overloads to customize Seq when you move to production, but this is all you need to start experimenting locally.
If you haven’t already, install Seq on your development machine (or run the Docker container) and navigate to the Seq app at http://localhost:5341. In a different tab, open your app, and start browsing your app and generating logs. Back in Seq, if you refresh the page, you’ll see a list of logs, something like figure 26.11. Clicking a log expands it and shows you the structured data recorded for the log.
Figure 26.11 The Seq UI. Logs are presented as a list. You can view the structured logging details of individual logs, view analytics for logs in aggregate, and search by log properties.
ASP.NET Core supports structured logging by treating each captured parameter from your message format string as a key-value pair. If you create a log message using the following format string,
_log.LogInformation("Loaded {RecipeCount} recipes", Recipes.Count);the Seq logging provider creates a RecipeCount parameter with a value of Recipes.Count. These parameters are added as properties to each structured log, as you can see in figure 26.11.
Structured logs are generally easier to read than your standard-issue console output, but their real power comes when you need to answer a specific question. Consider the problem from before, where you see this error:
Could not find recipe with id 3245You want to get a feel for how widespread the problem is. The first step would be to identify how many times this error has occurred and to see whether it’s happened to any other recipes. Seq lets you filter your logs, but it also lets you craft SQL queries to analyze your data, so finding the answer to the question takes a matter of seconds, as shown in figure 26.12.
Figure 26.12 Querying logs in Seq. Structured logging makes log analysis like this example easy.
NOTE You don’t need query languages like SQL for simple queries, but they make digging into the data easier. Other structured logging providers may provide query languages other than SQL, but the principle is the same as in this Seq example.
A quick search shows that you’ve recorded the log message with EventId.Id=12 (the EventId of the warning we’re interested in) 13 times, and every time, the offending RecipeId was 3245. This suggests that there may be something wrong with that recipe specifically, which points you in the right direction to find the problem.
More often than not, figuring out errors in production involves logging detective work like this to isolate where the problem occurred. Structured logging makes this process significantly easier, so it’s well worth considering, whether you choose Seq, Elasticsearch, or a different provider.
I’ve already described how you can add structured properties to your log messages using variables and parameters from the message. But as you can see in figure 26.11, there are far more properties visible than exist in the message alone.
Scopes provide a way to add arbitrary data to your log messages. They’re available in some unstructured logging providers, but they shine when used with structured logging providers. In the final section of this chapter I’ll demonstrate how you can use them to add data to your log messages.
26.5.2 Using scopes to add properties to your logs
You’ll often find in your apps that you have a group of operations that all use the same data, which would be useful to attach to logs. For example, you might have a series of database operations that all use the same transaction ID, or you might be performing multiple operations with the same user ID or recipe ID. Logging scopes provide a way of associating the same data to every log message in such a group.
DEFINITION Logging scopes are used to group multiple operations by adding relevant data to multiple log message.
Logging scopes in ASP.NET Core are created by calling ILogger.BeginScope
Listing 26.8 Adding scope properties to log messages with BeginScope
_logger.LogInformation("No, I don't have scope"); #A
using(_logger.BeginScope("Scope value")) #B
using(_logger.BeginScope(new Dictionary<string, object> #C
{{ "CustomValue1", 12345 } })) #C
{
_logger.LogInformation("Yes, I have the scope!"); #D
}
_logger.LogInformation("No, I lost it again"); #A❶ Log messages written outside the scope block don’t include the scope state.
❷ Calling BeginScope starts a scope block, with a scope state of “Scope value”.
❸ You can pass anything as the state for a scope.
❹ Log messages written inside the scope block include the scope state.
The scope state can be any object at all: an int, a string, or a Dictionary, for example. It’s up to each logging provider implementation to decide how to handle the state you provide in the BeginScope call, but typically, it is serialized using ToString().
TIP The most common use for scopes I’ve found is to attach additional key-value pairs to logs. To achieve this behavior in Seq, you need to pass Dictionary<string, object> as the state object. Nicholas Blumhardt, the creator of Serilog and Seq, has examples and the reasoning for this on his blog in the “The semantics of ILogger.BeginScope()” article: http://mng.bz/GxDD.
When the log messages inside the scope block are written, the scope state is captured and written as part of the log, as shown in figure 26.13. The Dictionary<> of key-value pairs is added directly to the log message (CustomValue1), and the remaining state values are added to the Scope property. You will likely find the dictionary approach the more useful of the two, as the added properties are more easily filtered on, as you saw in figure 26.12.
Figure 26.13 Adding properties to logs using scopes. Any scope state that is added using the dictionary approach is added as structured logging properties, but other state is added to the Scope property. Adding properties makes it easier to associate related logs with one another.
That brings us to the end of this chapter on logging. Whether you use the built-in logging providers or opt to use a third-party provider like Serilog or NLog, ASP.NET Core makes it easy to get detailed logs not only for your app code, but also for the libraries that make up your app’s infrastructure, like Kestrel and EF Core. Whichever you choose, I encourage you to add more logs than you think you’ll need; you’ll thank me when it comes time to track down a problem.
In the next chapter we’re going to be looking at your ASP.NET Core application from a different point of view. Instead of focusing on the code and logic behind your app, we’re going to look at how you prepare an app for production. You’ll see how to specify the URLs your application uses and how to publish an app so that it can be hosted in IIS. Finally, you’ll learn about the bundling and minification of client-side assets, why you should care, and how to use BundlerMinifier in ASP.NET Core.
26.6 Summary
Logging is critical for quickly diagnosing errors in production apps. You should always configure logging for your application so that logs are written to a durable location such as a filesystem or other service, not just to the console, where they will be lost if the window closes or the server restarts.
You can add logging to your own services by injecting ILogger
The log level of a message indicates how important it is and ranges from Trace to Critical. Typically, you’ll create many low-importance log messages and a few high-importance log messages.
You specify the log level of a log by using the appropriate extension method of ILogger to create your log. To write an Information level log, use ILogger.LogInformation(message).
The log category indicates which component created the log. It is typically set to the fully qualified name of the class creating the log, but you can set it to any string if you wish. ILogger
You can format messages with placeholder values, similar to the string.Format method, but with meaningful names for the parameters. Calling logger.LogInfo("Loading Recipe with id {RecipeId}", 1234) would create a log reading "Loading Recipe with id 1234", but it would also capture the value RecipeId=1234. This structured logging makes analyzing log messages much easier.
ASP.NET Core includes many logging providers out of the box, including the console, debug, EventLog, and EventSource providers. Alternatively, you can add third-party logging providers.
You can configure multiple ILoggerProvider instances in ASP.NET Core, which define where logs are output. WebApplicationBuilder adds the console and debug providers, and you can add providers using the Logging property.
You can control logging output verbosity using configuration. WebApplicationBuilder uses the "Logging" configuration section to control output verbosity. You typically filter out more logs in production than when developing your application.
Only a single log filtering rule is selected for each logging provider when determining whether to output a log message. The most specific rule is selected based on the logging provider and the category of the log message.
Structured logging involves recording logs so that they can be easily queried and filtered, instead of the default unstructured format that’s output to the console. This makes analyzing logs, searching for problems, and identifying patterns easier.
You can add properties to a structured log by using scope blocks. A scope block is created by calling ILogger.BeginScope