Aspnetcore: EnableBuffering not working on .Net Core 3.0.100

[SledgeHammer01]

.Net Core 3.0.100

Startup.cs:

        app.Use(next => context =>
        {
            var syncIOFeature = context.Features.Get<IHttpBodyControlFeature>();
            if (syncIOFeature != null)
            {
                syncIOFeature.AllowSynchronousIO = true;
            }

            context.Request.EnableBuffering();
            return next(context);
        });

When I try to access the stream by context.HttpContext.Request.Body later on, it reports that the stream has already been disposed and an exception is thrown.

[SledgeHammer01]

Also tried:

services.Configure(options =>
{
options.AllowSynchronousIO = true;
});

Same result.

[anurse]

Can you post a minimal, runnable, sample project that reproduces the issue. Specifically, it's important to know exactly when in the control flow you are accessing HttpContext.Request.Body.

[halter73]

If you're getting an ObjectDisposedException from HttpContext.Request.Body, that means that the middleware handling the request has already completed.

[SledgeHammer01]

Hi, some further information:

Startup.cs:

in ConfigureServices(IServiceCollection services)...

        services.Configure<IISServerOptions>(options =>
        {
            options.AllowSynchronousIO = true;
        });

        // set Mvc / Json options

        services.AddMvc(options => options.EnableEndpointRouting = false).AddNewtonsoftJson(options =>

in Configure(IApplicationBuilder app, IWebHostEnvironment env)…

        // enable response buffering

        app.UseResponseBuffering();

        // enable request stream rewinding

        app.Use(next => context =>
        {
            context.Request.EnableBuffering();
            return next(context);
        });

All controllers derive from ControllerBase class which derives from Controller.

In ControllerBase.cs:

public override async Task OnActionExecutionAsync(ActionExecutingContext context, ActionExecutionDelegate next)
{
}

I am trying to access the request body in there so I can log the full json. This worked in .Net 1.x and 2.x. In 3.0, I get that the stream has been disposed.

[halter73]

I get that the stream has been disposed.

Do you have logs and/or exception details including a stack trace indicating where the ObjectDisposedException was thrown from?

[SledgeHammer01]

The callstack of the exception itself is:

at System.IO.MemoryStream.get_Length()
at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.get_Length()

The app call stack is:

yyy.dll!xxx.yyy.Common.ControllerBase.OnActionExecutionAsync(Microsoft.AspNetCore.Mvc.Filters.ActionExecutingContext context, Microsoft.AspNetCore.Mvc.Filters.ActionExecutionDelegate next) Line 46 C#
[External Code]
yyy.dll!xxx.yyy.Startup.Configure.AnonymousMethod__3(Microsoft.AspNetCore.Http.HttpContext context) Line 164 C#
[External Code]

[davidfowl]

@SledgeHammer01 can you provide a runnable example with all of the code? It's diffcult to figure out what's going on without seeing the entire application. Even better would be to come up with a minimal repro.

[SledgeHammer01]

I'm trying to put together an example, just cleaning it up... but got a fuller stack trace... will post an example probably tomorrow morning.

System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'FileBufferingReadStream'.
   at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.ThrowIfDisposed()
   at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.Seek(Int64 offset, SeekOrigin origin)
   at MyCompany.Test.Common.ControllerBase.OnActionExecutionAsync(ActionExecutingContext context, ActionExecutionDelegate next) in C:\Users\xxx\Documents\Visual Studio 2019\Projects\Test\Common\ControllerBase.cs:line 41
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Builder.RouterMiddleware.Invoke(HttpContext httpContext)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Buffering.ResponseBufferingMiddleware.Invoke(HttpContext httpContext)
   at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)

HEADERS

Accept: application/json
Accept-Encoding: gzip, deflate
Accept-Language: en-US
Cache-Control: no-cache
Connection: Keep-Alive
Content-Length: 103
Content-Type: application/json
Host: localhost:52580
Referer: http://localhost:52580/swagger/index.html
User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; Trident/7.0; rv:11.0) like Gecko

[SledgeHammer01]

Ok, here you go...

Test.zip

When you run, it'll bring up the Swagger page, and try out testMethod2 for example, it'll throw the exception in ControllerBase.cs : OnActionExecutionAsync.

Thanks!

[halter73]

I added the area-mvc label because it looks like something in MVC is disposing the request stream when it wasn't before. This is likely the regression.

I'm leaving the area-servers label because it might be better for FileBufferingReadStream.Dispose() to no-op like it does for the raw request stream.

[SledgeHammer01]

Is there a work-around? The goal is to be able to log the raw request in a central location.

[davidfowl]

@pranavkm Did we change anything here that you're aware of?

[pranavkm]

Did we change anything here that you're aware of?

The Json.NET based input formatter buffers the request body to avoid synchronously reading the request body. MVC avoids double buffering if it thinks that the request is already buffered: https://github.com/aspnet/AspNetCore/blob/master/src/Mvc/Mvc.NewtonsoftJson/src/NewtonsoftJsonInputFormatter.cs#L132

[halter73]

https://github.com/aspnet/AspNetCore/blob/b44e9c6a24528c5ebec95da60295b4b74f83f8ec/src/Mvc/Mvc.NewtonsoftJson/src/NewtonsoftJsonInputFormatter.cs#L173-L176

The above seems super suspect. It appears as if NewtonsoftJsonInputFormatter assumes that if readStream is a FileBufferingReadStream, it was created here:

https://github.com/aspnet/AspNetCore/blob/b44e9c6a24528c5ebec95da60295b4b74f83f8ec/src/Mvc/Mvc.NewtonsoftJson/src/NewtonsoftJsonInputFormatter.cs#L144

But it's possible that readStream is still a reference to HttpContext.Request.Body that just happened to be set to a FileBufferingReadStream before the NewtonsoftJsonInputFormatter ran:

https://github.com/aspnet/AspNetCore/blob/b44e9c6a24528c5ebec95da60295b4b74f83f8ec/src/Mvc/Mvc.NewtonsoftJson/src/NewtonsoftJsonInputFormatter.cs#L131

[pranavkm]

Yeah, that's the bug. We'll need to set a flag that says that MVC owns the stream. @mkArtakMSFT this is a small enough change we could consider squeezing in for 3.1.

[mkArtakMSFT]

Is this a regression in 3.0?

[davidfowl]

Yes

[keenjus]

Is there a work-around? The goal is to be able to log the raw request in a central location.

Remove calls to AddNewtonsoftJson()

[SledgeHammer01]

@keenjus -- I can't remove that. We use some of the Json.Net hooks to correct the wrong serialization. The new json serializer has the same issues (doesn't maintain correct property order).

[davidfowl]

There’s no workaround and this should be considered for patching in 3.1

[davidfowl]

Well I take that back, the workaround is to create a wrapping stream that does nothing when dispose is called (but has to dispose the inner stream at the right time as well)

[SledgeHammer01]

Hi David, I did actually find a temp work-around... pulling out the body right after the call to EnableBuffering and then rewinding the stream to 0 and not disposing it.

[afshawnlotfi]

@SledgeHammer01 I tried that still getting "" as the response. I'm using F# but the concept is the same:

    let GetRequestBody (context : HttpContext) = 
        task {
            try
                context.Request.EnableBuffering()
                let reader = new StreamReader(context.Request.Body, encoding = Encoding.UTF8, detectEncodingFromByteOrderMarks = false, bufferSize = 1024, leaveOpen = true) 
                let! body = (reader.ReadToEndAsync())
                context.Request.Body.Position <- 0L;

                return Ok body
            with _ ->
                return Error "failed to get http body"

        }

[halter73]

@afshawnlotfi where is GetRequestBody(context) being called from? Is it possible the request was already read? Did you debug to see if body was an empty string?

[pranavkm]

We've addressed the reported issue as part of https://github.com/aspnet/AspNetCore/commit/fcc20ace2a78c24f923ea185fad0cafabd2199ad. This should be fixed in 3.1-preview2. In the meanwhile, @davidfowl's suggestion here - https://github.com/aspnet/AspNetCore/issues/14396#issuecomment-538016232 - would be the way to go.

@afshawnlotfi could you please file a separate issue?

[RomanTymchyshyn]

Decided to tell my case here. Hope it will help somebody and save time 😃

I ran into a similar issue because I was using .AddNewtonsoftJson and middleware with .EnableBuffering, which resulted in FileBufferingReadStream being disposed in NewtonsoftJsonInputFormatter.

Here is my workaround as suggested by the comment https://github.com/aspnet/AspNetCore/issues/14396#issuecomment-538016232

Workaround:
https://repl.it/@RomanTymchyshyn/EnableBufferingPatched

.EnableBufferingPatched extension replaces .EnableBuffering and uses FileBufferingReadStreamNoDispose which will do actual dispose only when called through reference to IDisposable or IDisposableAsync.
I had to add BufferRequest method and drain the request body manually, because if request CanSeek, then NewtonsoftJsonInputFormatter will not drain it and it will result in synchronous reads from original request stream.

Looks hacky, but it works 🤣

Other way to go in my case is to read request before passing it down the pipeline.

I had logging middleware like this:

await context.Request.BufferRequest();

var originalBodyStream = context.Response.Body;

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

    try
    {
        await next(context);
    }
    catch (Exception e)
    {
        await LogRequestResponse(context, responseBody, originalBodyStream, e);
        throw;
    }

    await LogRequestResponse(context, responseBody, originalBodyStream);
}

LogRequestResponse tried to read disposed stream.
So, instead of introducing a hacky solution with wrapper stream I can read the request body before passing it to next and then log already fetched body in LogRequestResponse.

[RomanTymchyshyn]

BTW, is it OK that NewtonsoftJsonInputFormatter will not drain and reset the stream if it CanSeek?
Sees like in 3.1-preview2 if EnableBuffering is used, app will throw sync IO exception instead of closed stream.

[pranavkm]

BTW, is it OK that NewtonsoftJsonInputFormatter will not drain and reset the stream if it CanSeek?

@davidfowl we spoke about this. Think we should just address this in the formatter, it improves the experience for everyone involved.

[davidfowl]

Auto drain? Yes I agree

[aidbal]

Hey guys, as 3.1-preview2 is out, the same issue still occurs. I have enabled httpContext.Request.EnableBuffering(), but I still get "Cannot access a disposed object". Are there more pending changes that are not released yet?

[pranavkm]

@aidbal would you mind starting a new issue for this so we can track it correctly?