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

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:

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.

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

After signing in and calling GET api/contacts/{contactId} we get:
Out of box log

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

These are the properties we get from the request:

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:

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:

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:

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:

… and …

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.

This now includes the parameter value in the log entry:

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.

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.

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

… and our EF call:

… and our response information:

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:

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

Consumer exception

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.

Perf with middleware

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

Not that much slower!

Recommended reading for building great ASP.NET Web APIs:

Share this:Share on RedditTweet about this on TwitterShare on LinkedInShare on Google+

Leave a Reply

Your email address will not be published. Required fields are marked *