Openfoodnetwork: Payment taken from customer by PayPal but no order created on platform

[lbwright22]

Description

Customer placed an order with Tamar Valley Food Hub (UK) at 9:30 26/08/20 (end of their OC). She paid by Paypal and used Chrome browser.

1. First attempt at payment Paypal redirected customer back to basket as butternut squash was out of stock. Customer amended order.
2. Customer submits order 2nd time. Time is now after 9:30 am. Order does not go through. No order number generated. No customer order notification sent. No order generated in the admin section of OFN for Tamar. (Order created later by Tamar in backoffice)
3. Customer receives receipt from Paypal for their order. Payment to Tamar went through- confirmed by Tamar.

Bugsnag report here:
https://app.bugsnag.com/yaycode/openfoodnetwork-uk/errors/5f2954c78473a50018ef45a9?filters%5Bevent.since%5D%5B%5D%5Btype%5D=eq&filters%5Bevent.since%5D%5B%5D%5Bvalue%5D=30d&filters%5Berror.status%5D%5B%5D%5Btype%5D=eq&filters%5Berror.status%5D%5B%5D%5Bvalue%5D=open&filters%5Bevent.unhandled%5D%5B%5D%5Btype%5D=eq&filters%5Bevent.unhandled%5D%5B%5D%5Bvalue%5D=true&event_id=5f44cbb4005e08c5dcde0000

Expected Behavior

Customer submits an order to a hub/shop after OC has closed. Order fails and no payment is taken.

Actual Behaviour

Customer submits and order to hub/shop shortly after OC has closed. Order fails but PayPal (payment gateway) OKs the order and takes payment.

Steps to Reproduce

1.
2.
3.
4.

Animated Gif/Screenshot

Workaround

Severity

S3

Your Environment

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

Chrome

Possible Fix

slack thread: https://openfoodnetwork.slack.com/archives/CDLKH9MM0/p1598513843029000

[lin-d-hop]

There are two potential things to unpack here.

1) The relation to the OC closing. This is a case that should be covered here: https://github.com/openfoodfoundation/openfoodnetwork/issues/5372

2) The Bugsnag is about stock running out between the trigger of payment in paypal and the successful payment return to OFN.
In this case the solution is:

a) OFN successfully processes the order
b) The order in OFN is created with the AVAILABLE stock
c) The order has an overpayment because more stock was paid for than is in the order so should have the payment state 'Balance Owing'

[lin-d-hop]

There have been 11 events of this on UK bugsnag in the past month. Only one from an actual customer.

[lbwright22]

Re-occurrence of this issue:
Date: 13th Nov
Order id: R003653045 (Order ID is printed on the PayPal statement for both the customer and enterprise not there is no order with that ID on the system).
Customer placed order and paid with PayPal.

Order total was £116.39.
Order included Mince and Ribs which were out of stock. Incomplete order total was £104.42

This is the order list from enterprise's Paypal records:

Fruit bag | 1 | £3.85 GBP | £3.85 GBP
-- | -- | -- | --
  | Organic Salad Leaves | 1 | £2.12 GBP | £2.12 GBP
  | Seasonal English Veg Bag with Potatoes | 1 | £5.38 GBP | £5.38 GBP
  | Half-n-Half Loaf | 1 | £2.50 GBP | £2.50 GBP
  | Sourdough - Mixed Olive | 1 | £3.50 GBP | £3.50 GBP
  | Cheddar - mature | 1 | £2.62 GBP | £2.62 GBP
  | Eggs - Hen | 2 | £1.10 GBP | £2.20 GBP
  | Bacon | 1 | £2.31 GBP | £2.31 GBP
  | Bacon | 1 | £1.72 GBP | £1.72 GBP
  | Beef Steak - usually frozen | 2 | £4.13 GBP | £8.26 GBP
  | Christmas Free Range Goose Deposit - pre-order by 8 Dec | 1 | £9.75 GBP | £9.75 GBP
  | Sausages - usually frozen | 1 | £3.18 GBP | £3.18 GBP
  | Sausages - usually frozen | 1 | £3.18 GBP | £3.18 GBP
  | Lasagne - Beef (family size) FROZEN | 1 | £8.05 GBP | £8.05 GBP
  | Lasagne - Roast Vegetable (family size) FROZEN | 1 | £8.05 GBP | £8.05 GBP
  | Cornish Ketchup Company | 1 | £2.46 GBP | £2.46 GBP
  | Kingston Special Chutney | 1 | £2.12 GBP | £2.12 GBP
  | Peanut Butter - Freda's | 1 | £3.00 GBP | £3.00 GBP
  | Seville Orange & Ginger Marmalade | 1 | £2.12 GBP | £2.12 GBP
  | Beef Mince - usually frozen | 1 | £3.18 GBP | £3.18 GBP
  | Malted Multi-Seed Loaf | 1 | £2.75 GBP | £2.75 GBP
  | Tomatoes - Sun Dried | 1 | £1.36 GBP | £1.36 GBP
  | Pork Roasting Joint - usually frozen | 1 | £8.64 GBP | £8.64 GBP
  | Ribs | 2 | £2.38 GBP | £4.76 GBP

Escalating to S2 on advice of @lin-d-hop

[Matt-Yorkley]

Dev notes

• There are 3 occurrences of these errors related to Paypal processing in Bugsnag over the last 3 month period.
• In relation to the total volume of payments successfully processed, I'd say this bug is quite rare.
• There's a lot of similar errors for the same failed stock validation that are _not_ related to payments, and these are all in products #bulk_update. Side note: I'd love to :fire: all of our bulk_update code at some point...
• There's a correlation between these stock failures and spikes in the frequency of database deadlocks.
• I don't see similar errors related to Stripe payments anywhere, maybe Stripe is more robust?

So... I think this is happening around periods of high traffic where multiple shoppers are buying the same last stock items, and even then only in rare cases. I imagine replicating this issue and/or writing specs for it might be very difficult.

Possible next steps:

• Have a look at the Paypal code specifically and see if there are specific ways to make it more robust in relation to failed order validations on stock levels?
• Take a step back and look more broadly at how our strategy for handling locks might be improved?

[Matt-Yorkley]

Additional note in relation to improving locks: there are certain processes that hold on to locks whilst doing things that have performance issues, so they hold the locks for an unreasonable amount of time, and I think we definitely have this issue around checkout submission.

[Matt-Yorkley]

Additional note on concurrency issues: Rails 5 has an entire concurrency support module baked in, which would probably help deal with some of these hard problems. I think we would also need to switch from multi-process Unicorn to multi-_threaded_ Puma to benefit from it.

[Matt-Yorkley]

Investigation round two:

I think we can fix this outside of our concurrency issues.

Firstly our paypal test coverage is woefully inadequate, so that's step one. We don't have any feature specs covering either the "happy path" of a successful payment, or the "unhappy path" of a failed payment.

Secondly, the issue is that we only reduce stock after the paypal transaction has completed, which means the stock could have been reduced to zero by the time paypal fires it's webhook back to us to confirm the payment went through, causing the order to not be saved to the failed validation (that's the mechanics of this edge case). So the solution is a potentially messy rewrite of this logic so that we reduce the stock when the checkout is _submitted_, then process the payment, then if the payment was not successful we _replace_ the stock and reset the order to cart state.

[lin-d-hop]

This sounds woefully similar to the idea of an item being held while in the cart.

I wonder if there is a way to write the logic that might be reusable for the various cases in which stock needs to be held for a time period then replaced... ?

[Matt-Yorkley]

I'm just getting into the mechanics of it now. There could be several ways to make this change, but yes it might be possible to generalise it for all payment methods where there's a gap between the payment confirmation and reducing the stock.

[Matt-Yorkley]

I think the previous ideas around holding the stock while it's in the cart would be quite tricky to implement, as all kinds of stock could be held for any length of time, and managing the consequences of that requires a lot of additional complexity. Basically as soon as you do that you have half a dozen other problems which then also need to be solved :see_no_evil: My guess is it would spiral out of control into a massive feature...

I think we can do something much simpler here to resolve the immediate issue. We'll probably see this bug occurring more and more frequently as the holiday season ramps up and shopper activity intensifies (unless we fix it). :fire: :santa: :christmas_tree:

[RachL]

Just FYI previous discussion where here: https://community.openfoodnetwork.org/t/secure-products-availability-during-checkout-process/1933

So you can see that the first problem was not that the cart did not secure anything, but the checkout page. Could this be the case here as well?

Securing stuff in the cart is tricky indeed, I think that why most website add a timer to it.

[Matt-Yorkley]

I think that why most website add a timer to it.

Yeah, but implementing the functionality for that timer and the issues around what happens when you re-stock after the timer runs out would also be complex.

What I'm thinking of here would not solve the general issues of shoppers being annoyed when something goes out of stock and they are sent back to the basket, just the issue of payments going through on orders which then vanish from the system.

[Matt-Yorkley]

Luis's thoughts on the timer from that discourse thread: "The timer is not easy (stock management). I think this is too much for OFN right now."

[RachL]

@Matt-Yorkley yes I was not suggesting to do the timer ;) I was wondering if here the case could be that the product goes out of stock while the user is transfered to Paypal's window. So the customer lands on Paypal but when they confirm payments the product is considered as unavailable on OFN side so the order kind of vanishes?

So maybe a check on the stock level is missing before the payment is confirmed?

[Matt-Yorkley]

So the customer lands on Paypal but when they confirm payments the product is considered as unavailable on OFN side so the order kind of vanishes?

Yes, that's it.

So maybe a check on the stock level is missing before the payment is confirmed?

We already check the stock again just before the payment takes place (we previously made some improvements in this area), but it's not sufficient in this case. It still leaves a small gap in which the stock can change before the payment completion is 100% confirmed.

[Matt-Yorkley]

I changed direction a bit on this after adding new specs for the full paypal checkout workflow and digging depper into the logic. Anyway, I think I've got it fixed :tada: