Openfoodnetwork: Subscriptions Failing to Generate and products within them with NaN prices

[lbwright22]

Description

Enterprise: Down Farm (200490)
Order Cycle 207581
The enterprise had 19 subscriptions which should have been generated on 5th March (and for which payment collected on 9th March).
Enterprise does not allow orders to be changed while the order cycle is open. Receives only the 'Summary of Recently Confirmed' Subscription orders email when the order cycle is closed.
This documented that 14 orders were successfully processed.
No mention of 5 orders not being processed.

The five orders not processed were the 5 most recently created subscriptions (belonging to customers linda@rsw... rosie.smerdon@... lull... rchrd... and hello@down-farm...)

Viewing Subscriptions while OC 207581 was open displayed '1' for Open Orders under all of the five above customers. In each case there was an item in the order displaying with price = NaN

Products in the subscriptions are all set to infinite stock. No product overrides.
The same items appear in other customer's subscriptions with a price.

The subscriptions affected have all been processed successfully in the past.

Expected Behavior

A Subscription generates an automatic order when an order cycle opens.
If the order fails to generate for any reason then this is documented in the summary of recently placed subscription orders sent to the hub manager.
Products which are in stock all have prices.

Actual Behaviour

Some subscriptions fail to generate an order automatically.
These failed orders are not documented in the email sent to the hub manager.
Products which are in stock have NaN price values for some customers and not others in their subscriptions.

Steps to Reproduce

1. Open the following week's order cycle for Enterprise 200490
2. Add the relevant schedules
3. Visit Subscriptions
4. Notice that under all the relevant customers there is an order pending.
5. View the orders for each customer in turn
6. Notice that for some customers a product appears with price Nan and for others it appears with the correct price.
   eg. OC 207652
   customer jjoy.. veg box - small price £11.00 (correct) BUT customer annfearnley... veg box - small price £NaN (incorrect)

Animated Gif/Screenshot

Workaround

No work around

Severity

S2

Your Environment

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

Possible Fix

[Matt-Yorkley]

I've just had a look through those orders and I don't see NaN anywhere..? Have they been changed?

[lbwright22]

No. It's still visible to me. @Matt-Yorkley

[Matt-Yorkley]

Okay, I see them now. I notice some of these orders have an associated error message:

Initial notes: I've had a looking the database, and these SubscriptionLineItem objects have nil for their price_estimate. I see there are 47 similar line items with no price estimate, with creation dates going back to 2019. Looks like the NaN is generated on the frontend, multiplying the price estimate by the quantity (nil * 1).

[Matt-Yorkley]

Hmm okay... we have 120 Spree::Price objects (prices of variants) where the price is nil:

irb(main):005:0> Spree::Price.where(amount: nil).count
=> 120

Looking at Subscriptions::Estimator, I think those variants would cause the price_estimate for those items to be nil as well...

[lbwright22]

The same enterprise opened their OC this morning for the week.
18 out of 20 subscriptions generated correctly.

subscription ID 370 didn't generate and the order R637841483 was mentioned in the email sent to the hub manager as having encountered an error- no error message present.
When I first looked at the order it was not marked as 'complete'. The state was 'delivery'. Visiting Edit Order made the order become active and it is now showing as 'complete' with payment pending at the end of the OC.

the other order (R021217278) had an error message in the email sent to the hub which states that one item was out of stock: 'Bread - Rye Sourdough'.
I have checked and the product is out of stock.
BUT this is not clear to the hub manager when you view the subscription the red 'no open or upcoming order cycles for this product...' is not written underneath the item

ping @Matt-Yorkley

[Matt-Yorkley]

Dev notes: I had another look at those Spree::Price objects with amount: nil and they mostly seem to be either master variants (which are fine to not have a price) or deleted variants. The relevant variants here seem to have reasonable price objects.

Variants going out of stock seems to be a factor here. Some of the placed orders were fine, and some were clearly out of stock and somewhere in between we have these weird issues. I'm wondering if this could be related to #6680 where line items with zero quantity can be left on the order if the item is out of stock...

[andrewpbrett]

@Matt-Yorkley actually it looks like your initial suspicion was correct about nil prices. I downloaded the UK db and got the proxy orders by doing ProxyOrder.where(order_cycle_id: oc.id) and filtering for the subscriptions that @lbwright22 mentioned (linda@r... etc.)

When I call proxy_order.initialise_order! on each one, each one fails because of a nil price. None of the variants are master variants.

So I ran SubscriptionPlacementJob.perform_now and I would expect us to get a #<NoMethodError: undefined method *' for nil:NilClass> in Bugsnag from line 39 in the job. I don't see it in UK Bugsnag, though. There are, however, two timeout errors that suspiciously coincide with the dates that Louise mentions.

Because this error only notifies Bugsnag and doesn't stop execution of the job for the ProxyOrder, we now continue the job with a ProxyOrder whose order is nil (Spoiler alert: this ends badly).

When we go to record the issue, we assume that the order is present, calling record_and_log_error with a nil order inside the rescue clause. The record_and_log_error method calls order.errors which then throws our favorite exception, undefined method for nil.

So that explains why the orders aren't showing up on the emails at all.

I created #7207 to address the fact that the subscriptions fail silently.

I think to close this issue we'll want to also address how those variants got created or updated with nil prices.

I just realized I was getting nil prices because my local config was set to the default of AUD and the database dump was in GBP 😑

[andrewpbrett]

Okay, taking another look at this. I reloaded the UK database and set the currency to GBP. In a console:

> ProxyOrder.not_canceled.where.not(placed_at: nil).where(order_id: nil).joins(:order_cycle).
joins(:subscription).where(order_cycle_id: 207581).count
=> 5
> ProxyOrder.not_canceled.where.not(placed_at: nil).where(order_id: nil).joins(:order_cycle).
joins(:subscription).where(order_cycle_id: 207581).map { |p| p.subscription.customer.email }
=> [ the five emails from above ]

So these five subscriptions have proxy orders that have a placed_at, but failed to create an order from the proxy order. This could happen in any number of ways.

The most suspicious thing is that while all of the variants in question do have prices, not all of the SubscriptionLineItems have a price_estimate. However, when I modify the SubscriptionPlacementJob to pick these five proxy orders and try to place order from them again, it has no problem creating placing all five orders. This suggests, as @Matt-Yorkley mentions, something to do with variants being out of stock (and then back in stock in the database dump I'm working with).

There may be multiple things going on here, but based on the fact that we are definitely seeing the job run and not generate orders for all the proxy orders, I think https://github.com/openfoodfoundation/openfoodnetwork/pull/7207 is the best first step. That PR will at least make the hub manager aware of the failures.

The second scenario you mention @lbwright22 sounds like it's something different, since in that case, you were able to see the order numbers. We may want to create a separate issue for it; let's see how far #7207 gets us and go from there.

[andrewpbrett]

If/when that PR #7207 gets merged, I think we could downgrade this to an S3 since the hub manager will at least be notified of the failure now.

[sauloperez]

So these five subscriptions have proxy orders that have a placed_at, but failed to create an order from the proxy order. This could happen in any number of ways.

that always bugged me of the design of subscriptions. The last time we debugged them together @andrewpbrett we realized placed_at conveys the meaning that there was an attempt at processing these proxy orders and thought it was best no to change this meaning (my memory might not serve me right). I truly think we should then have a separate timestamp column that conveys the meaning "successfully processed" so that we can retry those that have it nil. IMO not being able to retry failed subs misses most of the point of background jobs.

[andrewpbrett]

I began addressing this in 8867f1ef7a5c8a92086fdac460dbc1e553b00ea6 by moving the line that updates placed_at and confirming that we've actually created the order before we set it.

[Matt-Yorkley]

Closed via #7207