How to log everything using middleware and httpClient handler
Anyone who has any experience with microservice can tell you about their advantages over a monolith, but they can also tell you about their biggest drawback: sometimes it takes a lot of work to understand what is going on.
As your system grows and involves more and more services it gets harder to keep track of which services each flow is using, and when something is broken it`s hard to find where the issue is coming from.
A potential solution to this is to log everything that each service receives and sends out so we can create a call graph and understand what is going on, and where things break. However, we don't want to do this all the time, as the cost of storing all of our logs will get astronomical.
So let's see how we can use middleware, HttpClientHandler, and AsyncLocal to get this done.
Lets start with the middleware
public class LogsMiddleware
{
private readonly RequestDelegate _next;
private readonly ILogService _logService;
public LogsMiddleware(RequestDelegate next, ILogService logService)
{
_next = next;
_logService = logService;
}
public async Task InvokeAsync(HttpContext httpContext)
{
httpContext.Request.Headers.TryGetValue("x-master-log-should-log",
out var shouldLog);
if (shouldLog == "true")
{
var wasTraceIdFound = httpContext.Request.Headers
.TryGetValue("x-master-log-trace-id", out var traceIdValue);
var wasLevelFound = httpContext.Request.Headers
.TryGetValue("x-master-log-level", out var levelValue);
var data = new TraceData
{
TraceId = wasTraceIdFound ?
traceIdValue.ToString() : Guid.NewGuid().ToString("N"),
Level = wasLevelFound ? int.Parse(levelValue.ToString()) : 1
};
httpContext.Items.Add("data", data);
TraceStorage<TraceData>.Store(data);
await LogRequest(httpContext.Request, "DemoService", data);
}
//Adds a delegate to be invoked just before
//response headers will be sent to the client.
httpContext.Response.OnStarting(state =>
{
httpContext.Items.TryGetValue("data", out var data);
if (data != null)
{
httpContext.Response.Headers.TryAdd("x-master-log-trace-id",
((TraceData)data).TraceId);
}
return Task.CompletedTask;
}, httpContext);
// Call the next delegate/middleware in the pipeline.
await _next(httpContext);
}
private async Task LogRequest(HttpRequest request,
string currentServiceName, TraceData traceData)
{
var logString = $"[{traceData.Level}] [{traceData.TraceId}] {currentServiceName} Got the request :" +
$"{request.Method};{request.GetDisplayUrl()}";
foreach (var queryValue in request.Query)
{
logString += $"{queryValue.Key}-{queryValue.Value}";
}
logString += ";headers:";
foreach (var requestHeader in request.Headers)
{
logString += $"{requestHeader.Key}-{requestHeader.Value}";
}
if (request.Body.CanSeek)
{
var bodyObject = await JsonNode.ParseAsync(request.Body);
logString += $";body:{bodyObject?.ToJsonString()}";
}
//log the string
await _logService.Log(logString);
}
} The first thing we need to do for each request is to know if we will log it or not. We do this by checking if it has the request header x-master-log-should-log with the value ‘true’. This way we can only log the request we need.
Assuming that we want to log the request we need to check for 2 more request headers :
x-master-log-level - this tells us our level in the call graph, we can use it to understand the order of the calls between services.
x-master-log-trace-id — this is the ID of the request, we can use it to search the logs and find all log records from all our services.
We don't expect to have these headers of the first call we get from the user, so if they are missing, we need to add them for the following services. We need to generate a random trace ID and set the level to 1.
We will put the level and trace ID in an object called TraceData and save it in the TraceStorage<TraceData> (more on that later).
Then we log the request. As I am not working with a real logger here, I am just creating a string from all the important things that we have in the request (URL, HTTP method, headers, and body) with the trace ID, level, and our service name. In a real application, this should be a JSON value or tags.
Then we pass a callback method to httpContext.Response.OnStarting to add the trace ID in the response headers so we can return it and search for it in the logs.
What is AsyncLocal?
According to the Microsoft documentation, AsyncLocal:
Represents ambient data that is local to a given asynchronous control flow, such as an asynchronous method.
In other words, it allows us to pass data down our code exception path without having to pass it manually in each method.
I am using an idea that I found in a great blog post about this to easily save stuff to AsyncLocal and retrieve it.
public static class TraceStorage<T> where T : new()
{
private static readonly AsyncLocal<T> _asyncLocal = new AsyncLocal<T>();
public static T Store(T val)
{
_asyncLocal.Value = val;
return _asyncLocal.Value;
}
public static T? Retrieve()
{
return _asyncLocal.Value;
}
}A small detour, for a talk about HttpClientFactory
Most of us have been using HttpClient and we have not been using it the right way.
That is not me saying it, but Microsoft documentation about this, and also this great blog post about this.
If you don't want to read it, the short version is: do not create new instances of HttpClient by using the new keyword but use a HttpClientFactory.
//bad
var client= new HttpClient();
//good
//get IHttpClientFactory httpClientFactor from DI
using HttpClient client = httpClientFactory.CreateClient();I am bringing this up here, as using HttpClientFacroty has another benefit: the ability to create different HttpClients. For example, we may want to do some things for calls to different services in our system and other things when calling outside services.
We may want to an ApiKey from configuration when calling some 3rd party service and adding cache headers when calling internal services.
//get IHttpClientFactory httpClientFactor from DI
using HttpClient intenalClient = httpClientFactory.CreateClient("internal");
using HttpClient externalClient= httpClientFactory.CreateClient("external");What is a HttpClientHandler?
HttpClientHandler is a middleware for HTTP calls. Just like an ASP.NET middleware, it can execute code before and after we send an HTTP request.
We can pass HttpClientHandlers to an instance of HttpClient and get different behaviors.
This is how we set it using the build-in DI:
builder.Services.AddTransient<SendTraceHandler>();
builder.Services.AddHttpClient("internal")
.AddHttpMessageHandler<SendTraceHandler>();First, we register the handler, then we register a named version of a HttpClient and register its usage of the handler.
We can use it like so:
public class BusinessService(IHttpClientFactory httpClientFactory) : IBusinessService
{
public async Task<bool> DoBusinessStuff()
{
var client = httpClientFactory.
CreateClient("internal");
var response = await client.GetAsync("http://demo.com/cool-stuff");
return response.IsSuccessStatusCode;
}
}What does a handler look like:
public class SendTraceHandler : DelegatingHandler
{
private readonly ILogService _logService;
public SendTraceHandler(ILogService logService)
{
_logService = logService;
}
//for unit tests
public SendTraceHandler(ILogService logService,
HttpClientHandler innerHandler)
{
_logService = logService;
InnerHandler = innerHandler;
}
protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
CancellationToken cancellationToken)
{
var traceData = TraceStorage<TraceData>.Retrieve();
if (traceData != null)
{
AddTraceHeadersToRequest(request, traceData);
}
HttpResponseMessage response = await base.SendAsync(request, cancellationToken);
if (traceData != null)
{
await Log(CreateRequestString(request, traceData), response);
}
return response;
}
private void AddTraceHeadersToRequest(HttpRequestMessage request, TraceData data)
{
request.Headers.Add("x-master-log-should-log", "true");
request.Headers.Add("x-master-log-trace-id", data.TraceId);
request.Headers.Add("x-master-log-level", data.Level.ToString());
}
private string CreateRequestString(HttpRequestMessage request, TraceData traceData)
{
var logString = $"[{traceData.Level}] [{traceData.TraceId}] Sending the request :{request.Method};" +
$"{request.RequestUri}";
logString += ";headers:";
foreach (var requestHeader in request.Headers)
{
logString += $"{requestHeader.Key}-{requestHeader.Value}";
}
if (request.Content != null)
{
StreamReader reader = new StreamReader(request.Content?.ReadAsStream());
string body = reader.ReadToEnd();
logString += $";body:{body}";
}
return logString;
}
private async Task Log(string requestString, HttpResponseMessage response)
{
string responseBody = await response.Content.ReadAsStringAsync();
var logString = $"{requestString}: Response:[{response.StatusCode}] {responseBody}";
//log the string
await _logService.Log(logString);
}
}As you may have noticed our handler extends the DelegatingHandler class. A DelegatingHandler delegates the processing of HTTP response messages to another handler, called the inner handler.
When we register a handler to be used by a named HttpClient we don't need to worry about it, but if we want to unit test the handler we need to assign something to the InnerHandler Property. That is why my handler has 2 contractors, one is used in run-time and one for unit tests.
The SendAsync method is called when we use the HttpClient SendAsync method. Here we check the TraceStorage to see if this request should be logged, if it should we add the trace ID, level and the “should log” header to the request header so it can be sent to the next service,
and when we get the response we also log the request and the response.
Now let's write some Unit Tests
This is how we unit test a middleware:
[TestMethod]
public async Task LogEveryThingMiddleware_ShouldLog_FirstCall()
{
var logService = A.Fake<ILogService>();
var logMiddleware = new LogsMiddleware(
async innerContext =>
{
innerContext.Items.TryGetValue("data", out var data);
if (data != null)
{
Assert.AreEqual(((TraceData)data).Level.ToString(), "1");
}
await innerContext.Response.StartAsync();
},
logService);
var context = new DefaultHttpContext
{
Response = { Body = new MemoryStream() }
};
//add stuff to the request header
context.Request.Headers.Append("x-master-log-should-log", "true");
//add data to request body
context.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes("{\"userName\" :\"John\"}"));
//add stuff to the query string
context.Request.QueryString = context.Request.QueryString.Add("filter", "1");
//Call the middleware
await logMiddleware.InvokeAsync(context);
A.CallTo(() => logService.Log(A<string>.That.Matches(x => ValidateString(x, 1, "John", "1", null))))
.MustHaveHappened();
}We create an instance of our middleware and pass it to a delegate, and any other service we need.
The delegate is just a method that gets HttpContext and returns a Task
This can work just fine:
var logMiddleware = new LogsMiddleware(
innerHttpContext => Task.CompletedTask,
logService);In my test, I am using the delegate to make sure the trace ID was set to the HttpContext items.
Then we create an instance of DefaultHttpContext set its request property to mock a request, and invoke the middleware.
How to unit test the HttpClientHandler?
Testing a HttpClientHandler can be a bit trickier as we can't easily see what it sends to HttpClient or mock the response that the client returns, but you know what can do that? The inner handler.
Yes, I am creating a new HttpClientHandler to test our main HttpClientHandler.
Handlers are like middleware, after all, they can be nested.
So we pass to our SendTraceHandler a new handler (MockHeadersHandler) that will check that it gets a specific list of headers.
Then we pass our handler to a HttpClient and call it:
[TestMethod]
public async Task SendRequest_ShouldLog()
{
var traceId = Guid.NewGuid().ToString("N");
var logService = A.Fake<ILogService>();
var handler = new SendTraceHandler(logService,
new MockHeadersHandler(new Dictionary<string, string>
{
{"x-master-log-should-log","true"},
{"x-master-log-trace-id",traceId},
{"x-master-log-level","1"}
}));
var client = new HttpClient(handler);
var data = new TraceData
{
TraceId = traceId,
Level = 1
};
TraceStorage<TraceData>.Store(data);
var response = await client.SendAsync(new HttpRequestMessage
{
RequestUri = new Uri("http://demo.com/cool-stuff?filter=1"),
Content = JsonContent.Create(new { firstName = "John" })
});
A.CallTo(() => logService.Log(A<string>.That.Matches(x => ValidateString(x, 1, "John", "1", traceId))))
.MustHaveHappened();
}
private bool ValidateString(string log, int expectedLevel,
string bodyValue, string qsValue, string? expectedTraceId = null)
{
Assert.IsTrue(log.Contains($"[{expectedLevel}]"));
Assert.IsTrue(log.Contains($"{bodyValue}"));
Assert.IsTrue(log.Contains($"{qsValue}"));
if (expectedTraceId != null)
{
Assert.IsTrue(log.Contains($"[{expectedTraceId}]"));
}
return true;
}
class MockHeadersHandler : HttpClientHandler
{
private readonly Dictionary<string, string> _excpected;
public MockHeadersHandler(Dictionary<string, string> excpected)
{
_excpected = excpected;
}
protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
CancellationToken cancellationToken)
{
foreach (var item in _excpected)
{
var headerValue = request.Headers.GetValues(item.Key);
Assert.AreEqual(headerValue.First(), item.Value);
}
return await base.SendAsync(request, cancellationToken);
}
}You can see the full code here
