HttpContext from an Enricher or a Middleware

[alexandrejobin]

Hi everyone,

I'm using .Net Core 3.1 and I've read a lot on how to enrich Serilog with HttpContext information. I've found more than one way to do it and i would like to have your opinion.

Suppose that I would like to enrich with the logged username. I must have access to the HttpContext. Here's the 2 ways that I've found:

1. Create a new class UserNameEnricher that receive IHttpContextAccessor in the constructor and add it to the Serilog configuration
2. Create a new class SerilogUserNameMiddleware and add it to the pipeline in the Configure function

UserNameEnricher

public static class UserNameLoggerConfigurationExtensions
{
    public static LoggerConfiguration WithUserName(this LoggerEnrichmentConfiguration enrichmentConfiguration)
    {
        if (enrichmentConfiguration == null) throw new ArgumentNullException(nameof(enrichmentConfiguration));
        return enrichmentConfiguration.With<UserNameEnricher>();
    }
}

public class UserNameEnricher : ILogEventEnricher
{
    private readonly IHttpContextAccessor _contextAccessor;

    public UserNameEnricher() : this(new HttpContextAccessor())
    {
    }

    public UserNameEnricher(IHttpContextAccessor contextAccessor)
    {
        _contextAccessor = contextAccessor;
    }

    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        var userName = _contextAccessor.HttpContext?.User?.Identity?.Name;
        var property = propertyFactory.CreateProperty("UserName", userName);

        logEvent.AddOrUpdateProperty(property);
    }
}

And then, add it to Serilog

public class Program
{
    public static int Main(string[] args)
    {
        var configuration = new ConfigurationBuilder()
            .AddJsonFile("appsettings.json", optional: false, reloadOnChange: true)
            .AddEnvironmentVariables()
            .Build();

        // Configure logger
        Log.Logger = new LoggerConfiguration()
            .ReadFrom.Configuration(configuration)
            .Enrich.FromLogContext()
            .Enrich.WithUserName()
            .CreateLogger();

        try
        {
            Log.Information("Configuring host...");
            var host = CreateHostBuilder(args).Build();

            Log.Information("Starting host...");
            host.Run();

            Log.Information("Program terminated successfully!");
            return 0;
        }
        catch (Exception ex)
        {
            Log.Fatal(ex, "Program terminated unexpectedly!");
            return 1;
        }
        finally
        {
            Log.CloseAndFlush();
        }
    }

    private static IHostBuilder CreateHostBuilder(string[] args)
    {
        var builder = Host.CreateDefaultBuilder(args)
                        .ConfigureWebHostDefaults(webBuilder =>
                        {
                            webBuilder.UseStartup<Startup>();
                            webBuilder.UseSerilog();
                        });

        return builder;
    }        
}

SerilogUserNameMiddleware

public class SerilogUserNameMiddleware
{
    readonly RequestDelegate _next;

    public SerilogUserNameMiddleware(RequestDelegate next)
    {
        if (next == null)
        {
            throw new ArgumentNullException(nameof(next));
        }

        _next = next;
    }

    public async Task Invoke(HttpContext httpContext)
    {
        if (httpContext == null)
        {
            throw new ArgumentNullException(nameof(httpContext));
        }

        var userName = httpContext.User?.Identity?.Name;

        // Push the user name into the log context so that it is included in all log entries
        using (LogContext.PushProperty("UserName", userName))
        {
            await _next(httpContext);
        }            
    }
}

And add it to the pipeline

public void Configure(IApplicationBuilder app)
{
    app.UseStaticFiles();
    app.UseRouting();
    app.UseMiddleware<SerilogUserNameMiddleware>();
    app.UseCookiePolicy();
    app.UseEndpoints(endpoints =>
    {
        endpoints.MapControllers();
    });
}

So what is the best way to implement the Enricher if we must consider speed, memory allocation, etc. My goal is to add all the HttpRequest information available for the log (headers, querystring, etc).

My opinion would be to use the Enricher since that its seems to be cleaner than the middleware. Also, the code is only executed if the code use the logger. With the middleware, it is executed everytime. But since that many user propose the middleware, i'm a little bit confused.

[sungam3r]

Both options are working. Do not worry that you need to choose some one truly true. I believe that the second option is more natural, because it does not go beyond the scope of the request. In the first case, even for background tasks, you will have a UserName property in the logs. In my practice I use both approaches :)

[alexandrejobin]

I've made an HttpRequestEnricherMiddleware because I can use async method more easly to read the request body. By using the Serilog Enricher, I had to read it async but synchronise it afterward and I think it is not recommended. But when I read the log, i'm getting a $type": "HttpContextInfo. Is it possible to get ride of it?

/// <summary>
/// Add the current http request to the Serilog context.
/// </summary>
public class HttpRequestEnricherMiddleware
{
    private const string HttpRequestPropertyName = "HttpRequest";
    readonly RequestDelegate _next;

    public HttpRequestEnricherMiddleware(RequestDelegate next)
    {
        if (next == null)
        {
            throw new ArgumentNullException(nameof(next));
        }

        _next = next;
    }

    public async Task Invoke(HttpContext httpContext)
    {
        if (httpContext == null)
        {
            throw new ArgumentNullException(nameof(httpContext));
        }

        var httpRequestInfo = await GetHttpRequestInfoAsync(httpContext);

        // Push the user name into the log context so that it is included in all log entries
        using (LogContext.PushProperty(HttpRequestPropertyName, httpRequestInfo, true))
        {
            await _next(httpContext);
        }
    }

    private async Task<HttpContextInfo> GetHttpRequestInfoAsync(HttpContext httpContext)
    {
        var httpRequest = httpContext?.Request;

        if (httpRequest == null)
        {
            return null;
        }

        string body = "";

        if (httpRequest.ContentLength.HasValue && httpRequest.ContentLength > 0)
        {
            httpRequest.EnableBuffering();

            using (var reader = new StreamReader(httpRequest.Body, Encoding.UTF8, false, 1024, true))
            {
                body = await reader.ReadToEndAsync();
            }

            // Reset the request body stream position so the next middleware can read it
            httpRequest.Body.Position = 0;
        }

        return new HttpContextInfo()
        {
            Host = httpRequest.Host.ToString(),
            Path = httpRequest.Path,
            Scheme = httpRequest.Scheme,
            Method = httpRequest.Method,
            Protocol = httpRequest.Protocol,
            QueryString = httpRequest.Query.ToDictionary(x => x.Key, y => y.Value.ToString()),
            Headers = httpRequest.Headers
                        .Where(x => x.Key != "Cookie") // remove Cookie from header since it is analysed separatly
                        .ToDictionary(x => x.Key, y => y.Value.ToString()),
            Cookies = httpRequest.Cookies.ToDictionary(x => x.Key, y => y.Value.ToString()),
            Body = body
        };
    }
}

internal class HttpContextInfo
{
    public string Host { get; set; }
    public string Path { get; set; }
    public string Scheme { get; set; }        
    public string Method { get; set; }        
    public string Protocol { get; set; }        
    public Dictionary<string, string> QueryString { get; set; }        
    public Dictionary<string, string> Headers { get; set; }        
    public Dictionary<string, string> Cookies { get; set; }        
    public string Body { get; set; }
}

[sungam3r]

But when I read the log, i'm getting a $type": "HttpContextInfo. Is it possible to get ride of it?

Yes, I got rid of it myself. Use JsonValueFormatter(typeTagName: null)

[alexandrejobin]

Ok... i see that I have to declare it in code. Any way to declare it in appsettings?

[sungam3r]

I installed it in code.

[alexandrejobin]

I've just faced a problem when using the middleware path. The enrichment is not permanent for the request. Let's suppose that I have configured the middleware that way:

public void Configure(IApplicationBuilder app)
{
    app.UseMiddleware<SerilogCatch404Middleware>();

    if (_env.IsDevelopment())
    {
        app.UseDeveloperExceptionPage();
    }
    else
    {
        app.UseExceptionHandler("/Home/Error");
        app.UseHsts();
    }

    app.UseStaticFiles();
    app.UseSerilogHttpRequestEnricher();
    app.UseSerilogRemoteIpAddressEnricher();
    app.UseRouting();
    app.UseAuthentication();
    app.UseSerilogUserNameEnricher();
    app.UseAuthorization();
    app.UseCookiePolicy();
    app.UseEndpoints(endpoints =>
    {
        endpoints.MapControllers();
    });
}

I've added the SerilogCatch404Middleware as the first middleware in the pipeline because I would like to catch all 404 coming from everywhere. After that, I enrich serilog with 2 middlewares, UseSerilogHttpRequestEnricher and UseSerilogRemoteIpAddressEnricher and after I declare UseAuthentication, I can also add the UseSerilogUserNameEnricher.

So if a 404 occur, I do not have the enrichment from UseSerilogHttpRequestEnricher, UseSerilogRemoteIpAddressEnricher and UseSerilogUserNameEnricher.

I can move some middlewares that way:

public void Configure(IApplicationBuilder app)
{
    app.UseSerilogHttpRequestEnricher();
    app.UseSerilogRemoteIpAddressEnricher();
    app.UseMiddleware<SerilogCatch404Middleware>();

    if (_env.IsDevelopment())
    {
        app.UseDeveloperExceptionPage();
    }
    else
    {
        app.UseExceptionHandler("/Home/Error");
        app.UseHsts();
    }

    app.UseStaticFiles();
    app.UseRouting();
    app.UseAuthentication();
    app.UseSerilogUserNameEnricher();
    app.UseAuthorization();
    app.UseCookiePolicy();
    app.UseEndpoints(endpoints =>
    {
        endpoints.MapControllers();
    });
}

But I'm still missing the Authentification info because I must use UseSerilogUserNameEnricher after UseAuthentication.

So my assumption here is that using middlewares is good but can be a real headache when you want to have combine information but different middleware.

I think that I would not have this problem when using real Enricher.

What is you thought?

[sungam3r]

The middleware call order is chosen by the developer. Some middlewars stop the request processing chain and do not call next(). This is the natural order of things. You can always move logging middlewares to the beginning of the chain.

[alexandrejobin]

I understand but it seems that if you put everything at the beginning, it can consume a lot for nothing. Personally, I have converted everything in real Enrichers. It will be called only of a log is requested.

public class HttpRequestEnricher : ILogEventEnricher
{
    private const string HttpRequestPropertyName = "HttpRequest";
    private const string HttpRequestPropertyCacheName = "Serilog.Enrichers.AspnetCore.HttpRequestEnricher";
    private IHttpContextAccessor _httpContextAccessor;

    public HttpRequestEnricher()
        : this(new HttpContextAccessor())
    {
    }

    public HttpRequestEnricher(IHttpContextAccessor httpContextAccessor)
    {
        this._httpContextAccessor = httpContextAccessor;
    }

    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        var httpContext = _httpContextAccessor.HttpContext;

        if (httpContext == null && httpContext.Request == null)
        {
            return;
        }

        var httpRequestPropertyCache = httpContext.Items[HttpRequestPropertyCacheName] as LogEventProperty;

        if (httpRequestPropertyCache == null)
        {
            httpRequestPropertyCache = CreateProperty(propertyFactory, httpContext);
            httpContext.Items[HttpRequestPropertyCacheName] = httpRequestPropertyCache;
        }

        logEvent.AddPropertyIfAbsent(httpRequestPropertyCache);
    }

    private LogEventProperty CreateProperty(ILogEventPropertyFactory propertyFactory, HttpContext httpContext)
    {
        var httpRequest = httpContext.Request;

        string body = "";

        if (httpRequest.ContentLength.HasValue && httpRequest.ContentLength > 0)
        {
            httpRequest.EnableBuffering();

            using (var reader = new StreamReader(httpRequest.Body, Encoding.UTF8, false, 1024, true))
            {
                body = AsyncUtil.RunSync(() => reader.ReadToEndAsync());
            }

            // Reset the request body stream position so the next middleware can read it
            httpRequest.Body.Position = 0;
        }

        var httpRequestInfo = new HttpRequestInfo()
        {
            Host = httpRequest.Host.ToString(),
            Path = httpRequest.Path,
            Scheme = httpRequest.Scheme,
            Method = httpRequest.Method,
            Protocol = httpRequest.Protocol,
            QueryString = httpRequest.Query.ToDictionary(x => x.Key, y => y.Value.ToString()),
            Headers = httpRequest.Headers
                        .Where(x => x.Key != "Cookie") // remove Cookie from header since it is analysed separatly
                        .ToDictionary(x => x.Key, y => y.Value.ToString()),
            Cookies = httpRequest.Cookies.ToDictionary(x => x.Key, y => y.Value.ToString()),
            Body = body
        };

        var httpRequestProperty = propertyFactory.CreateProperty(HttpRequestPropertyName, httpRequestInfo, true);

        return httpRequestProperty;
    }
}

/// <summary>
/// Helper class to run async methods within a sync process.
/// </summary>
internal static class AsyncUtil
{
    private static readonly TaskFactory _taskFactory = new TaskFactory(CancellationToken.None, TaskCreationOptions.None, TaskContinuationOptions.None, TaskScheduler.Default);

    /// <summary>
    /// Executes an async Task method which has a void return value synchronously
    /// USAGE: AsyncUtil.RunSync(() => AsyncMethod());
    /// </summary>
    /// <param name="task">Task method to execute</param>
    public static void RunSync(Func<Task> task)
        => _taskFactory
            .StartNew(task)
            .Unwrap()
            .GetAwaiter()
            .GetResult();

    /// <summary>
    /// Executes an async Task<T> method which has a T return type synchronously
    /// USAGE: T result = AsyncUtil.RunSync(() => AsyncMethod<T>());
    /// </summary>
    /// <typeparam name="TResult">Return Type</typeparam>
    /// <param name="task">Task<T> method to execute</param>
    /// <returns></returns>
    public static TResult RunSync<TResult>(Func<Task<TResult>> task)
        => _taskFactory
            .StartNew(task)
            .Unwrap()
            .GetAwaiter()
            .GetResult();
}

[sungam3r]

Well, it looks a bit confusing to modify HttpContext from enricher. Also regarding this

 public static TResult RunSync<TResult>(Func<Task<TResult>> task)
        => _taskFactory
            .StartNew(task)
            .Unwrap()
            .GetAwaiter()
            .GetResult();

Why not

reader.ReadToEndAsync().GetAwaiter().GetResult();

?

[alexandrejobin]

I've searched the web on how to read in sync an async method and I've found that there's no "good" way to do this. The reader.ReadToEndAsync().GetAwaiter().GetResult(); could cause some bad behaviors and I've come across this article: https://www.ryadel.com/en/asyncutil-c-helper-class-async-method-sync-result-wait/

But if you say that your way is secure, I can remove my helper.

About modifying the HttpContext from enricher, maybe there's better way to keep the result in cache for the next log call from the same request. I've just used what i've found online and it seems to work fine.

[sungam3r]

If you have an .NET Core application, then no deadlock problems will occur, since such applications do not have a synchronization context. Your helper methods are nothing more than just complication. There may indeed be problems with deadlocks when synchronously waiting, but in other types of applications - WPF, WinForms, ASP.NET (not Core). See https://blog.stephencleary.com/2017/03/aspnetcore-synchronization-context.html

[alexandrejobin]

So do you suggest to only use reader.ReadToEndAsync().GetAwaiter().GetResult();?

[sungam3r]

Yes.

[terryaney]

Running this, the constructor with the IHttpContextAccessor param seems to never used via the asp.net dependency injection. But rather HttpRequestEnricher is constructed one time from the Program.Main with the empty constructor (creating the HttpContextAccessor itself). It seems to work. Is that the standard practice? Looking at this repo (https://github.com/trenoncourt/serilog-enrichers-aspnetcore-httpcontext), he seems to try and do something much more complicated. Know Pros/Cons of each method?

[sungam3r]

 public class HttpContextAccessor : IHttpContextAccessor
    {
        private static AsyncLocal<HttpContextHolder> _httpContextCurrent = new AsyncLocal<HttpContextHolder>();

        public HttpContext HttpContext
        {
            get
            {
                return  _httpContextCurrent.Value?.Context;
            }
            set
            {
                var holder = _httpContextCurrent.Value;
                if (holder != null)
                {
                    // Clear current HttpContext trapped in the AsyncLocals, as its done.
                    holder.Context = null;
                }

                if (value != null)
                {
                    // Use an object indirection to hold the HttpContext in the AsyncLocal,
                    // so it can be cleared in all ExecutionContexts when its cleared.
                    _httpContextCurrent.Value = new HttpContextHolder { Context = value };
                }
            }
        }

        private class HttpContextHolder
        {
            public HttpContext Context;
        }
    }

So nothing bad happens if you create HttpContextAccessor manually.

[thomaswurtz]

I had problems getting the approach with ILogEventEnricher to work, but later found that you need to add a call to AddHttpContextAccessor() in ConfigureServices to be able to get the correct instance of IHttpContextAccessor. Otherwise it will use the one created in the default constructor which will always have HttpContext = null.

public void ConfigureServices(IServiceCollection services)
{
    services.AddHttpContextAccessor();
    ...
}

See: https://docs.microsoft.com/en-us/aspnet/core/fundamentals/http-context?view=aspnetcore-5.0#use-httpcontext-from-custom-components