extensions icon indicating copy to clipboard operation
extensions copied to clipboard

ExtendedHttpClientLogging LogBody cannot read again when using GetAsync and debugger attached

Open universorum opened this issue 9 months ago • 2 comments

Description

Try to using Microsoft.Extensions.Http.Diagnostics to log the request/response for httpclient.

When application running in debug mode (debugger is attached, not debug build, release bug will failed too), InvalidOperationException: The stream was already consumed. will be thrown if you sent the request by GetAsync, PostAsync etc.

Run it without debug will be fine.

Reproduction Steps

using System.Net.Mime;
using System.Text;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;

var builder = Host.CreateApplicationBuilder(args);

builder.Services.AddRedaction();
builder.Services.AddHttpClient("Client")
    .AddExtendedHttpClientLogging(logging =>
    {
        logging.LogBody = true;
        logging.ResponseBodyContentTypes.Add(MediaTypeNames.Application.Json);
    });
builder.Services.AddHostedService<Worker>();

var host = builder.Build();
host.Run();


class Worker(ILogger<Worker> logger, IHttpClientFactory factory) : BackgroundService
{
    private HttpClient Client => factory.CreateClient("Client");

    protected override async Task ExecuteAsync(CancellationToken stoppingToken)
    {
        await Ok();
        await Fail();
    }

    private async Task Ok()
    {
        using var httpRequestMessage = new HttpRequestMessage();
        httpRequestMessage.Method     = HttpMethod.Get;
        httpRequestMessage.RequestUri = new("https://google.com/");

        using var content = await Client.SendAsync(httpRequestMessage, HttpCompletionOption.ResponseHeadersRead)
            .ConfigureAwait(false);

        await using var responseStream = await content.Content.ReadAsStreamAsync().ConfigureAwait(false);
        var             buffer         = new byte[32768];
        _ = await responseStream.ReadAsync(buffer, 0, 32768);
        _ = Encoding.UTF8.GetString(buffer);
    }

    private async Task Fail()
    {
        try { _ = await Client.GetAsync("https://google.com/").ConfigureAwait(false); }
        catch (Exception ex) { logger.LogError(ex, "Failed"); }
    }
}

Expected behavior

info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Production
info: Microsoft.Hosting.Lifetime[0]
      Content root path: /Users/user/Projects/ConsoleLab/ConsoleLab/bin/Debug/net9.0
info: Microsoft.Extensions.Http.Logging.HttpClientLogger[1]
      GET google.com/REDACTED
info: Microsoft.Extensions.Http.Logging.HttpClientLogger[1]
      GET google.com/REDACTED

Actual behavior

info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Production
info: Microsoft.Hosting.Lifetime[0]
      Content root path: /Users/user/Projects/ConsoleLab/ConsoleLab/bin/Debug/net9.0
info: Microsoft.Extensions.Http.Logging.HttpClientLogger[1]
      GET google.com/REDACTED
info: Microsoft.Extensions.Http.Logging.HttpClientLogger[1]
      GET google.com/REDACTED
fail: Worker[0]
      Failed
      System.InvalidOperationException: The stream was already consumed. It cannot be read again.
         at System.Net.Http.HttpConnectionResponseContent.ConsumeStream()
         at System.Net.Http.HttpConnectionResponseContent.<SerializeToStreamAsync>g__Impl|6_0(Stream stream, CancellationToken cancellationToken)
         at System.Net.Http.HttpContent.LoadIntoBufferAsyncCore(Task serializeToStreamTask, MemoryStream tempBuffer)
         at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
         at Worker.Fail() in /Users/user/Projects/ConsoleLab/ConsoleLab/Program.cs:line 49

Regression?

No response

Known Workarounds

No response

Configuration

.NET 9.0 (SDK 9.0.200) Microsoft.Extensions.Http.Diagnostics 9.2.0

Windows: Visual Studio 17.13.0 Preview 5 / Rider 2025.1 EAP6 macOS: Rider 2025.1 EAP6

Other information

No response

Edit: I noticed that I am not running it at .NET 9. But I can reproduce it on .NET 9 simply.

universorum avatar Mar 03 '25 05:03 universorum

I am also seeing the same, interestingly it is also happening with an Api hosted through Aspire (without debugging), when i run the API outside of the aspire host it does not have this issue

danpowell88 avatar Mar 05 '25 22:03 danpowell88

The issue appears to stem from how HttpResponseBodyReader.ResponseReadTimeout is set Image When running under a debugger, Timeout.InfiniteTimeSpan is assigned. This value is negative, which then triggers the following check in ReadFromStreamWithTimeoutAsync Cancelling the joinedTokenSource immediately causes the OperationCanceledException to be thrown, which is then caught here Image

BerkovskyiMykola avatar Nov 24 '25 22:11 BerkovskyiMykola