.Net 6 - Custom Middleware Logging - Mixing responses and requests

Question

I have written custom middleware that logs requests and responses made to our APIs.

What I've realised is that the requests and responses are not matching, they seem to get mixed up, which is very odd.

This seems to happen when a lot of requests are made within a very short time. Not sure how, but it seems like when LogResponse is called, it's not within the same scope as LogRequest.

I've implemented a version of: https://stackoverflow.com/a/43404745/2286743

Am I missing anything?

Trimmed down version of actual code

using System;
using System.IO;
using System.Text;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Http;
using Microsoft.AspNetCore.Http.Features;

namespace Middleware
{
    public class Web
    {
        private readonly RequestDelegate _next;

        private Logging.AuditLog _auditLog;

        public Web(RequestDelegate next)
        {
            _next = next;
        }

        public async Task Invoke(HttpContext context)
        {
            try
            {
                EndpointMetadataCollection endpointMetaData = context.Features.Get<IEndpointFeature>()?.Endpoint.Metadata;

                context.Request.EnableBuffering();

                await LogRequest(context);
                await LogResponse(context);
            }
            catch (UnauthorizedAccessException)
            {
                throw;
            }
            catch (Exception ex)
            {
                //Custom exception logging here
            }
        }

        public async Task LogRequest(HttpContext context)
        {
            IHttpRequestFeature features = context.Features.Get<IHttpRequestFeature>();
            string url = $"{features.Scheme}://{context.Request.Host.Value}{features.RawTarget}";

            IFormCollection form = null;
            string formString = string.Empty;

            if (context.Request.HasFormContentType)
            {
                form = context.Request.Form;
            }
            else
            {
                formString = await new StreamReader(context.Request.Body).ReadToEndAsync();
                var injectedRequestStream = new MemoryStream();
                byte[] bytesToWrite = Encoding.UTF8.GetBytes(formString);
                injectedRequestStream.Write(bytesToWrite, 0, bytesToWrite.Length);
                injectedRequestStream.Seek(0, SeekOrigin.Begin);
                context.Request.Body = injectedRequestStream;
            }

            _auditLog = new Logging.AuditLog()
            {
                RemoteHost = context.Connection.RemoteIpAddress.ToString(),
                HttpURL = url,
                LocalAddress = context.Connection.LocalIpAddress.ToString(),
                Headers = Newtonsoft.Json.JsonConvert.SerializeObject(context.Request.Headers),
                Form = form != null ? Newtonsoft.Json.JsonConvert.SerializeObject(form) : formString
            };
        }

        public async Task LogResponse(HttpContext context)
        {
            if (_auditLog == null)
            {
                await _next(context);
                return;
            }

            Stream originalBody = context.Response.Body;

            try
            {

                using (var memStream = new MemoryStream())
                {
                    context.Response.Body = memStream;

                    await _next(context);

                    memStream.Position = 0;
                    string responseBody = new StreamReader(memStream).ReadToEnd();

                    _auditLog.ResponseStatusCode = context.Response.StatusCode;
                    _auditLog.ResponseBody = responseBody;
                    _auditLog = _auditLog.Save();

                    memStream.Position = 0;
                    await memStream.CopyToAsync(originalBody);
                }
            }
            catch
            {
                _auditLog?.Save();
                throw;
            }
            finally
            {
                context.Response.Body = originalBody;
            }
        }
    }
}

Answer 1

So I was able to resolve this after some investigations.

The global variables set, is what was causing the mix-up. They are being re-used by all other endpoints.

private Logging.AuditLog _auditLog; has to be used within the methods to function as intended. If set globally, when a new endpoint is invoked, it will re-write the _auditLog variable with a new object. The other endpoint, still being executed, will have it's object for _auditLog replaced. That caused duplicates and mismatching response to request bodies.

The changes I made:

OLD

await LogRequest(context);
await LogResponse(context);

NEW

var auditLog = await LogRequest(context);
await LogResponse(context, auditLog);

The rest is self explanatory.

Here is the full page:

using System;
using System.IO;
using System.Text;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Http;
using Microsoft.AspNetCore.Http.Features;

namespace Middleware
{
    public class Web
    {
        private readonly RequestDelegate _next;

        public Web(RequestDelegate next)
        {
            _next = next;
        }

        public async Task Invoke(HttpContext context)
        {
            try
            {
                EndpointMetadataCollection endpointMetaData = context.Features.Get<IEndpointFeature>()?.Endpoint.Metadata;

                context.Request.EnableBuffering();

                var auditLog = await LogRequest(context);
                await LogResponse(context, auditLog);
            }
            catch (UnauthorizedAccessException)
            {
                throw;
            }
            catch (Exception ex)
            {
                //Custom exception logging here
            }
        }

        public async Task<Logging.AuditLog> LogRequest(HttpContext context)
        {
            IHttpRequestFeature features = context.Features.Get<IHttpRequestFeature>();
            string url = $"{features.Scheme}://{context.Request.Host.Value}{features.RawTarget}";

            IFormCollection form = null;
            string formString = string.Empty;

            if (context.Request.HasFormContentType)
            {
                form = context.Request.Form;
            }
            else
            {
                formString = await new StreamReader(context.Request.Body).ReadToEndAsync();
                var injectedRequestStream = new MemoryStream();
                byte[] bytesToWrite = Encoding.UTF8.GetBytes(formString);
                injectedRequestStream.Write(bytesToWrite, 0, bytesToWrite.Length);
                injectedRequestStream.Seek(0, SeekOrigin.Begin);
                context.Request.Body = injectedRequestStream;
            }

            return new Logging.AuditLog()
            {
                RemoteHost = context.Connection.RemoteIpAddress.ToString(),
                HttpURL = url,
                LocalAddress = context.Connection.LocalIpAddress.ToString(),
                Headers = Newtonsoft.Json.JsonConvert.SerializeObject(context.Request.Headers),
                Form = form != null ? Newtonsoft.Json.JsonConvert.SerializeObject(form) : formString
            };
        }

        public async Task LogResponse(HttpContext context, Logging.AuditLog auditLog)
        {
            if (auditLog == null)
            {
                await _next(context);
                return;
            }

            Stream originalBody = context.Response.Body;

            try
            {

                using (var memStream = new MemoryStream())
                {
                    context.Response.Body = memStream;

                    await _next(context);

                    memStream.Position = 0;
                    string responseBody = new StreamReader(memStream).ReadToEnd();

                    auditLog.ResponseStatusCode = context.Response.StatusCode;
                    auditLog.ResponseBody = responseBody;
                    auditLog = auditLog.Save();

                    memStream.Position = 0;
                    await memStream.CopyToAsync(originalBody);
                }
            }
            catch
            {
                auditLog?.Save();
                throw;
            }
            finally
            {
                context.Response.Body = originalBody;
            }
        }
    }
}