Using Attribute and ActionFilters for logging request and response of controller and actions

Question

I am trying to find an elegant way of logging every request and response in my Web API using Filters in Asp.net Core 3.1 rather than have them in each action and each controller.

Haven't found a nice solution that seems performable well to deploy in production.

I've been trying to do something like this (below) but no much success.

Any other suggestion would be appreciated.

public class LogFilter : IAsyncActionFilter
    {
        private readonly ILogger _logger;

        public LogFilter(ILogger logger)
        {
            _logger = logger;
        }
        
        public async Task OnActionExecutionAsync(ActionExecutingContext context, ActionExecutionDelegate next)
        {
            var requestBodyData = context.ActionArguments["request"];
            var responseBodyData = "";//how to get the response result
            
            _logger.LogInformation($"{AppDomain.CurrentDomain.FriendlyName} Endpoint: {nameof(context.ActionDescriptor.DisplayName)} - Request Body: {requestBodyData}");
            
            await next();
            
            _logger.LogInformation($"{AppDomain.CurrentDomain.FriendlyName} Endpoint: {nameof(context.ActionDescriptor.DisplayName)} - Response Body: {responseBodyData}");
            
        }
        
    }

Answer 1

I think logging the response should be done in debugging mode only and really can be done at your service API (by using DI interception). That way you don't need to use IActionFilter which actually can provide you only a wrapper IActionResult which wraps the raw value from the action method (which is usually the result returned from your service API). Note that at the phase of action execution (starting & ending can be intercepted by using IActionFilter or IAsyncActionFilter), the HttpContext.Response may have not been fully written (because there are next phases that may write more data to it). So you cannot read the full response there. But here I suppose you mean reading the action result (later I'll show you how to read the actual full response body in a correct phase). When it comes to IActionResult, you have various kinds of IActionResult including custom ones. So it's hard to have a general solution to read the raw wrapped data (which may not even be exposed in some custom implementations). That means you need to target some specific well-known action results to handle it correctly. Here I introduce code to read JsonResult as an example:

public async Task OnActionExecutionAsync(ActionExecutingContext context, ActionExecutionDelegate next)
    {
        var requestBodyData = context.ActionArguments["request"];            
        _logger.LogInformation($"{AppDomain.CurrentDomain.FriendlyName} Endpoint: {nameof(context.ActionDescriptor.DisplayName)} - Request Body: {requestBodyData}");
        
        var actionExecutedContext = await next();
        var responseBodyData = "not supported result";
        //sample for JsonResult
        if(actionExecutedContext.Result is JsonResult jsonResult){
            responseBodyData = JsonSerializer.Serialize(jsonResult.Value);
        }
        //check for other kinds of IActionResult if any ...
        //...
        _logger.LogInformation($"{AppDomain.CurrentDomain.FriendlyName} Endpoint: {nameof(context.ActionDescriptor.DisplayName)} - Response Body: {responseBodyData}");
        
    }

IActionResult has a method called ExecuteResultAsync which can trigger the next processing phase (result execution). That's when the action result is fully written to the HttpContext.Response. So you can try creating a dummy pipeline (starting with a dummy ActionContext) on which to execute the action result and get the final data written to the response body. However that's what I can imagine in theory. It would be very complicated to go that way. Instead you can just use a custom IResultFilter or IAsyncResultFilter to try getting the response body there. Now there is one issue, the default HttpContext.Response.Body is an HttpResponseStream which does not support reading & seeking at all (CanRead & CanSeek are false), we can only write to that kind of stream. So there is a hacky way to help us mock in a readable stream (such as MemoryStream) before running the code that executes the result. After that we swap out the readable stream and swap back the original HttpResponseStream in after copying data from the readable stream to that stream. Here is an extension method to help achieve that:

public static class ResponseBodyCloningHttpContextExtensions
{
    public static async Task<Stream> CloneBodyAsync(this HttpContext context, Func<Task> writeBody)
    {
        var readableStream = new MemoryStream();
        var originalBody = context.Response.Body;
        context.Response.Body = readableStream;
        try
        {
            await writeBody();
            readableStream.Position = 0;
            await readableStream.CopyToAsync(originalBody);
            readableStream.Position = 0;                
        }                        
        finally
        {
            context.Response.Body = originalBody;
        }
        return readableStream;            
    }
}

Now we can use that extension method in an IAsyncResultFilter like this:

//this logs the result only, to write the log entry for starting/beginning the action 
//you can rely on the IAsyncActionFilter as how you use it.
public class LoggingAsyncResultFilterAttribute : Attribute, IAsyncResultFilter
{
    //missing code to inject _logger here ...

    public async Task OnResultExecutionAsync(ResultExecutingContext context, ResultExecutionDelegate next)
    {
        var readableStream = await context.HttpContext.CloneBodyAsync(() => next());
        //suppose the response body contains text-based content
        using (var sr = new StreamReader(readableStream))
        {
            var responseText = await sr.ReadToEndAsync();
            _logger.LogInformation($"{AppDomain.CurrentDomain.FriendlyName} Endpoint: {nameof(context.ActionDescriptor.DisplayName)} - Response Body: {responseText}");
        }
    }
}

You can also use an IAsyncResourceFilter instead, which can capture result written by IExceptionFilter. Or maybe the best, use an IAsyncAlwaysRunResultFilter which can capture the result in all cases.

I assume that you know how to register IAsyncActionFilter so you should know how to register IAsyncResultFilter as well as other kinds of filter. It's just the same.

Answer 2

starting with dotnet 6 asp has HTTP logging built in. Microsoft has taken into account redacting information and other important concepts that need to be considered when logging requests.

var builder = WebApplication.CreateBuilder(args);
var app = builder.Build();
/*  enabled HttpLogging with this line  */
app.UseHttpLogging();
if (!app.Environment.IsDevelopment())
{
    app.UseExceptionHandler("/Error");
}
app.UseStaticFiles();
app.MapGet("/", () => "Hello World!");
app.Run();

https://docs.microsoft.com/en-us/aspnet/core/fundamentals/http-logging/?view=aspnetcore-6.0#enabling-http-logging