Logging & Configuration

In this module we are going to set up a global application wide logging system to catch any application errors once in production. This way we will have some clues to help us track down where errors and glitches are coming from when users report them.

Table Of Contents
  1. Review EditPost in the Vehicles controller
  2. The Logging Service
  3. Create a Log Entry from Program.cs
  4. Create a Log Entry from a Controller
  5. Log the DbUpdateException from EditPost
  6. Persist Log Entries with Serilog
  7. Run Unit Tests
  8. Fix the Unit Tests
  9. What's Next

Review EditPost in the Vehicles controller

In module 24, Create the Update Page, we have the update for a Vehicle edit in a try/catch block.

FredsCars\Controllers\VehiclesController.cs

[HttpPost]
[ActionName("Edit")]
[ValidateAntiForgeryToken]
public async Task<IActionResult> EditPost(int id)
{
    ... existing code ...
    
    {
        try
        {
            // TEST DbUpdateException
            // throw new DbUpdateException("500 error on vehicle update.");
            await _vehicleRepo.UpdateAsync(vehicle!);
            return RedirectToAction("Index", "Home");
        }
        catch (DbUpdateException ex)
        {
            // Log the exception
            //ex.Message, ex.Source, ex.StackTrace
            ModelState.AddModelError("",
                "There was a problem updating the vehicle."
                + "Please contact your system administrator." );
        }
    }

    ... existing code ...
}

Recall in the code above we try to update a Vehicle edit from a user form submission in the try block and have a catch block ready to handle a DbUpdate exception. If a DbUpdate exception occurs, we add a model error message to the ModelState. We also have a comment in the catch block to log the exception. That is exactly what we are going to do in this module. But first, let’s spend a little time talking about logging and configuration.

The Logging Service

ASP.Net Core provides a logging service that can be used to write and store messages about the state of the application.

Logging Providers

The Logging Service uses Logging Providers to write and store log messages.

ASP.Net Core project templates call WebApplication.CreateBuilder in Program.cs.

var builder = WebApplication.CreateBuilder(args);

The CreateBuilder method adds four out-of-the-box providers.

Default Logging Providers

ConsoleWrites messages to the console.
DebugWrites messages to the debug window in Visual Studio IDE when running in debug mode.
EventSourceUseful for performance monitoring. Consumed by tools like PerfView & Windows Recorder.
EventLog (Windows Only)Writes messages to Windows EventViewer.

You can also opt in to other providers. For example, the Azure Application Insights provider stores logs in Azure Application Insights.

Logging Configuration

Logging is typically configured in the Logging section of appsettings.json and the
appsettings.{environment}.json files such as appsettings.development.json as well as the stage and production appsettings files.

The following code is the Logging section for both the appsettings.json and appsettings.development.json files that were created from the ASP.Net Core empty web project template we used to create the FredsCars MVC project.

Note that if both files contain the same category with different values, appsettings.development.json will take precedence when the environment is Debug. Anytime you run the project from Visual Studio the environment will be Debug.

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.AspNetCore": "Warning"
    }
  },
... existing code ...

In the Logging section of the configuration code above, we are specifying a LogLevel for one category and the Default LogLevel.

First we specify a LogLevel of Information as the Default LogLevel for any category not listed in the LogLevel section. Secondly, we specify a LogLevel of Warning for the Microsoft.AspNetCore category. The category usually represents the class writing or storing the Log message.
Applying the Information LogLevel to the Microsoft.AspNetCore category means it will apply to any category starting with Microsoft.AspNetCore such as Microsoft.AspNetCore.Routing.

Also the LogSeverity level of 2, Information, applied to Microsoft.AspNetCore, will log information for each severity level with 2 and up;
* 2 – Information
* 3 – Warning
* 4 – Error
* 5 – Critical

6 – None, is not applied. We set a severity level of 6 – None when we want to suppress all log messages and entries for a category.

So, when we run the application from a console window, we can see the log messages that the Console Logging Provider writes to that console on startup.

In the above screen shot we can see several Information Level messages written for both the Microsoft.EntityFrameworkCore.Database.Command
and
Microsoft.Hosting.Lifetime categories.
Both of these categories default to the Information LogLevel since they are not listed or given a specific category in the Logging/LogLevel section of any appsettings file.

The number in brackets following each category name is the EventId. The ASP.Net Core Logging Service assigns an EventID to each log entry.

Log Levels

Let’s dig a little deeper on this concept of LogLevels.

A LogLevel specifies the minimum severity level to log for a specific category.
LogLevels range in severity from 0 to 6.

0TraceUsed for low-level debugging during development.
1DebugUsed for low-level debugging during development or production issue resolution.
2InformationUsed to provide general information about the state of the application.
3WarningUsed to record unexpected, but minor, problems. Unlikely to disrupt application.
4ErrorUsed to record exceptions or errors not handled by the application.
5CriticalUsed to record serious failures.
6NoneSuppresses all log entries and messages for a category.

The level assigned to a log message or category reflects its importance and detail. The severity levels range from Trace, for the most detailed information, to Critical, the most important information requiring immediate response and resolution.

Create a Log Entry from Program.cs

You can create log entries from within Program.cs using the Logger object property of the WebApplication object once it has been built using the WebApplicationBuilder.Build method.

var app = builder.Build();

Make the following changes to Program.cs shown below.

FredsCars\Program.cs

using FredsCars.Data;
using FredsCars.Models;
using FredsCars.Models.Repositories;
using Microsoft.EntityFrameworkCore;

var builder = WebApplication.CreateBuilder(args);

// Add Services

... existing code ...

var app = builder.Build();

// Configure the HTTP request pipeline.
app.Logger.LogDebug("Pipeline configuration starting.");

app.UseStaticFiles();

// Add custom routes
app.MapControllerRoute("cat-and-page",
    "{category}/Page{pageNumber:int}",
    new { Controller = "Home", action = "Index" });

app.MapControllerRoute("paging",
    "Page{pageNumber:int}",
    new { Controller = "Home", action = "Index" });

/*** Add endpoints for controller actions and
       the default route ***/
app.MapDefaultControllerRoute();

// Log chosen route to console
app.Use(async (context, next) =>
{
    var endpoint = context.GetEndpoint();
    var routeNameMetadata = endpoint?.Metadata.GetMetadata<RouteNameMetadata>();
    var routeName = routeNameMetadata?.RouteName;
    
    if (endpoint is RouteEndpoint routeEndpoint)
    {
        Console.WriteLine($"Matched route: {routeEndpoint.RoutePattern.RawText}");
        Console.WriteLine($"RouteName: {routeName}");
    }
    await next();
});

app.Logger.LogDebug("Pipeline configuration finished.");

... existing code ...

app.Run();

... existing code ...

In the code above we are writing debug level logging messages to the console on startup to see when Pipeline configuration is starting and when it is finished.

app.Logger.LogDebug("Pipeline configuration starting.");
app.Logger.LogDebug("Pipeline configuration finished.");

Update appsettings.development.json

In order to see debug level logging messages in the Console we need to configure a LogLevel of Debug for a FredsCars category in the development appsettings file.

Make the changes shown below to appsettings.development.json.

FredsCars\appsettings.development.json

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.AspNetCore": "Warning",
      "FredsCars": "Debug"
    }
  },
... existing code ...

If we simply changed Default to Debug we would see way to many debug statements in the Console window we are not interested in. So we create a new category called FredsCars so we only see additional debug statements from Program.cs in the FredsCars project. We will also see debug and any level higher than debug log messages from any class in a namespace starting with FredsCars such as FredsCars.Controllers.VehiclesController.

Restart the application in the console window and you should see statements similar to the following.

PS C:\Development\FredsCars\MVC\Module27\FredsCars\FredsCars> dotnet run --launch-profile "HTTPS"
Using launch settings from C:\Development\FredsCars\MVC\Module27\FredsCars\FredsCars\Properties\launchSettings.json...
Building...
dbug: FredsCars[0]
      Pipeline configuration starting.
dbug: FredsCars[0]
      Pipeline configuration finished.
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (15ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT CASE
          WHEN EXISTS (
              SELECT 1
              FROM [Vehicle] AS [v]) THEN CAST(1 AS bit)
          ELSE CAST(0 AS bit)
      END
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (3ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT CASE
          WHEN EXISTS (
              SELECT 1
              FROM [VehicleType] AS [v]) THEN CAST(1 AS bit)
          ELSE CAST(0 AS bit)
      END
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://localhost:40443
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: http://localhost:40080
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: C:\Development\FredsCars\MVC\Module27\FredsCars\FredsCars

You can see the two new two new debug log messages at the top of the console window.

dbug: FredsCars[0]
      Pipeline configuration starting.
dbug: FredsCars[0]
      Pipeline configuration finished.

Create a Log Entry from a Controller

Create an Index for the VIN property

In order to demonstrate a DbUpdateException in action, we are going to make the VIN property of the Vehicle model unique by adding an Index to it.

Modify the FredsCars DbContext as shown below.

FredsCars\Data\FredsCarsDbContext.cs

... existing code ...

    public class FredsCarsDbContext : DbContext
    {
        ... existing code ...

        public virtual DbSet<Vehicle> Vehicles => Set<Vehicle>();
        public DbSet<VehicleType> VehicleTypes => Set<VehicleType>();

        protected override void OnModelCreating(ModelBuilder modelBuilder)
        {
            ... existing code ...

            modelBuilder.Entity<Vehicle>()
                .HasIndex(v => v.VIN)
                .IsUnique();
        }
    }
}

In the code above we have added a statement at the end of the OnModelCreating method to give the VIN column of the database an Index and make it unique.

The index will make searching on the VIN column faster and making it unique will prevent a user from inserting a Vehicle record with a duplicate VIN number and throw a DbUpdateException if an attempt is made to do so.

Create a migration & update the database schema

The next thing we need to do is create a migration and update the database.

Run the following commands in the FredsCars project directory. (The one with the FredsCars.csproj file in it.)

dotnet ef migrations add IndexVin
dotnet ef database update

If we look at the Vehicle Table in SSOX data designer view we will see that its SQL Server type is now NVarChar(450) instead of NVarChar(Max). EF Core had to narrow its length down because a searchable index cannot be more than 450 chars in length. Also there will be a new index on the VIN column specifying that the column is unique (IX_Vehicle_VIN).

Demonstrate throwing DbUpdate Exception from browser

Now navigate to the main landing page at https://localhost:40443 and click the update button for the New 2021 Dodge Challenger.

Once on the Update page enter a duplicate VIN number (one that already exists for another vehicle in the database).

In the above screenshot for the update page of the New 2021 Dodge Challenger, I am about to try and enter a VIN number that already exists for the New 2025 Gladiator Rubicon 4 X 4.

Change the value of the VIN number in your browser to match that in the above screen shot and click the edit button. (Value to enter for VIN: 1C6RJTBG0SL532163)

The catch block we set up in the EditPost method of the Vehicle controller to handle a DbUpdateException adds a model error message to the ModelState and re-renders the form where the user can see the message.

Now that we have updated the database schema to make the VIN field unique, we are finally ready to go back and add logging to the Update page for a DbUpdateException.

Inject an ILogger service into the controller

In order to write log entries and messages from the Vehicles controller we need to inject an ILogger service into its constructor.

Modify the VehiclesController class with the code shown below.

FredsCars\Controllers\VehiclesController.cs

... existing code ...
public class VehiclesController : Controller
{
    private IVehicleRepository _vehicleRepo;
    private IVehicleTypeRepository _vehicleTypeRepo;
    private ILogger _logger;

    public VehiclesController(IVehicleRepository vRepo,
        IVehicleTypeRepository vtRepo,
        ILogger<VehiclesController> logger)
    {
        _vehicleRepo = vRepo;
        _vehicleTypeRepo = vtRepo;
        _logger = logger;
    }
... existing code ...

In the code above we are injecting an ILogger of type VehiclesController.

ILogger<VehiclesController> logger

The type we specify for the Generic Logger service class will be the category of the log entry. So the category for all log entries and messages written from the Vehicles controller will be VehiclesController.

Log the DbUpdateException from EditPost

Modify the EditPost method in the VehiclesController class with the following changes shown below.

FredsCars\Controllers\VehiclesController.cs

namespace FredsCars.Controllers
{
    public class VehiclesController : Controller
    {
        private IVehicleRepository _vehicleRepo;
        private IVehicleTypeRepository _vehicleTypeRepo;
        private ILogger _logger;

        public VehiclesController(IVehicleRepository vRepo,
            IVehicleTypeRepository vtRepo,
            ILogger<VehiclesController> logger)
        {
            _vehicleRepo = vRepo;
            _vehicleTypeRepo = vtRepo;
            _logger = logger;
        }

        [HttpPost]
        [ActionName("Edit")]
        [ValidateAntiForgeryToken]
        public async Task<IActionResult> EditPost(int id)
        {
            var vehicle = await _vehicleRepo.Vehicles
                .Include(v => v.VehicleType)
                .FirstOrDefaultAsync(v => v.Id == id);

            if (await TryUpdateModelAsync<Vehicle>(vehicle!,
                    "",
                    v => v.Status, v => v.Year, v => v.Make,
                    v => v.Model, v => v.Color, v => v.Price,
                    v => v.VIN, v => v.ImagePath, v => v.VehicleTypeId
            ))
            {
                try
                {
                    // TEST DbUpdateException
                    // throw new DbUpdateException("500 error on vehicle update.");
                    await _vehicleRepo.UpdateAsync(vehicle!);
                    return RedirectToAction("Index", "Home");
                }
                catch (DbUpdateException ex)
                {
                    // Log the exception
                    var eventId = new EventId(id, "DbUpdateFailure");

                    var message = ex.Message;
                    var inner = ex.InnerException;
                    while (inner != null)
                    {
                        message += " --> " + inner.Message;
                        inner = inner.InnerException;
                    }

                    _logger.LogError(eventId, "DbUpdate error for Vehicle ID {id}\nMessage: {Message}\nSource: {Source}\nStackTrace: {StackTrace}\nTargetSite{TargetSite}",
                        id,
                        message,
                        ex.Source,
                        ex.StackTrace,
                        ex.TargetSite
                    );
                    
                    //ex.Message, ex.Source, ex.StackTrace
                    ModelState.AddModelError("",
                        "There was a problem updating the vehicle."
                        + "Please contact your system administrator." );
                }
            }

            var vehicleTypes =
                _vehicleTypeRepo.VehicleTypes;

            ViewBag.VehicleTypeList = new SelectList(vehicleTypes,
                "Id", "Name");

            return View();
        }

... existing code ...

In the code above we modify the catch block and replace the log comment reminder that was there with some actual logging code.

We start off by creating an EventId object and assign it to a variable called eventId.

var eventId = new EventId(id, "DbUpdateFailure");

The first parameter of the EventId constructor is an int representing the Event.Id and we assign it the incoming id of a Vehicle from the URL route value. The second parameter is a string representing the Event.Name and we assign it the literal string “DbUpdateFailure“.

Recall the EventId is the part of a log message in brackets at the end.

// LogLevel: Category[EventId]
info: Microsoft.Hosting.Lifetime[14]

There are 4 overloaded methods for the EventId constructor. We could have just assigned an Id and no string like this.

var eventId = new EventId(id);

rather then

var eventId = new EventId(id, "DbUpdateFailure");

Here I chose to use an overload of the EventId constructor where I can also assign a string name, or Event.Name, “DbUdateFailure”.

The string portion, or Event.Name, of an EventId is semantic and can have any meaning the developer intends. It could be an error type or code. Or it could represent a transaction. So I could make many log statements from the catch block and feed them all the same EventId with the same Event.Name, here DbUpdateFailure, and know they all represent a specific transaction, like updating an edited Vehicle in the EditPost method of the Vehicles controller.

Framework teams like ASP.NET Hosting, Kestrel, EF Core, etc. assign fixed IDs to each type of event.
For example:

Microsoft.Hosting.Lifetime[14]
Application started. Press Ctrl+C to shut down.

Here, 14 = “ApplicationStarted” (a specific kind of event).

By default, the built-in logging providers in ASP.NET Core (Console, Debug, EventSource, EventLog) only render the numeric EventId.Id — not the EventId.Name.

So, unfortunately, we will not see the Event.Name of our log messages in the Console window. But, we will be able to see the Event.Name property when we get to persisting our logs using… spoiler alert, Serilog.

Next, we prepare the message we are going to log. We are actually going to log the message of the top level exception and the message of every inner exception going all the way down the chain until we reach the original calling code. In order to do that we are going to use a kind of recursive while loop.

var message = ex.Message;
var inner = ex.InnerException;
while (inner != null)
{
    message += " --> " + inner.Message;
    inner = inner.InnerException;
}

In the code above we assign the exception’s string message to a variable called message. And we assign the exception’s inner exception to a variable called inner. These two variables are our initial setup data points as we enter the while loop which will iterate until inner, the current InnerException, is null.

Inside of each iteration of the while loop, message is concatenated with a literal string acting as a separator, ” –> ” and the message of the InnerException‘s message. Then we set inner to the InnerException of the current InnerException, or the next level down. If the current InnerException‘s own InnerException is null then we break out of the current while loop and continue on. Otherwise another iteration is performed.

Finally, we create the actual logging statement using the ILogger<T>.LogError method (where T is VehiclesController).

_logger.LogError(eventId, "DbUpdate error for Vehicle ID {id}\nMessage: {Message}\nSource: {Source}\nStackTrace: {StackTrace}\nTargetSite{TargetSite}",
    id,
    message,
    ex.Source,
    ex.StackTrace,
    ex.TargetSite
);

In the above code snippet we are using the LogError method off of our private class variable _logger of type ILogger<VehiclesController> to write an Error LogLevel log message.

The first parameter we feed LogError is the eventId we created back in the first step. The second parameter is a string message for the log entry.

"DbUpdate error for Vehicle ID {id}\nMessage: {Message}\nSource: {Source}\nStackTrace: {StackTrace}\nTargetSite{TargetSite}"

The squiggly brackets, {Message}, {Source}, etc., are placeholders for all other following parameters and the ‘\n’ character sequences are escape sequences that create a new line in the string.

The next five parameters make up a C# parameter array of nullable objects and fill in the place holder values for the LogError’s message string.

params object[]

idthe VehicleId received in the parameter list of the EditPost method from the URL routeValues.
messagethe top level message and all contained InnerException messages built in the while loop.
ex.Sourcethe fully qualified namespace.class that causes the errror.
ex.StackTracedescribes the immediate frames of the call stack. Critical for pinpointing where the error occurred (method, file, line number)
ex.TargetSiteGets the method that throws the current exception.

A params array in C# allows a developer to pass a variable number of arguments to a method without explicitly creating an array. And, that is exactly what we need here.

Now restart the application and follow the same steps we did in the section, Demonstrate throwing DbUpdate Exception from browser, where we were able to see the ModelState error message shown to the user in the browser that we added in the EditPost method’s catch block.

This will trigger our log message in the console window that the application is running from. (You’ll have to scroll down past some other logging information of course to see our specific error log)

The first line in the log entry shown above displays the LogLevel, fail, in red, followed by a colon, the fully qualified classname of the category, and the EventId in brackets.

fail: FredsCars.Controllers.VehiclesController[2]

The built-in ASP.Net Core Console logger maps log levels to short labels.
It doesn’t literally print the enum name (LogLevel.Error), it prints a friendly label.

Here’s the mapping:

LogLevel enum valueConsole logger label
Tracetrce
Debugdbug
Informationinfo
Warningwarn
Errorfail
Criticalcrit
None(no output)

The rest of the log entry shows the results of the string with placeholder values we passed from the params array to the _logger.LogError method.

"DbUpdate error for Vehicle ID {id}\nMessage: {Message}\nSource: {Source}\nStackTrace: {StackTrace}\nTargetSite{TargetSite}"

The portion of the string:
DbUpdate error for Vehicle ID {id}\n
displays the following line in the console and then breaks to a new line.

 DbUpdate error for Vehicle ID 2

The placeholder, {id}, was filled in with the value 2 from the id parameter of the params array.

_logger.LogError(eventId, "DbUpdate error for Vehicle ID {id}\nMessage: {Message}\nSource: {Source}\nStackTrace: {StackTrace}\nTargetSite{TargetSite}",
    id,  // gets id from URL route value
    message,
    ex.Source,
    ex.StackTrace,
    ex.TargetSite
);

The next portion of the string:
Message: {Message}\n
displays the top level exception message and all of the InnerException messages down the chain to the calling code that created the error.

Message: An error occurred while saving the entity changes. See the inner exception for details. 
    --> Cannot insert duplicate key row in object 'dbo.Vehicle' with unique index 'IX_Vehicle_VIN'. The duplicate key value is (1C6RJTBG0SL532163).

There is only one InnerException here but hopefully you get the point. The inner exception message shows the cause of the error is that we tried to insert a duplicate value on a unique field, VIN.

The placeholder, {Message}, was filled in with the message string we built up in the recursive while loop.

_logger.LogError(eventId, "DbUpdate error for Vehicle ID {id}\nMessage: {Message}\nSource: {Source}\nStackTrace: {StackTrace}\nTargetSite{TargetSite}",
    id,
    message,  // built in recursive while loop
    ex.Source,
    ex.StackTrace,
    ex.TargetSite
);

The next portion of the string:
Source: {Source}\n
displays the name of the assembly or module that threw the exception. This is helpful if you have multiple projects/libraries in play.

Source: Microsoft.EntityFrameworkCore.Relational

The next portion of the string:
StackTrace: {StackTrace}\n
displays the StackTrace which is critical for pinpointing where the error occurred (method, file, line number).
The StackTrace in .Net is a snapshot of the call stack at the moment an exception (or error) occurs. It shows the chain of method calls that led up to the exception, which is extremely useful for diagnosing bugs.

StackTrace:    at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeAsync(RelationalDataReader reader, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.SqlServer.Update.Internal.SqlServerModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Storage.RelationalDatabase.SaveChangesAsync(IList`1 entries, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(IList`1 entriesToSave, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(StateManager stateManager, Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
         at FredsCars.Models.Repositories.EFVehicleRepository.UpdateAsync(Vehicle vehicle) in C:\Development\FredsCars\MVC\Module27\FredsCars\FredsCars\Models\Repositories\EFVehicleRepository.cs:line 26
         at FredsCars.Controllers.VehiclesController.EditPost(Int32 id) in C:\Development\FredsCars\MVC\Module27\FredsCars\FredsCars\Controllers\VehiclesController.cs:line 113

From the StackTrace above we can glean from the bottom line that the error was thrown from the VehiclesController at line 113. Your line numbers may vary slightly from mine but, this is the exact statement in the controller where we try to update the vehicle.

await _vehicleRepo.UpdateAsync(vehicle!);

That code calls UpdateAsync in our EFVehicleRepository implementation of the IVehicleRepository service.

And that code calls SaveChangesAsync in the DbContext and so on all the way up the stack.

Persist Log Entries with Serilog

Sending log entries to the console is great for helping us to debug during development. But once we deploy to production and possibly thousands or even millions of users are using the application, errors will occur, whether from a bug in the code, a down network connection or database, or some other unforeseeable circumstance.

We need a way to persist the log entries to a database table, so when a user reports an error or a bug, we have an existing record we can search to help us diagnose and solve the problem.

Unfortunately none of the default or out-of-the box logging providers log to a database table.

There are however plenty of third party logging providers that implement the ILogger interface that can do the job and persist our logs to a database. In this section we are going to implement one of the most popular logging providers called Serilog.

What is Serilog

Serilog is a popular third-party logging library for .Net.

Unlike traditional loggers that just write plain text, Serilog is structured logging. It captures log data as key-value pairs, making logs searchable, filterable, indexed and exportable.

It can log to multiple sinks (destinations), such as:

  • Console
  • File (rolling log files)
  • MSSqlServer
  • Elasticsearch / Kibana
  • Datadog, Splunk, Application Insights, etc.

Install the packages

First we need to install the required packages. The three packages we will be using are:

Serilog.AspNetCoreIntegrates Serilog into the ASP.NET Core host.
Serilog.Settings.ConfigurationEnables configuring Serilog directly from appsettings.json and appsettings.{environment}.json files.
Serilog.Sinks.MSSqlServerProvides the sink that writes log events into a SQL Server database table.
* It can auto-create the table for you if it doesn’t exist.
* Default table is Logs, but you can name it anything.

Stop the application if it is running (Ctrl-C) and run the following commands in the FredsCars project folder.

dotnet add package Serilog.AspNetCore --version 9.0.0
dotnet add package Serilog.Settings.Configuration --version 9.0.0
dotnet add package Serilog.Sinks.MSSqlServer --version 8.2.2

At the time of this writing the only .Net 9.0 version for Serilog.Sinks.MSSqlServer is developmental and causes conflicts with the .Net 9.0 Microsoft.EntityFrameworkCore.SqlServer package. So I went with the latest stable version for .Net 8, which is 8.2.2.

Configure Serilog

Modify Program.cs to add support for Serilog as shown below.

FredsCars\FredsCars\Program.cs

using FredsCars.Data;
using FredsCars.Models;
using FredsCars.Models.Repositories;
using Microsoft.EntityFrameworkCore;
using Serilog;
using Serilog.Events;
using Serilog.Sinks.MSSqlServer;

var builder = WebApplication.CreateBuilder(args);

// Add Serilog support
// -- configuring Host
if (AppDomain.CurrentDomain.FriendlyName != "ef")
{
    builder.Host.UseSerilog((ctx, lc) => lc
        .ReadFrom.Configuration(ctx.Configuration)
        .WriteTo.MSSqlServer(connectionString:
            ctx.Configuration.GetConnectionString("FredsCarsMvcConnection"),
            restrictedToMinimumLevel: LogEventLevel.Debug,
            sinkOptions: new MSSqlServerSinkOptions
            {
                TableName = "LogEvents",
                AutoCreateSqlTable = true
            },
            columnOptions: columnOptions
        ),
        .WriteTo.Console()
     );
}

// Add Services
builder.Services.AddControllersWithViews();
... existing code ...

In the code above, at the top of the file, we added three using statements so we can use the code from the packages we just installed.

using Serilog;
using Serilog.Events;
using Serilog.Sinks.MSSqlServer;

The actual configuration is contained in an if block.

if (AppDomain.CurrentDomain.FriendlyName != "ef")
{
   ... configure Serilog ...
}

The if condition above only configures Serilog if the Current Domain is not EF Core. We need this guard because if we delete or drop the FredsCarsMvc database and try to recreate it using:
dotnet ef database update
the Serilog configuration:
builder.Host.UseSerilog((ctx, lc) => lc
.ReadFrom(...
will error out the EF Db creation process.
So now
dotnet ef database update
will work and create the database.
And then the first time we run the application in runtime it will reseed the newly created database with data, configure Serilog, and log all the events

Next we configure the host using the WebApplicationBuilder.IHostBuilder interface to replace the default Microsoft logging system and logging providers with Serilog and sinks/destinations.

The WebApplicationBuilder.Host.UseSerilog(ctx, lc) method takes in two parameters:

  • HostBuilderContext -> ctx
  • LoggerConfiguration – lc

We instruct Serilog to read its configuration settings from the context’s IConfiguration which includes appsettings.json, all appsettings.{environment}.json files, and secrets.json.

.ReadFrom.Configuration(ctx.Configuration)

And we configure two sinks for Serilog to write to: MSSqlServer and Console.

We configure the MSSqlServer sink to use the FredsCarsMvcConnection connection string from the IConfiguration containing the merged configuration of the application, set the minimum LogLevel to Debug, and automatically create a database table called LogEvents to store and persist logs to if one does not already exist.

.WriteTo.MSSqlServer(connectionString:
    ctx.Configuration.GetConnectionString("FredsCarsMvcConnection"),
    restrictedToMinimumLevel: LogEventLevel.Debug,
    sinkOptions: new MSSqlServerSinkOptions
    {
        TableName = "LogEvents",
        AutoCreateSqlTable = true
    }
)
.WriteTo.Console()

At this point if you restart the application, a new LogEvents table is added to the database, all logs are now stored and persisted to the new table, and still continue to also be written to the console.

You can ignore the null reference warnings for now.
But, it looks like we lost our debug logging from Program.cs about pipeline configuration:

dbug: FredsCars[0]
      Pipeline configuration starting.
dbug: FredsCars[0]
      Pipeline configuration finished.

Also, notice the Serilog logging format is different then Microsoft’s.

Instead of Microsoft’s:
LogLevel: category/class[EventId] format, where each type of LogLevel has a specific color, like green for info, which I like, and the actual messaging starts on the next line:

info: Microsoft.EntityFrameworkCore.Database.Command[20101]
 Executed DbCommand (13ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT CASE
          WHEN EXISTS (
              SELECT 1
              FROM [Vehicle] AS [v]) THEN CAST(1 AS bit)
          ELSE CAST(0 AS bit)
      END

Serilog’s format is just brackets with a TimeStamp and its own shortcut name for the LogLevel, here INF rather than info. And the messaging starts on the same line. It has kind of an all-run-together look for me.

[07:26:49 INF] Executed DbCommand (6ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
SELECT CASE
    WHEN EXISTS (
        SELECT 1
        FROM [Vehicle] AS [v]) THEN CAST(1 AS bit)
    ELSE CAST(0 AS bit)
END

I think the format of the LogEvents table and the way the messages get logged to SQL Server are fine for now.

The first column, Message, stores the completed actual message:

Executed DbCommand ("6"ms) [Parameters=[""], CommandType='Text', CommandTimeout='30']"
""SELECT CASE
    WHEN EXISTS (
        SELECT 1
        FROM [Vehicle] AS [v]) THEN CAST(1 AS bit)
    ELSE CAST(0 AS bit)
END"

The second column, MessageTemplate, stores the message template with placeholders embedded in the message that was used for the log entry. Serilog uses key value pairs to create messages within these string templates.

Executed DbCommand ({elapsed}ms) [Parameters=[{parameters}], CommandType='{commandType}', CommandTimeout='{commandTimeout}']{newLine}{commandText}

The third column stores the LogLevel, for instance, information.

The fourth column is a timestamp.

The fifth column is the exception if you pass the exception to the log entry like so:

Log.Error(ex, "An error occurred while dividing.");

The sixth and final column, Properties, stores useful information (missing from Serilog Console logging) in property key/value pairs of the log entry like EventId, Name (category/class), Source Context, and commandText for database commands in XML format.

<properties><property key='elapsed'>6</property><property key='parameters'></property><property key='commandType'>Text</property><property key='commandTimeout'>30</property><property key='newLine'>
</property><property key='commandText'>SELECT CASE
    WHEN EXISTS (
        SELECT 1
        FROM [Vehicle] AS [v]) THEN CAST(1 AS bit)
    ELSE CAST(0 AS bit)
END</property><property key='EventId'><structure type=''><property key='Id'>20101</property><property key='Name'>Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted</property></structure></property><property key='SourceContext'>Microsoft.EntityFrameworkCore.Database.Command</property></properties>

I personally like the default console logging provided by Microsoft’s default logging abstraction in .Net, Microsoft.Extensions.Logging, and its interface ILogger better than Serilog’s. So let’s change the Console logging back to the .Net Console logging provider and disable the Serilog Console sink.

Make the following change to the Serilog configuration in Program.cs.

FredsCars\Program.cs

... existing code ...
// Add Serilog support
// -- configuring Host
builder.Host.UseSerilog((ctx, lc) => lc
    .ReadFrom.Configuration(ctx.Configuration)
    .WriteTo.MSSqlServer(connectionString:
        ctx.Configuration.GetConnectionString("FredsCarsMvcConnection"),
        restrictedToMinimumLevel: LogEventLevel.Debug,
        sinkOptions: new MSSqlServerSinkOptions
        {
            TableName = "LogEvents",
            AutoCreateSqlTable = true
        }
    ),
    //.WriteTo.Console()
    writeToProviders: true
);
... existing code ...

In the code above, for Serilog configuration, we commented out:
.WriteTo.Console()
removing the Serilog console sink and added:
writeToProviders: true.

By default, Serilog does not write events to ILoggerProvider(s) registered through the Microsoft.Extensions.Logging API. Normally Serilog sinks are used in place of providers. Here we specify true on writeToProviders to write events to all providers, including console.

Now, if you restart the application, we are back to our more appealing Microsoft console format at startup, and Serilog still continues to log entries to SQL Server.

info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand ("8"ms) [Parameters=[""], CommandType='Text', CommandTimeout='30']"
      ""SELECT CASE
          WHEN EXISTS (
              SELECT 1
              FROM [Vehicle] AS [v]) THEN CAST(1 AS bit)
          ELSE CAST(0 AS bit)
      END"
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand ("2"ms) [Parameters=[""], CommandType='Text', CommandTimeout='30']"
      ""SELECT CASE
          WHEN EXISTS (
              SELECT 1
              FROM [VehicleType] AS [v]) THEN CAST(1 AS bit)
          ELSE CAST(0 AS bit)
      END"
info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[63]
      User profile is available. Using '"C:\Users\smill\AppData\Local\ASP.NET\DataProtection-Keys"' as key repository and Windows DPAPI to encrypt keys at rest.
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: "https://localhost:40443"
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: "http://localhost:40080"
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: "Development"
info: Microsoft.Hosting.Lifetime[0]
      Content root path: "C:\Development\FredsCars\MVC\Module27\FredsCars\FredsCars"

All of the logging shown immediately above are framework generated log entries (e.g., Microsoft.Hosting.Lifetime, Microsoft.EntityFrameworkCore.Database.Command, etc.)

But we are still missing the pipeline debug log entries we created earlier in Proram.cs with the
WebApplication.Logger.LogDebug() method before implementing Serilog:

app.Logger.LogDebug("Pipeline configuration starting.");app.Logger.LogDebug("Pipeline configuration finished.");
dbug: FredsCars[0]
      Pipeline configuration starting.
dbug: FredsCars[0]
      Pipeline configuration finished.

Let’s fix that now.

Modify appsettings.develoment.json and appsettings.json with the changes shown below.

FredsCars\appsettings.development.json

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.AspNetCore": "Warning",
      "FredsCars": "Debug"
    }
  },
  "Serilog": {
    "MinimumLevel": {
      "Override": {
        "FredsCars": "Debug"
      }
    }
  },
  "AllowedHosts": "*",
  "ConnectionStrings": {
    "FredsCarsMvcConnection": "Server=(localdb)\\MSSQLLocalDB;Database=FredsCarsMvc;Trusted_Connection=True;MultipleActiveResultSets=true"
  }
}

FredsCars\appsettings.json

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.AspNetCore": "Warning"
    }
  },
  "Serilog": {
    "MinimumLevel": {
      "Override": {
        "FredsCars": "Debug"
      }
    }
  },
  "AllowedHosts": "*"
}

And now, after restarting the application, our console logging looks the same as it did before we implemented Serilog to persist our log entries to the database.

dbug: FredsCars[0]
      Pipeline configuration starting.
dbug: FredsCars[0]
      Pipeline configuration finished.
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand ("4"ms) [Parameters=[""], CommandType='Text', CommandTimeout='30']"
      ""SELECT CASE
          WHEN EXISTS (
              SELECT 1
              FROM [Vehicle] AS [v]) THEN CAST(1 AS bit)
          ELSE CAST(0 AS bit)
      END"
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand ("1"ms) [Parameters=[""], CommandType='Text', CommandTimeout='30']"
      ""SELECT CASE
          WHEN EXISTS (
              SELECT 1
              FROM [VehicleType] AS [v]) THEN CAST(1 AS bit)
          ELSE CAST(0 AS bit)
      END"
info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[63]
      User profile is available. Using '"C:\Users\smill\AppData\Local\ASP.NET\DataProtection-Keys"' as key repository and Windows DPAPI to encrypt keys at rest.
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: "https://localhost:40443"
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: "http://localhost:40080"
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: "Development"
info: Microsoft.Hosting.Lifetime[0]
      Content root path: "C:\Development\FredsCars\MVC\Module27\FredsCars\FredsCars"

Now, once again throw the DbUpdate Exception in EditPost by following the steps in the section Demonstrate throwing DbUpdate Exception from browser.

We still see the error (shortcut name: fail) LogLevel message we log to the console from the catch bock of EditPost:

_logger.LogError(eventId, "DbUpdate error for Vehicle ID {id}\nMessage: {Message}\nSource: {Source}\nStackTrace: {StackTrace}\nTargetSite{TargetSite}",
    id,
    message,
    ex.Source,
    ex.StackTrace,
    ex.TargetSite
);
fail: FredsCars.Controllers.VehiclesController[2]
      DbUpdate error for Vehicle ID 2
Message: "An error occurred while saving the entity changes. See the inner exception for details. --> Cannot insert duplicate key row in object 'dbo.Vehicle' with unique index 'IX_Vehicle_VIN'. The duplicate key value is (1C6RJTBG0SL532163)."
Source: "Microsoft.EntityFrameworkCore.Relational"
StackTrace: "   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeAsync(RelationalDataReader reader, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.SqlServer.Update.Internal.SqlServerModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Storage.RelationalDatabase.SaveChangesAsync(IList`1 entries, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(IList`1 entriesToSave, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(StateManager stateManager, Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
         at FredsCars.Models.Repositories.EFVehicleRepository.UpdateAsync(Vehicle vehicle) in C:\Development\FredsCars\MVC\Module27\FredsCars\FredsCars\Models\Repositories\EFVehicleRepository.cs:line 26
         at FredsCars.Controllers.VehiclesController.EditPost(Int32 id) in C:\Development\FredsCars\MVC\Module27\FredsCars\FredsCars\Controllers\VehiclesController.cs:line 113"
TargetSite"Void MoveNext()"

But now we can also see the log entry stored in SQL Server (from either SSMS or SSOX) with the message string that starts with “DbUpdate error for Vehicle ID 2”.

And as promised that error log is searchable.
Now we could run an SQL Query similar to the following to find this error:

Search Serilog Properties: key/value pairs

Query XML

As noted earlier, Serilog uses key/value pairs to create log entries. And these key/value(s) are stored for each SQL Server log entry in the properties column in XML format.

The following is the XML stored in the properties column for a log entry that was created in the catch block of EditPost where we log DbUpdateException(s).

<properties><property key='id'>2</property>
<property key='Message'>An error occurred while saving the entity changes.
	See the inner exception for details.
	--&gt; Cannot insert duplicate key row in object 'dbo.Vehicle'
	with unique index 'IX_Vehicle_VIN'.
	The duplicate key value is (1C6RJTBG0SL532163).
</property>
<property key='Source'>
	Microsoft.EntityFrameworkCore.Relational
</property>
<property key='StackTrace'>
	at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeAsync(RelationalDataReader reader, CancellationToken cancellationToken)
	at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
	at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
	at Microsoft.EntityFrameworkCore.SqlServer.Update.Internal.SqlServerModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
	at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
	at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
	at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
	at Microsoft.EntityFrameworkCore.Storage.RelationalDatabase.SaveChangesAsync(IList`1 entries, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(IList`1 entriesToSave, CancellationToken cancellationToken)
	at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(StateManager stateManager, Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
	at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
	at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
	at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
	at FredsCars.Models.Repositories.EFVehicleRepository.UpdateAsync(Vehicle vehicle) in C:\Development\FredsCars\MVC\Module27\FredsCars\FredsCars\Models\Repositories\EFVehicleRepository.cs:line 26
	at FredsCars.Controllers.VehiclesController.EditPost(Int32 id) in C:\Development\FredsCars\MVC\Module27\FredsCars\FredsCars\Controllers\VehiclesController.cs:line 113</property>
<property key='TargetSite'>
	Void MoveNext()
</property>

<property key='EventId'>
	<structure type=''>
		<property key='Id'>2</property>
		<property key='Name'>DbUpdateFailure</property>
	</structure>
</property>

<property key='SourceContext'>
	FredsCars.Controllers.VehiclesController
</property>
<property key='ActionId'>
	b6b79c06-00f5-41c4-aedc-ce629d522141
</property>
<property key='ActionName'>
	FredsCars.Controllers.VehiclesController.EditPost (FredsCars)
</property>
<property key='RequestId'>0HNFABQPDF0O8:00000001</property>

<property key='RequestPath'>
	/Vehicles/Edit/2
</property>

<property key='ConnectionId'>0HNFABQPDF0O8</property></properties>

Let’s zero in on one of the specific property nodes in the above XML with the key EventId:

<property key='EventId'>
	<structure type=''>
		<property key='Id'>2</property>
		<property key='Name'>DbUpdateFailure</property>
	</structure>
</property>

Remember when we log the event in the catch block of EditPost the first thing we do is create an EventId:

var eventId = new EventId(id, "DbUpdateFailure");

The first parameter, Event.Id, receives its value from the id value in the querystring representing the Vehicle being updated. The Event.Id shows up in brackets in the console. But, recall it was disappointing we could not see the Event.Name, here “DbUpdateFailure”, in the console.

Fortunately, it does show up in the Properties column of an SQL Server entry in the EventId/Name Property node of the XML.

<property key='EventId'>
	<structure type=''>
		<property key='Id'>2</property>
		<property key='Name'>DbUpdateFailure</property>
	</structure>
</property>

The XML property node above with the key EventId itself has two property nodes contained in a structure. The first with a key of Id representing Event.Id ([2]), and the second with a key of Name representing Event.Name (DbUpdateFailure).
(Maybe DbVehicleUpdateFailue would have been a more specific name for us to use here.)

Say we get a report that a user was trying to update a vehicle on September 2nd, 2025 and received an error:
There was a problem updating the vehicle.Please contact your system administrator.

We could now perform an SQL Query from SSMS or SSOX to search for the error in the FredsCarsMvc.LogEvents table in SQL Server.

SELECT * FROM
(
	SELECT ID, Message, Level, TimeStamp,
		CAST(Properties AS xml).value('(/properties/property[@key="EventId"]/structure/property[@key="Id"]/text())[1]', 'int') AS EventId,
		CAST(Properties AS xml).value('(/properties/property[@key="EventId"]/structure/property[@key="Name"]/text())[1]', 'nvarchar(100)') AS EventName
	FROM LogEvents
) AS x
WHERE CAST(TimeStamp AS date) = '2025-09-02'
AND EventId = 2
AND EventName = 'DbUpdateFailure'

In the above SQL, we are querying the LogEvents table to return the ID, Message, Level, and TimeStamp columns along with the EventId and EventName values from the Properties XML from all rows where the date is ‘2025-09-02’, EventId is 2, and EventName equals the string ‘DbUpdateFailure’.

The results would look similar to the following:

IDMessageLevelTimeStampEventIdEventName
207DbUpdate error for Vehicle ID 2 Message: “An error occurred…”Error2025-09-02 16:27:04.7902DbUpdateFailure

Note: If you don’t know what SQL is, it stands for Structured Query Language. It is the language used to query databases. There is a standardized version of SQL called ANSII SQL by the American National Standards Institute. But all databases implement their own versions with their own special features.
For instance SQL Server has MSSQL. And Oracle has PL/SQL.

The XML stored in the Properties column and the SQL to query it tend to look a bit tortured. XML is an older configuration and storage format. One of its biggest benefits was supposed to be that it was human readable. But it’s file size can become enormous to transfer across the network, and it can actually be quite cumbersome to read, and query.

In pre-Core ASP.Net, before there was any such thing as appsettings.json, configuration was stored in an XML file called web.config. It was not pretty. And that is all I will say on that.

The current preferred configuration and transfer format is now JSON (JavaScript Object Notation). We have seen a few examples of JSON configuration files in our own project including appsettings.json and libman.json.

Query JSON

By default, Serilog.Sinks.MSSqlServer (the SQL Server sink) supports two formats for the keys/values column:

  • XML: default formatter
    • The default, for backward compatibility with its very early version.
    • Logs to a column called Properties.
    • This is why we saw xml: <properties>...</properties> in the Properties column.
    • Querying requires XQuery, which is clunkier than JSON functions.
  • JSON: JsonFormatter
    • Logs to a column called LogEvent
    • Much easier to query

Since we have acknowledged how clunky working with XML is, let’s see if we can get Serilog to store key/value fields as JSON instead.

Modify the Serilog configuration in Program.cs with the following changes below.

FredsCars\Program.cs

... existing code ...
var builder = WebApplication.CreateBuilder(args);

// Add Serilog support
// -- configuring Host
var columnOptions = new ColumnOptions();
columnOptions.Store.Remove(StandardColumn.Properties);
columnOptions.Store.Add(StandardColumn.LogEvent);

builder.Host.UseSerilog((ctx, lc) => lc
    .ReadFrom.Configuration(ctx.Configuration)
    .WriteTo.MSSqlServer(connectionString:
        ctx.Configuration.GetConnectionString("FredsCarsMvcConnection"),
        restrictedToMinimumLevel: LogEventLevel.Debug,
        sinkOptions: new MSSqlServerSinkOptions
        {
            TableName = "LogEvents",
            AutoCreateSqlTable = true
        },
        columnOptions: columnOptions
    ),
    //.WriteTo.Console()
    writeToProviders: true
);

// Add Services
builder.Services.AddControllersWithViews();
... existing code ...

In the code above we are adding a ColumnOptions object to the Serilog MSSqlServer sink configuration. In building the ColumnOptions object, we remove the column used to store key/value pairs in XML, Properties, and add the column used to store key/value pairs in JSON, LogEvent.

var columnOptions = new ColumnOptions();
columnOptions.Store.Remove(StandardColumn.Properties);
columnOptions.Store.Add(StandardColumn.LogEvent);

Then we add the ColumnOptions object right after the sinkOptions in the configuration.

sinkOptions: new MSSqlServerSinkOptions
{
    TableName = "LogEvents",
    AutoCreateSqlTable = true
},
columnOptions: columnOptions

At this point we can get rid of the Properties column by deleting the FredsCarsMvc database. We will then recreate the database without the Properties column and with the LogEvent column by running the application with the new ColumnOptions configuration. Run the following command in the command window with the command prompt pointed at the FredsCars project folder.

dotnet ef database drop

Answer ‘y’ when asked:

Are you sure you want to drop the database 'FredsCarsMvc' on server '(localdb)\MSSQLLocalDB'? (y/N)

Now run the application from a command window pointed at the FredsCars project folder with the following command as usual.

 dotnet run --launch-profile "HTTPS"

The FredsCarsMvc database gets recreated withe the LogEvents column to store key/value pairs in JSON and their is no XML Properties column.

Since we dropped the database and recreated it, go ahead and re-insert the 2025 Jeep Gladiator Rubicon 4 X 4 we created in module 23 following the instruction in the section Insert a new Vehicle.

Now, once again recreate a DbUpdateException in EditPost by following the instructions in the Demonstrate throwing DbUpdate Exception from browser section.

In SSOX or SSMS run the SQL query:

SELECT * FROM LogEvents
WHERE Message LIKE 'DbUpdate error for Vehicle ID%'

In the results pane shown above you can see we get back one row from LogEvents where we threw a DbUpdateException trying to insert a duplicate VIN number.

And, the LogEvent column contains the Serilog key/value pairs in JSON format as shown below. (When I cut and pasted into textpad it was all on one line. But I am showing it in indented format below.)

{
	"TimeStamp":"2025-09-08T07:48:01.3562240",
	"Level":"Error",
	"Message":"DbUpdate error for Vehicle ID 1\nMessage: \"An error occurred while saving the entity changes. See the inner exception for details. 
		--> Cannot insert duplicate key row in object 'dbo.Vehicle' with unique index 'IX_Vehicle_VIN'.
			The duplicate key value is (1C6RJTBG0SL532163).\"\n
	Source: \"Microsoft.EntityFrameworkCore.Relational\"\n
	StackTrace: \"   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeAsync(RelationalDataReader reader, CancellationToken cancellationToken)\r\n
		at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)\r\n   at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)\r\n   
		at Microsoft.EntityFrameworkCore.SqlServer.Update.Internal.SqlServerModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)\r\n   
		at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)\r\n   
		at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)\r\n   
		at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)\r\n   
		at Microsoft.EntityFrameworkCore.Storage.RelationalDatabase.SaveChangesAsync(IList`1 entries, CancellationToken cancellationToken)\r\n   
		at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(IList`1 entriesToSave, CancellationToken cancellationToken)\r\n   
		at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(StateManager stateManager, Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)\r\n   
		at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)\r\n   
		at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)\r\n   
		at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)\r\n   
		at FredsCars.Models.Repositories.EFVehicleRepository.UpdateAsync(Vehicle vehicle) in C:\\Development\\FredsCars\\MVC\\Module27\\FredsCars\\FredsCars\\Models\\Repositories\\EFVehicleRepository.cs:line 26\r\n
		at FredsCars.Controllers.VehiclesController.EditPost(Int32 id) in C:\\Development\\FredsCars\\MVC\\Module27\\FredsCars\\FredsCars\\Controllers\\VehiclesController.cs:line 113\"\n
	TargetSite\"Void MoveNext()\"","MessageTemplate":"DbUpdate error for Vehicle ID {id}\nMessage: {Message}\n
	Source: {Source}\nStackTrace: {StackTrace}\n
	TargetSite{TargetSite}",
	"Properties":{
		"id":1,
		"Message":"An error occurred while saving the entity changes.
			See the inner exception for details. 
			--> Cannot insert duplicate key row in object 'dbo.Vehicle' with unique index 'IX_Vehicle_VIN'.
			The duplicate key value is (1C6RJTBG0SL532163).",
		"Source":"Microsoft.EntityFrameworkCore.Relational",
		"StackTrace":"   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeAsync(RelationalDataReader reader, CancellationToken cancellationToken)\r\n
			at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)\r\n   
			at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)\r\n   
			at Microsoft.EntityFrameworkCore.SqlServer.Update.Internal.SqlServerModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)\r\n   
			at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)\r\n   
			at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)\r\n   
			at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)\r\n   
			at Microsoft.EntityFrameworkCore.Storage.RelationalDatabase.SaveChangesAsync(IList`1 entries, CancellationToken cancellationToken)\r\n   
			at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(IList`1 entriesToSave, CancellationToken cancellationToken)\r\n   
			at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(StateManager stateManager, Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)\r\n   
			at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)\r\n   
			at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)\r\n   
			at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)\r\n   
			at FredsCars.Models.Repositories.EFVehicleRepository.UpdateAsync(Vehicle vehicle) in C:\\Development\\FredsCars\\MVC\\Module27\\FredsCars\\FredsCars\\Models\\Repositories\\EFVehicleRepository.cs:line 26\r\n
			at FredsCars.Controllers.VehiclesController.EditPost(Int32 id) in C:\\Development\\FredsCars\\MVC\\Module27\\FredsCars\\FredsCars\\Controllers\\VehiclesController.cs:line 113",
		"TargetSite":"Void MoveNext()",
		"EventId":{"Id":1,"Name":"DbUpdateFailure"},
		"SourceContext":"FredsCars.Controllers.VehiclesController","ActionId":"acee95ba-5a7f-4579-a1c1-deac5fc1a872",
		"ActionName":"FredsCars.Controllers.VehiclesController.EditPost (FredsCars)",
		"RequestId":"0HNFE5EUM95EO:0000002F",
		"RequestPath":"/Vehicles/Edit/1","ConnectionId":"0HNFE5EUM95EO"
	}
}

Just like in the XML format, we can hone in on the EventId property in the JSON.

"EventId":{"Id":1,"Name":"DbUpdateFailure"}

And again, we can see the EventId.Name property, “DbUpdateFailure”.

Now if a user reports an error occured while trying to create a Vehicle on September 8th, 2025, we could run a SQL query similar to the following to find it.

SELECT * FROM
(
	SELECT ID, Message, Level, TimeStamp,
		JSON_VALUE(LogEvent, '$.Properties.EventId.Id') AS EventId,
		JSON_VALUE(LogEvent, '$.Properties.EventId.Name') AS EventName
	FROM LogEvents
) AS x
WHERE CAST(TimeStamp AS date) = '2025-09-08'  --Replace with your time
AND EventId = 1
AND EventName = 'DbUpdateFailure'

Run Unit Tests

Any time we have completed a substantial amount of work like we have in this module and reached another milestone having completed another feature, in this case logging, we should always give all of our unit tests a run.

Go ahead and run all of the test as usual from Test Explorer.

A pop up dialogue in Visual Studio will alert you that there were build errors. And the Error List pane at the bottom of the VS IDE shows us there are four errors in the VehiclesControllerTests class.

Because we added an ILogger parameter to the VehiclesController constructor, we now need to pass some sort of ILogger every time we try to instantiate a VehiclesController from a Unit test.

Fix the Unit Tests

Let’s start by setting up a global ILogger to use from all of our unit tests in the VehiclesControllerTests class.

Make the following changes to the VehiclesControllerTests shown below.

FredsCars\FredsCars.Tests\Controllers\VehiclesControllerTests.cs

using FredsCars.Models.Repositories;
using FredsCars.Tests.Infrastructure;
using Microsoft.AspNetCore.Mvc;
using Microsoft.EntityFrameworkCore;
using Microsoft.Extensions.Logging;
using MockQueryable;
using Moq;
using System.Text.RegularExpressions;

namespace FredsCars.Tests.Controllers
{
    public class VehiclesControllerTests 
    {
        #region class fields for tests that use SqliteInMemory db
        private readonly SqliteInMemoryDbContextFactory _factory;
        private readonly FredsCarsDbContext _context;
        private readonly EFVehicleRepository _vRepo;
        private readonly EFVehicleTypeRepository _vtRepo;
        #endregion

        private readonly Mock<ILogger<VehiclesController>> _mockLogger;

        public VehiclesControllerTests()
        {
            #region Setup for for tests that use SqliteInMemory db
            _factory = new SqliteInMemoryDbContextFactory();
            _context = _factory.CreateContext();
            _vRepo = new EFVehicleRepository(_context);
            _vtRepo = new EFVehicleTypeRepository(_context);
            #endregion

            _mockLogger = new Mock<ILogger<VehiclesController>>();
        }

In the above code we have set up a global class level private field to hold our mock ILogger. Make sure to include the using Microsoft.Extensions.Logging namespace in a using statement at the top of the file as shown.

using Microsoft.Extensions.Logging;

Now we need to pass the mock ILogger in each of the four unit tests we instantiate the VehiclesController.

[Fact]
public async Task Can_Access_Vehicle_ById()
{
    // Arrange
    // 1 - create a List<T> with test items
    var vehicles = new List<Vehicle>
    {
       ... existing code ...

    // 2 - build mock using MockQueryable.Moq extension 
    var mockVehiclesIQueryable = vehicles.BuildMock();

    // 3 - build mock IVehicleRepository
    ... existing code ...

    VehiclesController controller =
        new VehiclesController(mockVehicleRepo.Object,
            mockVehicleTypeRepo.Object,
            _mockLogger.Object);
 [Fact]
 public async Task Can_Send_NoVehicleFoundMessage()
 {
     // Arrange
     // 1 - create a List<T> with test items
     var vehicles = new List<Vehicle>
     {
         ... existing code ...
     };

     // 2 - build mock using MockQueryable.Moq extension 
     var mockVehiclesIQueryable = vehicles.BuildMock();

     // 3 - build mock IVehicleRepository
     
     ... existing code ...
     
     VehiclesController controller =
         new VehiclesController(mockVehicleRepo.Object,
         mockVehicleTypeRepo.Object,
         _mockLogger.Object);
         
    ... existing code ...
[Fact]
public async Task Can_Create_Vehicle()
{
    // Arrange
    var options =
        new DbContextOptionsBuilder<FredsCarsDbContext>()
            .UseInMemoryDatabase($"FredCars-{Guid.NewGuid().ToString()}")
            .Options;

    using var context = new FredsCarsDbContext(options);

    var vRepo = new EFVehicleRepository(context);
    var vtRepo = new EFVehicleTypeRepository(context);

    var target = new VehiclesController(
        vRepo, vtRepo,
        _mockLogger.Object);
[Fact]
public async Task Can_Delete_Vehicle()
{
    // Arrange
    #region Arrange - seed VehicleTypes
    await _context.VehicleTypes.AddRangeAsync(
        ... existing code ...
    );
    await _context.SaveChangesAsync();
    #endregion

    #region Arrange - seed Vehicles test data
    
    ... existing code ...

    // Check vehicles were created
    Assert.True(_vRepo.Vehicles.Count() == 2);

    // Arrange - controller
    var target = new VehiclesController(
        _vRepo, _vtRepo,
        _mockLogger.Object);

Once the four tests have been updated to pass the mock ILogger to the controller constructor, again run all of the tests from Test Explorer. This time the project will build and the tests will all run and pass except for one; Can_Update_Vehicle.

The error Message property displays the following text mentioning the connection string cannot be null:

Message: 
System.ArgumentNullException : Value cannot be null. (Parameter 'connectionString')

And the StackTrace is referencing the MSSqlServerSinkFactory:

MSSqlServerSinkFactory.Create(String connectionString...

Since it mentions the SQL Server sink factory, and a null connection string, we have a hint that for some reason Serilog cannot find the connection string in the Program.cs setup when run from the Can_Update_Vehicle test.

Fix Can_Update_Vehicle unit test

Make the following change to Program.cs

FredsCars\Program.cs

... existing code ...
// Add Serilog support
// -- configuring Host
if (AppDomain.CurrentDomain.FriendlyName != "ef"
    && AppDomain.CurrentDomain.FriendlyName != "testhost")
{
    var columnOptions = new ColumnOptions();
    columnOptions.Store.Remove(StandardColumn.Properties);
    columnOptions.Store.Add(StandardColumn.LogEvent);

    builder.Host.UseSerilog((ctx, lc) => lc
        .ReadFrom.Configuration(ctx.Configuration)
        .WriteTo.MSSqlServer(connectionString:
            ctx.Configuration.GetConnectionString("FredsCarsMvcConnection"),
            restrictedToMinimumLevel: LogEventLevel.Debug,
            sinkOptions: new MSSqlServerSinkOptions
            {
                TableName = "LogEvents",
                AutoCreateSqlTable = true
            },
            columnOptions: columnOptions
        ),
        //.WriteTo.Console()
        writeToProviders: true
    );
}
... existing code ...

In the code above we have added a condition to the if/block containing the Serilog configuration code.

if (AppDomain.CurrentDomain.FriendlyName != “ef”
&& AppDomain.CurrentDomain.FriendlyName != “testhost”)

Now, the Serilog configuration will not run if the current AppDomain is EF Core, because if we drop the database we don’t want EF Core to try and configure Serilog when we recreate the DB with
dotnet ef database update.
And now we also do not want to configure Serilog if the application is running in test mode.

Go ahead and run the Can_Update_Vehicle unit test and it should pass.

What’s Next

In this module we learned all about logging in ASP.Net Core. We learned about the ILogger service, logging providers, LogLevels, and configuration. We looked at how framework log entries get generated as well as how to log our own from Program.cs and our code. We also learned how to persist log entries to a database using a third party logging library called Serilog.

Since logging and configuration are so tied together, I also want to talk about a feature called Secrets, which allows a developer to keep configuration settings such as connection strings and passwords stored on their machine in a mannor where they will not be copied into the code repository every time the developer checks in their code. And that is what we are going to do in the next module.

< Prev
Next >

Leave a Reply