Openfoodnetwork: Multiple Stripe payments collected for incomplete order created in back office

[lbwright22]

Description

Order ID R506827701

Order created in the back office by hub manager.
Each time they added a card payment it stated that there was 'An Error Saving Payment'

I am unable to find a bugsnag for this. NOTE billing name is different to the name on bank card used for final payment, but consistent otherwise

Order remains 'incomplete' at 'Payment' stage on OFN platform with four pending payments showing:

Stripe records show that all four payments have been collected:

Clicking on the 'X' to void the last three payments on the OFN system and 'tick' on the first (to capture one payment on OFN and hence move the order to 'complete' for delivery and supplier reporting) resulted in three payments as 'void' and one as 'failed'.

But on Stripe ALL FOUR are refunded:#

Expected Behavior

Order created in back office.
Shopper pays by card over and hub manager enters in card details.
If card details are correct, OFN and Stripe both record payment has successfully been taken. OFN order moves from the incomplete 'Payment' status to 'complete' 'paid' status.
If card details are not correct OFN shows incomplete payment failed. No payment collected by Stripe- this also shows 'failed' payment attempt. Order remains at 'Payment' status on OFN platform.

Actual Behaviour

Order created in back office.
Shopper pays by card over and hub manager enters in card details.
OFN displays 'Error in taking payment' notice but Stripe processes the payment.
Order remains in 'Payment' incomplete status on OFN platform.
Payment collected from shopper multiple times.

Steps to Reproduce

1.
2.
3.
4.

Animated Gif/Screenshot

Workaround

Severity

Bug S1

Your Environment

• Version used:
• Browser name and version:
• Operating System and version (desktop or mobile):

Possible Fix

[lbwright22]

Note that further investigation shows that two items in the order were out of stock:

1. Hogget leg on the bone 1.5kg (two were in the basket but only one available)
2. salad leaves with edible flowers 150g bags (2 in basket but none available)

[andrewpbrett]

@lbwright22 thanks for reporting this, we're looking into it. Is that first screenshot from you reproducing the error, or from the hub manager?

[lbwright22]

@andrewpbrett the first screen shot is from the hub manager (although I edited out the customer details)

[andrewpbrett]

Thanks @lbwright22!

This is the relevant bugsnag: https://app.bugsnag.com/yaycode/openfoodnetwork-uk/errors/5f2954c78473a50018ef45a9

It does looks like the root cause is those items being out of stock, but we should obviously be handling it differently. Thanks for noting that, very helpful when debugging.

I'm hoping to have a PR written to address this soon. Is there anything else you need immediately to address this specific payment @lbwright22? The sort-of-good news is that it only occurs in this case where one of the order's items is out of stock, and not to all backoffice payments.

[Matt-Yorkley]

Shout if you want some backup @andrewpbrett.

Also we could do some rubber-ducking in the issue comments, it might help with asynchronous problem solving?

[andrewpbrett]

🦆 🦆 🦆 🦆 🦆 🦆 🦆 🦆 🦆 🦆 🦆 🦆 🦆 🦆

So according to the Bugsnag, this is happening because we try to save a StockItem with a negative quantity.

And we get to that part of the code by doing OrderWorkflow.new(@order).complete!:

https://github.com/openfoodfoundation/openfoodnetwork/blob/4932e1dcb5473891ce867811f63b2c2559e4aaec/app/controllers/spree/admin/payments_controller.rb#L28-L50

I can reproduce the error message by raising any kind of 500 in this controller method.

What I'm still puzzled by is how the payment is getting processed in this case, since @payment.process! is only called if @order.completed? == true. In the Bugsnag, we're in the other branch of that if statement.

[andrewpbrett]

Ah, okay. Before we get to that if-branch, we call authorize_stripe_sca_payment on line 34. That's consistent with the payments showing up as Pending in the OFN backend. Again, however, the payment should not be taken at that point. I'll look in to the Stripe logs next.

Also of note: there are other Bugsnag reports that trace back to this same line, where we try to save! a StockItem, but the trace leads somewhere else (products#bulk_update, for example).

[andrewpbrett]

So the call to authorize_stripe_sca_payment is fine and what we should be doing. It's not collecting the payment. We're collecting it because we process the payments before we transition the Order to complete:

https://github.com/openfoodfoundation/openfoodnetwork/blob/4932e1dcb5473891ce867811f63b2c2559e4aaec/app/models/spree/order/checkout.rb#L70-L74

And we call finalize! after the transition:

https://github.com/openfoodfoundation/openfoodnetwork/blob/4932e1dcb5473891ce867811f63b2c2559e4aaec/app/models/spree/order/checkout.rb#L82

The call to finalize! is what triggers the callback cascade that eventually tries to save a StockItem with negative stock, raising RecordInvalid, thus returning the 422 from that controller method.

This behavior has been this way for a long time, as far as I can tell; we haven't changed anything with these order state machine callbacks recently. I think the reason it hasn't been spotted yet is that it requires the items to go out of stock in between the time that the hub manager creates the order and the time that the payment is created on the backend. If the product is already out of stock when creating the order, it can't be added to the order.

Indeed, I can now reproduce this exactly with the following:

Create a new order and add a product that's On Demand (or otherwise in stock)
Add customer details
Go to the Products list and set the product to have 0 stock, and not On Demand
Add a payment with a credit card (no SCA required)
Get the "Error Saving Payment" message

[andrewpbrett]

@Matt-Yorkley I have to put this down for a little while (maybe until tomorrow) so feel free to pick it up from here if it hasn't advanced by the time you see it.

I think because of the edge-case-iness it might not have the urgency of an S1 any more. Still a big bug to fix, but unlikely that it will pop up again any time soon.

Throwing out some ideas on how we could fix it from here:

We could check all the line items to make sure they're in stock before processing the payments. One way would be doing finalize before process_payments. But... I have a feeling there's a reason we're doing it in the order we are.

So maybe we need to specifically check that the order's items are all in stock before processing payments. But that's solving this specific problem; in the future, there could be other things that could go wrong when we call finalize! and ideally we'd have a way to recover from any of them. But I don't think the solution should be to process the payments, and then reverse/refund them if something goes wrong. We need a way to tell if finalize is going to succeed, like a dry run flag or something...

Or we could go back to the first suggestion, examine why exactly we call process_payments before calling finalize! instead of the other way around, and reverse the order.

[Matt-Yorkley]

Nice digging! :duck:

So... the stock is actually reduced at the point the order is "finalized" (competed), but in order to do that the order needs to have a valid payment that's been created (even if the payment is actually not paid yet). But... we're not checking the stock levels before reaching that completion step when we create an order via admin, and in admin the final step that kicks the order into completion happens here in the payments controller after the new payment has been submitted...

I think the #process_payments! call that happens in the checkout flow isn't what _creates_ the actual payment object though, right? It processes a payment object which should already exist at the point the order is finalized? At least in the frontoffice checkout flow.

I think we just need to do an explicit stock check and bounce the user back to first page with an error message if something is out of stock, before that point where we try to call OrderWorkflow.new(@order).complete! in Spree::Admin::PaymentsController#create. It'll only be needed on incomplete orders.

[andrewpbrett]

That first paragraph is an excellent summary 👍

I think we just need to do an explicit stock check

Yeah I'm also leaning toward that route. If I get a PR together I'll push it up and @-mention you @Matt-Yorkley, even if it's WIP, so we're not duplicating work. I don't have a ton of time left today but it'd be nice to get this in this week's release. I think we'll have to redraft anyway because of #7644.