Log HttpClient request and response based on custom conditions in .NET Core

#csharp #dotnet #httpclient #logging

In my team, we created a lot of code for calling some 3rd party services. From time to time we needed to see what how did the actual HTTP request and response looked like. Usually when something goes "south" from various reasons.

It is not a hard task to log each request and response, but if you take into consideration performance, log size, logging of sensitive data, etc. you might not want to do that for each request.

We knew when we would like to log:

If there was some error while communicating to 3rd party service, so we can have request/response for their support (or for our reproduction of the issue)
We explicitly wanted to send some parameter to capture request/response, for various reasons, even though everything went fine (or looked like it did)
Based on some response HTTP code or something else from the response, but that was different from service to service.

What we also knew is that:

We would like to have it reusable
It should not make our Service class (the one that implements adapter to 3rd party service) bloated and
We should be able to add it as any other Delegating Handler through HttpClient setup

Delegating Handler

We created a delegating handler with two parameters in constructor



internal class TraceLogHandler : DelegatingHandler
{
  public TraceLogHandler(IHttpContextAccessor httpContextAccessor, 
    Func<HttpResponseMessage, bool> shouldLog)
    {
        ...

First we need IHttpContextAccessor to allow us to acces current HttpContext. We need it for two purposes - to access to query parameters and check if "traceme" was sent.



bool traceMe = _httpContextAccessor.HttpContext.Request.Query
  .ContainsKey("traceme");

That is a signal for us we should log, no matter what. It is also good to add that value through some middleware in all log messages, but I skip that part for this sample.

Second one is for purpose of creating a logger as HttpContext also allow us access to IServiceProvider (the RequestServices property).



var logger = _httpContextAccessor.HttpContext.RequestServices
  .GetRequiredService<ILogger<TraceLogHandler>>();

Second constructor parameter is a Func that accepts HttpResponseMessage (response from 3rd party service) and should return bool value. Remember I said we wanted some dynamic decision based on response? Well, this is it. To give you an example how it could look, let's go to the Startup.cs where I setup HttpClient.



services.AddHttpClient(HelloService.ServiceName, config =>
{
    // Some custom configuration like request timeout
    config.Timeout = TimeSpan.FromSeconds(5);
})
.AddTraceLogHandler((response) =>
{
  // Here we setup that if Response status code is not 200-299, 
  // we should log entire HttpClient request and response 
  // to 3rd party service.
  // You can setup any condition based on the HttpResponseMessage.

  return !response.IsSuccessStatusCode;
});

As explained in a comment, you can setup any condition based on HttpResponseMessage. If your function returns true, delegating handler will log request and response.

We needed this to be variable per HttpClient, since different 3rd party services behave differently - we have one that throws HTTP status 500 when record is not found, other one returns for the same situation status 200 with some text message... don't ask...

AddTraceLogHandler is an extension method so we can add handler easier. Here are two extension methods as an example.



public static class HttpClientBuilderExtensions
{
  public static IHttpClientBuilder AddTraceLogHandler(
    this IHttpClientBuilder builder, 
    Func<HttpResponseMessage, bool> shouldLog)
  {
    return builder.AddHttpMessageHandler((services) => 
      new TraceLogHandler(services
        .GetRequiredService<IHttpContextAccessor>(), shouldLog));
  }

  public static IHttpClientBuilder AddTraceLogHandler(
    this IHttpClientBuilder builder)
  {
    return builder.AddHttpMessageHandler((services) => 
      new TraceLogHandler(services
        .GetRequiredService<IHttpContextAccessor>(), 
      (HttpResponseMessage) => { return false; }));
  }
}

Show us the code!

Right, almost forgot - code of the handler itself. You can find it here on the GitHub https://github.com/nikolic-bojan/soap-client/blob/master/Api/Handlers/TraceLogHandler.cs as a part of my SoapClient repository.

There I use it for calling some SOAP 3rd party service with some "magic" for using HttpClient for calling SOAP, but that doesn't matter, that is just a regular delegating handler, so you can use it for any HttpClient.



internal class TraceLogHandler : DelegatingHandler
{
    private readonly IHttpContextAccessor _httpContextAccessor;
    private readonly Func<HttpResponseMessage, bool> _shouldLog;

    public TraceLogHandler(IHttpContextAccessor httpContextAccessor, Func<HttpResponseMessage, bool> shouldLog)
    {
        _httpContextAccessor = httpContextAccessor;
        _shouldLog = shouldLog;
    }

    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
    {
        bool logPayloads = false;

        // If you pass a query string parameter "traceme", HttpClient request/response will be logged.
        bool traceMe = _httpContextAccessor.HttpContext.Request.Query.ContainsKey("traceme");

        logPayloads = logPayloads || traceMe;

        HttpResponseMessage response = null;
        try
        {
            response = await base.SendAsync(request, cancellationToken);

            // We run the ShouldLog function that calculates, based on HttpResponseMessage, if we should log HttpClient request/response.
            logPayloads = logPayloads || _shouldLog(response);
        }
        catch (Exception)
        {
            // We want to log HttpClient request/response when some exception occurs, so we can reproduce what caused it.
            logPayloads = true;
            throw;
        }
        finally
        {
            // Finally, we check if we decided to log HttpClient request/response or not.
            // Only if we want to, we will have some allocations for the logger and try to read headers and contents.
            if (logPayloads)
            {
                var logger = _httpContextAccessor.HttpContext.RequestServices.GetRequiredService<ILogger<TraceLogHandler>>();
                Dictionary<string, object> scope = new Dictionary<string, object>();

                scope.TryAdd("request_headers", request);
                if (request?.Content != null)
                {
                    scope.Add("request_body", await request.Content.ReadAsStringAsync());
                }
                scope.TryAdd("response_headers", response);
                if (response?.Content != null)
                {
                    scope.Add("response_body", await response.Content.ReadAsStringAsync());
                }
                using (logger.BeginScope(scope))
                {
                    logger.LogInformation("[TRACE] request/response");
                }
            }
        }

        return response;
    }
}

To explain briefly - if either of the conditions for logging was true (we have "traceme" query string parameter, there was some exception, function based on HTTP response returned true), we will create logger, add request and response headers and content to log scope and log that on information level.

This is how that look in Seq. Looks good to me!

Check out the SoapClient repository for full code https://github.com/nikolic-bojan/soap-client and copy the parts you need to see it working in your project.

Hope to see some comments and questions!

BR,
Bojan