Logging

Log Requests and Responses in ASP.NET Core 3

This post is going to be a refresh of the Log Requests and Responses in ASP.NET Core post which no longer works more modern versions of ASP.NET Core. For the most part, this post will exactly match the original but with the code bits updated.

As part of trying to do some debugging, I needed a way to log the requests and responses. Writing a piece of middleware seemed to be a good way to handle this problem. It also turned out to be more complicated than I had expected to deal with the request and response bodies.

Middleware

In ASP.NET Core middleware are the components that make up the HTTP pipeline that handles requests and responses for the application. Each piece of middleware called has the option to do some processing on the request before calling the next piece of middleware in line. After execution returns from the call to the next middleware, there is an opportunity to do processing on the response.

The HTTP pipeline for an application is set in the Configure function of the Startup class. Run, Map and Use are the three types of middleware available. Run should only be used to terminate the pipeline. Map is used for pipeline branching. Use seems to be the most common type of middleware that does some processing and call the next middleware in line. For more detail see the official docs.

Creating Middleware

Middleware can be implemented as a lambda directly in the Configure function, but more typically it is implemented as a class that is added to the pipeline using an extension method on IApplicationBuilder. This example will be using the class route.

This example is a piece of middleware that uses ASP.NET Core’s built-in logging to log requests and responses. Create a class called RequestResponseLoggingMiddleware.

The class will need a constructor that takes two arguments both will be provided by ASP.NET Core’s dependency injection system. The first is a RequestDelegate which will be the next piece of middleware in the pipeline. The second is an instance of an ILoggerFactory which will be used to create a logger. The RequestDelegate is stored to the class level _next variable and the loggerFactory is used to create a logger that is stored to the class level _logger variable.

public class RequestResponseLoggingMiddleware
{
    private readonly RequestDelegate _next;
    private readonly ILogger _logger;

    public RequestResponseLoggingMiddleware(RequestDelegate next,
                                            ILoggerFactory loggerFactory)
    {
        _next = next;
        _logger = loggerFactory
                  .CreateLogger<RequestResponseLoggingMiddleware>();
    }
}

Add an Invoke function which is the function that will be called when your middleware is run by the pipeline. The following is the function that does nothing other than call the next middleware in the pipeline.

public async Task Invoke(HttpContext context)
{
     //code dealing with the request

     await _next(context);

     //code dealing with the response
}

Next, add a static class to simplify adding the middleware to the application’s pipeline. This is the same pattern the built-in middleware uses.

public static class RequestResponseLoggingMiddlewareExtensions
{
    public static IApplicationBuilder UseRequestResponseLogging(this IApplicationBuilder builder)
    {
        return builder.UseMiddleware<RequestResponseLoggingMiddleware>();
    }
}

Adding to the pipeline

To add the new middleware to the pipeline open the Startup.cs file and add the following line to the Configure function.

app.UseRequestResponseLogging();

Keep in mind that the order in which middleware is added can make a difference in how the application behaves. Since the middleware this post is dealing with is logging I have placed it near the start of the pipeline.

Logging requests and responses

Now that the setup work for our new middleware is done we will come back to its Invoke function. As I stated above this ended up being more complicated than I expected, but thankfully I found this by Sul Aga which really helped me work through the issues I was having along with a lot of feedback on the original version of this post.

One of the bits of feedback on the original version of this post was about a potential memory leak and using recyclable memory streams. First, add a NuGet reference to the Microsoft.IO.RecyclableMemoryStream package. Next, we will add a class-level variable to hold an instance of a RecyclableMemoryStreamManager which we will create in the constructor. The following is an updated class view with these changes as well as changes to the Invoke function and stubs for the logging methods.

public class RequestResponseLoggingMiddleware
{
    private readonly RequestDelegate _next;
    private readonly ILogger _logger;
    private readonly RecyclableMemoryStreamManager _recyclableMemoryStreamManager;

    public RequestResponseLoggingMiddleware(RequestDelegate next,
                                            ILoggerFactory loggerFactory)
    {
        _next = next;
        _logger = loggerFactory
                  .CreateLogger<RequestResponseLoggingMiddleware>();
        _recyclableMemoryStreamManager = new RecyclableMemoryStreamManager();
    }

    public async Task Invoke(HttpContext context)
    {
        await LogRequest(context);
        await LogResponse(context);
    }
  
    private async Task LogRequest(HttpContext context) {}
    private async Task LogResponse(HttpContext context) {}
}

First, we are going to look at the LogRequest function, and a helper function it uses.

private async Task LogRequest(HttpContext context)
{
    context.Request.EnableBuffering();

    await using var requestStream = _recyclableMemoryStreamManager.GetStream();
    await context.Request.Body.CopyToAsync(requestStream);
    _logger.LogInformation($"Http Request Information:{Environment.NewLine}" +
                           $"Schema:{context.Request.Scheme} " +
                           $"Host: {context.Request.Host} " +
                           $"Path: {context.Request.Path} " +
                           $"QueryString: {context.Request.QueryString} " +
                           $"Request Body: {ReadStreamInChunks(requestStream)}");
    context.Request.Body.Position = 0;
}

private static string ReadStreamInChunks(Stream stream)
{
    const int readChunkBufferLength = 4096;

    stream.Seek(0, SeekOrigin.Begin);

    using var textWriter = new StringWriter();
    using var reader = new StreamReader(stream);

    var readChunk = new char[readChunkBufferLength];
    int readChunkLength;

    do
    {
        readChunkLength = reader.ReadBlock(readChunk, 
                                           0, 
                                           readChunkBufferLength);
        textWriter.Write(readChunk, 0, readChunkLength);
    } while (readChunkLength > 0);

    return textWriter.ToString();
}

The key to getting this function to work and allow reading of the request body was context.Request.EnableBuffering() which allows us to read from the beginning of the stream. The rest of the function is pretty straight forward.

The next function is LogResponse which is used to execute the next bit of middleware in the pipeline, using await _next(context) and then logging the response body after the rest of the pipeline has run.

private async Task LogResponse(HttpContext context)
{
    var originalBodyStream = context.Response.Body;

    await using var responseBody = _recyclableMemoryStreamManager.GetStream();
    context.Response.Body = responseBody;

    await _next(context);

    context.Response.Body.Seek(0, SeekOrigin.Begin);
    var text = await new StreamReader(context.Response.Body).ReadToEndAsync();
    context.Response.Body.Seek(0, SeekOrigin.Begin);

    _logger.LogInformation($"Http Response Information:{Environment.NewLine}" +
                           $"Schema:{context.Request.Scheme} " +
                           $"Host: {context.Request.Host} " +
                           $"Path: {context.Request.Path} " +
                           $"QueryString: {context.Request.QueryString} " +
                           $"Response Body: {text}");

    await responseBody.CopyToAsync(originalBodyStream);
}

As you can see the trick to reading the response body is replacing the stream being used with a new MemoryStream and then copying the data back to the original body steam. I don’t know how much this affects performance and would make sure to study how it scales before using it in a production environment.

Wrapping up

I hope this updated post turns out to be as helpful as the original seemed to be. This round I do have the code in a GitHub repo and the commit with the related changes can be found here.

Log Requests and Responses in ASP.NET Core 3 Read More »

Azure Function App Log Streaming

One of the things I have noticed while exploring Azure Function Apps is it is important to find ways to track what is going on during execution. While exploring the Azure Portal for one of my functions apps I noticed an option for steaming logs. This post is going to show how to get to the streaming logs for a Function App.

Log Streaming Location

From the Azure Portal open your Function App and select Platform features and then click the Log streaming link.

Log Streaming View

The following screenshot is from my sample App and has two different function executions listed.

Wrapping Up

For this small sample application, this feature isn’t critical, but on a larger application, it would become much more important. Log streaming is a quick way to get an idea of what is going on, but would only be one part of knowing what is going on.

Azure Function App Log Streaming Read More »

Entity Framework Core: Logging

The other day I was having to dig into some performance issues around a process that is using Entity Framework Core. As part of the process, I need to see the queries generated by Entity Framework Core to make sure they were not the source of the issue (they were not). I’m going to be making these changes using the Contacts project from my ASP.NET Core Basics repo if you want to see where I started from.

First, we will cover adding a logging provider. Next, I’m going to show you what I came up with and then I will show you the method suggested by the Microsoft docs (which I didn’t find until later).

Logging Providers

First, we need to do pick how we want the information logged. A good starting place is using one of the Microsoft provides which can be found on NuGet. Right-click on the project you want to add the logging to and click Manage NuGet Packages.

In the search box enter Microsoft.Extensions.Logging for a list of good list of logging options. For this post, we will be using the console logger provided by Microsoft. Select Microsoft.Extensions.Logging.Console and then click the Install button on the upper right side of the screen.

First Go

For my first try at this, all the change are in the ConfigureServices function of the Startup class. The following is the code I added at the end of the function that will log all the queries to the console window (if you are using IIS Express then use the Debug logger instead).

var scopeFactory = services.BuildServiceProvider()
                           .GetRequiredService<IServiceScopeFactory>();

using (var scope = scopeFactory.CreateScope())
{
    using (var context = scope.ServiceProvider
                              .GetRequiredService<ContactsContext>())
    {
        var loggerFactory = context.GetInfrastructure()
                                   .GetService<ILoggerFactory>();
        loggerFactory.AddProvider(new ConsoleLoggerProvider((_, __) => true, true));
    }
}

This code is creating a scope to get an instance of the ContactsContext and then using the context to get it’s associated logger factory and adding a console logger to it. This isn’t the cleanest in the world but gets the job done especially if this is just for a quick debug session and not something that will stay.

Microsoft Way

While the above works I ended up finding a logging page in the Entity Framework Core docs. After undoing the changes made above open the ContactsContext (or whatever your DBContext is) and add a class level static variable for a logger factory. This class level variable will be used to prevent memory and performance issues that would be caused by creating a new instance of the logging classes every time a context is created.

public static readonly LoggerFactory LoggerFactory = 
       new LoggerFactory(new[] {new ConsoleLoggerProvider((_, __) => true, true)});

Next, add/update an override to the OnConfiguring to use the logger factory defined above. The following is the full function in my case.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
{
    base.OnConfiguring(optionsBuilder);

    optionsBuilder.UseLoggerFactory(LoggerFactory);
}

The Output

Either way, the following is an example of the output you will get with logging on.

The query is highlighted in the red box above. As you can see there is a lot of output, but there are options for filtering which are detailed in the docs.

Wrapping Up

Entity Framework Core does a great job, but the above gives you an option to check in on what it is doing. If you are using SQL Server you could also get the queries using SQL Server Profiler.

Entity Framework Core: Logging Read More »

Log Requests and Responses in ASP.NET Core

Note: An updated version of this post for ASP.NET Core 3 and above is available.

As part of trying to do some debugging, I needed a way to log the requests and responses. Writing a piece of middleware seemed to be a good way to handle this problem. It also turned out to be more complicated that I had expected to deal with the request and response bodies.

Middleware

In ASP.NET Core middleware are the components that make up the pipeline that handles request and responses for the application. Each piece of middleware called has the option to do some processing on the request before calling next piece of middleware in line. After execution returns from the call to the next middleware, there is an opportunity to do processing on the response.

The pipeline for an application is set in the Configure function of the Startup class. Run, Map and Use are the three types of middleware. Run should only be used to terminate the pipeline. Map is used for pipeline branching. Use seems to be the most common type of middleware that does some processing and call the next middleware in line. For more detail see the official docs.

Creating Middleware

Middleware can be implemented as a lambda directly in the Configure function, but more typically it is implemented as a class that is added to the pipeline using an extension method on IApplicationBuilder. This example will be going the class route.

This example is a piece of middleware that using ASP.NET Cores built-in logging to log requests and responses. Create a class called RequestResponseLoggingMiddleware.

The class will need a constructor that takes to arguments both will be provided by ASP.NET Core’s dependency injection system. The first is a RequestDelegate for the next piece of middleware to be called. The second is an ILoggerFactory which will be used to create a logger. The RequestDelegate is stored to the class level _next variable and the loggerFactory is used to create a logger which is stored to the class level _logger variable.

public class RequestResponseLoggingMiddleware
{
    private readonly RequestDelegate _next;
    private readonly ILogger _logger;

    public RequestResponseLoggingMiddleware(RequestDelegate next,
                                            ILoggerFactory loggerFactory)
    {
        _next = next;
        _logger = loggerFactory
                  .CreateLogger<RequestResponseLoggingMiddleware>();
    }
}

Add an Invoke function which is the function that will be called when your middleware is run by the pipeline. The following is the function that does nothing other than call the next middleware in the pipeline.

public async Task Invoke(HttpContext context)
{
     //code dealing with request

     await _next(context);

     //code dealing with response
}

Next, add a static class to simplify adding the middleware to the application’s pipeline. This is the same pattern the built-in middleware uses.

public static class RequestResponseLoggingMiddlewareExtensions
{
    public static IApplicationBuilder UseRequestResponseLogging(this IApplicationBuilder builder)
    {
        return builder.UseMiddleware<RequestResponseLoggingMiddleware>();
    }
}

Adding to the pipeline

To add the new middleware to the pipeline open the Startup to the Configure function and add the following line.

app.UseRequestResponseLogging();

Keep in mind that the order in which middleware is added can make a difference in how the application behaves. Since the middleware this post is dealing with is logging I have placed it near the begging of the pipeline just before app.UseStaticFiles().

Logging requests and responses

Now that the setup work for our new middleware is done we will come back to its Invoke function. As I stated above this ended up being more complicated that I expected, but thankfully I found this by Sul Aga which really helped me work through the issues I was having.

I created a couple of helper functions that we will look at first. The following is the function call to create the string that will be logged for a request.

private async Task<string> FormatRequest(HttpRequest request)
{
    var body = request.Body;
    request.EnableRewind();

    var buffer = new byte[Convert.ToInt32(request.ContentLength)];
    await request.Body.ReadAsync(buffer, 0, buffer.Length);
    var bodyAsText = Encoding.UTF8.GetString(buffer);
    request.Body = body;

    return $"{request.Scheme} {request.Host}{request.Path} {request.QueryString} {bodyAsText}";
}

The key to getting this function to work and allow reading of the request body was request.EnableRewind() which allows us to read from the beginning of the stream. The rest of the function is pretty straight forward.

The next function is used to get the string to that will be used to log the response body. This function looks simpler than it is and only works because of how it is called from the Invoke function.

private async Task<string> FormatResponse(HttpResponse response)
{
    response.Body.Seek(0, SeekOrigin.Begin);
    var text = await new StreamReader(response.Body).ReadToEndAsync(); 
    response.Body.Seek(0, SeekOrigin.Begin);

    return $"Response {text}";
}

Finally, the Invoke which does the logging and jumps through some hoops to allow the response body to be read.

public async Task Invoke(HttpContext context)
{
    _logger.LogInformation(await FormatRequest(context.Request));

    var originalBodyStream = context.Response.Body;

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

        await _next(context);

        _logger.LogInformation(await FormatResponse(context.Response));
        await responseBody.CopyToAsync(originalBodyStream);
    }
}

As you can see the trick to reading the response body is replacing the stream being used with a new MemoryStream and then copying the data back to the original body steam. This works and is a concept I found in Sul’s blog post. I don’t know how much the affect performance and would make sure to study how it scales or just avoid using it in production as much as possible.

Wrapping up

This entry didn’t turn out anything like I expected. I came into this looking to do a very simple post due to some time restrictions and it turned into something larger. I hope you find it helpful. I didn’t do a full repo for this week’s post, but you can a gist with the middleware classes here.

Log Requests and Responses in ASP.NET Core Read More »