Adding Useful Information to ASP.NET Core Web API Serilog Logs

January 14, 2018

dotnet

In my last post, we setup structured logging leveraging Serilog and SQL Server. In this post, we’ll look closely at the log entries themselves for a web API - what comes out of the box, what’s missing and how we can fill the gaps …

A good log saves debugging time - particularly in production, by quickly helping us to pin point the root of a problem. A log containing a wealth of relevant information, reduces the amount of “I can’t reproduce” issues.

What we get out of the box

Let’s look at what we get out of the box then. We’ve already enabled Serilog with SQL Server as the destination. Let’s now tell Serilog to log as much as it can in appSettings.json:

"Serilog": {
    "MinimumLevel": {
        "Default": "Debug",
        "Override": {
            "Microsoft": "Debug"
        }
    },
    ...
}

We have a super simple controller for a contact resource in our web API that sits on top of an EF core data context. We only have methods for getting a record and inserting a record. This will be fine for allowing us to have close look at the log entries that are generated.

[Route("api/Contacts")]
public class ContactsController : Controller
{
    private readonly DataContext dataContext;

    public ContactsController(DataContext dataContext)
    {
        this.dataContext = dataContext;
    }

    [HttpGet("{contactId}", Name = "GetContact")]
    public IActionResult GetById(Guid contactId)
    {
        Contact contact = dataContext.Contacts.Where(c => c.ContactId == contactId).SingleOrDefault();

        if (contact == null)
        {
            return NotFound();
        }

        return Ok(contact);
    }

    [HttpPost]
    public IActionResult Post([FromBody]Contact contact)
    {
        contact.ContactId = Guid.NewGuid();
        dataContext.Contacts.Add(contact);
        dataContext.SaveChanges();

        return CreatedAtRoute("GetContact", new { contactId = contact.ContactId }, contact);
    }
}

We also have an even more simplistic authentication controller that signs us in as “Carl” if we POST api/auth

[Route("api/auth")]
public class AuthController : Controller
{
    [HttpPost]
    public async Task<IActionResult> Post()
    {
        var claims = new List<Claim> {
            new Claim(ClaimTypes.Name, "Carl")
        };
        var claimsIdentity = new ClaimsIdentity(claims, CookieAuthenticationDefaults.AuthenticationScheme);

        await HttpContext.SignInAsync(CookieAuthenticationDefaults.AuthenticationScheme, new ClaimsPrincipal(claimsIdentity));

        return Ok();
    }
}

After signing in and calling GET api/contacts/{contactId} we get:

That’s quite a bit of information, but let’s drill in more …

These are the properties we get from the request:

<properties>
  <property key="Protocol">HTTP/1.1</property>
  <property key="Method">GET</property>
  <property key="ContentType" />
  <property key="ContentLength" />
  <property key="Scheme">http</property>
  <property key="Host">localhost:1798</property>
  <property key="PathBase" />
  <property key="Path">/api/contacts/f7d10f53-4c11-44f4-8dce-d0e0e22cb6ab</property>
  <property key="QueryString" />
  <property key="HostingRequestStartingLog">Request starting HTTP/1.1 GET http://localhost:1798/api/contacts/f7d10f53-4c11-44f4-8dce-d0e0e22cb6ab  </property>
  <property key="EventId">
    <structure type="">
      <property key="Id">1</property>
    </structure>
  </property>
  <property key="SourceContext">Microsoft.AspNetCore.Hosting.Internal.WebHost</property>
  <property key="RequestId">0HLAR88PEA3OA:00000002</property>
  <property key="RequestPath">/api/contacts/f7d10f53-4c11-44f4-8dce-d0e0e22cb6ab</property>
  <property key="Version">1.0.0.0</property>
</properties>

Notice that the request headers and body are missing. There is no information about the signed in user.

These are the properties we get from the response:

<properties>
  <property key="ElapsedMilliseconds">327.8173</property>
  <property key="StatusCode">200</property>
  <property key="ContentType">application/json; charset=utf-8</property>
  <property key="HostingRequestFinishedLog">Request finished in 327.8173ms 200 application/json; charset=utf-8</property>
  <property key="EventId">
    <structure type="">
      <property key="Id">2</property>
    </structure>
  </property>
  <property key="SourceContext">Microsoft.AspNetCore.Hosting.Internal.WebHost</property>
  <property key="RequestId">0HLAR88PEA3OA:00000002</property>
  <property key="RequestPath">/api/contacts/f7d10f53-4c11-44f4-8dce-d0e0e22cb6ab</property>
  <property key="Version">1.0.0.0</property>
</properties>

Notice that the response headers and body are missing. Again there is no information about the signed in user.

These are the properties we get from an EF core query execution:

<properties>
  <property key="elapsed">46</property>
  <property key="parameters">@__contactId_0='?'</property>
  <property key="commandType">Text</property>
  <property key="commandTimeout">30</property>
  <property key="newLine" />
  <property key="commandText">SELECT TOP(2) [c].[ContactPK], [c].[ContactId], [c].[FirstName], [c].[Surname], [c].[Title]
FROM [Contact] AS [c]
WHERE [c].[ContactId] = @__contactId_0</property>
  <property key="EventId">
    <structure type="">
      <property key="Id">200101</property>
      <property key="Name">Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted</property>
    </structure>
  </property>
  <property key="SourceContext">Microsoft.EntityFrameworkCore.Database.Command</property>
  <property key="ActionId">1af4d794-a694-4b3a-bb19-1c35e8c01794</property>
  <property key="ActionName">Logging.Controllers.ContactsController.GetById (Logging)</property>
  <property key="RequestId">0HLAR88PEA3OA:00000002</property>
  <property key="RequestPath">/api/contacts/f7d10f53-4c11-44f4-8dce-d0e0e22cb6ab</property>
  <property key="Version">1.0.0.0</property>
</properties>

Notice that the parameter value is missing - we just get ”?“.

Let’s create an exception by adding a field in our data model class that doesn’t exist in the database:

public class Contact
{
    ...
    public string BadField { get; set; }}

Here’s what we get when GET api/contacts/{contactId}:

EF core exception

If we drill into the 2 highlighted entries, we have the following properties:

<properties>
  <property key="elapsed">76</property>
  <property key="parameters">@__contactId_0='?'</property>
  <property key="commandType">Text</property>
  <property key="commandTimeout">30</property>
  <property key="newLine" />
  <property key="commandText">SELECT TOP(2) [c].[ContactPK], [c].[BadField], [c].[ContactId], [c].[FirstName], [c].[Surname], [c].[Title]
FROM [Contact] AS [c]
WHERE [c].[ContactId] = @__contactId_0</property>
  <property key="EventId">
    <structure type="">
      <property key="Id">200102</property>
      <property key="Name">Microsoft.EntityFrameworkCore.Database.Command.CommandError</property>
    </structure>
  </property>
  <property key="SourceContext">Microsoft.EntityFrameworkCore.Database.Command</property>
  <property key="ActionId">ff8b09a9-f1f3-4847-89ca-84cddab443e0</property>
  <property key="ActionName">Logging.Controllers.ContactsController.GetById (Logging)</property>
  <property key="RequestId">0HLARAMC5QKA4:00000002</property>
  <property key="RequestPath">/api/contacts/f7d10f53-4c11-44f4-8dce-d0e0e22cb6ab</property>
  <property key="Version">1.0.0.0</property>
</properties>

… and …

<properties>
  <property key="contextType">Logging.DataContext</property>
  <property key="newline" />
  <property key="error">System.Data.SqlClient.SqlException (0x80131904): Invalid column name 'BadField'.
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean&amp; dataReady)
   at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task&amp; task, Boolean asyncWrite, SqlDataReader ds)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior)
   at Microsoft.EntityFrameworkCore.Storage.Internal.RelationalCommand.Execute(IRelationalConnection connection, DbCommandMethod executeMethod, IReadOnlyDictionary`2 parameterValues)
   at Microsoft.EntityFrameworkCore.Storage.Internal.RelationalCommand.ExecuteReader(IRelationalConnection connection, IReadOnlyDictionary`2 parameterValues)
   at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.BufferlessMoveNext(Boolean buffer)
   at Microsoft.EntityFrameworkCore.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
   at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.MoveNext()
   at System.Linq.Enumerable.SingleOrDefault[TSource](IEnumerable`1 source)
   at lambda_method(Closure , QueryContext )
   at Microsoft.EntityFrameworkCore.Query.Internal.QueryCompiler.&lt;&gt;c__DisplayClass17_0`1.&lt;CompileQueryCore&gt;b__0(QueryContext qc)
ClientConnectionId:668b9fed-d230-48f3-9033-001ae29d8e2d
Error Number:207,State:1,Class:16</property>
  <property key="EventId">
    <structure type="">
      <property key="Id">100100</property>
      <property key="Name">Microsoft.EntityFrameworkCore.Query.QueryIterationFailed</property>
    </structure>
  </property>
  <property key="SourceContext">Microsoft.EntityFrameworkCore.Query</property>
  <property key="ActionId">ff8b09a9-f1f3-4847-89ca-84cddab443e0</property>
  <property key="ActionName">Logging.Controllers.ContactsController.GetById (Logging)</property>
  <property key="RequestId">0HLARAMC5QKA4:00000002</property>
  <property key="RequestPath">/api/contacts/f7d10f53-4c11-44f4-8dce-d0e0e22cb6ab</property>
  <property key="Version">1.0.0.0</property>
</properties>

So, it’s great that we have the call stack and SQL but the parameter value for the SQL would have been nice.

What’s missing and why?

So, the key information that is missing is:

The request headers
The request body
The response headers
The response body
The EF core query parameter values
The user name

I don’t know for sure why the above are missing but I’m guessing it’s a combination of security and performance.

In terms of security, we need to secure the logs. Irregardless of adding more sensitive data, they already contain sensitive information about the internals of our app. We’ve taken a great first step by putting them in SQL Server because a person will need a valid SQL logon in order to be able to access the log directly. If we expose the log via a web page, we need to make sure that page is authenticated and also protected by an appropriate authorisation rule. So, if we secure the log properly I think we are good to add the missing information.

In terms of performance, let’s do a bench mark performance test now and do the same again after we’ve added the missing information to determine the impact. We’re going to use Rick Strahl’s excellent Web Surge tool for the test.

Here’s the results of the bench mark test where we repeatedly GET api/contacts/{contactId} for 10 seconds. So, the average request time is 3.2ms when the app is running in IIS.

Before we go on and add this stuff, why do we need these bits of information? The information will help us pin problems down. The request headers and body are particularly important for web APIs - it’s much easier to reproduce a problem with a request, if we have all the information to replay it. If the problem is receiving unexpected data rather than an unexpected exception then the response headers and body give us all the information we need to work back through the request to determine what happened. In terms of the EF core queries, we can’t replay an exact query without the parameter values - e.g. a performance issue may be dependent on specific parameter values. Finally some problems are user specific, so capturing the user, allows us to quickly get all the log entries for the problematic user.

Adding EF core parameter values

This is a quick one. All we need to do is switch on “EnableSensitiveDataLogging” when the data context is configured.

public class DataContext : DbContext
{
    ...
    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    {
        optionsBuilder.EnableSensitiveDataLogging();    }
    ...
}

This now includes the parameter value in the log entry:

<properties>
  <property key="parameters">@__contactId_0='f7d10f53-4c11-44f4-8dce-d0e0e22cb6ab'</property>  ...
  <property key="commandText">SELECT TOP(2) [c].[ContactPK], [c].[ContactId], [c].[FirstName], [c].[Surname], [c].[Title]
FROM [Contact] AS [c]
WHERE [c].[ContactId] = @__contactId_0</property>
  ...
</properties>

Adding missing request and response information

This is a little more work. We’re going to use middleware so that we only have to write the code once (rather than add code to each controller and action method).

We’re going to call our middleware, SerilogRequestLogger. So, let’s register this when the app starts up. It is important that this is just after we add authentication in the middleware pipeline or we won’t have access to the user information.

public class Startup
{
    ...
    public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory, IServiceProvider serviceProvider)
    {
        app.UseAuthentication();
		app.UseMiddleware<SerilogRequestLogger>();        ...
        app.UseMvc();
    }
}

Now on to the implementation of the middleware. We add the user name to all the log entries by using LogContext.PushProperty. You can see capturing the request and response body is a little tricky because they are streams.

public class SerilogRequestLogger
{
    readonly RequestDelegate _next;

    public SerilogRequestLogger(RequestDelegate next)
    {
        if (next == null) throw new ArgumentNullException(nameof(next));
        _next = next;
    }

    public async Task Invoke(HttpContext httpContext)
    {
        if (httpContext == null) throw new ArgumentNullException(nameof(httpContext));

        // Push the user name into the log context so that it is included in all log entries
        LogContext.PushProperty("UserName", httpContext.User.Identity.Name);

        // Getting the request body is a little tricky because it's a stream
        // So, we need to read the stream and then rewind it back to the beginning
        string requestBody = "";
        httpContext.Request.EnableRewind();
        Stream body = httpContext.Request.Body;
        byte[] buffer = new byte[Convert.ToInt32(httpContext.Request.ContentLength)];
        await httpContext.Request.Body.ReadAsync(buffer, 0, buffer.Length);
        requestBody = Encoding.UTF8.GetString(buffer);
        body.Seek(0, SeekOrigin.Begin);
        httpContext.Request.Body = body;

        Log.ForContext("RequestHeaders", httpContext.Request.Headers.ToDictionary(h => h.Key, h => h.Value.ToString()), destructureObjects: true)
           .ForContext("RequestBody", requestBody)
           .Debug("Request information {RequestMethod} {RequestPath} information", httpContext.Request.Method, httpContext.Request.Path);


        // The reponse body is also a stream so we need to:
        // - hold a reference to the original response body stream
        // - re-point the response body to a new memory stream
        // - read the response body after the request is handled into our memory stream
        // - copy the response in the memory stream out to the original response stream
        using (var responseBodyMemoryStream = new MemoryStream())
        {
            var originalResponseBodyReference = httpContext.Response.Body;
            httpContext.Response.Body = responseBodyMemoryStream;

            await _next(httpContext);

            httpContext.Response.Body.Seek(0, SeekOrigin.Begin);
            var responseBody = await new StreamReader(httpContext.Response.Body).ReadToEndAsync();
            httpContext.Response.Body.Seek(0, SeekOrigin.Begin);

            Log.ForContext("RequestBody", requestBody)
               .ForContext("ResponseBody", responseBody)
               .Debug("Response information {RequestMethod} {RequestPath} {statusCode}", httpContext.Request.Method, httpContext.Request.Path, httpContext.Response.StatusCode);

            await responseBodyMemoryStream.CopyToAsync(originalResponseBodyReference);
        }
    }
}

Here’s an example of what we get in our request information log entry for a POST to api/contacts:

<properties>
  <property key="RequestMethod">POST</property>
  <property key="RequestPath">/api/contacts</property>
  <property key="RequestBody">{
    "title": "Mr",
    "firstName": "Carl",
    "surname": "Rippon"
}</property>
  <property key="RequestHeaders">
    <dictionary>
      <item key="Connection">Keep-Alive</item>
      <item key="Content-Type">application/json</item>
      <item key="Accept">*/*</item>
      <item key="Accept-Encoding">gzip, deflate</item>
      <item key="Cookie">.AspNetCore.Cookies=CfDJ8HTFDbvnzW5Hq8Go_JFbIbVl_3hh2ZcG1dYGV9eYn_i6U45lkzYQcno0lH34w6GMEIFtt4Azl8Sh8aNZySDlAmYc_DzTDhsOWsCk9AaWPh8kLh2mk3ilYckSuJfQ9qNr2Jc-urJXmBhMa9JqCcjd5CgfcW0nkXYbU3mzEqO6wcwgyh4oE_CZcQ5JvEPWhAiH9-4T7mfmcEH3WWqOCHK1ozvLXPgurRG2wPHlGXWvJsZ4pnCgmwqyC-fzIz8de97oiGthJL-taSiFw8C3X9sB4CaH4oggE7IJQG1x9Wjia5kQ</item>
      <item key="Host">localhost:1798</item>
      <item key="User-Agent">PostmanRuntime/6.4.1</item>
      <item key="Content-Length">71</item>
      <item key="Postman-Token">8693ff71-e18d-4d07-9a6f-291955133c5a</item>
      <item key="MS-ASPNETCORE-TOKEN">28610056-48fa-4830-ad91-fe34c106c7fa</item>
      <item key="X-Original-Proto">http</item>
      <item key="X-Original-For">127.0.0.1:5194</item>
    </dictionary>
  </property>
  <property key="UserName">Carl</property>
  <property key="RequestId">0HLARDEAMTRQN:00000003</property>
  <property key="Version">1.0.0.0</property>
</properties>

… and our EF call:

<properties>
  <property key="elapsed">55</property>
  <property key="parameters">@p0='821ec2a2-9a2a-4931-bd11-27232a33dc06' (Nullable = true), @p1='Carl' (Size = 4000), @p2='Rippon' (Size = 4000), @p3='Mr' (Size = 4000)</property>
  <property key="commandType">Text</property>
  <property key="commandTimeout">30</property>
  <property key="newLine" />
  <property key="commandText">SET NOCOUNT ON;
INSERT INTO [Contact] ([ContactId], [FirstName], [Surname], [Title])
VALUES (@p0, @p1, @p2, @p3);
SELECT [ContactPK]
FROM [Contact]
WHERE @@ROWCOUNT = 1 AND [ContactPK] = scope_identity();</property>
  <property key="EventId">
    <structure type="">
      <property key="Id">200101</property>
      <property key="Name">Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted</property>
    </structure>
  </property>
  <property key="SourceContext">Microsoft.EntityFrameworkCore.Database.Command</property>
  <property key="ActionId">730d1604-86c0-48e4-a496-211403a39b48</property>
  <property key="ActionName">Logging.Controllers.ContactsController.Post (Logging)</property>
  <property key="RequestId">0HLARDEAMTRQN:00000003</property>
  <property key="RequestPath">/api/contacts</property>
  <property key="UserName">Carl</property>
  <property key="Version">1.0.0.0</property>
</properties>

… and our response information:

<properties>
  <property key="RequestMethod">POST</property>
  <property key="RequestPath">/api/contacts</property>
  <property key="statusCode">201</property>
  <property key="ResponseBody">{"contactPK":529,"contactId":"821ec2a2-9a2a-4931-bd11-27232a33dc06","title":"Mr","firstName":"Carl","surname":"Rippon"}</property>
  <property key="RequestBody">{
    "title": "Mr",
    "firstName": "Carl",
    "surname": "Rippon"
}</property>
  <property key="UserName">Carl</property>
  <property key="RequestId">0HLARDEAMTRQN:00000003</property>
  <property key="Version">1.0.0.0</property>
</properties>

Dealing with exceptions

So, far so good - we have added some extra useful information and this is included in exceptions as well (even though I’ve not shown it above). We can go a bit further though …

We can improve the experience of the consumer of the API by giving them an error reference that they can quote when raising a support ticket. We need to wrap an exception handler around line await _next(httpContext) in our middleware:

try
{
    await _next(httpContext);
}
catch(Exception exception)
{
    Guid errorId = Guid.NewGuid();
    Log.ForContext("Type", "Error")
        .ForContext("Exception", exception, destructureObjects: true)
        .Error(exception, exception.Message + ". {@errorId}", errorId);

    var result = JsonConvert.SerializeObject(new { error = "Sorry, an unexpected error has occurred", errorId = errorId });
    httpContext.Response.ContentType = "application/json";
    httpContext.Response.StatusCode = 500;
    await httpContext.Response.WriteAsync(result);
}

Here’s what the consumer gets when they hit a problem in our code:

We can quickly get to that entry in our log by writing a SQL query to filter on the errorId property:

How much slower is our middleware?

To finish this post off, let’s see the performance impact of logging all this extra stuff. Let’s again repeatedly call GET api/contacts/{contactId} for 10 seconds.

The average request time was 3.6ms. So, roughly an addition of 0.4ms for this test.

Not that much slower!

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?

ASP.NET Core Logging with Serilog and SQL Server

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

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