Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

System.InvalidOperationException: Reading is already in progress. #2655

Open
marekott opened this issue Nov 18, 2024 · 7 comments
Open

System.InvalidOperationException: Reading is already in progress. #2655

marekott opened this issue Nov 18, 2024 · 7 comments
Labels
External: AspNetCore This work will mostly be done in the dotnet/aspnetcore repo Type: Tracking Tracking work to be done in other repositories.
Milestone

Comments

@marekott
Copy link
Contributor

Hi, we have encountered below exception in our microservice serving as reverse proxy:

"MessageTemplate": "Connection id \"{ConnectionId}\", Request id \"{TraceIdentifier}\": An unhandled exception was thrown by the application.",
"RenderedMessage": "Connection id \"0HN7I0DFFRG93\", Request id \"0HN7I0DFFRG93:0000008C\": An unhandled exception was thrown by the application.",
"Exception": "Microsoft.AspNetCore.Connections.ConnectionAbortedException: The connection was aborted by the application.\n ---> System.InvalidOperationException: Reading is already in progress.\n   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1MessageBody.OnConsumeAsync()\n   --- End of inner exception stack trace ---"

I have found several issues related to this topic:

The last one is suggesting that the reason may be invalid handling of reading request body. In our scenario there were no such operations (also buffering was not enabled). The only manipulation on body was as follows:

var originalBodyStream = context.Response.Body;
// Decorator counting bytes written to the stream
await using var monitoringStream = new Decorator(originalBodyStream);

try
{
    context.Response.Body = monitoringStream;

    await next(context);

    await LogRequest();
}
catch (Exception)
{
    // Error handling
}
finally
{
    //Reassigning according to this advice: https://github.com/microsoft/reverse-proxy/issues/2385
    context.Response.Body = originalBodyStream;
}

LogRequest is designed to log incoming request with optional logging of body. This option is however currently disabled. The only action taken is context.Response.Body = originalBodyStream;. What could be a cause of above exception and how could we prevent it?

We are currently using Yarp.ReverseProxy in 2.0.1 version (not updated because of #2631).

@marekott marekott added the Type: Bug Something isn't working label Nov 18, 2024
@MihaZupan
Copy link
Member

What does the implementation of Decorator look like?
Are you able to create a minimal runnable repro sample?

@marekott
Copy link
Contributor Author

internal class Decorator : Stream
{
    private readonly Stream innerStream;
    public long BytesWritten { get; private set; }
    
    public override bool CanRead => false;
    public override bool CanSeek => false;
    public override bool CanWrite => innerStream.CanWrite;
    public override long Length => innerStream.Length;
    public override long Position { get => innerStream.Position; set => throw new NotSupportedException(); }

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

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

    public override Task FlushAsync(CancellationToken cancellationToken) => innerStream.FlushAsync(cancellationToken);
    
    public override void Flush() => throw new NotSupportedException();
    public override void Write(byte[] buffer, int offset, int count) => throw new NotSupportedException();
    public override Task WriteAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToken) => throw new NotSupportedException();
    public override int Read(byte[] buffer, int offset, int count) => throw new NotSupportedException();
    public override Task<int> ReadAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToken) => throw new NotSupportedException();
    public override ValueTask<int> ReadAsync(Memory<byte> buffer, CancellationToken cancellationToken = default) => throw new NotSupportedException();
    public override long Seek(long offset, SeekOrigin origin) => throw new NotSupportedException();
    public override void SetLength(long value) => throw new NotSupportedException();
    
}

In case of reproduction, unfortunately I am not able to do it. This error occurs on once in a million requests (literally).

@MihaZupan
Copy link
Member

Are you able to collect the full stack trace for the exception (ex.ToString() in that catch block)?
That might give a hint for where things are going wrong.

@MihaZupan MihaZupan added the needs-author-action An issue or pull request that requires more info or actions from the author. label Nov 26, 2024
@marekott
Copy link
Contributor Author

marekott commented Dec 3, 2024

I am not sure where to do it. This exception was thrown either before or after my pipeline, above middelware was mentioned only because it works with request body. Exception was not thrown there or in any of my middelwares (I assume that because there are no other logs that should be produced by my application in such case). Source context of that error is: "SourceContext": "Microsoft.AspNetCore.Server.Kestrel".

BTW ex.ToString() should produce more info that error logged with Serilog?

@MihaZupan
Copy link
Member

BTW ex.ToString() should produce more info that error logged with Serilog?

From the message you've shared it looked like it may have only been including the top-most exception information, but looking into dotnet/aspnetcore#17840 more, that may just be all the info that's available at the time.

This sounds like a bug in ASP.NET Core, not much we can do about it in YARP. YARP itself isn't using the request body pipe directly, and from your description neither are you.
It's possible this is just an error handling issue during cancellation.

@MihaZupan MihaZupan added the External: AspNetCore This work will mostly be done in the dotnet/aspnetcore repo label Dec 4, 2024
@marekott
Copy link
Contributor Author

marekott commented Dec 5, 2024

@MihaZupan could you report issue in appropriate repo of ASP.NET Core?

@MihaZupan
Copy link
Member

Do you mean dotnet/aspnetcore#17840?

@MihaZupan MihaZupan added this to the Backlog milestone Dec 6, 2024
@MihaZupan MihaZupan added Type: Tracking Tracking work to be done in other repositories. and removed Type: Bug Something isn't working needs-author-action An issue or pull request that requires more info or actions from the author. labels Dec 6, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
External: AspNetCore This work will mostly be done in the dotnet/aspnetcore repo Type: Tracking Tracking work to be done in other repositories.
Projects
None yet
Development

No branches or pull requests

2 participants