12 Troubleshooting your application
- Understanding the nature of an exception
- Using StatusCodePages middleware to control the display of client error messages
- Implementing logging within a Razor Pages application
By now, you’ve probably written a fair amount of code as you have worked your way through the chapters. Chances are you have encountered an error or two while doing so. Some of these will be compile-time errors your development tool will have caught, so you can fix them as you work. Others will have surfaced only at run time, raising exceptions that result in an error page of some kind being displayed. As you build more complex applications, other types of errors creep in: logical errors. These kinds of errors won’t stop your application from running, but they will result in unpredictable behavior. Coding errors, whether they are simply typos or logical errors, are a fact of a developer’s life.
In this chapter, we will explore the nature of errors in a bit more detail, so that you can understand what you’re dealing with. Ideally, you should code to prevent errors in the first place, but it is the nature of development that bugs will creep in and that forces outside of your control will affect things such as the availability of databases, mail servers, and other external services. We will look at how the application behaves at runtime when an error happens that results in an exception being raised and what opportunities there are to take control over that behavior.
Errors can also originate from the client. We will look at what happens when a client makes a request for a page that doesn’t exist, for example. You will learn how to use middleware—StatusCodePages middleware—to manage how your application responds to this very common event and how to control what the user sees.
Unless your users report back to you, you may never know that an error has taken place. Often, when a user does report a fault, they cannot remember precisely what they were doing, so you spend a lot of time trying to replicate the issue but lack the knowledge required to do so successfully. Ideally, you would like someone to watch over the user’s shoulder who can report every detail of what they were doing when something went wrong. Clearly, that’s not feasible, but the next best thing is including a mechanism to record user actions at the time an error occurred. This mechanism is called logging, and we will explore how it is supported within an ASP.NET Core application. You will learn how to categorize the information the logs capture, so that you can more easily control what is recorded, and we will explore the options for controlling where log output goes.
The default support for logging in ASP.NET Core is limited in terms of where logs are written. In the event you want to output logs to a different medium, you may need to implement your own log provider. This chapter covers the basic steps required to implement a simple provider that writes logs to email. Alternatively, rather than write and maintain your own logging solution, you might prefer to use a tried and trusted solution from a third party. There are plenty available that support ASP.NET Core applications. See http://mng.bz/Qngv for more details. You could use any of the solutions listed in the documentation, but in this book, I will walk you through installing and using one called Serilog.
Logging isn’t just useful for error reporting. It can be used for tracking user behavior and auditing activity as well. The standard output format for most logging systems is an unstructured string. Consequently, anything more than very simple analysis of the output is difficult. Ideally, you want to be able to query logs in the same way you can query the contents of a database. The solution to this problem is structured logging, which is supported by Serilog. Structured logging involves generating logs in a structured data format that enables advanced querying and filtering. In the final section of this chapter, you will learn more about this approach to logging and understand the benefits it brings.
12.1 Exception management
Exceptions are raised when a .NET application encounters an error condition. As a developer, you can choose to attempt to handle exceptions or not. If you don’t handle an exception, your application stops execution of the current operation. What happens by default in a Razor Pages application at that point depends on whether the application is running in Development mode or not. This is determined by examining the application’s IWebHostEnvironment, which we will look at in more detail in the final chapter when we explore environments. If the application is not running in Development mode, the default configuration results in ExceptionHandlerMiddleware intervening and executing the Error.cshtml page included in the initial project. This page is designed to provide no more than a bland message that an error has occurred. If the application is in Development mode, middleware invokes the Developer Exception page, which provides as much detail of the exception as possible.
12.1.1 The Developer Exception page
The purpose of the Developer Exception page is to help the developer to identify, locate, and fix any errors. Commonly, the Developer Exception page includes the exception type, its message, the filename, the line or lines of code where the exception was raised, and its stack trace. It also includes some information about the request, including details about cookies, request headers, the query string, and information about the route that was invoked. You can see this in action by removing the check for null in the CityModel’s OnGetAsync method and then navigating to the page, passing in a nonexistent city name in the URL. Change the OnGetAsync method in City.cshtml.cs to comment out the check for null.
Listing 12.1 Commenting out the null check
public async Task<IActionResult> OnGetAsync()
{
City = await _cityService.GetByNameAsync(Name);
//if (City == null) ❶
//{ ❶
// return NotFound(); ❶
//} ❶
return Page();
}Rebuild the application, and navigate to /city/mikebrind. The Developer Exception page should appear, informing you that an unhandled exception occurred while processing the request (figure 12.1).
Figure 12.1 The Developer Exception page with tabs showing the stack trace and request details, including the query string, cookies, headers, and routing
There is no City named mikebrind, so when the page tries to access a property of the Model.City variable, you get a NullReferenceException because the value returned from the city service, which is assigned to the City property of the PageModel, is null. The error page shows all of this in detail. On the second line, it tells you the type of the exception, followed by the actual exception message. This is repeated in bold at the top of the Stack tab content, followed by the name of the method that was called at the point the exception was raised:
CityBreaks.Pages.Pages_City.ExecuteAsync() in City.cshtml
The ExecuteAsync method belongs to the compiled Razor page. It is called at run time. The following listing shows how the start of it looks for your compiled City page.
Listing 12.2 The ExecuteAsync method for the compiled City page
public override async Task ExecuteAsync()
{
this.WriteLiteral("
");
this.ViewData["Title"] =
➥ string.Concat(this.Model.City.Name, " Details"); ❶
this.WriteLiteral("<h3 b-jbmzjjkv6t>");
this.Write(this.Model.City.Name);
this.WriteLiteral("</h3>
");❶ This line of code caused the exception to be raised.
Note In previous versions of Razor Pages, it is possible to easily see the C# code that is generated from a Razor page by navigating to /obj /Debug /[.Net app version] /Razor/Pages, where you will find a collection of files with a .g.cs extension. Each of these contains the generated source code for the matching Razor page. In .NET 6, the Razor compilation system was changed to support hot reload, and these intermediate files are no longer generated. Tools are available, such as the free JustDecompile from Telerik (https://www.telerik.com/products/decompiler.aspx), that enable you to decompile the generated assembly (.dll file) created by the build process. You can find the assembly in inDebug [.NET app version] .
The string.Concat method in the ExecuteAsync method was generated by the Razor parser from your original interpolated string:
ViewData["Title"] = $"{Model.City.Name} Details";The Developer Exception page is clever enough to work out where in the original source code the exception was raised and points to the offending line of code in City.cshtml, highlighting it in red (figure 12.2).
Figure 12.2 The original source code that generates the exception is indented, displayed in a red color, and has a plus sign to the left.
To make things clearer, you can click the plus sign to the left of the single line of code to show more code. From a developer’s point of view, all this information is pure gold. You know exactly what broke, and you know which line or lines of code you need to focus on to fix it. If you are puzzled by the sometimes-obtuse error messages, you can always copy and paste them into a search engine. You’ll probably find you are not alone in your puzzlement and that lots of developers before you have posted questions in technical communities about the same error and got good answers that can likely help you.
From a user’s point of view, this is not gold at all. It doesn’t help them one bit, unless the source code revealed by clicking the plus icon includes some interesting tidbits, such as a helpline phone number. Chances are that the source code is more likely to include some comments you don’t want the world to see or, perhaps, the credentials for a mail server or database. For this reason, you are advised to use a generic page to report an error condition to the user.
12.1.2 ExceptionHandlerMiddleware
Use the UseExceptionHandler method within the application pipeline configuration to add ExceptionHandlerMiddleware to the application for capturing and displaying details of exceptions. The default template includes this middleware only if the application is not running in Development mode (listing 12.3). The middleware is positioned right at the start of the pipeline, so it can catch all exceptions. The method optionally takes a string representing the path to the page that should be displayed in the event of an unhandled exception occurring. When an exception happens, the middleware catches it, logs it, and reexecutes the request, so the configured error page can be displayed.
Listing 12.3 ExceptionHandlerMiddleware
if (!app.Environment.IsDevelopment()) ❶ { app.UseExceptionHandler("/Error"); ❷ }
❶ The condition checks whether the environment is Development.
❷ If it is not, you include the ExceptionHandlerMiddleware in the pipeline.
The default template configures the custom error page, named Error, which is included in the Pages folder. Given that this page is part of your application, it is easy to customize the content to your liking. If you prefer to use a different page to communicate an error condition to your users, change the value passed into the UseExceptionHandler method in Program.cs:
app.UseExceptionHandler("/Errors/MyCustomErrorPage");The default setup has a built-in flaw. It is automatically assigned a layout page via the _ViewStart file that sits in the same folder. Consequently, if the exception is generated by an error condition within the layout, you will get a potentially recursive situation in which the exception occurs and the framework tries to display the error page, resulting in the exception again. For this reason, one of the first steps I usually take when starting a new application is setting the Layout to null in the error page and ensuring its content is not reliant on anything that could result in another exception being raised.
Listing 12.4 Setting the Layout property to null in the custom error page
@page
@model ErrorModel
@{
Layout = null; ❶
ViewData["Title"] = "Error";
}As might be obvious from its name, the exception-handler middleware only works when an unhandled exception—a server error—occurs within the application, resulting in an HTTP 500 status code. Other kinds of errors can occur while a user is visiting your application. For example, before you commented it out, you called the NotFound method if the city name passed into the City page could not be found in the database. You might recall from chapter 3 when we looked at handler method return types that the NotFound method is a helper result that returns a NotFoundResult. The NotFoundResult returns an HTTP 404 status code, indicating a client error. When client errors occur, ASP.NET Core returns the status code and an empty response body. The browser is left to display some kind of notification to the user (although it is not obliged to). You can take control of what is displayed to the user yourself by adding StatusCodePages middleware to the request pipeline, which you will test out in the next section.
12.2 StatusCodePages
StatusCodePages middleware is designed to enable you to provide a response body in the event of a client error occurring. The default implementation generates a plain text response, but you can produce a custom HTML-based error page and configure the middleware to return the contents of that instead. This enables you to fully control the appearance of the error message, maintain your site branding if so desired, and give the user helpful information on what happened and what they can do next.
Use the UseStatusCodePages extension method (set in bold) to enable StatusCodePages middleware. Ideally this method call should be registered early in the pipeline, before any request handling components:
app.UseHttpsRedirection(); app.UseStatusCodePages(); app.UseStaticFiles();
The primary processing logic within StatusCodePages middleware comes after the await _next(context) call, which, if you remember from chapter 2, happens on the return leg of the pipeline, once the response status code has been set by other middleware—usually the Razor Pages middleware (figure 12.3).
Figure 12.3 StatusCodePages operates on the return journey (the bottom part of the pipeline in the diagram) after the HTTP status code has been set.
The default behavior of StatusCodePages middleware is to return a plain text response when the status code is between 400 and 599 (but not for unhandled exceptions) and the response is empty. For example, having implemented StatusCodePage middleware, if you navigate to /city /mikebrind, the response is very plain, as shown in figure 12.4.
Figure 12.4 The default implementation of StatusCodePages middleware returns a plain text response.
A number of alternative methods exist, enabling you to register StatusCodePages middleware and take control over what is presented to the user. For example, you can pass in a string representing the content type and a body formatted accordingly:
app.UseStatusCodePages("text/html", "<h1>Error!</h1>"); Within a Razor Pages application, you will most likely want to return different content based on the status code, and you will also want to use Razor Pages to generate the HTML, rather than having one HTML message returned for all status codes. There are two methods for registering StatusCodePages middleware that enable this:
Both methods take a format string that indicates where a page for the specific status code is to be found. The difference between them is in how they operate in the event that they are needed. The first method redirects the user to the specified error page, whereas the second reexecutes the request pipeline but changes the actual page being executed to the custom error page.
12.2.1 Exploring WithRedirects
When you use the WithRedirects version, the StatusCodePages middleware intercepts responses that have a status code in the 400-599 range, changes the status code to a 302 Temporarily Moved code, and includes the location of the custom error page within the location header of the response. The browser then makes another request, this time, for the error page, which is presented to the user. The status code for this request is 200 OK. This is illustrated in figure 12.5.
Figure 12.5 The flow of execution when using StatusCodePages middleware with redirects. The initial request for the nonexistent page results in a 404, which is then replaced with a 302 by the middleware. The browser is redirected to the custom error page, which is returned successfully.
You can examine this behavior in your application. First add a new folder to the Pages folder named Errors. Within that, add a new Razor page named 404.cshtml. The content of the Razor page is shown in the following listing.
Listing 12.5 The content for the custom error page
@page
@model CityBreaks.Pages.Errors._404Model
@{
}
<h1>Sorry</h1>
<p>The page you are looking for doesn't exist on this site.
Check the URL and try again. </p>Next register StatusCodePages middleware with redirects in Program.cs. The format string passed into the registration method in listing 12.6 includes a placeholder for the status code. At run time, in the event of an error resulting in a 404 status code, the middleware will redirect to /errors/404 if it exists.
Listing 12.6 Registering StatusCodePages middleware with redirects
app.UseHttpsRedirection();
app.UseStatusCodePagesWithRedirects("/errors/{0}"); ❶
app.UseStaticFiles();❶ The registration method takes a format string representing the HTTP status code.
Now run the application, and ensure you have the browser developer tools open in the Network tab. Then navigate to /city/mikebrind again. You should see the content of your 404 page displayed, and you should see that the request for mikebrind resulted in a 302 followed by a 200, as the error page was returned successfully to the browser (figure 12.6). One other thing to notice is that the URL in the browser address bar has also been changed to that of your custom error page (figure 12.7).
Figure 12.6 The initial request resulted in a 302 followed by a 200.
Figure 12.7 The browser address is changed to the custom error page.
There are a couple problems with this. Your error page suggests that the user checks the URL and tries again. However, the original request URL has been lost (unless they know how to use the developer tools). The second issue concerns search engines. Imagine if someone copies a link to the Paris city page, /city /paris, but omits the last character and pastes the result into something indexed by a search engine: /city/pari. The result of following that link is a 302 followed by a 200. The search engine will continue to index the resource, and users will be directed to the error page.
12.2.2 StatusCodePages WithReExecute
Ideally, you want the search engine to drop listings of any pages that cannot be found. If you are using Google webmaster tools, you can also get a report of requests that result in a 404, which enables you to act on them, such as setting up permanent redirects if they are the result of a typo in a URL, for example. So you need to allow the original 404 status code to reach the user agent. And this is what the second method for registering StatusCodePages middleware supports. Rather than sending a redirect to the user agent, the StatusCodePages middleware intercepts the response with the 404 status code and reexecutes the request using the specified custom error page, while retaining the status code and original request URL (figure 12.8).
Figure 12.8 WithReExecute results in the request being reexecuted within the application using the custom error page, while the status code and original request URL are retained.
To register the reexecute option, use the UseStatusCodePagesWithReExecute method that takes a format string for the path and, optionally, another format string for a query string (shown in bold):
app.UseHttpsRedirection();
app.UseStatusCodePagesWithReExecute("/errors/{0}");
app.UseStaticFiles();Run the application again, and navigate to /city /mikebrind. This time, you can see that the URL is preserved in the browser address bar, and the 404 status code is preserved (figure 12.9).
Figure 12.9 The URL is preserved in the browser along with the 404 status code when using the reexecute method.
You can clearly see the original request URL in the browser address bar in figure 12.9, but sometimes it’s not possible to check the URL in a browser address bar. Browsers on smaller devices, such as cell phones, don’t show the complete URL. To get around this, you might want to display the incorrect URL to the user as part of the error message you provide them, so they can see if there is anything obviously wrong with it. When doing so, you would usually render Request.Path or similar, but the StatusCodePages middleware changes the request to the custom error page, so Request.Path will resolve to /errors/404.
All is not lost, however, because the StatusCodePages middleware adds a feature called IStatusCodeReExecuteFeature to the HttpContext, where details of the original request are retained; you will be able to access that to get the original request URL. The example in the following listing shows how to access this feature to extract the original request path.
Listing 12.7 Accessing the original request path when the request is reexecuted
public class _404Model : PageModel
{
public string RequestUrl { get; set; } ❶
public void OnGet()
{
var feature =
➥ HttpContext.Features.Get<IStatusCodeReExecuteFeature>(); ❷
RequestUrl = feature?.OriginalPath; ❸
}
}❶ Create a public property to store the request URL.
❷ Access the IStatusCodeReExecuteFeature, which the StatusCodePages middleware should have added to the HttpContext.
❸ Assign the OriginalPath property to the RequestUrl.
In addition to the OriginalPath property, you can obtain details of any query string values via the OriginalQueryString property or route values from the RouteValues property. Finally, amend the content of the custom 404 page as follows.
Listing 12.8 The custom error page including the original request URL
<h1>Sorry</h1>
<p>
The page you are looking for:
<span class="fw-bold">@Model.RequestUrl</span>
doesn't exist on this site.
</p>Table 12.1 Redirect compared to reexecute
Table 12.1 recaps the differences between the reexecute and redirect options provided by the StatusCodePages middleware. Going by the summary provided in table 12.1, it should be clear that WithReExecute should be the default choice when implementing StatusCodePages middleware in a Razor Pages application. If the error occurred because the requested resource could not be found, the user can check the original URL they requested in the browser address bar. The status code is preserved, so user agents can act accordingly, updating indexes if necessary.
You now know how to use StatusCodePages middleware or the DeveloperExceptionPage middleware to control the message the user sees when client or server errors occur within the application. However, you won’t know these errors have occurred in the application when it is running live on the web server, unless a user makes the effort to inform you. Ideally, you need to be notified whenever an error has occurred, and you want that notification to include sufficient detail about the error, so you can attempt to identify the cause, locate it, and fix it, if at all possible.
You can satisfy these requirements by implementing application logging, which generates a record of events that take place within the running application. You can then refer to these log records to identify what happened, when it happened, and where it happened.
12.3 Logging
Logging is supported as a first-class citizen within ASP.NET Core. Several logging providers are enabled as part of the preconfigured defaults when the WebApplication .CreateBuilder method call is made in the Program class. A logging provider is responsible for the actual generation and output of log messages. Each one targets one or more different sources. The built-in providers enabled by default are the following:
In addition to these, you can enable your own logging provider. We will explore how to do that later in the chapter when you create a custom logger that gives you immediate notification that something has gone wrong in the application by outputting the log to email. You will learn about structured, or semantic, logging, which gives you rich data about the log and enables useful scenarios like querying and filtering of log messages. We will also look at integrating a third-party logging solution that includes support for ASP.NET Core and structured logging.
12.3.1 Logging basics
If you have been implementing the examples in this book so far, you may already have noticed the console logger at work, either in the console window that opens when you run your application from Visual Studio or the integrated terminal in VS Code. Various parts of the ASP.NET Core and EF Core frameworks are instrumented to output informational logs as a result of normal running of applications. You can see this in figure 12.10, which shows the integrated terminal in VS Code, while the application is running.
Figure 12.10 Logs (on the right) are output to the terminal window in VS Code.
Have a look at the structure of an individual log. It is composed of four elements:
Figure 12.11 The log output comprises a level, category, event ID, and message.
In the next few sections, we will explore each of these elements in more detail.
12.3.2 Log levels
Log levels are used to convey the severity of the event that caused a log to be written. Table 12.2 lists the log levels used by .NET Core logging in order of severity, ranging from least severe to most severe.
The ILogger interface is the primary abstraction for logging within .NET. It has a number of extension methods that determine the level of the log generated. They are nice and predictable in that they take the form Log[Level], so to generate an informational log, you use the LogInformation method.
The next code examples show how to generate logs based on the name of the city passed in to the City page. If it is found in the database, you log an informational message. If not, you log a warning. First, you need to get a reference to the logger. You do that by injecting ILogger<T> into the PageModel constructor.
Listing 12.9 Making loggers available using dependency injection
public class CityModel : PageModel
{
private readonly ICityService _cityService;
private readonly IPropertyService _propertyService;
private readonly ILogger<CityModel> _logger; ❶
public CityModel(ICityService cityService,
IPropertyService propertyService,
ILogger<CityModel> logger) ❷
{
_cityService = cityService;
_propertyService = propertyService;
_logger = logger; ❸
}❶ Add a field for an ILogger<T>.
❷ Inject the ILogger<T> into the constructor.
❸ Assign the parameter to the field.
The Logger<T> takes a generic parameter representing the category of the logger. We will look at categories in more detail soon, but for now, pass in the name of the class that uses the logger.
The next listing shows the amended OnGetAsync method in the CityModel class. In it, you use the logger instance to log a warning if the city passed in the URL is not found and an informational message if it is.
Listing 12.10 The amended OnGetAsync class incorporating logging
public async Task<IActionResult> OnGetAsync()
{
City = await _cityService.GetByNameAsync(Name);
if (City == null)
{
_logger.LogWarning("City "{name}" not found", Name); ❶
return NotFound();
}
_logger.LogInformation("City "{name}"
➥ found", Name); ❷
return Page();
}❶ Log a warning if the city is not found.
❷ Log an informational message if the city is found.
When you run the application normally and click a city on the home page, the log is output to the console with the log level specified at the start (info):
info: CityBreaks.Pages.CityModel[0]
City "amsterdam" foundWhen you try to navigate to /city/mikebrind, the warning is recorded, prefixed with warn:
warn: CityBreaks.Pages.CityModel[0]
City "mikebrind" not foundNow that you have a basic understanding of log levels, we will move on to the next element: the log category.
12.3.3 Log categories
Log categories provide a way to label a log with an arbitrary string, which can be useful when you want to perform some kind of filtering on log entries. As you saw in the previous example, the ILogger<T> takes a parameter, which is used to generate the category. You can pass in any type you want to the T parameter, but the convention is to pass in the name of the consumer. In this example, that’s the CityModel class. Its full name is then used as the category: CityBreaks.Pages.CityModel.
The type you pass in to the Ilogger<T> to generate the category name is constrained to only those types that your application recognizes. That doesn’t fit the label a log with an arbitrary string definition. There is another way to instantiate loggers that allows you to provide any string you like as the category name. You can use IloggerFactory to create instances of loggers instead. Using this approach, you inject IloggerFactory into the consuming class and then use its CreateLogger method to instantiate an instance of Ilogger as needed. The CreateLogger method takes a string to represent the logger category. The following listing shows the relevant amendments to the CityModel in bold. The constructor of the CityModel class is amended to accommodate an Ilogger-Factory, which is assigned to a field. The factory is used within the OnGetAsync method to instantiate an instance of Ilogger for use within that method only, with a suitable category name.
Listing 12.11 Using an IloggerFactory to customize the category name
private readonly IcityService _cityService; private readonly IpropertyService _propertyService; private readonly IloggerFactory _loggerFactory; ❶ public CityModel(IcityService cityService, IpropertyService propertyService, IloggerFactory loggerFactory) ❶ { _cityService = cityService; _propertyService = propertyService; _loggerFactory = loggerFactory; ❶ } [BindProperty(SupportsGet = true)] public string Name { get; set; } public City City { get; set; } public async Task<IactionResult> OnGetAsync() { var logger = _loggerFactory.CreateLogger("City page OnGetAsync"); ❷ City = await _cityService.GetByNameAsync(Name); if (City == null) { logger.LogWarning(404, "City "{name}" not found", Name); return NotFound(); } logger.LogInformation("City "{name}" found", Name); return Page(); }
❶ Inject the ILoggerFactory into the constructor.
❷ Use the CreateLogger method to instantiate a logger with a custom category name.
When you navigate to the City page, the log output differs in view of the fact that your customized category name is used:
info: City Page OnGetAsync[0]
City "amsterdam" foundThis approach can be useful if you want to create logger categories at the method level, for example, but otherwise, you will most likely use an ILogger<T> within your application.
12.3.4 Using EventIds
Event IDs provide another way to filter log messages. For example, you might want to filter all logs that are recorded when a page cannot be found, so if necessary, you can redirect the user (and search engines) to a new permanent address. Accordingly, you might decide to associate warning logs for missing pages with an EventId of 404. In this case, you pass an EventId in as the first parameter to one of the Log* methods. The EventId type is a struct, so you can associate an EventId with a log as follows:
_logger.LogWarning(new EventId(404), "City "{name}" not found", Name);However, there is an implicit conversion between an int and an EventId, so you are more likely to use the following approach:
_logger.LogWarning(404, "City "{name}" not found", Name);Event IDs are not required as part of a log. If you don’t provide a value, the event ID defaults to zero.
12.3.5 Formatting the log message
The string you pass to the various Log* methods is referred to as a template. It can contain placeholders for variable values, which are supplied as a params array argument. Your examples so far include only one parameter, {name}, representing the city name, the value for which is passed in after the template. When constructing a template, you are advised to use named placeholders in this way. This is primarily so you can take advantage of the benefits of structured logging. Some third-party logging libraries are able to store the parameter names and values separately, which makes it easier to query logs for more detailed analysis. This is known as structured, or semantic, logging.
The log message template looks similar to a standard format string, but it does not behave in the same way. Parameter values are inserted into the template according to their position in the parameter array, not according to their name. You must provide at least as many arguments to the parameter array as there are placeholders in the template; otherwise, a runtime exception occurs. This means if you want to repeat a value within the message template, you must include it in the parameter array again, like this:
_logger.LogWarning("{name} searched for. {name} not found", Name, Name); Now that you have a basic understanding of logging within ASP.NET Core, you will look at how to configure logging within your application.
12.3.6 Applying log filter rules
I’ve discussed filtering logs according to their level, category, and so on. Now it’s time to look at ways to specify rules you can apply to filtering logs. The recommended way to specify log-filtering rules is via the application’s main configuration file—appSettings.json—within the Logging section. Take a look at the default template version of the relevant section (listing 12.12).
Listing 12.12 The Logging section in the appSettings.json file
"Logging": {
"LogLevel": { ❶
"Default": "Information", ❷
"Microsoft.AspNetCore": "Warning" ❸
}
}❶ This is the log level property.
❷ The default minimum log level is Information.
❸ The minimum log level for the Microsoft.AspNetCore category is Warning.
The LogLevel property within the Logging section is where you define defaults for all logging providers. In this example, the minimum default log level is set to Information. That means only logs at Information level or above will be generated by all providers in all categories, unless a different rule is specified elsewhere. In the very next line, a different rule is indeed specified for all loggers in the Microsoft.AspNetCore category. This states that any logger that has a category name starting with Microsoft .AspNetCore will only generate logs at the Warning level or above.
You can override the rules specified in the LogLevel section by specifying new rules that apply to individual providers. In the next listing, add a section for the Console provider that results in logs being generated at Debug level and above, except for those in the Microsoft category, where you are only interested in seeing errors or critical events being recorded.
Listing 12.13 Adding a provider-specific filter rule
"Logging": {
"LogLevel": {
"Default": "Information",
"Microsoft.AspNetCore": "Warning"
},
"Console": { ❶
"LogLevel": {
"Default": "Debug", ❷
"Microsoft": "Error" ❸
}
}
}❶ New rules that only apply to the Console logger
❷ The default minimum logging level is set to Debug.
❸ The minimum logging level for categories starting with Microsoft is Error.
The Console section applies only to the console logger. Other loggers—the debug logger and the event source logger, for example—do not have specific rules, so their behavior is governed by the settings in the LogLevel section.
We have looked at working with the default logging implementations, but they are limited in terms of their application. When your website is live, you need to know when a show-stopping error has occurred. You also need details of the error. As discussed previously, you cannot rely on users giving you this information in a timely, accurate manner—if at all. The default logging providers won’t give you immediate notification that an error has occurred (unless you spend your day watching a console window on a server), so you need another provider that does. In the next section, you will learn the steps required to create your own logging provider.
12.3.7 Custom email logger
In this section, you will implement a simple logging provider that writes to email. The primary purpose of this exercise is to gain an understanding of the moving parts involved in implementing your own logging provider. For more robust solutions, you should consider implementing a reputable third-party logging solution. Most of them are capable of supporting multiple targets, including email. We will look at implementing one such solution in the next section.
The component responsible for generating the log output implements the ILogger interface. The contract defined by the interface requires three methods to be implemented:
-
BeginScope—This method enables the grouping of a set of logging operations within a scope and sharing of data between the operations. Your logger won’t support scopes, but we will explore this feature in more detail later.
-
Log—This method takes a number of parameters and is responsible for outputting the log.
-
IsEnabled—This method takes a LogLevel as a parameter and determines whether the logger is enabled for the specified LogLevel.
The email logger implementation takes the IEmailSender used in chapter 9 as a dependency and will use its SendEmailAsync method to generate and send the email. First, create a folder for the logger code files named Logging. This is created in the root of the project. Then add a class file named EmailLogger.cs with the following code.
Listing 12.14 The EmailLogger implementation
using Microsoft.AspNetCore.Identity.UI.Services; ❶ namespace CityBreaks.Logging { public class EmailLogger : ILogger ❷ { private readonly IEmailSender _emailSender; ❸ public EmailLogger(IEmailSender emailSender) ❸ { ❸ _emailSender = emailSender; ❸ } ❸ public IDisposable BeginScope<TState>(TState state) => null; ❹ public bool IsEnabled(LogLevel logLevel) => ❺ ➥ logLevel == LogLevel.Error || logLevel == LogLevel.Critical; ❺ public void Log<TState>(LogLevel logLevel, EventId eventId, ❻ ➥ TState state, Exception exception, Func<TState, ❻ ➥ Exception, string> formatter) ❻ { ❻ if (!IsEnabled(logLevel)) ❻ return; ❻ var htmlMessage = state.ToString() + "<br><br>" + ❻ exception?.Message + "<br><br>" + ❻ exception?.StackTrace; ❻ Task.Run(() => SendLog(htmlMessage)); ❻ } ❻ private async Task SendLog(string htmlMessage) ❼ { ❼ var subject = "Error in application"; ❼ var to = "[email protected]"; ❼ await _emailSender.SendEmailAsync(to, subject, htmlMessage); ❼ } ❼ } }
❶ A using directive is needed to bring the IEmailSender into scope.
❷ Implement the ILogger interface.
❸ Inject an IEmailSender and assign it to a field.
❹ This logger will not support scopes.
❺ If the log level is Error or Critical, this logger is enabled.
❻ Within the Log method, you establish whether the logger is enabled. If not, you return. Otherwise, you construct some HTML from the state and any exception that is passed in.
❼ The SendLog method uses the IEmailSender to send the email.
The Log method takes a number of parameters. The first is the LogLevel of the log. You will use this to determine if the logger is enabled. If it is, you ignore the EventId because you are not interested in it. Instead, you are interested in the state that contains any values passed in to the log, and you are interested in the exception, if there is one. The state can be cast to an IEnumerable<KeyValuePair<string, object>>, with each entry containing the name of a placeholder as its key and an object representing its value. When the framework logs an exception, it adds one entry to the collection, which has a key of {OriginalFormat} and a value of An unhandled exception has occurred while executing the request. You can get this value simply by calling ToString() on the state variable. Then you attempt to reference the message and stack trace of the exception and include those in the email message.
The next component you need to create is an implementation of ILoggerProvider, which is responsible for creating the logger on demand. Add another class file to the Logging folder named EmailLoggerProvider with the code shown in the following listing.
Listing 12.15 The EmailLoggerProvider class
using Microsoft.AspNetCore.Identity.UI.Services;
namespace CityBreaks.Logging
{
public class EmailLoggerProvider : ILoggerProvider
{
private readonly IEmailSender _emailService;
public EmailLoggerProvider(IEmailSender emailService)
{
_emailService = emailService;
}
public ILogger CreateLogger(string categoryName)
{
return new EmailLogger(emailService);
}
public void Dispose() { }
}
}The ILoggerProvider interface defines one method: CreateLogger. This method is responsible for instantiating an instance of the logger. Your logger takes a dependency on the IEmailSender, so you inject that and assign it to a field. The ILoggerProvider implements IDisposable, so you also need to include a Dispose method, although it does nothing in this example.
You register the ILoggerProvider with the service container:
builder.Services.AddTransient<ILoggerProvider, EmailLoggerProvider>();
Now it is ready to be used and will start writing any logs that have a log level of Error or Critical. To test this, you can manufacture an unhandled exception in the OnGetAsync method of the home page’s IndexModel.
Listing 12.16 Adding an unhandled exception to the application
public async Task OnGetAsync()
{
Cities = await _cityService.GetAllAsync();
throw new ApplicationException("Testing the logger");
}Run the application, and you should find a new email has been generated in the TempMail folder you created in chapter 9. The email includes the state, the error message, and the stack trace, including the line of code where the error occurred (figure 12.12).
Figure 12.12 The email logger output
This example is designed to illustrate the basic steps required to implement your own custom logger. It is not an example of best practices and is certainly not production ready. For example, the Log method is not asynchronous, but you are calling an asynchronous API within it—hence the use of the Task.Run method. The best practice for writing logs to email, databases, or other slow (asynchronous) log stores is writing to an intermediate store, such as a buffer or message queue and then processing the queue separately. (See http://mng.bz/XaAa for more guidance.) In more complex applications, the general advice is to look for a third-party logger that offers all the features you need rather than trying to roll your own.
12.3.8 Structured logging with Serilog
Having explored the desirability of using a proven, tested, third-party logging solution, in this section, we will look at the steps required to implement logging with Serilog (https://github.com/serilog) in a Razor Pages application. The default implementation of Serilog includes logging providers (or sinks, in Serilog parlance) for console, file, and debug. The file option writes to a rolling log file, which means you can configure the logging system to create a new log file for each day, each hour, or after the file has reached a certain size, for example. In addition, you can specify that the file output is formatted as JSON, so you can see the structure of the logs, which will hopefully give you some idea of the usefulness of structured logging.
As well as the default sinks, there is a massive ecosystem of alternative sinks (http://mng.bz/ya2d) that target a wide variety of outputs, including email, databases, message queues, cloud-based service providers, and more. Just like .NET Core logging, Serilog outputs to all configured sinks. In this walk-through, you will configure Serilog to output to the console and a file as JSON.
The recommended version of Serilog for ASP.NET Core application logging is Serilog.AspNetCore (http://mng.bz/M0WB). So use your preferred method for installing that package from NuGet. Your project file should be updated with a new package reference accordingly, although the version number might differ:
<PackageReference Include="Serilog.AspNetCore" Version="4.1.0" />
Serilog recommends the logger to be configured prior to the WebApplication .CreateBuilder method call in Program.cs, so it can log any application startup errors. Serilog supports two configuration strategies:
-
You can use the appSettings.json file to configure Serilog, just as you have done with the default logging.
-
Alternatively, you can use a fluent API. This is the recommended approach and the one that you will adopt in the chapter.
The main reason for recommending the fluent API approach is the appSettings.json configuration is not available until after the WebApplication.CreateBuilder method has been called. If you want to use appSettings.json for logging configuration, you will either need to create two loggers—one for application start (that will use the fluent API anyway) and another that reads its config from appSettings.json after the Create-Builder call—or create just one logger and forego logging details of application start errors.
To begin, you will add three additional using directives at the top of the Program.cs file, the first of which you will always need when working with Serilog; the other two are optional, depending on what you want to configure. They enable you to refer to the LogEventLevel and the JsonFormatter during configuration, respectively.
Listing 12.17 The using directives required for Serilog
using Serilog; ❶ using Serilog.Events; ❷ using Serilog.Formatting.Json; ❸
❷ Optional—enables you to refer to LogEventLevel during configuration
❸ Optional—enables you to refer to the JsonFormatter during configuration
The next block of code is placed immediately after the using directives and before the WebApplication.CreateBuilder call.
Listing 12.18 Example Serilog configuration using the fluent API
Log.Logger = new LoggerConfiguration()
.MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning)
.MinimumLevel.Override("Microsoft.EntityFrameworkCore", LogEventLevel.Warning)
.WriteTo.Console()
.WriteTo.File(path: "Logs\log.json",
➥ formatter: new JsonFormatter(), rollingInterval: RollingInterval.Day)
.CreateLogger();
Log.Information("Starting up");You use the static Log.Logger method to create a logger with the specified configuration. Your configuration specifies a minimum log level of Warning for the Microsoft AspNetCore and EntityFramework categories to reduce log verbosity. You use the WriteTo method to configure sinks. Your chosen sinks are the console and the file. You will use the default settings for the console output, but you have configured the file logger to output using JSON. You have also specified that a new file should be created each day via the rollingInterval parameter. Your log file will be written to a folder within the application named Logs. You don’t need to create the folder yourself because Serilog will create it if it doesn’t exist.
The existing content in Program.cs is placed in a try-catch block, so any exceptions raised during the startup phase are caught and logged. Listing 12.19 shows the code from the CreateBuilder method call all the way down to the final app.Run call being placed in a try block, with the addition of the UseSerilog method call, which removes existing logging providers and enables Serilog as their replacement
Listing 12.19 Handling and logging any potential startup exceptions
try ❶ { var builder = WebApplication.CreateBuilder(args); builder.Host.UseSerilog(); ❷ builder.Services.AddRazorPages(options => ... app.Run(); } catch (Exception ex) ❸ { Log.Fatal(ex, "Application start failed"); } finally ❹ { Log.Information("Shut down complete"); Log.CloseAndFlush(); }
❶ Place a try block around the existing code in Program.cs.
❷ Add a call to UseSerilog on the Host property of the WebApplicationBuilder.
❸ Log any exceptions encountered during app configuration and start.
❹ Flush any buffered log messages to their destination.
Serilog log levels are mostly identical to those provided by the .NET logging system, except the lowest level is called Verbose (instead of Trace), and the highest level is called Fatal (instead of Critical). You will use the Log.Fatal method to record details of any exceptions that prevented the application from starting.
Now that you have replaced the existing log providers with Serilog, it’s time to test that the replacement works. Remove the line that throws the exception in the OnGetAsync method of the main IndexModel, and then run the application. You should see something along the lines of the following listing in the console.
Listing 12.20 The Serilog console logger output
[08:35:58 INF] Starting up
[08:35:59 INF] Now listening on: https://localhost:7236
[08:35:59 INF] Now listening on: http://localhost:5236
[08:35:59 INF] Application started. Press Ctrl+C to shut down.
[08:35:59 INF] Hosting environment: Development
[08:35:59 INF] Content root path: D:
epos
➥ Razor-Pages-In-ActionChapter12SerilogCityBreaks
[08:36:00 INF] 12 Cities retrievedNotice the difference from the default loggers. There is no category included in the log message. You can change that by passing a string to the outputTemplate parameter of the WriteTo.Console method (http://mng.bz/M0WB). Serilog refers to the category as the SourceContext. The following template includes the category and uses the NewLine property to place the log message over multiple lines:
"[{Timestamp:HH:mm:ss} {Level:u3}]
➥ {SourceContext}{NewLine}{Message:lj}{NewLine}{Exception}"Of more interest from a structured log point of view is the contents of the log file created in the Logs folder. This should now contain a number of logs in JSON format, each one on a separate line. The file content as a whole is not true JSON, but each standalone entry is. The following listing shows how the last entry looks once it has been formatted in a more friendly way.
Listing 12.21 The Serilog default JSON formatter output
{
"Timestamp": "2022-01-08T08:42:50.6276136+00:00",
"Level": "Information",
"MessageTemplate": "{count} Cities retrieved",
"Properties": {
"count": 12,
"SourceContext": "CityBreaks.Pages.IndexModel",
"ActionId": "cda34ae3-2c8f-457a-964b-d7200a0f64df",
"ActionName": "/Index",
"RequestId": "0HMEIGBD156VF:00000001",
"RequestPath": "/",
"ConnectionId": "0HMEIGBD156VF"
}
}Note the level of detail here. The property bag, represented by the Properties node, includes more information than the console logger. As well as request details and the log category, it includes a property named count, which has been taken from your log message template. This enables querying of the property by tools that can parse the JSON log and illustrates why you should use named placeholders in your log message templates instead of interpolation or plain string concatenation.
It is not unusual for users to make mistakes when they modify data within an application. Sadly, I’ve also found it is not unusual for some users to evade responsibility, blaming someone else or the system for their mistake. What would be really useful in these situations would be to show the state of the data before they made an update and then again after the update was made, so there is clear evidence of the changes made and when they were made. In other words, you want a kind of transaction log.
Serilog enables capturing this level of information very simply, preserving an object’s structure when it is logged. To see how powerful this can be, add another logging call to the application. Amend the OnGetPropertyDetails handler in the City.cshtml.cs file as follows. Note that the placeholder name is prefixed with your old friend the @ symbol, known in Serilog as the destructuring operator.
Listing 12.22 The @ destructuring operator preserving object structure
public async Task<PartialViewResult> OnGetPropertyDetails(int id)
{
var property = await _propertyService.FindAsync(id);
_logger.LogInformation("Property {@property}
➥ retrieved by {user}", property, User.Identity.Name); ❶
var model = new BookingInputModel { Property = property };
return Partial("_PropertyDetailsPartial", model);
}❶ Log details of the property that was retrieved and who it was retrieved by.
This time, the rendered log message (the relevant part of which is shown in the following listing) includes a destructured version of the property variable.
Listing 12.23 The rendered log including full details of the property
"Level": "Information",
"MessageTemplate": "Property {@property} retrieved by {user}",
"Properties": {
"property": {
"_typeTag": "Property",
"Id": 38,
"Name": "Hotel Colonial",
"Address": "Via Laietana",
"CityId": 2,
"City": null,
"MaxNumberOfGuests": 3,
"DayRate": 88.0,
"SmokingPermitted": false,
"AvailableFrom": "0001-01-01T00:00:00.0000000",
"Deleted": null,
"CreatorId": null,
"Creator": null
},
"user": "[email protected]",
"SourceContext": "CityBreaks.Pages.CityModel",While it is possible to write your own log-querying tools for working with structured logs, there are existing tools out there already, such as Seq (pronounced seek) and Elasticsearch, both of which Serilog includes sinks for. These third-party services may not be free; you should check their cost against the likely cost of developing and maintaining your own solution.
In this chapter, we’ve covered the main ways you can control how your application behaves in the event of errors occurring that you did not anticipate in code. We’ve also explored logging, primarily as a mechanism for capturing as much information about exceptions that get raised as possible, although it can be used to capture details of any kind of activity for any purpose. In the next chapter, we will look at protecting your application against external threats.
Summary
-
During development, the Developer Exception page is displayed in the event of an unhandled exception, providing details of the exception and the line of code where it was raised.
-
When the application is exposed to users, you should use ExceptionHandlerMiddleware to show a generic error page to hide details of errors.
-
ExceptionHandlerMiddleware should be placed very early in the application pipeline.
-
StatusCodePages middleware is designed to control how the application behaves when client errors occur.
-
With StatusCodePages middleware, you can incorporate the HTTP status code into the path or query string of the custom error page that is presented.
-
Use the WithRedirects approach if you want StatusCodePages middleware to issue a redirect to the browser. The original status code and request path are replaced.
-
Use the WithReExecute approach to retain the HTTP status code and the original path in the browser address bar.
-
Logging is supported as a first-class citizen in Razor Pages applications.
-
Log categories help you identify the class that generated the log.
-
Recommended practice is to use named placeholders in format strings (templates) to generate log messages, so structured logging can extract their properties and values.
-
Custom loggers consist of implementing the ILogger and ILoggerProvider interfaces, then registering the ILoggerProvider with the service container.
-
Many third-party logging providers are available for ASP.NET Core applications.
-
Structured logging generates logs in a structured format that facilitates advanced querying and filtering.