umbraco / Umbraco.Commerce.PaymentProviders.PayPal

MIT License
0 stars 3 forks source link

Cannot access a disposed object. Object name: 'FileBufferingReadStream'. #5

Closed PeterKvayt closed 2 months ago

PeterKvayt commented 4 months ago

Describe the bug When I tried to complete order, the following exception occurred: "System.ObjectDisposedException: Cannot access a disposed object. Object name: 'FileBufferingReadStream'"

Steps To Reproduce Steps to reproduce the behavior:

  1. Create order with one of payment providers (in my case it was umbraco.Commerce.PaymentProvider.PayPal)
  2. Complete it
  3. PayPal webhook callback triggered
  4. In umbraco logs exception occurred

Expected behavior There is no exception "System.ObjectDisposedException: Cannot access a disposed object. Object name: 'FileBufferingReadStream'"

Additional context There is a stack trace of exception:

System.ObjectDisposedException: Cannot access a disposed object. Object name: 'FileBufferingReadStream'. at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.ThrowIfDisposed() at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.set_Position(Int64 value) at Umbraco.Commerce.Web.Mvc.HttpRequestMessageFeature.CreateHttpRequestMessage(HttpContext httpContext) at Umbraco.Commerce.Cms.Web.Controllers.UmbracoCommercePaymentController.get_RequestMessage() at Umbraco.Commerce.Cms.Web.Controllers.UmbracoCommercePaymentController.HandleRequestWithoutOrder(String requestType, String paymentProviderAlias, Guid paymentMethodId, Func3 handler) at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments) at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask1 actionResultValueTask) at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.gAwaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted) at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context) at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted) at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync() --- End of stack trace from previous location --- at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.g__Awaited|25_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 --- at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.gAwaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope) at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.gAwaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope) at Microsoft.AspNetCore.Routing.EndpointMiddleware.g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger) at SEOChecker.Common.Middleware.UrlRedirectMiddleware.InvokeAsync(HttpContext context, IContextInfo contextInfo, INiceUrlHelper niceUrlHelper, IUrlRewriteProviderFactory urlRewriteProviderFactory, IPageNotFoundRepository pageNotFoundRepository, INotFoundHelper notFoundHelper, IIOHelper ioHelper, IUriResolverService uriResolverService, IUmbracoUrlHelper umbracoUrlHelper, IUmbracoContextFactory umbracoContextFactory, IRequestProviderService requestProviderService, IConfigService1 configurationService, IOptions1 contentOptions, ILogger1 logger) at SEOChecker.Common.Middleware.UrlRewriteMiddleware.InvokeAsync(HttpContext context, IUrlRewriteProviderFactory urlRewriteProviderFactory, IUmbracoUrlHelper umbracoUrlHelper, IUmbracoContextFactory umbracoContextFactory, IConfigService1 configurationService, ILogger`1 logger) at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context) at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context) at Microsoft.AspNetCore.Localization.RequestLocalizationMiddleware.Invoke(HttpContext context) at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context) at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context) at SixLabors.ImageSharp.Web.Middleware.ImageSharpMiddleware.Invoke(HttpContext httpContext, Boolean retry) at StackExchange.Profiling.MiniProfilerMiddleware.Invoke(HttpContext context) in C:\projects\dotnet\src\MiniProfiler.AspNetCore\MiniProfilerMiddleware.cs:line 121 at Umbraco.Cms.Web.Common.Middleware.UmbracoRequestMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Umbraco.Cms.Web.Common.Middleware.UmbracoRequestMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>cDisplayClass6_1.<b1>d.MoveNext() --- End of stack trace from previous location --- at Umbraco.Cms.Web.Common.Middleware.PreviewAuthenticationMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>cDisplayClass6_1.<b1>d.MoveNext() --- End of stack trace from previous location --- at Umbraco.Cms.Web.Common.Middleware.UmbracoRequestLoggingMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>cDisplayClass6_1.<b1>d.MoveNext() --- End of stack trace from previous location --- at Foo.CMS.Web.Core.Features.UmbracoCommerce.Features.Backoffice.Middlewares.DynamicBackofficeViewsMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in D:\Projects\Bar\Foo\git\src\Foo.CMS.Web.Core\Features\UmbracoCommerce\Features\Backoffice\Middlewares\DynamicBackofficeViewsMiddleware.cs:line 48 at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>cDisplayClass6_1.<b1>d.MoveNext() --- End of stack trace from previous location --- at Umbraco.Forms.Web.HttpModules.ProtectFormUploadRequestsMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>cDisplayClass6_1.<b1>d.MoveNext() --- End of stack trace from previous location --- at Umbraco.Commerce.Cms.Web.Mvc.UmbracoCommerceRequestBufferingMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>cDisplayClass6_1.<b__1>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)

Umbraco Commerce version: v10.0.10

Umbraco.Commerce.PaymentProviders.PayPal: v10.0.0

Possible fix It may caused by enabled request buffering, but umbraco commerce already has Umbraco.Commerce.Cms.Web.Mvc.UmbracoCommerceRequestBufferingMiddleware which enable it.

Another possible reason is storing HttpContext in field of Umbraco.Commerce.Web.Mvc.HttpRequestMessageFeature class. Even though scoped services in ASP.NET Core have a lifetime that matches the request, there are still compelling reasons to avoid storing HttpContext directly in fields within those services. Here's why:

  1. Potential for Inconsistent State The HttpContext and its features like ISession are designed to be accessed per-request and are tied to the specific HTTP request lifecycle. Storing them in a field and accessing them later can lead to an inconsistent state if the service instance is reused in a different context within the same request or if the session state changes.
  2. Disposal and Resource Management ASP.NET Core manages the disposal of HttpContext and its components. If you store these components in fields, you risk accessing disposed objects, especially if any asynchronous operations are involved that might delay the service method execution.
  3. Thread Safety HttpContext and its features are not thread-safe. Storing them in a field increases the risk of concurrent access issues. Each access to HttpContext should be fresh and scoped to the current request processing pipeline to ensure thread safety.
  4. Proper DI Pattern ASP.NET Core's Dependency Injection (DI) pattern is designed for services to access their dependencies directly. This means services should use IHttpContextAccessor to access HttpContext or ISession on-demand. This ensures that you always get the current, correct instance without risking lifecycle or concurrency issues.

I think storing HttpContext in field of Umbraco.Commerce.Web.Mvc.HttpRequestMessageFeature leading this issue and insted storing HttpContext in field we should use IHttpContextAccessor.

Thanks for help)

mattbrailsford commented 4 months ago

Hmm, yea, that usually occurs when something messes with the request buffering. We need to allow requests to be replayed as Umbraco Commerce needs to do some processing, but then the payment provider needs to do their processing also.

I can't see why the HttpContext thing would be an issue as that class is copied from Microsofts own code https://github.com/aspnet/Mvc/blob/release/2.2/src/Microsoft.AspNetCore.Mvc.WebApiCompatShim/HttpRequestMessage/HttpRequestMessageFeature.cs

If you are introducing your own Middlware or enabling buffering yourself, I'd be more inclined to test around this and seeing if disabling those resolves this.

PeterKvayt commented 4 months ago

Hmm, thanks for the link https://github.com/aspnet/Mvc/blob/release/2.2/src/Microsoft.AspNetCore.Mvc.WebApiCompatShim/HttpRequestMessage/HttpRequestMessageFeature.cs, it is interesting.

I will check all my middlewares one more time, but it seems them is not the issue.

PeterKvayt commented 4 months ago

@mattbrailsford After deep investigation I found out more details and I think the main issue reason.

This issue was not caused by Umbraco.Commerce.Cms.Web.Mvc.UmbracoCommerceRequestBufferingMiddleware. It woks as expected.

The main reason here is that PayPal disposing request.Content, which is the HttpContext.Request.Body property in Umbraco.Commerce.PaymentProviders.PayPal.Api.PayPalClient.ParseWebhookEventAsync.

After that code continue executing from line 176 (Umbraco.Commerce.Cms.Web.Controllers.UmbracoCommercePaymentController), but, it is important, now HttpContext.Request.Body is disposed.

image

Then if an exception occurred somewhere from line 176 to 211, catch clause will catch it and log the exception, but here is the most interesting: in log logic we trying to get base.Request.RequestUri.ToString() and here we get another exception with the following stack trace:

Cannot access a closed Stream. at System.IO.MemoryStream.get_Position() at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.get_Position() at System.Net.Http.StreamContent.InitializeContent(Stream content, Int32 bufferSize) at System.Net.Http.StreamContent..ctor(Stream content) at Microsoft.AspNetCore.Mvc.WebApiCompatShim.HttpRequestMessageFeature.CreateHttpRequestMessage(HttpContext httpContext) at Microsoft.AspNetCore.Mvc.WebApiCompatShim.HttpRequestMessageFeature.get_HttpRequestMessage() at Microsoft.AspNetCore.Mvc.WebApiCompatShim.HttpRequestMessageHttpContextExtensions.GetHttpRequestMessage(HttpContext httpContext) at System.Web.Http.ApiController.get_Request() at Umbraco.Commerce.Cms.Web.Controllers.UmbracoCommercePaymentController.Callback(IPaymentProvider paymentProvider, PaymentProviderContext ctx) at Umbraco.Commerce.Cms.Web.Controllers.UmbracoCommercePaymentController.HandleRequestWithoutOrder(String requestType, String paymentProviderAlias, Guid paymentMethodId, Func3 handler) at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments) at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask1 actionResultValueTask) at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.gAwaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted) at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context) at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted) at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted) at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.gAwaited|25_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.gAwaited|20_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted) at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope) at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.gAwaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope) at Microsoft.AspNetCore.Routing.EndpointMiddleware.gAwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger) at Umbraco.Cms.Web.Common.Middleware.BasicAuthenticationMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<b1>d.MoveNext() --- End of stack trace from previous location --- at Umbraco.Cms.Web.BackOffice.Middleware.BackOfficeExternalLoginProviderErrorMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<b__1>d.MoveNext() --- End of stack trace from previous location --- at Foo.CMS.Web.MyTestMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in D:\Projects\Bar\Foo\git\src\Foo.CMS.Web\Startup.cs:line 18

This exception throw hides the original exception, so I cant find out what exactly happened inside the Callback method.

You can reproduce this behaviour, just use PayPal payment provider and throw any exception inside Callback method from line 166, you have to throw exception after call await paymentProvider.ProcessCallbackAsync(ctx, token).ConfigureAwait(continueOnCapturedContext: false); (line 176). In my case exception was thrown in line 190.

The simple way to reproduce the issue:

  1. Create base mvc app
  2. implement the following api controller

    public class MyController : System.Web.Http.ApiController // Microsoft.AspNetCore.Mvc.WebApiCompatShim Version=2.2.0.0
    {
    public async Task Index()
    {
        Context.Request.EnableBuffering(); // it is important
    
        var request = Context.Request;
    
        if(request.Body.CanSeek)
        {
            request.Body.Position = 0L;
        }
    
        var stream = new StreamContent(request.Body); // NOTE: creating new stream from request body
    
        using(var s = await stream.ReadAsStreamAsync().ConfigureAwait(false))
        {
            if(s.CanSeek)
            {
                s.Seek(0, SeekOrigin.Begin);
            }
    
            using(var reader = new StreamReader(s))
            {
                var json = await reader.ReadToEndAsync().ConfigureAwait(false);
    
                Console.WriteLine(json);
            }
        } // here request body disposed
    
        try
        {
            var uri = Request.RequestUri.ToString(); // and now we trying to get disposed request
    
            Console.WriteLine(uri);
        }
        catch(Exception e)
        {
            throw e;
        }
    }
    }
  3. Call it.

Possible resolution: please add logic to check Request before using it in logging logic. The main purpose is do not lose original exception.

I think I should create new issue for PayPal payment provider with reference to this issue.

Thanks for support)

PeterKvayt commented 4 months ago

Issue with exception Cannot access a disposed object. Object name: 'FileBufferingReadStream'. is consiquence of exception Cannot access a closed Stream.. The exception Cannot access a disposed object. Object name: 'FileBufferingReadStream' was caused by SEOChecker.Common.Middleware.UrlRedirectMiddleware, cause this middleware can process the same request twice if exception has been thrown.

mattbrailsford commented 4 months ago

Hey @PeterKvayt

Really great investigation work so thank you so much for digging in and pinpointing the issue. I think I should be able to transfer this issue over to the PayPal provider repo so I'll try and do so that all the info is kept.

mattbrailsford commented 4 months ago

@PeterKvayt i've just pushed a 10.0.12--preview.1 to our night feed which should no longer log the URL, rather instead it logs the payment provider name and the order number. This won't fix the overal issue, but it should prevent the second error masking the original exception.

Would you be in a position to give it a test and see if it sheds any further light on the real underlying issue?

See info here for how to use a nightly feed https://docs.umbraco.com/umbraco-cms/fundamentals/setup/install/installing-nightly-builds

PeterKvayt commented 4 months ago

Hi @mattbrailsford

I am glad to hear that you have been pushed 10.0.12--preview.1. I can test the fix locally, but the main issue was discovered on our stand. So it can take a while to test this fix on stand and give you feedback (it can take from one to couple weeks, depends on our deliveries).

I will notice you about my local investigation results as soon as possible.

Btw what else was changed in 10.0.12--preview.1? Is there only one change (this fix) between 10.0.11 and 10.0.12--preview.1. It is important for me.

Thanks for support

mattbrailsford commented 4 months ago

Hi @PeterKvayt yea, this is the only thing in there at the moment.

As I say, i don't think this is going to be the final solution, just I'm hoping this lets us skip the second issue you highlighted and then hopefully lets us see what the realy issue is (ie, what throws the first exception). Fingers crossed it's a different error we can resolve more easily 😁

PeterKvayt commented 4 months ago

Hi @mattbrailsford !

I have just reproduced error on my local environment with syntetic exception to see can I find the original exception in logs. I could find it, great😁.

The following step is to deliver your fixed version 10.0.12--preview.1.gaae1bd2 (10.0.12--preview.1) to stand and find out the original error on stand.

I will keep you updated.

mattbrailsford commented 4 months ago

@PeterKvayt fantastic. Fingers crossed we can get there 🤞

PeterKvayt commented 3 months ago

Hi!

Little update is here: I have just caught internal exception which probably cause to error.

изображение

I am going to investigate it more deeper. Just wanted to keep you up to dated.

mattbrailsford commented 3 months ago

Ooh, excellent that we are seeing the right exception now.

Do you have code in your solution using entity framework? Umbraco Commerce doesn’t but I know CMS have started to in areas. At least is narrowed down to an area to look in to.

I appreciate the update. Fingers crossed we’re getting closer to a resolution. 🤞🏻

PeterKvayt commented 3 months ago

@mattbrailsford

I was able to reproduce this exception locally, It was caused by my code. I have two handlers for Order Finalized Notification which processed actions in parallel with one dbcontext instance.

My fix not on our testing stage yet, but I think it was the main exception which cause current issue.

So let's summarize:

Anyway thanks a lot for fast response and support!

I will write about results after my code deployed on our testing stage.

PeterKvayt commented 2 months ago

@mattbrailsford

Are there any plans to release new version of Umbraco.Commerce with fix from 10.12--preview.1.gaae1bd2? Soon we need to release our project and we want to use normal version with fix instead of nightly build 10.12--preview.1.gaae1bd2

mattbrailsford commented 2 months ago

Sorry, forgot to reply but 10.0.12 is out now 👍🏻

PeterKvayt commented 2 months ago

@mattbrailsford

As I can see fix from 10.12--preview.1.gaae1bd2 is already applied in 10.0.13 (maybe in 10.0.12 too, but I didn't check it)