Refit - Logging HTTP Traffic

When we got started with Refit in my previous post I left a question open: If we wanted detailed information on HTTP traffic in Refit, how would we go about it? Today, we’ll answer this question!

Full Example Source Code

A complete example using the code in this post is available here.

Defining a Logging Message Handler

Refit clients, as mentioned previously, are nothing more than named HttpClient instances. As such, we can configure them just like any other HttpClient, including having the ability to add custom message handlers to them. Let’s start by defining a simple handler that logs HTTP traffic:

namespace RefitSandbox;

public class HttpLoggingHandler(ILogger<HttpLoggingHandler> logger) : DelegatingHandler
{
  protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
  {
    Guid id = Guid.NewGuid();
    HttpResponseMessage response = await base.SendAsync(request, cancellationToken).ConfigureAwait(false);
    logger.LogInformation("[{Id}] Request: {Request}", id, request);
    logger.LogInformation("[{Id}] Response: {Response}", id, response);
    return response;
  }
}

Now, this simple implementation won’t necessarily give much more info than what Verbose-level logging will already give you. For the most part, .NET will already log HttpRequestMesssage.ToString() and HttpResponseMessage.ToString(), which is all we’re doing here. About the only thing new in the above sample is prefixing a unique ID to each set of logs, so that if the application fires off multiple requests and they complete out of order, you can easily re-group them in the resulting logs. This seam allows you to log anything in the request/response, such as the actual content, or anything else on the incoming request or response objects that aren’t picked up natively. Take the above starting point and explore to your heart’s content!

Using the Handler in your Refit Client

With HttpLoggingHandler defined, let’s add it to the ICatFactsClient we created in the Getting Started with Refit post:

// Program.cs
IHttpClientBuilder refitClientBuilder = builder.Services.AddRefitClient<ICatFactsClient>()
  .ConfigureHttpClient(httpClient =>
  {
    httpClient.BaseAddress = new Uri("https://cat-fact.herokuapp.com/");
    // Will throw `TaskCanceledException` if the request goes longer than 3 seconds.
    httpClient.Timeout = TimeSpan.FromSeconds(3);
  });

// Adding our new handler here
refitClientBuilder.AddHttpMessageHandler(serviceProvider 
  => new HttpLoggingHandler(serviceProvider.GetRequiredService<ILogger<HttpLoggingHandler>>()));
refitClientBuilder.Services.AddSingleton<HttpLoggingHandler>();

Sharp eyes will notice we’re not adding our message handler the conventional way:

refitClientBuilder.AddHttpMessageHandler<HttpLoggingHandler>(); // Cleaner!

Unfortunately, we can’t use this flavor due to an issue in Refit where the inner handler chain is messed up when doing so. As such, we have to add our handler as we do above to avoid this error, manually invoking the IServiceProvider given in the lambda (serviceProvider) to manually construct our handler with its dependencies. I wanted to document this gotcha in particular more than anything else because it took me some digging to figure out why this wasn’t working!

Giving it a Spin

When we run our application, in addition to normal logging we get the following:

info: RefitSandbox.HttpLoggingHandler[0]
      [f7ae2093-729c-4e14-96db-8c924eaa6c54] Request: Method: GET, RequestUri:
        'https://cat-fact.herokuapp.com/facts', Version: 1.1, Content: <null>, Headers:
      {
      }
info: RefitSandbox.HttpLoggingHandler[0]
      [f7ae2093-729c-4e14-96db-8c924eaa6c54] Response: StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1,
      Content: System.Net.Http.HttpConnectionResponseContent, Headers:
      {
        Server: Cowboy
        Report-To: {"group":"heroku-nel","max_age":3600,"endpoints":[{"url":"https://nel.heroku.com/reports?ts=1702228787&sid=929419e7-33ea-4e2f-85f0-7d8b7cd5cbd6&s=5hBy8dAwfoYjTr62xNbm7GArZpsbh5rPlynp6xiR7w4%3D"}]}
        Reporting-Endpoints: heroku-nel=https://nel.heroku.com/reports?ts=1702228787&sid=929419e7-33ea-4e2f-85f0-7d8b7cd5cbd6&s=5hBy8dAwfoYjTr62xNbm7GArZpsbh5rPlynp6xiR7w4%3D
        Nel: {"report_to":"heroku-nel","max_age":3600,"success_fraction":0.005,"failure_fraction":0.05,"response_headers":["Via"]}
        Connection: keep-alive
        X-Powered-By: Express
        Access-Control-Allow-Origin: *
        ETag: W/"747-x/u8ZT4YD7H4GhrXTZH8+n4vTKY"
        Set-Cookie: connect.sid=s%3AvAIPfLP9QcCTkQpn1QoRuE9GDqA8hzFw.bVWyxAU%2BeYDu4n05DnTCrOyhDNPHBQYxQDUdFf6cRRo; Path=/; HttpOnly
        Date: Sun, 10 Dec 2023 17:19:47 GMT
        Via: 1.1 vegur
        Content-Type: application/json; charset=utf-8
        Content-Length: 1863
      }

[... other log messages ...]

You can see our new handler being used by virtue of seeing the unique ID being prepended to each message. Now, should we need to, we can dive deep into our Refit client usages to assist in debugging or for any other purpose. We can control whether we log all of this info by controlling the log level we write. If you have heavy HTTP traffic, this may log a ton of data. We can control whether we log all of this info by dictating the log level we use in our handler. The log level’s easily configurable at the application settings layer, which out of the box is set to Information:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.Hosting.Lifetime": "Information"
    }
  }
}

Be Careful What You Log

I’ll leave this post here with a note of caution regarding logging HTTP traffic. Sometimes you’ll be accessing resources that require authentication from the caller, usually in the form of secrets or bearer tokens, in the outgoing requests. Loggers such as this will happily log your precious credentials without care, and those secrets will then proliferate to everywhere logs are written to! The key advantage to having a custom logging handler (over relying on the default .NET output) is that we can filter out secret information from our logs. Basic steps can include:

• Changing the log level
• Examining the contents of the request and response strings, and blanking out known secret information
• Skipping logging of sensitive HTTP traffic altogether by examining the request path and skipping any endpoints that have secrets

In the next Refit post I’ll be detailing an example sending such a secret: What if we want to use Refit to access an endpoint that requires an OAuth Bearer Token?