Logging response body size about reverse-proxy

[plachor]

For the lowest overhead, make sure to override at least the ValueTask-based methods. As you're only interested in write byte count, you don't have to await anything either.

public override ValueTask WriteAsync(ReadOnlyMemory<byte> buffer, CancellationToken cancellationToken = default)
{
    BytesWritten += buffer.Length;
    return innerStream.WriteAsync(buffer, cancellationToken);
}

public override ValueTask<int> ReadAsync(Memory<byte> buffer, CancellationToken cancellationToken = default)
{
    return innerStream.ReadAsync(buffer, cancellationToken);
}

public override Task FlushAsync(CancellationToken cancellationToken)
{
    return innerStream.FlushAsync(cancellationToken);
}

Do I have a guarantee that entire response is present at this moment in a stream especially when Transfer-Encoding: chunked is used?

Yes. Note that the amount of data here is the amount of actual application-level data, not counting the chunked encoding overhead.

Hi @MihaZupan / @Tratcher in your sample you suggest to pass through reads is that on purpose ? I thought I should throw there not supported. Or is it required for websockets case (like SingalR)?

[MihaZupan]

You can either throw your own exception, or pass the read through and have the original stream do it for you.
In either case, nothing should ever be reading from this stream, so it shouldn't matter in practice.
You can skip overriding the ReadAsync(Memory) overload.

WebSocket connections won't go through the Response.Body stream, they use a different mechanism (IHttpUpgradeFeature / IHttpExtendedConnectFeature).

[MihaZupan]

Are you aware of https://learn.microsoft.com/aspnet/core/fundamentals/http-logging? You may not have to implement many of these things yourself.

Re: response content length, you can either set a custom response body stream that counts the amount of data written, or you can listen to the IForwarderTelemetryConsumer.OnContentTransferred event that includes the content length. See https://microsoft.github.io/reverse-proxy/articles/diagnosing-yarp-issues.html#using-telemetry-events

[marekott]

@MihaZupan thanks for a quick answer. Yes I am aware of http-logging provided by framework but it won't help me a lot. My reverse proxy is using common infrastructure components (nuget packages) which abstracts regular logging from me. Http logging send by you would be handled by it and produced to X sink with common enrichers. With those requests logs I am manually creating custom DTO and sending them to message bus in order to process them in a different way. I don't have possibility to change infrastructure logging and I still should use it to produce coherent logs (errors, warning etc. not request logs) with another microservices.

Regarding second suggestion with custom response body stream, you mean something like this?

public class CountingStreamDecorator : Stream
{
    private readonly Stream innerStream;
    public long BytesRead { get; private set; }

    public CountingStreamDecorator(Stream innerStream) => this.innerStream = innerStream;

    public override async Task WriteAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToken)
    {
        await innerStream.WriteAsync(buffer, offset, count, cancellationToken);
        BytesRead += count;
    }
    
    //Other required staff
}

Usage in custom middelware:

public async Task Invoke(HttpContext context)
{
    var originalBodyStream = context.Response.Body;

    using (var customStream = new CountingStreamDecorator(originalBodyStream))
    {
        context.Response.Body = customStream;
            
        await next(context);
        
        await TryLogIncomingRequest(customStream.BytesRead);
        
        context.Response.Body = originalBodyStream;
    }
}

Do I have a guarantee that entire response is present at this moment in a stream especially when Transfer-Encoding: chunked is used?

[MihaZupan]

For the lowest overhead, make sure to override at least the ValueTask-based methods. As you're only interested in write byte count, you don't have to await anything either.

public override ValueTask WriteAsync(ReadOnlyMemory<byte> buffer, CancellationToken cancellationToken = default)
{
    BytesWritten += buffer.Length;
    return innerStream.WriteAsync(buffer, cancellationToken);
}

public override ValueTask<int> ReadAsync(Memory<byte> buffer, CancellationToken cancellationToken = default)
{
    // Not really needed - no one should be reading from this stream
    return innerStream.ReadAsync(buffer, cancellationToken);
}

public override Task FlushAsync(CancellationToken cancellationToken)
{
    return innerStream.FlushAsync(cancellationToken);
}

Do I have a guarantee that entire response is present at this moment in a stream especially when Transfer-Encoding: chunked is used?

Yes. Note that the amount of data here is the amount of actual application-level data, not counting the chunked encoding overhead.

[marekott]

I was assuming that YARP would close connection to cluster when all data were transferred to client using small buffer to transfer it in chunks - streaming. This way YARP could reduce allocations.

So when you confirmed that in my custom middleware I have entire response already buffered, this is totally opposite to what I was assuming.

Could you clarify more?

[MihaZupan]

YARP won't buffer the entire response. When you call await next(context), YARP will make the request to the backend server and stream all of the response content back to the client. Writes to the response body stream all happen during that call.

By the time next returns, all of the content will have been transferred, and the amount of data reflected in your stream's BytesWritten.

[marekott]

Thank you for clarification @MihaZupan, it helps me a lot.

[marekott]

@MihaZupan one more question if I may. I am wondering what would be the best option to dispose my stream decorator. I am considering two options:

1. Dispose my decorator but not propagate that operation to inner stream and reassign original stream to context.Response.Body when I am finished in order to let framework dispose it.

public async Task Invoke(HttpContext context)
{
    var originalBodyStream = context.Response.Body;

    using (var customStream = new CountingStreamDecorator(originalBodyStream))
    {
        context.Response.Body = customStream;
            
        await next(context);
        
        await TryLogIncomingRequest(customStream.BytesRead);
        
        //Reassign original stream hoping that framework will dispose it
        context.Response.Body = originalBodyStream;
    }
}

2. When disposing my decorator, propagate it to inner stream and skip reassigning value. My custom middlewares that are executed after logging one are not using context.Response.Body.

public async Task Invoke(HttpContext context)
{
    var originalBodyStream = context.Response.Body;

    //Disposing the CountingStreamDecorator will also dispose originalBodyStream 
    using (var customStream = new CountingStreamDecorator(originalBodyStream))
    {
        context.Response.Body = customStream;
            
        await next(context);
        
        await TryLogIncomingRequest(customStream.BytesRead);
        
        //No reassign  of context.Response.Body
    }
}

Could you advice which option is correct or if both are not, how should it be handled? I am asking because I am not sure how framework is disposing context.Response.Body stream, I am guessing that it can either dispose anything that is assigned to it or it can hold reference to originalBodyStream and dispose only it no matter how many decorators are above it.

[Tratcher]

It's good practice to re-assign the original stream back to context.Response.Body at the end of your middleware so that upstream middleware see the context in the expected state.

Only dispose things you own, like your decorator. You don't own the original stream, the server does, it will take care of it.

[marekott]

Thank you @Tratcher.

[plachor]

I know this is closed but @MihaZupan could you comment ?