Yet another middleware request/response logging question

[vladimirvozar]

Hi,
I'm trying to implement request/response logging middleware that would be logging request and response body payload as serilog properties (logging to .json file).

For GET requests, body of the response should be logged (added to serilog context as a property), and for POST requests, both body of request and body of response should be logged.
I have created middleware and managed to properly retrieve data from request and response stream, and getting it as a string, but only the "RequestBody" is being logged properly.

When debugging, I can see that reading request/response body works fine.

Following is the code excerpt from Program->Main method:

Log.Logger = new LoggerConfiguration()
    .ReadFrom.Configuration(configuration)
    .Enrich.FromLogContext()
    .CreateLogger();

and code in the middleware:

public async Task Invoke(HttpContext context)
{
    // Read and log request body data
    string requestBodyPayload = await ReadRequestBody(context.Request);

    LogContext.PushProperty("RequestBody", requestBodyPayload);

    // Read and log response body data
    var originalBodyStream = context.Response.Body;
    using (var responseBody = new MemoryStream())
    {
        context.Response.Body = responseBody;
        await _next(context);
        string responseBodyPayload = await ReadResponseBody(context.Response);

        if (!context.Request.Path.ToString().Contains("swagger.json") && !context.Request.Path.ToString().Contains("index.html"))
        {
            LogContext.PushProperty("ResponseBody", responseBodyPayload);
        }

        await responseBody.CopyToAsync(originalBodyStream);
    }
}

private async Task<string> ReadRequestBody(HttpRequest request)
{
    HttpRequestRewindExtensions.EnableBuffering(request);

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

    return $"{requestBody}";
}

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

    return $"{responseBody}";
}

As I mentioned, "RequestBody" is properly logged to file (POST requests) , but nothing for "ResponseBody" (not even added as a property).
Appreciate any help

[sungam3r]

Where is the call to logger.Log() ?

[vladimirvozar]

Maybe I missunderstood how serilog works.
Shoudn't LogContext.PushProperty("ResponseBody", responseBodyPayload); be adding/writing a property to log structure?
"RequestBody" is being logged to file, but "ResponseBody" isn't.

[sungam3r]

LogContext.PushProperty() pushes property into AsyncLocal context. Then Serilog uses this context (if you called .Enrich.FromLogContext() in your config init) when you call logger.Log().

"RequestBody" is being logged to file

See SourceContext property - it is the name of logger which sent log.

So I mean that If you do not call any logger.Log() API then all pushes do nothing.

[vladimirvozar]

Thanks for helping
To trigger writing to log file, I've added Log.Information(""); (just underneath LogContext.PushProperty("ResponseBody", responseBodyPayload); line).

With this, I do get request and response body data logged (as another json object inside log file).
But, what I am trying to achieve is to add request and response body data (as properties) to Serilog's summary request log. My point is to have only one JSON object for every endpoint call, summary for that endpoint.

correct_log_format.txt
current_log_format.txt

To make it clear, I've attached two files: one is with current log format, and the other one is with the format of logs I am trying to get.

[nblumhardt]

Hi @vladimirvozar - you're looking for IDiagnosticContext.Set(), which does exactly this.

There are some posts describing how to use it at:

• https://nblumhardt.com/2019/10/serilog-mvc-logging/
• https://andrewlock.net/using-serilog-aspnetcore-in-asp-net-core-3-logging-the-selected-endpoint-name-with-serilog/

Hope this helps,
Nick

[vladimirvozar]

Hi,
@nblumhardt Thanks for the tips. I was actually following exactly these posts together with one more post that describes reading request/response body in the middleware:

• https://exceptionnotfound.net/using-middleware-to-log-requests-and-responses-in-asp-net-core/

Anyway, I didn't find a way to log both request and response body in one place only (in the Invoke method of the middleware), but I found a workaround. Because of the nature of the request processing pipeline, here is what I had to do:

Code in the Startup.cs:

app.UseMiddleware<RequestResponseLoggingMiddleware>();
app.UseSerilogRequestLogging(opts => opts.EnrichDiagnosticContext = LogHelper.EnrichFromRequest);

• I have used LogHelper class for enriching request properties, just as described in the Andrew Locks post.

• First, request processing hits the middleware and in the middleware's Invoke method I am reading only request body data, and setting this value to a static string property that I've added to LogHelper class. This way I have read and stored request body data as string, and can add it as enricher when LogHelper.EnrichFromRequest method gets called

• After reading request body data, I am copying a pointer to the original response body stream

• await _next(context); gets called, context.Response is populated, and request processing exits out from middleware's Invoke method, and goes to LogHelper.EnrichFromRequest

• at this moment LogHelper.EnrichFromRequest is executing, reading response body data and setting it as enricher, as well previously stored request body data and some additional properties

• processing returns to middleware Invoke method (right after await _next(context);), and copying the contents of the new memory stream (which contains the response) to the original stream,

You can see the code described above in attached files for LogHelper and RequestResponseLoggingMiddleware classes.

BR,
Vladimir

LogHelper.txt
RequestResponseLoggingMiddleware.txt

[IngoVals]

Quick question. Isn't the DiagnosticContext injectable? So you could inject it into the Middleware and do it all there. So no need for the LogHelper and the static string?

Or does the DiagnosticContext lose the context over the async await?

In the final version, what is the purpose of holding a copy of the ResponseBody stream?

Here is a mashup of the code and the solution I'm asking if is viable.

public class RequestResponseLoggingMiddleware
{
	private readonly RequestDelegate _next;
	private readonly IDiagnosticContext _diagnosticContext;

	public RequestResponseLoggingMiddleware(RequestDelegate next, IDiagnosticContext diagnosticContext)
	{
		_next = next;
		_diagnosticContext = diagnosticContext;
	}

	public async Task Invoke(HttpContext context)
	{
		// Set all the common properties available for every request
		diagnosticContext.Set("Host", request.Host);
		diagnosticContext.Set("Protocol", request.Protocol);
		diagnosticContext.Set("Scheme", request.Scheme);

		// Only set it if available. You're not sending sensitive data in a querystring right?!
		if (request.QueryString.HasValue)
		{
			diagnosticContext.Set("QueryString", request.QueryString.Value);
		}

		// Read and log request body data
		string requestBodyPayload = await ReadRequestBody(context.Request);
		diagnosticContext.Set("RequestBody", requestBodyPayload);

		// Retrieve the IEndpointFeature selected for the request
		var endpoint = httpContext.GetEndpoint();
		if (endpoint is object) // endpoint != null
		{
			diagnosticContext.Set("EndpointName", endpoint.DisplayName);
		}

		// Read and log response body data
		// Copy a pointer to the original response body stream
		var originalResponseBodyStream = context.Response.Body;

		// Create a new memory stream...
		using (var responseBody = new MemoryStream())
		{
			// ...and use that for the temporary response body
			context.Response.Body = responseBody;

			// Continue down the Middleware pipeline, eventually returning to this class
			await _next(context);

			// Copy the contents of the new memory stream (which contains the response) to the original stream, which is then returned to the client.
			await responseBody.CopyToAsync(originalResponseBodyStream);
		}

		string responseBodyPayload = await ReadResponseBody(context.Response);
		diagnosticContext.Set("ResponseBody", responseBodyPayload);

	}

	private async Task<string> ReadRequestBody(HttpRequest request)
	{
		HttpRequestRewindExtensions.EnableBuffering(request);

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

		return $"{requestBody}";
	}

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

		return $"{responseBody}";
	}

}

The idea being you have app.UseSerilogRequrestLogging() that will then use this diagnsoticContext when logging the request?

[abrasat]

@nblumhardt , @IngoVals
I injected the IDiagnosticContext into the middleware class as described in the sample above and set different diagnoseContext properties, but this additional information does not appear in the logs. What else is missing (I have already the call app.UseSerilogRequestLogging() ) ?
Do I still have to call somewhere EnrichDiagnosticContext() ? I would prefer a solution without the static LogHelper

[nblumhardt]

Sorry folks - it would be better to post questions about this to Stack Overflow, lets let this closed thread end.

[pwelter34]

This pull request implements request body logging. Vote it up if interested.

#400