Running AWS DynamoDB Locally for .NET Core Developers Configuring an ASP.NET Core application to use a local DynamoDB Docker container

Steve Gordon Leave a comment

For a recent set of .NET Core based microservices I have found myself using AWS DynamoDB as a data store. I recently discovered that AWS provides (and have done for 5 years!) a local version of DynamoDB which is perfect for testing applications offline and without the need to set up actual DynamoDB tables in the cloud. This can reduce the complexity of local development and reduce the costs associated with spinning up development DynamoDB tables. Recently, AWS added a Docker image that makes running DynamoDB locally really straightforward.

In this post, I will demonstrate how to get started with the local AWS DynamoDB Docker image and a basic ASP.NET Core application which can be conditionally configured to use the local version when in development.

AWS DynamoDB Docker Image

I’ll include the basic details of how to use the AWS DynamoDB Docker image here for completeness, however, the full documentation is available on the Docker Hub as well in the AWS Documentation.

NOTE: You will require Docker to be installed and running locally on your development machine in order to follow along!

The first step is to pull the DynamoDB Docker image down to your development machine. This can be done by running the docker pull amazon/dynamodb-local command. After a short time, you should see the pull command complete successfully…

Docker pull the AWS DynamoDB local image

Now that we have the image available we can start a container instance using the docker run -p 8000:8000 amazon/dynamodb-local command…

Docker run a AWS DynamoDB local container

This will start a container using the image that we previously pulled down. We have chosen to publish port 8000 from the container to our host machine on its port 8000. If this conflicts with other applications on your machine, you can specify a different host port number.

If you prefer to run the container without the interactive output then I suggest running in detached mode by adding the -d argument….

docker run -p 8000:8000 -d amazon/dynamodb-local.

As this point, we have a local instance of DynamoDB running in a container, available on our host machine on port 8000.

Utilising the local DynamoDB from an ASP.NET Core application

Next, we’re going to create a basic application to test the local DynamoDB instance. I’ve included the full sample on GitHub as a starting point. This sample was created using the basic ASP.NET Core API template available as part of the SDK.

NOTE: The sample does not include production-ready code. I’ve put together a very basic API application that allows us to write, read and delete from DynamoDB. Those actions are based on the AWS .NET Core SDK samples. The key thing I want to demonstrate is not how to read, write and delete from DynamoDB, but more specifically, how to include some configuration to enable the use of the local DynamoDB container when in development.

Adding NuGet packages

After creating a default project from the API template, we need to add two NuGet packages to our project. You can do this via the command line, NuGet package manager or by editing the csproj file directly.

We need to bring in the AWSSDK.DynamoDBv2 and AWSSDK.Extensions.NETCore.Setup packages.

AWSSDK.DynamoDBv2 adds the necessary support to interact with DynamoDB via the AWS .NET SDK. The AWSSDK.Extensions.NETCore.Setup package includes extension methods to support the configuration and registration of the AWS services with the Microsoft dependency injection container used in .NET Core applications.

After registering these, our project file looks something like this…

Adding Configuration

Next, we’ll add some configuration values to our appsettings.json file. These will support both the default AWS SDK behaviour as well as options to control running the application against the local DynamoDB container…

Here we’ve added an AWS section which includes the AWS region we wish to use. This will be used by the AWS SDK when running against the actual AWS DynamoDB service. We also have a DynamoDB section which defines a setting to control whether the local DynamoDB is used. By default we’re going to set this to false for now.

In order to support using the local DynamoDB when in development we’ll override the configuration values using an appsettings.Development.json file…

By default, ASP.NET Core loads the configuration for applications from a predetermined sequence of sources. In our case, when the application starts under the development environment (the default when debugging from Visual Studio) it will override previous configuration values using the settings from this additional JSON file. Here we have set the “LocalMode” to true and included a service URL for the local DynamoDB instance. We’ve specified the value as “http://localhost:8000” but if you chose to run the container on a different host port, you can update this accordingly.

Register the DynamoDB Services

Inside our Startup class, we now need to register the DynamoDB service. We’re going to do this conditionally, based on the configuration. The code for our ConfigureServices method looks like this…

First, we get the DynamoDb section from the application configuration. When running under the development environment (which will be the case when debugging with Visual Studio) the final values will be those that we set in our appsettings.Development.json file.

We then access the value of the “LocalMode” setting so that we can conditionally register the AWS DyanmoDB service.

If the LocalMode is true, we will manually register a service for the IAmazonDynamoDB interface. Here we use the overload that lets us provide an implementation factory that will return the actual implementation. In our case, we create an AmazonDynamoDBConfig instance, passing in the LocalServiceUrl from configuration. We then create and return the AmazonDynamoDBClient using that configuration. We have registered this as a singleton so this code will run once when the service is first needed.

If the LocalMode is false, instead we will use the AWS SDK helper method to add the service by calling AddAWSService. This is available because we included the AWSSDK.Extensions.NETCore.Setup package.

Reading, Writing and Deleting from DynamoDB

Now that we have the IAmazonDynamoDB registered in our application we can require it to be injected by the Microsoft dependency injection whenever we wish to work with AWS DynamoDB. In development, we’ll be given an implementation which will talk to the local DynamoDB running in Docker. In all other cases, it will attempt to reach the live AWS DynamoDB service. In the latter case, the AWS SDK will handle the authentication to reach the service. I haven’t described it here but you will need to have configured the credentials in one of the predefined locations for the .NET SDK to be able to connect to AWS.

I won’t show the specific code used to work with DynamoDB in this post, as it’s beyond the scope of what I want to demonstrate. In short; you can inject the IAmazonDynamoDB into a controller, for example, to provide your actions access to DynamoDB via the SDK. If you want to see this code (note, this is not production ready code) you can view the ValuesController in my sample.

Running the Sample

At this point, we can start our sample and debug it via Visual Studio. Our development appsettings will take effect and the application will start with the SDK configured to use the local DynamoDB Docker container.

My complete sample includes some basic actions that can be used to read, write and delete from the DynamoDB. If you’re running the sample for the first time, you’ll need to call the Initialise action (by issuing a GET request to the /api/values/init endpoint) to create the required table. Again, this is not a production ready sample but it is enough to demonstrate using the configured SDK to access either the local or the real DynamoDb service.

Summary

In this post, we’ve explored how we can easily use Docker to spin up a local instance of DynamoDB on our development machine. We then created a basic ASP.NET Core application which used configuration to determine whether to connect to the actual AWS service, or whether to use the local instance running inside a Docker container. This is controlled by registering the appropriately configured SDK service with the Microsoft dependency injection container. After the service is registered, the actual code used to work with AWS DynamoDB via the SDK requires no further changes.

ASP.NET Core 2.2 First Look – Endpoint Routing (aka Dispatcher) What is Endpoint Routing in ASP.NET Core 2.2?

Steve Gordon Leave a comment

The first preview of ASP.NET Core 2.2 is due (very) soon and it will be our first chance to test the changes and new features which are expected to be released by the end of this year.

ASP.NET Core 2.2 marks the next minor release of the ASP.NET Core framework, following on from the ASP.NET Core 2.1 release at the end of May. With these minor releases, the team are able to provide new features to us quickly and iterate on an already great product. ASP.NET Core 2.2 will be a “Current” release for those wanting to take advantage of the latest features more quickly. For some, the “current” releases may not be suitable as while offering newer features they do not offer the same long support commitment as long-term support (LTS). If you choose the “current” release train then you need to keep updating as new “current” releases are available (See the ASP.NET Core support policy for more details).

I’ve been watching the features planned for ASP.NET Core 2.2 since version 2.1 shipped. There are quite a few things which look pretty interesting. Today I want to take an early look at a new feature whose final name is Global Endpoint Routing. You may also see this referred to by its former name “Dispatcher”.

Update 18-08-2018: James Newton-King who works on the ASP.NET team, has confirmed that the name for this feature with be Endpoint routing.

NOTE: This post is based on reading and watching some limited early coverage of Dispatcher (Global Routing) from the ASP.NET team over the last few months. I’ve also spent a small amount of time looking at the source code and some early samples to form the content below. As a result, there are things I may not have 100% correct! This post is written prior to the first preview of ASP.NET Core 2.2 and as a result, some of this could change before the final release of ASP.NET Core 2.2. If you’re reading this in the future, treat it with some caution and keep an eye out for more recent posts where I will cover using the released versions of the feature. If you’re reading this in the past, I’m pleased to see that time travel is now a thing!!

Update 18-08-2018: After feedback from James Newton-King who works on the ASP.NET team, I understand that in the 2.2 timeframe the only supported way to use Endpoint Routing will be via MVC.

What is Global Endpoint Routing (the feature formerly known as Dispatcher)?

The current routing story with ASP.NET Core 2.1 MVC is that we define routes within MVC using either convention-based routing which uses a RouteBuilder when we register MVC into the middleware pipeline or via Route Attributes on our action methods. Personally, I tend towards the attribute approach for the APIs I build.

When a request reaches MVC, the route information is used to determine which Controller and Action should be invoked to handle the request, based on the URL path. At this point, MVC can invoke that action which will then return the response. If a suitable route is not found then a 404 is returned instead.

One issue with this approach to routing is that as the request flows through the middleware chain, all other middleware has no idea of where that request is eventually going to be handled.

With the Global Endpoint Routing feature, routing decisions can occur earlier into the pipeline so that incoming requests can be mapped to their eventual endpoint before MVC is even invoked. This gives other middleware an opportunity to make more reasoned choices and process requests armed with the knowledge of which Endpoint will eventually handle the request.

Implemented as middleware the URL matching can now be registered to run very early in the application middleware pipeline. After which, a set of known Endpoints will be registered. When a request is passed through the pipeline, other middleware will be able to inspect the final matched Endpoint and view/update its associated metadata.

In addition, Global Endpoint Routing looks like it should allow developers to build ASP.NET Core applications that don’t use MVC, but which can still rely on routing to handle requests. Developers can provide their own EndpointDataSource, complete with a set of route patterns and the corresponding RequestDelegates to be invoked for matches. There are opportunities here for some very lightweight APIs to be built without the sometimes unnecessary additional overhead of MVC.

Note: Based on the feedback from James Newton-King this feature is expected to work with MVC as the support way to use it in 2.2. For the 3.0 timeframe a public API for non MVC use is expected to be ready.

The original ASP.NET Core 2.2 features announcement (where the feature is known as “Dispatcher”) included a good example of where this Global Endpoint Routing concept can be useful. CORS is currently implemented as both a feature of MVC and as middleware. This is necessary as some requests will be handled outside of MVC, such as serving static files. However, to apply CORS for requests which do reach MVC, the policy can’t be applied until the MVC routing selects the controller and action for the request. Global Routing will enable CORS to be implemented more consistently since the routing and Endpoints will be known up front when a request is matched through the middleware.

Global Endpoint Routing is also integrated with the latest ASP.NET Core 2.2 MVC functionality, allowing MVC to work on top of this new Global Endpoint Routing feature. MVC in ASP.NET Core 2.2 includes code changes to support building up a list of available Endpoints for Global Endpoint Routing, using the existing MVC route provider.

I plan to dive into all of this more deeply in future posts. I’m currently spending a fair bit of time in the Microsoft.AspNetCore.Routing source code understanding the building blocks and Types involved.

A Small Sample

I’ll end with a basic example of what the services and middleware pipeline for an ASP.NET Core 2.2 application using Global Endpoint Routing could look like. In this case, there’s no MVC involved (this is based on the current RoutingSample from the Routing repository).

Update 18-08-2018: After feedback from James Newton-King who works on the ASP.NET team, I understand that in the 2.2 timeframe the only supported way to use Endpoint Routing will be via MVC.

Inside the Startup class, we must register the routing services in the ConfigureServices method as follows…

This sample manually adds a DefaultEndpointDataSource with a single Endpoint which is not necessary if you wish to use the MVC routes. MVC will populate Endpoints for you.

Once registered we can add Global Endpoint Routing to the pipeline as middleware in the Configure method…

The first middleware, UseEndpointRouting is responsible for inspecting the incoming request and matching it to an Endpoint. The matched Endpoint is set in the HttpContext.Features collection. At this point, all other middleware can retrieve the Endpoint from the Features collection as necessary.

Since we’re not using MVC in this sample we need something to invoke the matched RequestDelegate for the Endpoint. UseEndpoint registers the middleware which does exactly that.

Summary

Hopefully, this has been a useful primer of what to expect with the Global Endpoint Routing feature in ASP.NET Core 2.2. I expect this to be available in the first preview of ASP.NET Core 2.2 (perhaps due by the end of the month). I have started building up some fairly extensive notes as I explore the code and I hope to put together some follow up posts demonstrating more concrete samples once the previews are formally available (and at which point the API surface is less likely to change). I may also produce a deeper dive into how this all functions internally as its quite interesting code to explore.

Running a .NET Core Generic Host App as a Windows Service

Steve Gordon Leave a comment

I received a question at the weekend via a comment from Vadim on my Implementing IHostedService in ASP.NET Core 2.0 post. Vadim asked the following:

We have a lot of console applications that are listening to a queue and performing some work. In .net 4.6 we would make some of these classes inherit from ServiceBase class. Then we would use the sc.exe tool on the server to install these as Windows Services.

We are looking for a similar solution using .net core. The problem is, ServiceBase does not exist in .net core.

It seems like IHostedService is a good alternative. However, the one thing I don’t understand is, how do we take a .net core application with one or more IHostedServices and install them as a windows service? We want to be able to start/stop these applications from some kind of UI and we want them to always be running when the server is up.

This piqued my interest. I could vaguely recall reading something which described the process required to run an ASP.NET Core application as a Windows service. Off I went to Google and found the documentation which I’d previously read. The documentation was focused on running an ASP.NET Core app, hosted on Windows, as a Windows service. This looked like a good starting point.

I created a basic .NET Console application, using the Generic Host pattern and took a look to see if the RunAsService extension, mentioned in the ASP.NET Core documentation, would work. Turns out, it doesn’t, as it’s not available on the IHostBuilder interface, only for the IWebHostBuilder. Next, I thought I’d take a look at the ASP.NET Core Hosting repository to see if I could figure out if this was available under a different name or failing that to see if there were any plans for similar functionality for IHostBuilder. I came across this issue where Chris Ross (aka Tracher) linked to his GenericHostSample application.

Armed with that sample code I set about adding the relevant classes to my own app. It was mostly a copy/paste exercise; so full credit goes to Chris Ross for his sample code.

My next steps were then based on the ASP.NET Core documentation. However, as that document is specific to ASP.NET Core, I thought it would be valuable to summarise the steps required for running a generic host .NET core app as a Windows service here on my blog. I won’t cover everything in as much detail as the full documentation which I suggest you also go and read for additional context and explanation.

NOTE: A complete sample for a basic generic host based .NET Core Windows service can be found on my GitHub repository.

Project File

After creating a new .NET Core console application, the first thing we need to do is to add a reference to the Microsoft.Extensions.Hosting package and the Microsoft.AspNetCore.Hosting.WindowsServices System.ServiceProcess.ServiceController package (thanks to David Fowler for a PR to tidy up my dependencies in the sample).

As well as these package reference, you’ll see that in the main PropertyGroup section we’ve also set the RuntimeIdentifier to win7-x64. The RID (Runtime Identifier) in this case identifies that the target platform for this application is Windows. For more information about RIDs see the documentation. Since Windows Services are only available on Windows, it makes sense to set a windows target platform which will also ensure we produce a .EXE rather than .DLL file when building our application.

In the above sample we can also set the LangVersion to 7.1 to allow me to use an async Main method.

Program.cs

Next we need to setup our application entry point in Program.cs. The Main method is our entry point and in my sample is as follows:

I’ve based this example on the “Host ASP.NET Core in a Windows Service” documentation.

First it performs a check to see if we’re either debugging or if the application has been started having been passed an argument of “–console”. In that case we set the isService flag as false. We’ll use this later to allow us to debug the application from Visual Studio as a standard console application.

Next we create a HostBuilder which we’ll use to create the generic host. In here we register one service which is an implementation of the IHostedService interface. This is how we’ll run code within our application. See my earlier IHostedService post for more detail on how this interface can be used to run background workloads. We’ll look at the implementation for this application a little further down.

Finally, using the isService flag, we now call either the RunAsServiceAsync extension on the builder, or the RunConsoleAsync. The later will run the application as a normal .NET Core console app, perfect for local testing and debugging. The former is the extension method I was missing earlier. This comes from two files I have added, copied from the GenericHostSample mentioned earlier.

ServiceBaseLifetime.cs

I won’t go into the internals of this too deeply. This is entirely copied from the Microsoft sample. This class derives from the ServiceBase class used to define Windows services. It also implements the IHostLifetime interface from Microsoft.Extensions.Hosting.

ServiceBaseLifetimeHostExtensions.cs

This class is also copied from the GenericHostSample and adds the RunAsServiceAsync extension method which will ensure the ServiceBaseLifetime is registered as the implementation for IHostLifetime.

FileWriterService

This class implements IHostedService and once registered will be started and stopped by the IHost. We follow the generic host documentation and include a Timer which will fire every minute. It will run the code in WriteTimeToFile method which appends the current time to a file. Not particularly useful, but for this example it’s enough to show that something is actually happening. In the original question from Vadim the requirement was to poll a queue and process messages. We could just as easily perform that work here too.

At this point we now have our complete sample application. We can run this directly in Visual Studio to test it, but our main goal is to register this as a Windows service.

Again, if you want to download the source yourself you can do so from GitHub.

Creating the Windows Service

The final step is to build our code and register a service from the executable. We’ll follow the ASP.NET Core documentation to build our code and register a Windows service. Again, I won’t cover the detail here since the referenced documentation provides ample explanation. To summarise though, the steps are as follows:

Build and publish the project from the command line. This command can be run in the directory in which the project resides…

dotnet publish --configuration Release

Next, use sc.exe to create a service, passing the full path of the built executable…

sc create MyFileService binPath= "E:\Projects\IHostedServiceAsAService\IHostedServiceAsAService\bin\Release\netcoreapp2.1\win7-x64\publish\IHostedServiceAsAService.exe"

Next, use sc.exe to start the service (this needs to occur in a command prompt running as Administrator)…

sc start MyService

At this point, our service is running. In my case, I confirmed that a text file called TestApplication.txt appeared in my D: drive (that destination and filename is hardcoded in my sample), which confirms that the service is running as expected. Every minute, while the service is running, I can see a new line added to the text file.

Summary

If you’ve followed along, you should now have a .NET Core based Windows service running on your machine. As per the requirement in the original question, you could easily modify this service to read from a queue and process the messages it receives. Personally, I tend to deploy such services as a basic console application, running in Linux based Docker containers. For production workloads, this enables easy scaling and I can manage the services through our container orchestration in AWS ECS. However, should you need a Windows service, then hopefully this post is enough to get you started.

Hopefully, in a future release of ASP.NET Core, this functionality will be included in the framework. If that happens we won’t need to include our own ServiceBaseLifetime and ServiceBaseLifetimeHostExtensions classes. Based on a reply from Chris in the original GitHub issue, that looks like something which may be considered in the 3.0 timeframe as part of some wider hosting work they plan to do.

Working with Polly – Using the Context to Obtain the Retry Count for Diagnostics Exploring a basic use case the for Polly Context object to track diagnostic data

Steve Gordon Leave a comment

I’ve been using Polly for a number of years now. For the most part, my usage of the library has been to solve some quite basic problems; commonly to implement retry logic when calling external services for example. In this post, I want to explore a requirement I had when using Polly within a library that would be shared with various other internal projects.

The library acts as an “SDK” of sorts, wrapping an API we have written. This enables our consuming services to reference the package if they need to consume the API, avoiding repetition of the code required to interact with it.

The scenario that this post will focus on is how we can capture diagnostic information during policy execution for use in application monitoring.

The Requirement

Let’s take a simple example. We want to record application metrics about the number of retries that each attempt to call a third party service requires. I want to be able to get this information after the execution of the code that is wrapped in the policy is complete. In my case, some of my consuming applications will record this data to a third-party service called DataDog. We can then track and monitor this metric over time to understand if calls to the API are degraded.

I don’t want to force my SDK library to depend on DataDog directly since I can’t assume all consumers will need, nor want to record metrics. Instead, I want to capture data during policy execution which my SDK can pass back as part of a result object to the caller. Consuming projects can then choose to use that information if they need to, or disregard it if they don’t.

NOTE: One thing I should highlight at this point is that the Polly team are actively planning work on a diagnostics feature for Polly. Once that work is completed and becomes available then solving this requirement will become simpler.

The solution which I’ve come up with in the meantime is to utilise the Polly Context. Essentially the Context allows you to pass in a set of objects which can then be accessed during policy execution. The context includes a (lazily-initialised) dictionary to store any data/objects that you want.

The way I chose to implement my requirement was to set up the context and attach it to the policy executing the retry around the HTTP request.

Creating the policy

NOTE: Our library makes use of the new HttpClientFactory feature in .NET Core 2.1, so the examples here will mostly focus on that use case.

First, we’ll define a policy which will execute our HTTP request and utilise the Context to record the retries.

Update – 26-07-2018

Since publishing this post I’ve discussed this sample with Dylan Reisenberger who expertly suggested this can be simplified if we instead use the built-in retryCount to set the value on our context. 

We no longer need to increment our own count and can set/update the value for the “retrycount” key with less code.

Here we’ve used the HttpPolicyExtensions to help create a policy which will retry any transient errors that occur when making the request.

The WaitAndRetryAsync method, as one of its overloads, accepts an Action delegate, which as one of its arguments includes the Context object. In the preceding example, I try to access an item with the key “retrycount” from the Context dictionary. Using pattern matching we can check that the value is an integer and if so, assign it to a local variable called retries.

In the case where this value is available, we can then increment the retries value and assign it back into the context against the retrycount key.

Executing the policy

Before executing code wrapped in the policy, we need to create a Context to pass to the execution. Creating a Context is as simple as allocating one and adding an entry in its internal dictionary.

In the preceding code, we’ve created a context and added a retrycount integer to it, initialised with a value of zero. This can then be used to track the number of attempts made during an execution of a retry based policy.

With a Context object created, we can go ahead and pass it into the policy execution. The standard way to do this is to pass it as an argument to the Execute or ExecuteAsync method when utilising the policy. For example:

However, in my case, I am using the new HttpClientFactory feature. When using HttpClientFactory, clients are defined in the ConfigureServices method with any required Polly policies being added using the various Polly extension methods on the IHttpClientBuilder. See my previous post for more detail of how to use Polly with IHttpClientFactory.

With HttpClientFactory, we don’t directly execute the policy. That is done for us within the handlers.

To support the use of the context with HttpClientFactory, an extension method on the HttpRequestMessage is provided called SetPolicyExecutionContext. This accepts a Polly Context object which it then adds it to the request properties (a Dictionary<string, object>). During execution, the handler can access the context from the request and pass it into the policy it is executing.

We’ll use that approach in this case. Firstly we create the request and then call the SetPolicyExecutionContext to apply our context object:

We can then get a client from the HttpClientFactory. There are various ways to achieve this which I’ve covered in my HttpClientFactory series. For this example we manually use the factory to create a fresh client:

This client has had the retry policy added to it when defining it in the ConfigureServices method…

After the policy has executed, the retrycount can be accessed from the original reference to context object that we attached to the request.

At this point, I can add the retryCount value to an object which my library passes back to the caller. The caller can use that information if it needs to in order to log events or record DataDog metrics. I won’t include that code here.

Summary

Hopefully, this post demonstrates how easy it is to use the Polly context to pass data into and back out of the execution of policies. This is proving useful for my current scenarios as it allows general policies to be defined centrally which can then be used in multiple places. Remember, in future versions of Polly we can expect some new diagnostic functionality, perhaps in the form of events, which we can hook into to give a richer insight into details such as the number of executed retry attempts. For now, this quite straightforward approach is a solution which I’m pretty happy with.

HttpClientFactory in ASP.NET Core 2.1 (Part 5): Logging Exploring the default request and response logging and how to replace the logging implementation

Steve Gordon Leave a comment

In the 2.1 release of IHttpClientFactory, the ASP.NET team included some built-in logging of the HTTP calls made via HttpClients created by the factory. This can be useful for the diagnosis of failures, as well as to understand the time taken to complete HTTP calls to external services. 

In this post, I want to explore what is available in the default logging, how we can control what gets logged, how the logging is implemented and finally, how we can replace the logging with our implementation.

There’s quite a bit of technical detail in this post. I hope it proves useful and interesting for those working with the IHttpClientFactory. Click here, if you want to jump to the section on customising the logging by replacing the default implementation.

What’s in the logs?

IHttpClientFactory includes two levels of logging. At information level, the time taken to process and send the request is included. This can be useful for monitoring slow responding external services for example. Here’s an example of the console output when information level logging is enabled:

info: System.Net.Http.HttpClient.MyClient.LogicalHandler[100]
  Start processing HTTP request GET https://api.github.com/repos/aspnet/docs/branches

info: System.Net.Http.HttpClient.MyClient.ClientHandler[100]
  Sending HTTP request GET https://api.github.com/repos/aspnet/docs/branches

info: System.Net.Http.HttpClient.MyClient.ClientHandler[101]
  Received HTTP response after 682.9818ms - OK

info: System.Net.Http.HttpClient.MyClient.LogicalHandler[101]
  End processing HTTP request after 693.1094ms - OK

If you require a deeper level of detail regarding the requests, this is available at trace level. With trace level logging enabled, details about the request and response headers will also be included in the log messages. Here’s an example from a request with trace logging enabled:

info: System.Net.Http.HttpClient.MyClient.LogicalHandler[100]
 Start processing HTTP request GET https://api.github.com/repos/aspnet/docs/branches

trce: System.Net.Http.HttpClient.MyClient.LogicalHandler[102]
  Request Headers:
  Accept: application/vnd.github.v3+json
  User-Agent: HttpClientFactory-Sample

info: System.Net.Http.HttpClient.MyClient.ClientHandler[100]
  Sending HTTP request GET https://api.github.com/repos/aspnet/docs/branches

trce: System.Net.Http.HttpClient.MyClient.ClientHandler[102]
  Request Headers:
  Accept: application/vnd.github.v3+json
  User-Agent: HttpClientFactory-Sample

info: System.Net.Http.HttpClient.MyClient.ClientHandler[101]
  Received HTTP response after 795.6954ms - OK

trce: System.Net.Http.HttpClient.MyClient.ClientHandler[103]
  Response Headers:
  Server: GitHub.com
  Date: Sun, 08 Jul 2018 09:44:09 GMT
  Status: 200 OK
  X-RateLimit-Limit: 60
  X-RateLimit-Remaining: 58
  X-RateLimit-Reset: 1531046594
  Cache-Control: public, max-age=60, s-maxage=60
  Vary: Accept
  ETag: "f0452653b55e5fef139a58372e3a7bf3"
  X-GitHub-Media-Type: github.v3; format=json
  Access-Control-Expose-Headers: ETag, Link, Retry-After, X-GitHub-OTP, X-RateLimit-Limit, X-RateLimit-Remaining, X-RateLimit-Reset, X-OAuth-Scopes, X-Accepted-OAuth-Scopes, X-Poll-Interval
  Access-Control-Allow-Origin: *
  Strict-Transport-Security: max-age=31536000; includeSubdomains; preload
  X-Frame-Options: deny
  X-Content-Type-Options: nosniff
  X-XSS-Protection: 1; mode=block
  Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin
  Content-Security-Policy: default-src 'none'
  X-Runtime-rack: 0.029792
  X-GitHub-Request-Id: DCD6:3C9D:688D222:D064A9D:5B41DCE9
  Content-Type: application/json; charset=utf-8
  Content-Length: 2642

info: System.Net.Http.HttpClient.MyClient.LogicalHandler[101]
  End processing HTTP request after 818.4525ms - OK

trce: System.Net.Http.HttpClient.MyClient.LogicalHandler[103]
  Response Headers:
  Server: GitHub.com
  Date: Sun, 08 Jul 2018 09:44:09 GMT
  Status: 200 OK
  X-RateLimit-Limit: 60
  X-RateLimit-Remaining: 58
  X-RateLimit-Reset: 1531046594
  Cache-Control: public, max-age=60, s-maxage=60
  Vary: Accept
  ETag: "f0452653b55e5fef139a58372e3a7bf3"
  X-GitHub-Media-Type: github.v3; format=json
  Access-Control-Expose-Headers: ETag, Link, Retry-After, X-GitHub-OTP, X-RateLimit-Limit, X-RateLimit-Remaining, X-RateLimit-Reset, X-OAuth-Scopes, X-Accepted-OAuth-Scopes, X-Poll-Interval
  Access-Control-Allow-Origin: *
  Strict-Transport-Security: max-age=31536000; includeSubdomains; preload
  X-Frame-Options: deny
  X-Content-Type-Options: nosniff
  X-XSS-Protection: 1; mode=block
  Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin
  Content-Security-Policy: default-src 'none'
  X-Runtime-rack: 0.029792
  X-GitHub-Request-Id: DCD6:3C9D:688D222:D064A9D:5B41DCE9
  Content-Type: application/json; charset=utf-8
  Content-Length: 2642

As you can see and hopefully would expect, at trace level, the details are quite verbose. This can be useful to gain a more complete understanding of the headers during development. It is not recommended that you enable this in production since it will not only quickly fill logs, but it may expose secure data such as authorisation tokens for example.

Each log message includes an event ID so that you can quickly filter out the events you are interested in. There are two loggers in use by default. There is an outer “LogicalHandler” logger which wraps the entire handler pipeline. This will allow for the timing of the entire pipeline to be included in the logs. Additionally, as this will run first in the pipeline, it will log the request headers as they appear before the request passes through any other handlers. The other handlers in the pipeline may modify those headers. Using the trace level logging it’s possible to capture that information to your logs which can be useful if you need to diagnose failures.

The inner logger has the suffix, “ClientHandler” in the category name. This will be the innermost handler and therefore be the last custom handler to run before the request is sent over the network. As a result, this will be able to record the final request headers as they appear before the request is sent over the wire.

For reference, the event IDs included by these loggers are as follows:

Outer “LogicalHandler”

100 RequestPipelineStart
101 RequestPipelineEnd
102 RequestPipelineRequestHeader
103 RequestPipelineResponseHeader

Inner “ClientHandler”

100 RequestStart
101 RequestEnd
102 RequestHeader
103 ResponseHeader

How does IHttpClientFactory logging work?

The logging in IHttpClientFactory is applied to the pipeline just before HttpMessageHandlerBuilder.Build() method is called to return the final HttpMessageHandler pipeline.

This is achieved with the help of HttpMessageHandlerBuilder filters which are applied by the DefaultHttpClientFactory implementation. An interface named IHttpMessageHandlerBuilderFilter exists which can be implemented in order to define filters. By default, there is one implementation of this interface called LoggingHttpMessageHandlerBuilderFilter which is registered within DI. It’s possible to record more than one implementation against the interface. As long as the implementations are registered in DI, each one will be executed when building the pipeline.

The code in the LoggingHttpMessageHandlerBuilderFilter implementation of the Configure method is responsible for creating the two loggers and passing them to logging handlers, which themselves are implementations of the DelegatingHandler abstract base class. The code for LoggingHttpMessageHandlerBuilderFilter.Configure method is as follows:

When the delegate chain is called, the next(builder) call (line 11) will execute the next delegate (an Action<HttpMessageHandlerBuilder>) to ensure the entire handler pipeline is configured.

Then, the two loggers are created, using the name from the builder. This will be the name given to the named client or the type of the typed client.

The outer handler is added at index 0 to the AdditionalHandlers list so that it surrounds all other handlers and is the first to execute. The inner handler is added to the end of the AdditionalHandlers list, so it will be the last to execute before the internal handlers responsible for making the HTTP request.

Each of these logging handlers is responsible for logging their messages before and after the SendAsync calls to the other handlers. Using this approach a timer can be started before the SendAsync call and used afterwards to record the total HTTP request time as well as the overall handler pipeline execution time. I won’t copy the code for those handlers here as they are quite long. Instead, if you are interested you can view them on GitHub.

The outer “LogicalHandler” source can be viewed at here.

This class creates a logging scope as well as recording the log messages. Optionally, if Trace logging is enabled, it will iterate over the request and response headers, recording those to the logger also. The pattern used in this class is an example of the LoggerMessage approach to provide caching of the logging delegates for better performance. You can read more about this approach in the official documentation at docs.microsoft.com. It’s a little outside the scope of this post to go any deeper here.

The inner “ClientHandler” logger uses a very similar approach to record its log messages and the source for that can be viewed here.

Configuring the logging output

As with all logging which uses the Microsoft.Extensions.Logging library, you can control the log messages that are generated using configuration.

In the appsettings.json file, you can control and filter the logging which is recorded. The default production JSON file looks like this:

In this configuration, only warning messages and higher will be logged and as a result, no logging from the IHttpClientFactory handlers will be included. To enable logging we can add an extra log level configuration setting. If you read the “How does it work” section above you’ll recall that the loggers which are used to log the HTTP request log messages are defined with the category name beginning with “System.Net.Http”.

An option, therefore, is to enable the Information or Trace log levels for the System namespace:

However, this will also enable informational messages from all other components in the System root namespace. Therefore it may be better to configure the logging by limiting the configuration to “System.Net.Http.HttpClient” so that you only add in the messages from the HTTP requests through clients created via the HttpClientFactory:

We can take this filtering a step further and filter down to a specific named or typed client. For a typed client, the name will make the name of the registered type.

Let’s imagine we are only interested in logging the requests via a typed client named MyClient. Also, perhaps we only want the raw timing of the HTTP request itself. In this example we can enable logging just for the ClientHandler of our MyClient:

Customising the log messages

There may be cases where you want to add additional logging around HTTP requests through the clients managed by IHttpClientFactory. An option, in this case, is to introduce an extra handler into the pipeline. In part 3 of this series, I explored adding additional outgoing middleware handlers to your client configuration. Using that handler you can inspect the requests and responses, logging any data as necessary.

If you want to replace the default logging entirely to fully customise the message output, the recommended approach from the team is to replace the default implementation of the IHttpMessageHandlerBuilderFilter interface. In fact, this section of the post was inspired by an issue on the IHttpClientFactory GitHub repository. Let’s take a look at how we replace the logging so that we can record a correlation ID into the console messages. We want to replace the default implementation here since we don’t want additional log messages.

First, we’ll need to create a new implementation of IHttpMessageHandlerBuilderFilter:

I’ve pretty much copied the default implementation for this filter. The main difference is that for simplicity I’m only using one outer logger for this example. We create a logger and then add in a new CustomLoggingScopeHttpMessageHandler to the handler pipeline.

The CustomLoggingScopeHttpMessageHandler class is as follows:

There’s quite a lot to this class, but most of that is the static Log class and its methods. I won’t go into those too deeply here since they following the LoggerMessage advice for more performant logging that you can read in the docs. For the most part, I took the exiting LoggingScopeHttpMessageHandler method and tweaked it for my needs.

The first point to focus on here is that whole operation is wrapped in a logging scope. Before and after the SendAsync method is called on the base, we use the static Log methods to record the log events (lines 20 and 22)

Within the Log class, a few private delegates are defined to format the expected log messages.

Both _beginRequestPipelineScope and _requestPipelineStart accept a string which will be the correlation ID. They use the value to record the correlation ID into the scope properties as well as on the request started message.

A simple helper method has been added which parses a HTTP request for the expected correlation ID header and if present, returns it. The BeginRequestPipelineScope and RequestPipelineStart both use this method to extract the correlation ID.

The final step now that we have our filter implementation is to register it in DI, replacing the existing default filter applied by the HttpClientFactory library.

Inside the Startup class, ConfigureServices method we can call the replace extension on the ServiceCollection to swap out the default implementation with our one:

The replace method will find the first registered service of IHttpMessageHandlerBuilderFilter and replace that registration with this new one, where our CustomLoggingFilter is the implementation.

Now, when we run the application, the console logs include our correlation ID:

info: System.Net.Http.HttpClient.MyClient.LogicalHandler[100]
      Start processing HTTP request GET https://api.github.com/repos/aspnet/docs/branches [Correlation: 447c8d6b-e280-4538-bd31-56d508266b5b]

info: System.Net.Http.HttpClient.MyClient.LogicalHandler[101]
      End processing HTTP request - OK

As a side note, this filter approach is a great way to add common cross-cutting concerns for your whole application. It’s possible to register additional filters, each of which could add their own common handlers onto all clients created via HttpClientFactory.

Summary

In this post, we looked at the type of information available to us from the built-in logging, included as part of the HttpClientFactory library. We looked at how we can use log configuration to control which log messages we see and also looked at how logging has been implemented within the library. Finally, we explored using the IHttpMessageHandlerBuilderFilter interface to replace the default logging filter. I hope this has been helpful. I’ll be keeping an eye on the progress for the 2.2 release where we may see more logging, including some Polly integration making its way into the product.

Other Posts in this Series

Part 1 – An introduction to HttpClientFactory
Part 2 – Defining Named and Typed Clients
Part 3 – Outgoing request middleware with handlers
Part 4 – Integrating with Polly for transient fault handling
Part 5 – This post