2 Ways to Log the Current User in ASP.Net Core

Lee Richardson -

If you've ever had to debug a problem with a production system you know that good logs are absolutely essential.  However, knowing what information might be useful, and how much is too much is almost an artform.

I had the opportunity to develop that artform recently when I published an ASP.Net Boilerplate based system into production.  Overall the deployment went well, but I realized that I'd failed to include the currently logged in user or tenant in logs.  That made debugging issues harder.

Therefore, this is the story of how to how to add information about the currently logged in user, potentially including the tenant in a multi-tenant solution, in ASP.Net Core.  First I'll show it in ASP.Net Boilerplate with log4net.  Next I'll show how with ABP Framework and the Microsoft Logging Framework via Serilog.  Hopefully, you can find something here to adapt for your tech stack, and help you develop your inner log artistry.

ASP.Net Boilerplate + log4net

For log4net, the first trick is adding custom fields.  That happens in the log4net.config configuration file.  It turns out to be somewhat unintuitive via log4net's property{name} syntax:

<appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender" >
    ...
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%-5level %date [%-5.5property{userid}] [%-5.5property{tenantid}] [%-5.5thread] %-40.40logger - %message%newline" />
</layout>
</appender>

I surrounded the userid and tenantid fields with brackets and used the fixed-width pattern layout -5.5 to pad integer values less than 5 characters to 5 characters.

To populate those fields in log4net you need set the property on a context, which makes it available for all logs.  There are four contexts to choose from, but the one that makes the most sense here is the logical thread context, since that is the level at which requests are processed and it can persist across await points even if a different thread is used to resume the request.  The code then looks like LogicalThreadContext.Properties["userid"] = ??.  But where to set it.

The most appropriate place is in a middleware component during the request pipeline, right after authentication so that the current user is available.  In other words:

public void Configure(IApplicationBuilder app, ILoggerFactory loggerFactory)
{
    ...
    app.UseAuthentication();
    
    app.UseSessionLogging();
    
    ...
}

UseSessionLogging is an extension method that looks like this:

public static class SessionLoggingMiddlewareUtil
{
    public static void UseSessionLogging(this IApplicationBuilder app)
    {
        app.UseMiddleware<SessionLoggingMiddleware>();
    }
}

I chose Factory-based middleware activation in ASP.NET Core so that I could get dependency injection in order to get access to to an IAbpSession, upon which I could get the current user and tenant.  So the last piece of the puzzle is then:

public class SessionLoggingMiddleware : IMiddleware, ITransientDependency
{
    private readonly IAbpSession _session;

    public SessionLoggingMiddleware(IAbpSession session)
    {
        _session = session;
    }

    public async Task InvokeAsync(HttpContext context, RequestDelegate next)
    {
        LogicalThreadContext.Properties["userid"] = _session.UserId;
        LogicalThreadContext.Properties["tenantid"] = _session.TenantId;
        await next(context);
    }
}

The full code is available in LeesStore PR #30.  

Note that using other appenders like an ApplicationInsightsAppender are similar with some minor variation.  

<appender name="AiAppender" type="Microsoft.ApplicationInsights.Log4NetAppender.ApplicationInsightsAppender, Microsoft.ApplicationInsights.Log4NetAppender">
  <threshold value="Info" />
  <layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%-5level %property{userid} %property{tenantid} %message%newline"/>
  </layout>
</appender>

The AdoNetAppender is slightly trickier:

<appender name="AdoNetAppender" type="MicroKnights.Logging.AdoNetAppender, MicroKnights.Log4NetAdoNetAppender">
  ..
  <commandText value="INSERT INTO LogEntries ([Date],[Level],[Logger],[Message],[Exception],[UserId],[TenantId]) VALUES (@log_date, @log_level, @logger, @message, @exception, @userid, @tenantid)" />
    ...
    <parameter>
      <parameterName value="@userid" />
      <dbType value="Int32" />
      <layout type="log4net.Layout.RawPropertyLayout">
        <key value="auserid" />
      </layout>
    </parameter>
</appender>

ABP Framework + Serilog

I love log4net.  I've been using it forever.  But serilog is more modern and feels more elegant.  Using it's equivalent of custom fields for a "console appender" is as simple as placing them in curley brackets in an output template set up in Program.cs:

Log.Logger = new LoggerConfiguration()
    .Enrich.FromLogContext()
    .WriteTo.Async(c => c.File("Logs/logs.txt", outputTemplate:
        "{Level:u4} [{UserId}] [{TenantId}] [{Timestamp:HH:mm:ss}] {Message:lj}{NewLine}{Exception}"))
    .WriteTo.Async(c => c.Console())
    .CreateLogger();

Setting those custom fields is done with LogContext.PushProperty().  Where to place that code is a bit trickier.  I'm still a fan of a custom middleware component, but plugging in a middleware component in ABP Framework doesn't happen in Startup.cs.  That's because ABP Framework decentralizes that logic, allowing each dependent Module the ability to register custom middleware.

However, there's no need for a custom module.  Just add the middleware component like before but in the OnApplicationInitialization() method of the [MyProject]ApiHostModule.

public override void OnApplicationInitialization(ApplicationInitializationContext context)
{
    ...
    app.UseAuthentication();
    app.UseSessionLogging();
}

Then the middleware component itself is extremely similar to the last one:

public class SessionLoggingMiddleware : IMiddleware, ITransientDependency
{
    private readonly ICurrentUser _currentUser;
    private readonly ICurrentTenant _currentTenant;

    public SessionLoggingMiddleware(ICurrentUser currentUser, ICurrentTenant currentTenant)
    {
        _currentUser = currentUser;
        _currentTenant = currentTenant;
    }

    public async Task InvokeAsync(HttpContext context, RequestDelegate next)
    {
        using (Serilog.Context.LogContext.PushProperty("UserId", _currentUser.Id))
        using (Serilog.Context.LogContext.PushProperty("TenantId", _currentTenant.Id))
        {
            await next(context);
        }
    }
}

And now the console logs contain the user and tenant.

Or perhaps you're sending them to Application Insights.  Or if you're logging them to the database you can expose them on an internal page:

The full changes are in LeesStore PR 31

Conclusion

This concludes two fairly different approaches to logging.  Hopefully you can adapt something you learned here to avoid some production pain, or just to develop your artistic sensibilities.