Request Response Logging Middleware ASP.NET Core

• Download source code - 9.7 KB

Background

A middleware is a component class that is executed on every request in the ASP.NET application. There could be multiple middleware in the ASP.NET web application. It can be either framework provided or added via NuGet or your own custom middleware. This example uses middleware to log each request response and other information. Here, we will focus on how to generate and store logs using middleware.

Log Helpers

Log Model

This is the basic data structure of a log model, which contains information:

• Identifiers (project client, request, and other trace identifiers)
• Request data
• Response data
• Error information

public class RequestResponseLogModel
{
    public string LogId { get; set; }           /*Guid.NewGuid().ToString()*/
    public string Node { get; set; }            /*project name*/
    public string ClientIp { get; set; }
    public string TraceId { get; set; }         /*HttpContext TraceIdentifier*/


    public DateTime? RequestDateTimeUtc { get; set; }
    public DateTime? RequestDateTimeUtcActionLevel { get; set; }
    public string RequestPath { get; set; }
    public string RequestQuery { get; set; }
    public List<KeyValuePair<string, string>> RequestQueries { get; set; }
    public string RequestMethod { get; set; }
    public string RequestScheme { get; set; }
    public string RequestHost { get; set; }
    public Dictionary<string, string> RequestHeaders { get; set; }
    public string RequestBody { get; set; }
    public string RequestContentType { get; set; }


    public DateTime? ResponseDateTimeUtc { get; set; }
    public DateTime? ResponseDateTimeUtcActionLevel { get; set; }
    public string ResponseStatus { get; set; }
    public Dictionary<string, string> ResponseHeaders { get; set; }
    public string ResponseBody { get; set; }
    public string ResponseContentType { get; set; }


    public bool? IsExceptionActionLevel { get; set; }
    public string ExceptionMessage { get; set; }
    public string ExceptionStackTrace { get; set; }

    public RequestResponseLogModel()
    {
        LogId = Guid.NewGuid().ToString();
    }
}

Log Creator

The log creator will create/hold the log data model. Across the application, this will be used to assign necessary data to the log model. It is important to inject his creator class as scoped in the application. This means for every web request, a new instance of the class will be created. That way, it will be dedicated to a single request.

public interface IRequestResponseLogModelCreator
{
    RequestResponseLogModel LogModel { get; }
    string LogString();
}

public interface IRequestResponseLogger
{
    void Log(IRequestResponseLogModelCreator logCreator);
}

public class RequestResponseLogModelCreator : IRequestResponseLogModelCreator
{
    public RequestResponseLogModel LogModel { get; private set; }

    public RequestResponseLogModelCreator()
    {
        LogModel = new RequestResponseLogModel();
    }

    public string LogString()
    {
        var jsonString = JsonConvert.SerializeObject(LogModel);
        return jsonString;
    }
}

Logger

This logger class is responsible to serialize the log model and store logs. A singleton object would be just fine for this purpose.

public interface IRequestResponseLogger
{
    void Log(IRequestResponseLogModelCreator logCreator);
}

public class RequestResponseLogger : IRequestResponseLogger
{
    private readonly ILogger<RequestResponseLogger> _logger;

    public RequestResponseLogger(ILogger<RequestResponseLogger> logger)
    {
        _logger = logger;
    }
    public void Log(IRequestResponseLogModelCreator logCreator)
    {
        //_logger.LogTrace(jsonString);
        //_logger.LogInformation(jsonString);
        //_logger.LogWarning(jsonString);
        _logger.LogCritical(logCreator.LogString());
    }
}

Log Option

This is a controlling mechanism. Middleware will create/log request/response data if IsEnabled is true.

public class RequestResponseLoggerOption
{
    public bool IsEnabled { get; set; }
    public string Name { get; set; }
    public string DateTimeFormat { get; set; }
}

The option model will get serialized from app configuration or appsettings.json.

{
  "RequestResponseLogger": {
    "IsEnabled": true,
    "Name": "Cpm.Web.Api",
    "DateTimeFormat": "yyyy-MM-dd HH:mm:ss"
}

Middleware

Here, in InvokeAsync() method, we are assigning values to the log model from HttpRequest and HttpResponse.

using Microsoft.AspNetCore.Diagnostics;
using Microsoft.AspNetCore.Http;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Options;
using Newtonsoft.Json;
using System;
using System.IO;
using System.Linq;
using System.Text.Json;
using System.Threading.Tasks;

namespace Cpm.Web.Api.Middlewares
{
    public class RequestResponseLoggerMiddleware
    {
        private readonly RequestDelegate _next;
        private readonly RequestResponseLoggerOption _options;
        private readonly IRequestResponseLogger _logger;

        public RequestResponseLoggerMiddleware
        (RequestDelegate next, IOptions<RequestResponseLoggerOption> options, 
         IRequestResponseLogger logger)
        {
            _next = next;
            _options = options.Value;
            _logger = logger;
        }

        public async Task InvokeAsync(HttpContext httpContext, 
               IRequestResponseLogModelCreator logCreator)
        {
            RequestResponseLogModel log = logCreator.LogModel;
            // Middleware is enabled only when the 
            // EnableRequestResponseLogging config value is set.
            if (_options == null || !_options.IsEnabled)
            {
                await _next(httpContext);
                return;
            }
            log.RequestDateTimeUtc = DateTime.UtcNow;
            HttpRequest request = httpContext.Request;

            /*log*/
            log.LogId = Guid.NewGuid().ToString();
            log.TraceId = httpContext.TraceIdentifier;
            var ip = request.HttpContext.Connection.RemoteIpAddress;
            log.ClientIp = ip == null ? null : ip.ToString();
            log.Node = _options.Name;

            /*request*/
            log.RequestMethod = request.Method;
            log.RequestPath = request.Path;
            log.RequestQuery = request.QueryString.ToString();
            log.RequestQueries = FormatQueries(request.QueryString.ToString());
            log.RequestHeaders = FormatHeaders(request.Headers);
            log.RequestBody = await ReadBodyFromRequest(request);
            log.RequestScheme = request.Scheme;
            log.RequestHost = request.Host.ToString();
            log.RequestContentType = request.ContentType;

            // Temporarily replace the HttpResponseStream, 
            // which is a write-only stream, with a MemoryStream to capture 
            // its value in-flight.
            HttpResponse response = httpContext.Response;
            var originalResponseBody = response.Body;
            using var newResponseBody = new MemoryStream();
            response.Body = newResponseBody;

            // Call the next middleware in the pipeline
            try
            {
                await _next(httpContext);
            }
            catch (Exception exception)
            {
                /*exception: but was not managed at app.UseExceptionHandler() 
                  or by any middleware*/
                LogError(log, exception);
            }

            newResponseBody.Seek(0, SeekOrigin.Begin);
            var responseBodyText = 
                await new StreamReader(response.Body).ReadToEndAsync();

            newResponseBody.Seek(0, SeekOrigin.Begin);
            await newResponseBody.CopyToAsync(originalResponseBody);

            /*response*/
            log.ResponseContentType = response.ContentType;
            log.ResponseStatus = response.StatusCode.ToString();
            log.ResponseHeaders = FormatHeaders(response.Headers);
            log.ResponseBody = responseBodyText;
            log.ResponseDateTimeUtc = DateTime.UtcNow;


            /*exception: but was managed at app.UseExceptionHandler() 
              or by any middleware*/
            var contextFeature = 
                httpContext.Features.Get<IExceptionHandlerPathFeature>();
            if (contextFeature != null && contextFeature.Error != null)
            {
                Exception exception = contextFeature.Error;
                LogError(log, exception);
            }

            //var jsonString = logCreator.LogString(); /*log json*/
            _logger.Log(logCreator);
        }

        private void LogError(RequestResponseLogModel log, Exception exception)
        {
            log.ExceptionMessage = exception.Message;
            log.ExceptionStackTrace = exception.StackTrace;
        }

        private Dictionary<string, string> FormatHeaders(IHeaderDictionary headers) 
        {
            Dictionary<string, string> pairs = new Dictionary<string, string>();
            foreach (var header in headers)
            {
                pairs.Add(header.Key, header.Value);
            }
            return pairs;
        }

        private List<KeyValuePair<string, string>> FormatQueries(string queryString)
        {
            List<KeyValuePair<string, string>> pairs = 
                 new List<KeyValuePair<string, string>>();
            string key, value;
            foreach (var query in queryString.TrimStart('?').Split("&"))
            {
                var items = query.Split("=");
                key = items.Count() >= 1 ? items[0] : string.Empty;
                value = items.Count() >= 2 ? items[1] : string.Empty;
                if (!String.IsNullOrEmpty(key))
                {
                    pairs.Add(new KeyValuePair<string, string>(key, value));
                }    
            }
            return pairs;
        }

        private async Task<string> ReadBodyFromRequest(HttpRequest request)
        {
            // Ensure the request's body can be read multiple times 
            // (for the next middlewares in the pipeline).
            request.EnableBuffering();
            using var streamReader = new StreamReader(request.Body, leaveOpen: true);
            var requestBody = await streamReader.ReadToEndAsync();
            // Reset the request's body stream position for 
            // next middleware in the pipeline.
            request.Body.Position = 0;
            return requestBody;
        }
    }
}

To access the log model, we need to get IRequestResponseLogModelCreator, which will be injected as scoped. This injection will not work for the contractor. So we need to use this in the method InvokeAsync(HttpContext httpContext, IRequestResponseLogModelCreator logCreator).

Singletone injections only work at the constructor level for middleware. In middleware, usage of injection at the constructor level is very common. Even in the example, we are using injected IOptions<RequestResponseLoggerOption> options and IRequestResponseLogger logger.

We can uncomment this line and check log JSON string:

//var jsonString = logCreator.LogString(); /*log json*/

Filters

These filters are optional. In our case, we are using two filters to assign a few values to the log model. It is to demonstrate that we can even set additional log information from filters or controllers if needed. Same as the middleware IRequestResponseLogModelCreator will not be injectable at the constructor. That's why we are using context.RequestServices.GetService<IRequestResponseLogModelCreator>() to get the injected model.

RequestResponseLoggerActionFilter is assigning RequestDateTimeUtcActionLevel and ResponseDateTimeUtcActionLevel to calculate action level execution time.

using Cpm.Web.Api.Middlewares;
using Microsoft.AspNetCore.Mvc.Filters;
using System;
using System.Diagnostics;

namespace Cpm.Web.Api.Filters
{
    [AttributeUsage(validOn: AttributeTargets.Class | AttributeTargets.Method)]
    public class RequestResponseLoggerActionFilter : Attribute, IActionFilter
    {
        private RequestResponseLogModel GetLogModel(HttpContext context)
        {
            return context.RequestServices.GetService
                   <IRequestResponseLogModelCreator>().LogModel;
        }

        public void OnActionExecuting(ActionExecutingContext context)
        {
            var model = GetLogModel(context.HttpContext);
            model.RequestDateTimeUtcActionLevel = DateTime.UtcNow;
        }

        public void OnActionExecuted(ActionExecutedContext context)
        {
            var model = GetLogModel(context.HttpContext);
            model.ResponseDateTimeUtcActionLevel = DateTime.UtcNow;
        }
    }
}

RequestResponseLoggerErrorFilter assigning IsExceptionActionLevel to track if the error is at the action level or at somewhere else. In application, we may get into a scenario where controller actions are executed without any error, but face errors at other middleware or after processors.

using Cpm.Web.Api.Middlewares;
using Microsoft.AspNetCore.Mvc.Filters;
using System;
using System.Diagnostics;

namespace Cpm.Web.Api.Filters
{
    [AttributeUsage(validOn: AttributeTargets.Class | AttributeTargets.Method)]
    public class RequestResponseLoggerErrorFilter : Attribute, IExceptionFilter
    {
        private RequestResponseLogModel GetLogModel(HttpContext context)
        {
            return context.RequestServices.GetService
                   <IRequestResponseLogModelCreator>().LogModel;
        }

        public void OnException(ExceptionContext context)
        {
            var model = GetLogModel(context.HttpContext);
            model.IsExceptionActionLevel = true;
            if (model.ResponseDateTimeUtcActionLevel == null)
            {
                model.ResponseDateTimeUtcActionLevel = DateTime.UtcNow;
            }
        }
    }
}

Using Middleware/Filter

Let's add the middleware, filter, and dependency injections in Startup.cs or in the bootstrap file.

Inside void ConfigureServices(IServiceCollection services):

/*Options*/
services.AddOptions<RequestResponseLoggerOption>().Bind
(Configuration.GetSection("RequestResponseLogger")).ValidateDataAnnotations();
/*IOC*/
services.AddSingleton<IRequestResponseLogger, RequestResponseLogger>();
services.AddScoped<IRequestResponseLogModelCreator, RequestResponseLogModelCreator>();
/*Filter*/
services.AddMvc(options =>
{
    options.Filters.Add(new RequestResponseLoggerActionFilter());
    options.Filters.Add(new RequestResponseLoggerErrorFilter());
});

and in void Configure(IApplicationBuilder app, IWebHostEnvironment env):

/*Middleware*/
app.UseMiddleware<RequestResponseLoggerMiddleware>();

The full Startup.cs or in the bootstrap file:

using Cpm.Web.Api.Filters;
using Cpm.Web.Api.Middlewares;
using Microsoft.AspNetCore.Diagnostics;
using Microsoft.OpenApi.Models;

namespace Cpm.Web.Api
{
    public class Startup
    {
        public Startup(IConfiguration configuration)
        {
            Configuration = configuration;
        }

        public IConfiguration Configuration { get; }

        // This method gets called by the runtime. 
        // Use this method to add services to the container.
        public void ConfigureServices(IServiceCollection services)
        {
            services.AddControllers();
            services.AddSwaggerGen(c =>
            {
                c.SwaggerDoc("v1", new OpenApiInfo 
                { Title = "Cpm.Web.Api", Version = "v1" });
            });

            /*Options*/
            services.AddOptions<RequestResponseLoggerOption>().Bind
            (Configuration.GetSection("RequestResponseLogger")).ValidateDataAnnotations();
            /*IOC*/
            services.AddSingleton<IRequestResponseLogger, RequestResponseLogger>();
            services.AddScoped<IRequestResponseLogModelCreator, 
                               RequestResponseLogModelCreator>();
            /*Filter*/
            services.AddMvc(options =>
            {
                options.Filters.Add(new RequestResponseLoggerActionFilter());
                options.Filters.Add(new RequestResponseLoggerErrorFilter());
            });
        }

        // This method gets called by the runtime. 
        // Use this method to configure the HTTP request pipeline.
        public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
        {
            if (env.IsDevelopment())
            {
                app.UseDeveloperExceptionPage();
                app.UseSwagger();
                app.UseSwaggerUI(c => c.SwaggerEndpoint("/swagger/v1/swagger.json", 
                                 "Cpm.Web.Api v1"));
            }

            /*Middleware*/
            app.UseMiddleware<RequestResponseLoggerMiddleware>();

            /*error manage*/
            app.UseExceptionHandler(c => c.Run(async context =>
            {
                var exception = context.Features
                    .Get<IExceptionHandlerPathFeature>()
                    .Error;
                var response = new { details = "An error occurred" };
                await context.Response.WriteAsJsonAsync(response);
            }));

            app.UseHttpsRedirection();

            app.UseRouting();

            app.UseAuthorization();

            app.UseEndpoints(endpoints =>
            {
                endpoints.MapControllers();
            });
        }
    }
}

Testing the Code

Run the web application.

Curl

url -X POST "https://localhost:7178/api/Hello/Details/1?eventId=100&eventName=name" 
-H  "accept: text/plain" -H  "Content-Type: application/json" -d "{\"value\":\"here\"}"

Log Sample

{
   "LogId":"0b51f509-c8a0-471d-bd79-b3161afb19e7",
   "Node":"Cpm.Web.Api",
   "ClientIp":"::1",
   "TraceId":"0HMJ8HNMBP84I:00000007",
   "RequestDateTimeUtc":"2022-07-18T07:20:15.9655886Z",
   "RequestDateTimeUtcActionLevel":"2022-07-18T07:20:16.0408026Z",
   "RequestPath":"/api/Hello/Details/1",
   "RequestQuery":"?eventId=100&eventName=name",
   "RequestQueries":[
      {
         "Key":"eventId",
         "Value":"100"
      },
      {
         "Key":"eventName",
         "Value":"name"
      }
   ],
   "RequestMethod":"POST",
   "RequestScheme":"https",
   "RequestHost":"localhost:7178",
   "RequestHeaders":{
      "Accept":"text/plain",
      "Host":"localhost:7178",
      "User-Agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) 
       AppleWebKit/537.36 (KHTML, like Gecko) Chrome/103.0.0.0 Safari/537.36",
      ":method":"POST",
      "Accept-Encoding":"gzip, deflate, br",
      "Accept-Language":"en-GB,en-US;q=0.9,en;q=0.8",
      "Content-Type":"application/json",
      "Cookie":"ai_user=tfFT6|2022-02-03T10:19:20.897Z,
       _ga=GA1.1.1007006786.1656487658,.AspNetCore.Culture=c%3Den%7Cuic%3Den,
       ai_session=qUyl5|1658128684507|1658128810611.5",
      "Origin":"https://localhost:7178",
      "Referer":"https://localhost:7178/swagger/index.html",
      "Content-Length":"16",
      "sec-ch-ua":"\".Not/A)Brand\";v=\"99\", \"Google Chrome\";v=\"103\", 
                   \"Chromium\";v=\"103\"",
      "sec-ch-ua-mobile":"?0",
      "sec-ch-ua-platform":"\"Windows\"",
      "sec-fetch-site":"same-origin",
      "sec-fetch-mode":"cors",
      "sec-fetch-dest":"empty"
   },
   "RequestBody":"{\"value\":\"here\"}",
   "RequestContentType":"application/json",
   "ResponseDateTimeUtc":"2022-07-18T07:20:16.0454527Z",
   "ResponseDateTimeUtcActionLevel":"2022-07-18T07:20:16.0411664Z",
   "ResponseStatus":"200",
   "ResponseHeaders":{
      "Content-Type":"application/json; charset=utf-8",
      "Date":"Mon, 18 Jul 2022 07:20:15 GMT",
      "Server":"Kestrel"
   },
   "ResponseBody":"{\"value\":\"here\"}",
   "ResponseContentType":"application/json; charset=utf-8",
   "IsExceptionActionLevel":null,
   "ExceptionMessage":null,
   "ExceptionStackTrace":null
}

References

Request Response Log

• https://elanderson.net/2019/12/log-requests-and-responses-in-asp-net-core-3/
• https://exceptionnotfound.net/using-middleware-to-log-requests-and-responses-in-asp-net-core/
• https://stackoverflow.com/questions/63573551/how-to-add-request-body-in-serilogs-output-net-core

IP

• https://stackoverflow.com/questions/28664686/how-do-i-get-client-ip-address-in-asp-net-core

Observability

• https://devblogs.microsoft.com/dotnet/observability-asp-net-core-apps/

About Code Sample

• Visual Studio 2022 Solution
• ASP.NET 6
• This example is also tested in 5, 3.1

History

• 29^th July, 2022: Initial version