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

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

IHttpClientFactory Patterns: Using Typed Clients from Singleton Services Exploring an approach to reuse transient typed clients within singleton services

I’ve been following IHttpClientFactory for some time and have created a number of blog posts on the various features based on sample applications. Since then; with the release of ASP.NET Core 2.1 now available, I’ve begun using IHttpClientFactory in real production applications. In this post, I want to start covering some patterns I’ve begun to apply as I develop my applications.

This time I want to look at an issue regarding the scope of typed clients. This is based on something I’ve now directly encountered and that was raised as a comment on an earlier post by a reader named Yair.

When defining typed clients in your ConfigureServices method, the typed service is registered with transient scope. This means that a new instance is created by the DI container every time one is needed. The reason this occurs is that a HttpClient instance is injected into the typed client instance. That HttpClient instance is intended to be short lived so that the HttpClientFactory can ensure that the underlying handlers (and connections) are released and recycled.

This works in cases where you plan to consume the typed service from another transient service. A common place to use these in ASP.NET Core will be places such as Controllers for example. That works as expected since the controller is created by the framework for each request.

However, what if you want to use the typed client within a singleton service? That presents a problem. If this was allowed it would be created and injected once, and then held onto by the singleton service. This is not the behaviour we want.

Originally, when asked by Yair about how to use HttpClientFactory in singleton services I suggested instead using the named client approach and then injecting the IHttpClientFactory directly to your singleton service. From there, you can call CreateClient on the factory within methods on that singleton service, so that for each invocation, a new HttpClient is created for only a short lifetime.

The problem is that if we don’t get the typed client behaviour where we can encapsulate the work necessary to interact with a third party API as a service. Instead, we would have to make a service that depends on the IHttpClientFactory as I suggested above and then pass that into the necessary places in our code.

Having now tackled this in a real project where I am essentially building an SDK around an internal API that I’ve developed I have reassessed the options. What I ended up doing was using the typed client approach, but also providing my own factory which can return instances of that typed client. This is actually very simple to do by leveraging the DI service provider directly.

Here is an example of a typed client and its interface:

I won’t dive deeply into how this service works. It’s a typed client and you can read my earlier post about named and typed clients for more information.

In short; this service expects to have a HttpClient instance injected when it is created by the DI container. It then wraps the logic needed to call various endpoints of a remote API. Within this service, we can include the code needed to validate the response and deserialise the returned content from the request.

We can register the typed client in our ConfigureServices method as follows:

At this point, we have a typed client which can be consumed from other transient services and controllers. To make this accessible to singleton services in our application we can add a basic factory.

Here we have created a basic interface for an IConfigurationServiceFactory which defines a single GetConfigurationService method.

The implementation takes an IServiceProvider in its constructor, which will be injected by DI. With access to the service provider, we can use it to return an instance of IConfigurationService from the GetConfigurationService method. As this is a transient typed client, a new instance will be returned each time this method is called.

In ConfigureServices, we can register the factory with DI as a singleton:

As this is a singleton, we can consume this from any class where we need access to an instance of the typed client, even if that class is registered with singleton scope in DI.

The important thing here is that we don’t create an instance of the IConfigurationService and hold onto it for the lifetime of the singleton service. We can hold the IConfigurationServiceFactory and then we must use that whenever a method needs to get access to the IConfigurationService.

I’m sure there may be other ways to achieve similar results but I’m fairly happy with this approach for now.

Related Posts

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

How to record metrics to DataDog from ASP.NET Core Recording metrics and events to DataDog in development and production in AWS ECS.

I’m currently architecting and building a new microservices based system at work. A priority of mine has been to learn from the experience of building our first microservices project by putting a greater focus on logging and monitoring. We freely acknowledge that we didn’t get this as good as we would have liked in our first implementation. Logging is hugely important in a microservices design. Tracking down failures and bugs can be very difficult without good logging and even more importantly, a way to search and view those logs.

But logging isn’t what I want to cover in this post. Alongside logging, something we felt we were missing in our previous project was detailed performance and usage metrics. We can gain some insight into the state of the system using built-in AWS metrics for our ECS services and also by monitoring, again via CloudWatch things such as SQS queue metrics. This is all reasonably useful but at times it would be great to know a bit more about the services themselves.

With this new project, I’ve started instrumenting it with DataDog so that the application can record useful metrics that allow us to track it’s overall health, as well as understand how things are performing and what’s actually being used. The goal is to build up a much better profile of the application so that we can more easily see whether changes that we have deployed have improved the performance or whether they have degraded it. Having proper baselines of the application performance is key to being able to make such determinations.

The choice of DataDog was made, simply because our systems team use it already for monitoring the overall AWS environment. After a few quick enquiries, I found that recording metrics from the application code would be possible thanks to the availability of a C# library from DataDog called “dogstatsd-csharp-client”. My only concern is that the library seems to be a little stalled, with no commits since Nov 30th 2017. There is also a third party library called DatadogSharp which I may investigate in the future. Their readme suggests it is more performant than DataDog’s own library. Putting that aside for now; I decided I’d go ahead and prototype based on the DataDog library and revisit these concerns if they proved founded, once I was underway. I have built a small wrapper library over the static DogStatsd methods so I have a layer of abstraction if I decided to change the underlying client. It also allows me to centralise the use of some common tags which I wanted to include on all of my metrics.

In this post, I want to focus on the slightly higher level concepts by discussing how I got this working during development and more recently, deploying to a prototype in production running in AWS ECS.

Development

The DogStatsd client sends messages over UDP to an agent server which will collect these and eventually send them up to the DataDog service. You can read more about that flow on the DataDog DogStatsD page. Therefore, to test my code during development, I needed to have an agent server running somewhere.

In my case, I opted for a Docker image which I could run locally. After a bit of Googling, I ended up at the DogStatsD6 Docker Image GitHub repository. This image is hosted on the Docker Hub in the DataDog DogStatsD repository.

To begin working with this locally, I created a simple docker-compose file. I’ve not included some other elements I was running here for logging via the ELK stack as those are not necessary for this example. My docker-compose file looked like this:

The above example specifies a dogstatsd service which will be started using the DogStatsD6 image. By default, this DogStatsD agent server will be listening on UDP port 8125 for data. I expose that port to port 8125 on my host (development) machine. For the DogStatsD server to be able to send its data to DataDog we need to provide an API key. This can be done by passing the key into the DD_API_KEY environment variable.

At this point, I could run a docker-compose up -d command to start an instance of the DogStatsD container.

Sending Metrics and Events from an ASP.NET Core based API

As I mentioned earlier, I’ve created a wrapper library for sending DataDog metrics and events via the methods from the dogstatsd-csharp-client library. I won’t be covering that here as I want to keep this post focused on the core principles. Instead, let’s look at how we can begin with recording metrics and events to DataDog.

The first step, before we can send data to DataDog is to add the Nuget package for the dogstatsd-csharp-client library.

You can do this by searching for it via the NuGet package manager, or as I did, by editing the csproj file directly and adding the package reference.

<PackageReference Include="DogStatsD-CSharp-Client" Version="3.1.0" />

Once the library is added we must configure the client. All of the functionality for this client library is implemented as static methods. The first method we will call is the DogStatsd.Configure method. This takes a StatsdConfig object as a parameter. We’ll add a small static method in our Startup.cs class as follows:

We build up the configuration object using a server name string which we will pass into this helper method. This will be the hostname or IP of the server running the DogStatsd server. We also set the port it will be listening on. Finally, we can add a prefix which will be added to the front of any metric and event names. This is useful to make it easier to search for them in the DataDog application.

We then call the Configure method, passing in the config object.

Next, we need to call this method. We can do that from our Configure method in the Startup class. This is called once at application startup so is an appropriate place to do this. First, we’ll load the DogStatsd server name from ASP.NET Core configuration as this allows us to easily set it per environment. We’ll then call our ConfigureDataDog method, passing that server hostname through:

We’ll need to include a section for this configuration in our appsettings.json file:

During development, we can set this to the localhost IP address (127.0.01). Since we are running are DogStatsd server within a container and exposing its port through to the host we can access it this way. In production, we can then set an appropriate production hostname for the DogStatsd server.

At this point, everything is ready to go. We can now use the static DogStatsd methods to send metrics and events from our code.

The client library readme includes examples of the methods we can call but as a basic example, here’s some code we can call from our application to record a metric whenever a profiles endpoint is called.

DogStatsd.Increment("all_profiles_endpoint_call");

At this stage, we have added basic metrics to our application and have a DogStatsd server running locally in a container to collect and forward those metrics to DataDog.

Production

NOTE: Since trialling this approach, we have learned that because each sidecar is considered a new host, this may have cost implications with the DataDog pricing model. We are moving away from this approach to daemon mode containers (1 per ECS host). I will update accordingly once we are happier with that approach. For now, this stills works, but do consider how it affects your billing.

The final stage is to get this working in production. I felt there might be a few options here but the one I wanted to try was to run the DogStatsd server as a sidecar container. We use AWS Elastic Container Service (ECS) to run our production services as Docker containers.

To achieve this we will add a second container to our task definition for our ECS service. ECS services are the logical structure that represents a unit of scale and deployment for containers in ECS. The service can run multiple containers which generally is not something you need or want to do since it limits your scaling options. However, for this requirement, running a second supporting container, it is a reasonable use case. This container is directly used only by our main microservice and should scale with that service.

The final ECS task definition looks like this:

The new section in my case is the dogstatsd container definition near the bottom (lines 39-51). The task definition takes one or more container definitions which define the containers that will be started as part of the tasks for this service.

The dogstatsd one is quite simple. We tell it to use the same image as we used in development, “datadog/dogstatsd”, which will be pulled from the Docker Hub. We can pass in the API Key via an environment variable. We can mark this container as non-essential since we don’t want its failure to cascade to causing our service to restart unexpectedly.

The next change is to add the links to the main API server container definition (lines 35-37). This ensures that it will have a network link with the dogstatsd container. Finally, we can add an environment variable for the API container which sets the hostname for the DogStatsD server. This will override the 127.0.0.1 setting from our appsettings.json file. Since we have linked the containers we can reference the DogStatsd server by its container name.

With these changes made it was then a case of registering this new task definition and updating our ECS service. When the service starts tasks, it will start an instance of the DogStatsd container which our application containers can use to record their metrics and events.

Summary

It’s still early days, but this is working quite nicely in the production environment. I will be reviewing it over time as I learn more about the various elements at play. This is likely not the end of the story or our journey with DataDog. Hopefully, this is enough information to get you started if you are following a similar path. 

HttpClientFactory in ASP.NET Core 2.1 (Part 4) Integrating with Polly for transient fault handling

In the previous post in this series, I introduced the concept of outgoing middleware using DelegatingHandlers registered with named and typed clients. While that approach is available, the ASP.NET team hope that for most scenarios, we won’t need to resort to manually building our own handlers. In some cases, the built-in features of the library may provide the functionality we need. For example, it is sometimes useful to wrap requests within timing code to track how long they take to execute. This is now built into IHttpClientFactory as part of its default logging. In other cases, third-party integration may provide the functionality you require. For example, a common cross-cutting concern is handling transient faults during HTTP requests. In this case, rather than crafting our own retry logic, it’s much better to use a library such as Polly.

Polly is a popular transient fault handling library which provides a mechanism to define policies which can be applied when certain failures occur. One of the more commonly used policies is the retry policy. This allows you to wrap some code which, should a failure occur, will be retried; multiple times if necessary. This is very useful in situations where your application needs to communicate with external services. There is the ever-present risk when communicating with services over a transport such as HTTP that a transient fault will occur. A transient fault may prevent your request from being completed but is also likely to be a temporary problem. This makes retrying a sensible option in those cases.

As well as retries, Polly offers a number of other types of policy, many of which you may want to combine with retry to build up sophisticated ways to deal with failures. I will cover a few of the more general examples in this post, but if you want more comprehensive coverage I recommend you check out the Polly wiki.

The ASP.NET team have worked closely with Dylan and Joel, the primary maintainers of Polly, to include an integration pattern to make applying Polly policies to HttpClient instances really straightforward.

Before we can work with the Polly integrations we need to add a package reference to our project. The general IHttpClientFactory functionality lives inside the Microsoft.Extensions.Http package which is included as a dependency in the Microsoft.AspNetCore.App 2.1 meta package. This is a new meta package in ASP.NET Core 2.1 which doesn’t include third-party dependencies. Therefore, in order to use the Polly extensions for IHttpClientFactory we need to add the Microsoft.Extensions.Http.Polly package to our project.

After doing so in a basic project the csproj file will look something like this:

Applying a Policy

The Microsoft.Extensions.Http.Polly package includes an extension method called AddPolicyHandler on the IHttpClientBuilder that we can use to add a handler which will wrap all requests made using an instance of that client in a Polly policy. The IHttpClientBuilder is returned when we define a named or typed client.

We can then use the extensions in our ConfigureServices method…

In this example, we’re defining a client named “github” and we’ve used the AddPolicyHandler method to pass in a timeout policy. The policy you provide here must be an IAsyncPolicy<HttpResponseMessage>. This policy will timeout any requests after 10 seconds.

Reusing Policies

When using Polly, where possible, it is a good practice to define policies once and share them in cases where the same policy should be applied. This way, to change the rules for a policy, those changes only need to be made in one place. Also, it ensures that the policy is allocated only once. Certainly, policies such as the circuit breaker need to be shared if multiple callers expect to run through the same circuit breaker instance. 

For this example, we’ll declare the timeout policy from the last example once and share it with two named clients…

We’ll look at another option for policy reuse a little later in this post when we explore using a PolicyRegistry.

Transient Fault Handling

When dealing with HTTP requests, the most common scenarios we want to handle are transient faults. As this is a common requirement, the Microsoft.Extensions.Http.Polly package includes a specific extension that we can use to quickly setup policies that handle transient faults.

For example, to add a basic retry when a transient fault occurs for requests from a named client we can register the retry policy as follows:

In this case, all requests made through the client will retry when certain failure conditions are met. The AddTransientHttpErrorPolicy method takes a Func<PolicyBuilder<HttpResponseMessage>, IAsyncPolicy<HttpResponseMessage>>. The PolicyBuilder here will be preconfigured to handle HttpRequestExceptions, any responses returning a 5xx status code and also any responses with a 408 (request timeout) status code. This should be suitable for many situations. If you require the policy to apply under other conditions, you will need to use a different overload to pass in a more specific policy.

Be aware; when performing retries we need to consider idempotency. Retrying a HTTP GET is a pretty safe operation. If we’ve made the call and not received any response, we can safely retry the call without any danger. However, consider what might happen if we retry a HTTP POST request. In that case, we have to be more careful since it’s possible that your original request was actually received, but the response we received suggested a failure. In that case, retrying could lead to duplication of data, or corruption of the data stored in the downstream system. Here, you need to have more knowledge of what the downstream service will do if it receives the same request more than once. Is retrying a safe operation? When you own the downstream service, it is easier to control this. You might, for example, use some unique identifier to prevent duplicate POSTs.

When you have less control of the downstream system or you know that a duplicate POST might have negative consequences, you will need to control your policy more carefully. An option that might be suitable is to define different named/typed clients. You could create one for those requests that have no side effects and another for those that do. You can then use the correct client for the action being taken. However, this might become a little difficult to manage. A better option is to use an overload of AddPolicyHandler which gives us access to the HttpRequestMessage so that policies can be applied conditionally. That overload looks like this:

AddPolicyHandler(Func<HttpRequestMessage, IAsyncPolicy<HttpResponseMessage>> policySelector)

You’ll note that the policySelector delegate here has access to the HttpRequestMessage and is expected to return an IAsyncPolicy<HttpResponseMessage>. We don’t have access to a PolicyBuilder setup to handle transient faults as we did in our earlier example. If we want to handle the common transient errors, we’ll need to define the expected conditions for our policy. To make this easier, the Polly project includes a helper extension that we can use that sets up a PolicyBuilder ready to handle the common transient errors. To use the extension method we need to add the Polly.Extensions.Http package from Nuget.

We can then call HttpPolicyExtensions.HandleTranisentHttpError() to get a PolicyBuilder that is configured with the transient fault conditions. We can use that PolicyBuilder to create a suitable retry policy which can then be conditionally applied when the request is a HTTP GET. In this example, any other HTTP methods use the NoOp policy.

Using a PolicyRegistry

The last example I want to cover in this post is a basic demonstration of how policies can be applied from a policy registry. To support policy reuse, Polly provides the concept of a PolicyRegistry which is essentially a container for policies. These can be defined at application startup by adding policies into the registry. The registry can then be passed around and used to access the policies by name.

The extensions available on the IHttpClientBuilder also support adding Polly based handlers to a client using a registry.

First, we must register a PolicyRegistry with DI. The Microsoft.Extensions.Http.Polly package includes some extension methods to make this simple. In the above example, I call the AddPolicyRegistry method which is an extension on the IServiceCollection. This will create a new PolicyRegistry and add register it in DI as the implementation for IPolicyRegistry<string> and IReadOnlyPolicyRegistry<string>. The method returns the policy so that we have access to add policies to it.

In this example, we’ve added two timeout policies and given them names. Now when registering a client we can call the AddPolicyHandlerFromRegistry method available on the IHttpClientBuilder. This takes the name of the policy we want to use. When the factory creates instances of this named client, it will add the appropriate handler, wrapping calls in the “regular” retry policy which will be retrieved from the registry.

Summary

As a long time user of Polly, I’m very happy to see the integration being added with IHttpClientFactory. Together these libraries make it really easy to get up and running with HttpClient instances that are able to handle transient faults seamlessly. The examples I’ve shown are quite basic and general, but I hope they give the idea of how policies can be used and registered. For more detailed Polly documentation and examples, I recommend you check out the Polly wiki. It was great being involved in some of the early discussions with both the ASP.NET and Polly teams when this integration was being designed as I was able to suggest the usefulness of the policy registry extensions.

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 – This post

.NET South East – May Event New speakers night.

It’s been a while since I last got around to blogging about a .NET South East meetup event. I wanted to make sure I did this month as the plan for this week’s event was close to my heart. I had the idea back in December / January to try and organise a night for new speakers. The motivation behind that was my own experience. I’ve blogged in detail about that but in case you don’t have a few hours spare to both parts, the TL;DR is as follows…

Through my life, I’ve always hated public speaking. The idea of giving a talk or even an introduction to a room of people filled me with a fair degree of dread. Last year I faced my fear by taking part in an ALT.NET show and tell evening. I had 20 minutes to share my experience of working on the Humanitarian Toolbox project. While terrifying beforehand, the actual experience was actually quite enjoyable. Afterwards, the rush and positive feedback was a great feeling. After that first talk, I ended up speaking at two other user group events and two conferences in 2018. While I still get nervous, I’ve found that I actually really enjoy presenting and this year I am extending the number of events I submit and speak at.

Back to the meetup; I wanted if possible to offer other members of the community a safe place for them to try out public speaking. I set aside a date and started promoting the idea to our members. My biggest concern was that no one would be interested and the idea would fail at stage one. However, after a couple of months of asking for speakers, people started to come forward. I know from experience that taking that initial step and committing is no small thing for novice speakers.

With the speakers lined up, I was feeling better about the idea. The next concern was attendee numbers. I was conscious that in order to attend the meetup it requires people to give up a free evening. As a result, people are selective on which meetups they choose to attend. Frankly, I wasn’t sure if the idea of an evening of new speakers with shorter talks would draw in attendees. That concern slipped away as I saw that our RSVP numbers on meetup.com were looking healthy. I was very pleased that members of the community were coming together to support our peers and to join us for the evening.

The Event

The evening began as normal with me introducing the meetup and then going onto present some news items. I wasn’t short of content for this event, holding it the week after MS Build! One slight hitch was that the slides I’d carefully crafted at home hadn’t synced on my OneDrive and as a result, with an hour to go I found myself rapidly recreating the content!

I won’t go into too much detail here besides sharing some links but the items we covered were…

.NET Core 3.0 roadmap announcement – The main goal of this release is to support WPF and WinForms workloads.
ASP.NET Core 2.1 RC1 released – With RTM due by end of May.
Visual Studio Live Share – Announcement of the public preview release.
Intellicode – AI assisted IntelliSense based on machine learning across 2,000 open source projects. Now available in experimental preview.
ML.NET – An open-source, cross-platform, machine learning library.
Visual Studio 15.7 released

With the news complete, we entered the main part of the evening. I’d allocated each speaker twenty minutes of presentation time, plus five minutes for questions.

First up was Dave Mateer who presented a demo-heavy talk. Presenting demos is always daunting but Dave’s went off without a hitch. Dave crammed a lot into his 20 minutes, demonstrating how he’d taken a legacy and poorly configured WordPress site and migrated it to running in the cloud on Azure AKS. Azure AKS is Microsoft’s managed Kubernetes service and by all accounts looks like a great way to get started with containers in production. Dave highlighted the salient things he’d learned along the way. Showing how data volumes can be used to persist data outside of the container for example. Dave also highlighted the power of scripting which means he can quickly spin up and when required delete his Kubernetes environments. Within his twenty minutes, Dave had taken us on a journey from running a container locally, through to a scripted deployment to production, with the site running live on Azure. It was a great talk and really interesting to learn from Dave’s experience.

Dave Mateer presents at .NET South East

Next up was Steve Collins who talked about a SOLID approach to ASP.NET Core. His focus was on configuration and what he’s learned as he began working with ASP.NET Core. Steve first explained a history of configuration in ASP.NET through the previous version. He brought us up to date by showing how ASP.NET Core out of the box provides DI friendly configuration and the options pattern for accessing your configuration values. One of the gotchas that Steve highlighted was the need to use the IOptions and IOptionsSnapshot interfaces to access strongly typed configuration in your dependent classes. This isn’t necessarily easily discoverable for newcomers to ASP.NET Core. Steve then showed how he’d built out a more intuitive pattern over the top that allows for accessing configuration via a bridge class. It was a great talk and Steve touched on some patterns I’m finding myself using on my latest projects. Steve has documented the content that formed this talk in his great four-part blog series which I recommend you go and check out.

Steve Collins presents at .NET South East

We then had a short break before our final talk of the evening. Alex McAuliffe took to the stage to talk about “Falling down holes for beginners”. In this talk, he shared his experience of working on and maintaining an open source project. Alex covered some of the positives of open source before also discussing some things to watch out for. One of the really salient points regarding running your own project was around scoping and focus. As Alex described it’s very easy to get excited about lots of areas of the code and also trying to make things “perfect” which can easily lose the focus on actually completing things. Alex also talked about an unexpected outcome of working on the project; burnout. It’s not always something you would consider when working on a personal project but is certainly something to watch out for. Alex also shared some thoughts on tools for source control and to help maintain code quality. Finally, he concluded with some resources to blogs and people to follow on Twitter. Alex’s slides are available online.

Alex McAuliffe presents at .NET South East

It was extremely impressed by all three talks. Dave, Steve and Alex had clearly put a lot of effort into preparing their slides, demos and content. Despite having a quite short time limit, each one packed a lot of great content into their allotted time. Having spoken to some of the attendees after the event I got the sense that everyone had enjoyed listening to the talks and the format of the evening in general. I want to repeat my thanks once again to the speakers for volunteering and taking part. I know that standing up in front of a crowd can be intimidating and I hope that all three enjoyed the experience overall.