umbraco / Umbraco.Commerce.Issues

18 stars 2 forks source link

System.ObjectDisposedException: Cannot access a closed Stream. #412

Open konius opened 1 year ago

konius commented 1 year ago

Umbraco 10.4.1 Vendr 3.0.9 Stripe Checkout 2.0.1

Errors when 2 webhooks are setup for separate stores from the same Stripe account.

Orders don't fail to finalize, payment is taken, but web hook fail rate is growing.

System.ObjectDisposedException: Cannot access a closed Stream.
   at System.IO.MemoryStream.get_Position()
   at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.get_Position()
   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 Vendr.Umbraco.Web.Controllers.VendrPaymentController.Callback(IPaymentProvider paymentProvider, PaymentProviderContext ctx)
   at Vendr.Umbraco.Web.Controllers.VendrPaymentController.HandleRequestWithoutOrder(String requestType, String paymentProviderAlias, Guid paymentMethodId, Func`3 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__Logged|12_1(ControllerActionInvoker invoker)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|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>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|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>g__Awaited|20_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|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.<<UseMiddlewareInterface>b__1>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.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at Skybrud.Umbraco.Redirects.Middleware.RedirectsMiddleware.InvokeAsync(HttpContext context)
   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.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>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.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>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.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at Vendr.Umbraco.Web.Mvc.VendrRequestBufferingMiddleware.InvokeAsync(HttpContext context, RequestDelegate next)
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at SixLabors.ImageSharp.Web.Middleware.ImageSharpMiddleware.Invoke(HttpContext httpContext, Boolean retry)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
mattbrailsford commented 1 year ago

Hmm, I'm not quite sure why that would be the case.

My guess is the request stream hasn't been set to allow buffering, but we should have some middleware that enabled buffering for all /vendr/payment/ requests. I don't suppose you have any custom middleware that could be affecting this? Or have any URL rewrites or something that could alter the /vendr/payment/ url structure?

konius commented 1 year ago

No custom middleware, it's pretty much out of the box stuff. No rewrites too.

I've added the following code to Startup.cs before registering other bits and as last item, tested it:

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

            return next(context);
        });

However the error is happening still.

Rockerby commented 3 months ago

I've been receiving this sporadically on payments recently. Did you ever get to the bottom of this?

mattbrailsford commented 3 months ago

What Payment Providers are you using?

Rockerby commented 3 months ago

Sorry; that information would be helpful...! I'm using the Stripe payment provider.

mattbrailsford commented 3 months ago

I'm struggling to find details from .NET on when the request stream is actually closed. We do have request buffering enabled, but if you are both experiencing the same issue, the stack trace suggests it is failing to create the request buffer because the HttpContext.Request.Body stream is already in a closed state. Given this occurs right at the beginning of payment handler request, I can't see how it would be the processing code itself that is resetting the stream.

The best option I could think of at the moment is to maybe try catch this whole process and if it gets an ObjectDisposedException it just ends the request as there isn't really anything more it can do. We would just have to trust that the payment gateway would try again at some point, and hopefully that attempt would succeed.

mattbrailsford commented 3 months ago

I'm gonna cross link this issue as it sounds like there could be a connection https://github.com/umbraco/Umbraco.Commerce.PaymentProviders.PayPal/issues/5

If there is, it could be that the logging statements are actually hiding the real underlying error so I'll see what comes from that first.

Rockerby commented 2 months ago

Hey @mattbrailsford

I noticed that some code was pushed in the PayPal repo to try and pinpoint the issue. Would you be able to share what the update was? I have the project setup at source in my project, so even the code snippet for the change rather than a rull blown pre-release, I can test things out from this side.

mattbrailsford commented 2 months ago

Hey,

I don't think any changes in the PayPal provider are to do with the issue, rather we have made an update in Umbraco Commerce to avoid writing the URL into the logs as attempting to grab the URL fails with the stream exception because the request is closed and it looks like that exception is hiding the true exception.

Are you using Umbraco Commerce of Vendr?

Rockerby commented 2 months ago

OK - that makes sense. I did spend some time looking over how this package deals with the request to pinpoint anything, but can't recreate the issue so it's proving a little tricky to even test anything.

We're running Vendr.

mattbrailsford commented 2 months ago

Looking back at the original error, maybe I can add in what I've recently done for Umbraco Commerce which is to put a pessimistic lock around the webhook handling code to block when multiple requests come in at once. This ultimately sounds like the issue underneath it all 🤔

Not quite sure what our protocol is here though now that Vendr is EOL

Rockerby commented 2 months ago

Presuming there may be some cross over with this and the new work done in Umbraco Commerce for Stripe? I've added in what I took from your comment in a PR (the indentation completely broken the git change!) - if that's what you meant I'll use this as a starting point and dig deeper.

mattbrailsford commented 2 months ago

Nice.

What I added in Umbraco Commerce was this helper:

internal static class AsyncLockHelper
{
    private static ConcurrentDictionary<string, SemaphoreSlim> _locks = new();

    internal static SemaphoreSlim WithLock<TKey>(TKey key)
        => _locks.GetOrAdd(key.ToString()!.ToLower(), (k) => new SemaphoreSlim(1, 1));
}

Then the callback handler becomes

await AsyncLockHelper.WithLock(ctx.Order.Id).WaitAsync(token);

try
{
    // The original callback logic goes here
}
finally
{
    AsyncLockHelper.WithLock(ctx.Order.Id).Release();
}

The SemaphoreSlim is async safe where as a traditional lock isn't

Let me know if this helps

Rockerby commented 2 months ago

Legend. Let me give this a whirl and I'll report back. Thanks 🙏