Context

Logging is an important feature each application must have. When deploying a multi-threaded and multi-user application in production, logging becomes crucial, as it tends to be the go-to approach for understanding what has happened in case of a production error - I’m not saying this is the best way, just the most common one I’ve seen. To have a complete picture over an application running in production, logging should be accompanied by monitoring (e.g. Prometheus, etc.) and a centralized log aggregation solution (e.g. ELK stack, EFK stack, etc.).

The purpose of this article is to explain how to log the HTTP requests and responses handled by an ASP.NET Core web application using Log4Net. The application is based on one of the official ASP.NET Core tutorials, Create a web API with ASP.NET Core MVC.
The source code is hosted on GitHub, while the automatic builds are provided by Azure DevOps.

Development environment

  • .NET Core SDK v2.2.101
  • Visual Studio 2017 Community Edition v15.9.4
  • Windows 10 Pro x64, version 1809

When running dotnet –info command from any terminal, I see:

dotnet --info
.NET Core SDK (reflecting any global.json):
 Version:   2.2.101
 Commit:    236713b0b7

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.17763
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\2.2.101\

Host (useful for support):
  Version: 2.2.0
  Commit:  1249f08fed
...

Logging support in ASP.NET Core

General information

ASP.NET Core provides logging support integrated with its dependency injection mechanism via several NuGet packages, the important ones being:

Microsoft has done a pretty good job on documenting .NET Core and ASP.NET Core and logging is not an exception - see more here:Logging in ASP.NET Core.
A good companion for the aforementioned link is this one: High-performance logging with LoggerMessage in ASP.NET Core.

Built-in logging providers

By default, when instantiating a web host builder via the WebHost.CreateDefaultBuilder method in order to start a web application, ASP.NET Core will configure several of its built-in logging providers:

Here’s the code fragment used for configuring these logging providers (as seen inside the decompiled code):

namespace Microsoft.AspNetCore
{
    public static class WebHost
    {
        ...
        public static IWebHostBuilder CreateDefaultBuilder(string[] args)
        {
            ...ConfigureLogging((Action<WebHostBuilderContext, ILoggingBuilder>) ((hostingContext, logging) =>
            {
                logging.AddConfiguration((IConfiguration) hostingContext.Configuration.GetSection("Logging"));
                logging.AddConsole();
                logging.AddDebug();
                logging.AddEventSourceLogger();
            }))...
        }
        ...
    }

The console logging provider will display log message inside the terminal used for running the web application, so if you start the web app from Visual Studio, this provider is kind of useless.
Here’s several ways of starting an ASP.NET Core web app from CLI (they assume you are inside the solution root folder and you have opened a non-admin PowerShell terminal):

  • Using compiled solution:
 dotnet .\Sources\TodoWebApp\bin\Debug\netcoreapp2.2\TodoWebApp.dll
  • Using source code:
 dotnet run --project .\Sources\TodoWebApp\TodoWebApp.csproj
  • Using published output:
# Generate a self-contained deployment for any Windows OS running on 64 bits
dotnet publish .\Sources\TodoWebApp\TodoWebApp.csproj --self-contained --runtime win-x64
# Run the native EXE
.\Sources\TodoWebApp\bin\Debug\netcoreapp2.2\win-x64\publish\TodoWebApp.exe

The debug logging provider will display log messages inside the Visual Studio when starting the web app in debug mode (by default pressing F5 button). I suggest configuring your IDE to redirect all output to the Immediate Window by going to Visual Studio menu -> Tools -> Options -> Debugging -> General and then checking Redirect all Output Window text to the Immediate Window option.

I haven’t directly used event source logging provider until now, so please read more about it on its dedicated section found inside the official documentation page, Logging in ASP.NET Core.

In case you don’t need these logging providers, just call the ClearProviders method before configuring your own, e.g. Log4Net:

public void ConfigureServices(IServiceCollection services)
{
    // Configure logging
    services.AddLogging(loggingBuilder =>
    {
        // Ensure the built-in logging providers are no longer in use
        loggingBuilder.ClearProviders();

        // Configure Log4Net logging provider
        loggingBuilder.AddLog4Net();
    });
    ...
}

Configure a logging provider

The .NET community has provided many logging providers, like: Log4Net, NLog, Serilog, etc.
Pick your favorite one, install the appropriate NuGet package(s), then configure it by adding the proper code in one of several places:

  1. Program class, which builds the host running the web application: 
    public static class Program
{
     public static void Main(string[] args)
     {
         CreateWebHostBuilder(args).Build()
                                   .Run();
     }

     public static IWebHost CreateWebHostBuilder(string[] args) =>
         WebHost.CreateDefaultBuilder(args)
                .UseStartup<Startup>()
                .ConfigureLogging((hostingContext, logging) =>
                {
                    // Logging provider setup goes here
                })
                .Build();
     }
  2. Startup class
    2.1 ConfigureServices method: 
    public void ConfigureServices(IServiceCollection services)
{
     services.AddLogging(loggingBuilder =>
     {
         // Logging provider setup goes here
     });
     ...
}

    2.2 Configure method:

    public void Configure(IApplicationBuilder applicationBuilder
                    , IHostingEnvironment environment
                    , ILoggerFactory loggerFactory)
{
     // Use extensions methods against "loggerFactory" parameter
     // to setup your logging provider
     ...
}

I would personally use either ConfigureServices or Configure method of the Startup class for configuring logging since they allow very complex customizations; on the other hand, I would use the Program class for basic setup and optionally enhancing it with the aforementioned methods.

Here’s an example how to configure Log4Net via the Startup.ConfigureServices method:

public void ConfigureServices(IServiceCollection services)
{
    // Configure logging
    services.AddLogging(loggingBuilder =>
    {
        var log4NetProviderOptions = Configuration.GetSection("Log4NetCore")
                                                  .Get<Log4NetProviderOptions>();
        loggingBuilder.AddLog4Net(log4NetProviderOptions);
        loggingBuilder.SetMinimumLevel(LogLevel.Debug);
    });
    ...
}

The code above will read the section named Log4NetCore from the current configuration and will map it to a class, Log4NetProviderOptions, in order to have access to one of the most important Log4Net configuration properties, like the path to the XML file declaring loggers and appenders.
Then, the loggingBuilder.AddLog4Net method call will instruct ASP.NET Core to use Log4NetProvider class from now on as a factory for all needed ILogger objects.
The loggingBuilder.SetMinimumLevel method call is explained here.

Using an ILogger

When a class needs to log a message, it has to declare a dependency upon the ILogger<T> interface; the built-in ASP.NET Core dependency injection will resolve it automatically:

public class TodoService : ITodoService
{
    private readonly TodoDbContext todoDbContext;
    private readonly ILogger logger;

    public TodoService(TodoDbContext todoDbContext, ILogger<TodoService> logger)
    {
        this.todoDbContext = todoDbContext ?? throw new ArgumentNullException(nameof(todoDbContext));
        this.logger = logger ?? throw new ArgumentNullException(nameof(logger));
    }
    ...
}

Then, the class can use its logger field to log a message:

public IList<TodoItem> GetAll()
{
    if (logger.IsEnabled(LogLevel.Debug))
    {
        logger.LogDebug("GetAll() - BEGIN");
    }

    var result = todoDbContext.TodoItems.ToList();

    if (logger.IsEnabled(LogLevel.Debug))
    {
        logger.LogDebug("GetAll() - END");
    }

    return result;
}

Logging the current HTTP context

One of the best ways offered by ASP.NET Core to handle the current HTTP context and manipulate it it’s via a middleware.
The middleware found inside this particular web application will check whether a particular HTTP context must be logged and exactly what to log via several of its dependencies - to be more exact 2 interfaces - since deciding when to log should not depend on what and how to log.
The middleware constructor looks like this:

public LoggingMiddleware(RequestDelegate nextRequestDelegate
                       , IHttpContextLoggingHandler httpContextLoggingHandler
                       , IHttpObjectConverter httpObjectConverter
                       , ILogger<LoggingMiddleware> logger)
{
    this.nextRequestDelegate = nextRequestDelegate ?? throw new ArgumentNullException(nameof(nextRequestDelegate));
    this.httpContextLoggingHandler = httpContextLoggingHandler ?? throw new ArgumentNullException(nameof(httpContextLoggingHandler));
    this.httpObjectConverter = httpObjectConverter ?? throw new ArgumentNullException(nameof(httpObjectConverter));
    this.logger = logger ?? throw new ArgumentNullException(nameof(logger));
}

The middleware logic looks like this:


public async Task Invoke(HttpContext httpContext)
{
    if (httpContextLoggingHandler.ShouldLog(httpContext))
    {
        await Log(httpContext);
    }
    else
    {
        await nextRequestDelegate(httpContext);
    }
}

private async Task Log(HttpContext httpContext)
{
    // Code needed to log the given httpContext object
}

To enable this middleware, I have created an extension method and called it from the Startup class:

public void Configure(IApplicationBuilder applicationBuilder, IHostingEnvironment environment)
{
    // Ensure logging middleware is invoked as early as possible
    applicationBuilder.UseHttpLogging();
    ...
}

To keep things simple, I have written just one service class implementing IHttpContextLoggingHandler (when to log) and IHttpObjectConverter (what & how to log) interfaces - see LoggingService class.

The HttpContext class contains the Request and Response properties which will be converted to log messages by LoggingService class.
The log message generated for the request contains the path, query string, headers and the body, while the log message generated for the response contains the headers and the body.

An HTTP request log message looks like this:

2018-12-26 18:18:57,895 [11] DEBUG TodoWebApp.Logging.LoggingMiddleware
 --- REQUEST 0HLJ82DDDSHQS: BEGIN ---
POST /api/todo HTTP/2.0
Host: localhost
Content-Type: application/json; charset=utf-8

{"Id":-100,"Name":"todo-item-4-testing-ceaa5446ff7940138b8da9a9b7c52b9d","IsComplete":false}
--- REQUEST 0HLJ82DDDSHQS: END ---

The accompanying HTTP response log message looks like this:

2018-12-26 18:18:58,323 [11] DEBUG TodoWebApp.Logging.LoggingMiddleware
 --- RESPONSE 0HLJ82DDDSHQS: BEGIN ---
HTTP/2.0 400 BadRequest
Content-Type: application/json; charset=utf-8

{"Id":["The field Id must be between 1 and 9.22337203685478E+18."]}
--- RESPONSE 0HLJ82DDDSHQS: END ---

Correlation identifier

The 0HLJ82DDDSHQS string represents the so called correlation identifier, which helps in understanding the user journeys inside the application.
An HTTP request and its accompanying response will use the same correlation identifier; furthermore, any log message related to this pair should use this identifier too.
ASP.NET Core offers such correlation identifiers via the HttpContext.TraceIdentifier property, available on both the current HTTP request (the HttpRequest.HttpContext.TraceIdentifier property) and response (the HttpResponse.HttpContext.TraceIdentifier property).

Implementation

When to log

My approach to deciding when to log is based on whether the HTTP request is text-based, expects a text-based response or the request path starts with a given string. The HTTP protocol allows the request to signal its body content type via the Content-Type header, while the expected content type is signaled via the Accept header.
For instance, in case the Accept or Content-Type header is set to text/plain, application/json or application/xml, the request is seen as text-based and thus will be logged; otherwise, the request path is checked and if it starts with /api/ (e.g. /api/todo), the request will also be seen as text-based and will be logged.

Here’s the simplified version of my implementation for when to log:

public class LoggingService : IHttpContextLoggingHandler, IHttpObjectConverter
{
    ...
    private static readonly string[] textBasedHeaderNames = { "Accept", "Content-Type" };
    private static readonly string[] textBasedHeaderValues = { "application/json", "application/xml", "text/" };
    private const string ACCEPTABLE_REQUEST_URL_PREFIX = "/api/";

    public bool ShouldLog(HttpContext httpContext)
    {
        return IsTextBased(httpContext.Request);
    }

    private static bool IsTextBased(HttpRequest httpRequest)
    {
        return textBasedHeaderNames.Any(headerName => IsTextBased(httpRequest, headerName))
            || httpRequest.Path.ToUriComponent().StartsWith(ACCEPTABLE_REQUEST_URL_PREFIX);
    }

    private static bool IsTextBased(HttpRequest httpRequest, string headerName)
    {
        return httpRequest.Headers.TryGetValue(headerName, out var headerValues)
            && textBasedHeaderValues.Any(textBasedHeaderValue => headerValues.Any(headerValue => headerValue.StartsWith(textBasedHeaderValue)));
    }
    ...
}

Please note the logic above is just for demo purposes, as most probably your production-grade application is very different than this one, so please make sure you provide your own implementation for when to log before deploying to production!

What to log

The LoggingService class is converting both the HTTP request and response following the official HTTP message structure, as documented here.
Converting an HTTP request looks like this:

private const int REQUEST_SIZE = 1000;
...
public string ToLogMessage(HttpRequest httpRequest)
{
    if (httpRequest == null)
    {
        throw new ArgumentNullException(nameof(httpRequest));
    }

    if (logger.IsEnabled(LogLevel.Debug))
    {
        logger.LogDebug($"Converting HTTP request {httpRequest.HttpContext.TraceIdentifier} ...");
    }

    var stringBuilder = new StringBuilder(REQUEST_SIZE);
    stringBuilder.AppendLine($"--- REQUEST {httpRequest.HttpContext.TraceIdentifier}: BEGIN ---");
    stringBuilder.AppendLine($"{httpRequest.Method} {httpRequest.Path}{httpRequest.QueryString.ToUriComponent()} {httpRequest.Protocol}");

    if (httpRequest.Headers.Any())
    {
        foreach (var header in httpRequest.Headers)
        {
            stringBuilder.AppendLine($"{header.Key}: {header.Value}");
        }
    }

    stringBuilder.AppendLine();
    stringBuilder.AppendLine(httpRequest.Body.ReadAndReset());
    stringBuilder.AppendLine($"--- REQUEST {httpRequest.HttpContext.TraceIdentifier}: END ---");

    var result = stringBuilder.ToString();
    return result;
}

Converting an HTTP response looks like this:

private const int RESPONSE_SIZE = 1000;
...
public string ToLogMessage(HttpResponse httpResponse)
{
    if (httpResponse == null)
    {
        throw new ArgumentNullException(nameof(httpResponse));
    }

    if (logger.IsEnabled(LogLevel.Debug))
    {
        logger.LogDebug($"Converting HTTP response {httpResponse.HttpContext.TraceIdentifier} ...");
    }

    var stringBuilder = new StringBuilder(RESPONSE_SIZE);
    stringBuilder.AppendLine($"--- RESPONSE {httpResponse.HttpContext.TraceIdentifier}: BEGIN ---");
    stringBuilder.AppendLine($"{httpResponse.HttpContext.Request.Protocol} {httpResponse.StatusCode} {((HttpStatusCode)httpResponse.StatusCode).ToString()}");

    if (httpResponse.Headers.Any())
    {
        foreach (var header in httpResponse.Headers)
        {
            stringBuilder.AppendLine($"{header.Key}: {header.Value}");
        }
    }

    stringBuilder.AppendLine();
    stringBuilder.AppendLine(httpResponse.Body.ReadAndReset());
    stringBuilder.AppendLine($"--- RESPONSE {httpResponse.HttpContext.TraceIdentifier}: END ---");

    var result = stringBuilder.ToString();
    return result;
}

How to log

The LoggingMiddleware class must read both HTTP request and response in order to log them and must ensure that it will do these things without affecting any following middleware which might also need to read them too. Both HttpRequest.Body and HttpResponse.Body properties are streams which once read, cannot be reset to their initial position; this means that once a middleware has read the stream of any of these properties, the following middleware will have nothing to read from.
In order to bypass this problem, one can use the EnableRewind method against the HTTP request and replace the response body stream with a seekable one.

Enable rewinding the HTTP request stream:

httpContext.Request.EnableRewind();

Replacing the HTTP response stream with a seekable one:

private const int RESPONSE_BUFFER_SIZE_IN_BYTES = 1024 * 1024;
...
var originalResponseBodyStream = httpContext.Response.Body;

using (var stream = new MemoryStream(RESPONSE_BUFFER_SIZE_IN_BYTES))
{
    // Replace response body stream with a seekable one, like a MemoryStream, to allow logging it
    httpContext.Response.Body = stream;

    // Process current request
    await nextRequestDelegate(httpContext);

    // Logs the current HTTP response
    var httpResponseAsLogMessage = httpObjectConverter.ToLogMessage(httpContext.Response);
    logger.LogDebug(httpResponseAsLogMessage);

    // Ensure the original HTTP response is sent to the next middleware
    await stream.CopyToAsync(originalResponseBodyStream);
}

Both above code fragments can be found inside the LoggingMiddleware.Log method.

Conclusion

Logging an HTTP context in ASP.NET Core is not an easy task, but as seen above, it can be done.
Care must be taken when trying to log any large request and response bodies - I’m waiting for David Fowler’s recommendation for avoiding reading the entire request body or response body into memory - unfortunately, at the time of writing this paragraph, it’s still not done!
This article has only scratch the surface of the logging iceberg, but hopefully I will come back with more information helping tackling this very important topic.

aspnet-core   aspnet-core-middleware   dotnet   dotnet-core   log4net   logging   programming