ASP.NET Core Logging with Serilog and SQL Server

January 07, 2018

dotnetsqlserver

Serilog is a great 3rd party library for structured logging in our ASP.NET core apps. Structured logging is key to producing easily readable and filterable logs.

Using SQL Server as a log destination, allows us to leverage the power of SQL querying for log filtering. It can be a good choice if our app is already using SQL Server.

So, how do we implement a Serilog SQL log in ASP.NET Core 2.0 …

First we need to bring in the following nuget packages:

Serilog.AspNetCore
Serilog.Settings.Configuration
Serilog.Sinks.MSSqlServer

Next up, we need to change how logging is setup in Program.cs. The 3 lines at the start of Main() tells the program to use Serilog as the logger and to read the configuration from appsettings.json.

public class Program
{
    public static IConfiguration Configuration { get; } = new ConfigurationBuilder()        .SetBasePath(Directory.GetCurrentDirectory())        .AddJsonFile("appsettings.json", optional: false, reloadOnChange: true)        .AddJsonFile($"appsettings.{Environment.GetEnvironmentVariable("ASPNETCORE_ENVIRONMENT") ?? "Production"}.json", optional: true)        .Build();
    public static void Main(string[] args)
    {
        Log.Logger = new LoggerConfiguration()            .ReadFrom.Configuration(Configuration)            .CreateLogger();
        try
        {
            Log.Information("Getting the motors running...");

            BuildWebHost(args).Run();
        }
        catch (Exception ex)
        {
            Log.Fatal(ex, "Host terminated unexpectedly");
        }
        finally
        {
            Log.CloseAndFlush();
        }
    }

    public static IWebHost BuildWebHost(string[] args) =>
        WebHost.CreateDefaultBuilder(args)
               .UseStartup<Startup>()
               .UseConfiguration(Configuration)
               .UseSerilog()               .Build();
}

Serilog can then be configured to use SQL Server as a destination in appSettings.json, along with the minimum logging level. We need to specify the connection string for the logging database and the table name to log the data into.

{
  ...
  "Serilog": {
    "MinimumLevel": "Information",
    "WriteTo": [
      {
        "Name": "MSSqlServer",
        "Args": {
          "connectionString": "<our connection string>",
          "tableName": "Log"
        }
      }
    ]
  },
  ...
}

We can get Serilog to create our Log table automatically but let’s do this outselves so that we have control of our schema. For example, we want the Properties column to be based on the xml data type so that we can query it (serilog creates this as nvarchar).

Below is TSQL script to create the Log table:

CREATE TABLE [Log] (

   [Id] int IDENTITY(1,1) NOT NULL,
   [Message] nvarchar(max) NULL,
   [MessageTemplate] nvarchar(max) NULL,
   [Level] nvarchar(128) NULL,
   [TimeStamp] datetimeoffset(7) NOT NULL,
   [Exception] nvarchar(max) NULL,
   [Properties] xml NULL,
   [LogEvent] nvarchar(max) NULL

   CONSTRAINT [PK_Log]
     PRIMARY KEY CLUSTERED ([Id] ASC)

)

We can then write to the log in our code, logging structured objects using {@object} in the message template. Below is a web API action method for getting and returning a record (a contact in this case). We log when the contact is fetched from the cache / database and also when the contact is set in the cache.

[HttpGet("{contactId}")]
public async Task GetById(Guid contactId)
{
// Initialise the contact that is going to be returned
Contact contact = null;

    // Get the requested ETag
    string requestETag = "";
    if (Request.Headers.ContainsKey("If-None-Match"))
    {
        requestETag = Request.Headers["If-None-Match"].First();

        if (!string.IsNullOrEmpty(requestETag))
        {
            // The client has supplied an ETag, so, get this version of the contact from our cache

            // Construct the key for the cache which includes the entity type (i.e. "contact"), the contact id and the version of the contact record (i.e. the ETag value)
            string oldCacheKey = $"contact-{contactId}-{requestETag}";

            // Get the cached item
            string cachedContactJson = await cache.GetStringAsync(oldCacheKey);

            // If there was a cached item then deserialise this into our contact object
            if (!string.IsNullOrEmpty(cachedContactJson))
            {
                contact = JsonConvert.DeserializeObject(cachedContactJson);

                Log.Information("Contact {@contact} retrieved from cache", contact);            }
        }
    }

    // We have no cached contact, then get the contact from the database
    if (contact == null)
    {
        contact = await dataRepository.GetContactByIdAsync(contactId);

        Log.Information("Contact {@contact} retrieved from database", contact);    }

    // If no contact was found in the cache or the database, then return a 404
    if (contact == null)
    {
        Log.Information("Contact {@contactId} not found", contactId);        return NotFound();
    }

    // Construct the new ETag
    string responseETag = Convert.ToBase64String(contact.RowVersion);

    // Return a 304 if the ETag of the current record matches the ETag in the "If-None-Match" HTTP header
    if (Request.Headers.ContainsKey("If-None-Match") && responseETag == requestETag)
    {
        return StatusCode((int)HttpStatusCode.NotModified);
    }

    // Add the contact to the cache for 30 mins
    string cacheKey = $"contact-{contactId}-{responseETag}";
    await cache.SetStringAsync(cacheKey, JsonConvert.SerializeObject(contact), new DistributedCacheEntryOptions() { AbsoluteExpiration = DateTime.Now.AddMinutes(30) });
    Log.Information("Contact {@contact} added to cache with key {@cacheKey}", contact, cacheKey);
    // Add the current ETag to the HTTP header
    Response.Headers.Add("ETag", responseETag);

    return Ok(contact);
}

Now that Serilog and SQL Server are setup, wired together and we have some logging code, we should get our logs output to our SQL Server table.

Note that if we have problems getting the log to write to SQL Server, we can use Serilog.Debugging.SelfLog.Enable() in Program.Main() to surface errors from Serilog.

public class Program
{
    public static int Main(string[] args)
    {
        Log.Logger = new LoggerConfiguration()
            .ReadFrom.Configuration(Configuration)
            .CreateLogger();

        Serilog.Debugging.SelfLog.Enable(msg =>        {            Debug.Print(msg);            Debugger.Break();        });        ...
    }
    ...
}

The Properties column contains useful additional information, including what we specified in our structured log after the contact is added to the cache is:

We can extract specific data in the Properties column using XQuery syntax. We can even filter on values in the Properties column.

For example, if we wanted to find when a particular contact was added to the cache, we could use something like:

SELECT
	Properties.value('(/properties/property[@key="contact"]/structure[@type="Contact"]/property[@key="ContactId"])[1]', 'nvarchar(max)') AS ContactId,
	Properties.value('(/properties/property[@key="contact"]/structure[@type="Contact"]/property[@key="FirstName"])[1]', 'nvarchar(50)') AS FirstName,
	Properties.value('(/properties/property[@key="contact"]/structure[@type="Contact"]/property[@key="Surname"])[1]', 'nvarchar(100)') AS Surname,
	Properties.value('(/properties/property[@key="cacheKey"])[1]', 'nvarchar(100)') AS CacheKey,
	*
FROM Log
WHERE MessageTemplate = 'Contact {@contact} added to cache with key {@cacheKey}'
	AND Properties.value('(/properties/property[@key="contact"]/structure[@type="Contact"]/property[@key="ContactId"])[1]', 'nvarchar(max)') = 'f7d10f53-4c11-44f4-8dce-d0e0e22cb6ab'

Pretty useful!

If you to learn about using React with ASP.NET Core you might find my book useful:

ASP.NET Core 5 and React

Find out more

You might find some of my other posts interesting:

Why React with ASP.NET Core?

What's new in ASP.NET Core 3 for React SPAs?

Scalable and Performant ASP.NET Core Web APIs: Asynchronous Code

Integration Testing on ASP.NET Core Web API controllers with a SQL backend