Backoffice order blocked at 'Address' stage

[lbwright22]

Description

Create order in back office for enterprise 201078 using OC 207544 (also tested for OC 207889)
Unable to complete the order placement.
Can not access 'Payments' tab
Order remains with status = 'Address'

Product stock is overridden in inventory but inventory settings do not necessitate products being in the inventory for them to be added to an order cycle.
No tag rules
Products added to backoffice orders are in the corresponding OC and are in stock in inventory.
Enterprise has delivery shipping methods set up.

Tested another enterprise and back office order placement works as predicted.

Expected Behavior

Create order in back office for enterprise 201078 using OC 207544 (also tested for OC 207889)
Add product in 'Order Details'
Visit 'Customer Details' and add address
Visit 'Payments' and add a payment
complete the order

Actual Behaviour

Create order in back office for enterprise 201078 using OC 207544 (also tested for OC 207889)
Add product in 'Order Details'
Visit 'Customer details' and add address
click update
click on 'payments' to finalise order placement.
Taken back to 'customer details'

Revisit incomplete order and edit.
Products removed from 'Order Details' section. Fees remain only.

Steps to Reproduce

1. Create order in back office for enterprise 201078 using OC 207544 (also tested for OC 207889)

2. Add product in 'Order Details'

3. Visit 'Customer details' and add address

4. click update

5. click on 'payments' to finalise order placement.

6. Taken back to 'customer details'

7. Revisit incomplete order and edit.

8. Products removed from 'Order Details' section.

9. Observe Fees remain only.

Animated Gif/Screenshot

Workaround

Severity

bug s2

Your Environment

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

Possible Fix

[filipefurtad0]

Thanks for reporting this @lbwright22 .

I first observed this yesterday while testing this PR #6924. I second your observation, on staging-UK:

• As admin (pic below, left): The shipping section is missing from the Backoffice: It usually contains the shipping number, the shipping state and the line items to be shipped, shipping method and tracking number.
• As customer (pic below, right): Attempting to visit a placed order from which the shipping section is missing -> snail

Not sure what is the pattern for these orders. It seems to affect both admins and customers. Depending on the extent, could be an s1... Investigating.

[filipefurtad0]

For these orders, it appears that shipments are missing from the spree_shipments, in the DB (staging-UK).

A corrupt order:

   id   |   number   | item_total | total  |  state   | adjustment_total | user_id |         created_at         |         updated_at         |        completed_at        | bill_address_id | ship_address_id | payment_total | shipment_state | payment_state |              email               | special_instructions | distributor_id | currency | last_ip_address | order_cycle_id | customer_id | created_by_id | included_tax_total | additional_tax_total 
--------+------------+------------+--------+----------+------------------+---------+----------------------------+----------------------------+----------------------------+-----------------+-----------------+---------------+----------------+---------------+----------------------------------+----------------------+----------------+----------+-----------------+----------------+-------------+---------------+--------------------+----------------------
 716543 | R631265404 |     100.00 | 127.00 | complete |            27.00 |  208036 | 2021-04-01 17:08:53.839138 | 2021-04-01 17:16:53.907742 | 2021-04-01 17:08:56.497015 |          427847 |          427848 |        127.00 | shipped        | paid          | [email protected] |                      |         201402 | GBP      |                 |         203946 |        7419 |               |               0.00 |                 0.00

openfoodnetwork=> SELECT * FROM spree_shipments WHERE order_id='716543';

 id | tracking | number | cost | shipped_at | order_id | address_id | created_at | updated_at | state | stock_location_id | included_tax_total | additional_tax_total | adjustment_total 
----+----------+--------+------+------------+----------+------------+------------+------------+-------+-------------------+--------------------+----------------------+------------------
(0 rows)

A "healthy" order:

   id   |   number   | item_total | total |  state   | adjustment_total | user_id |         created_at         |         updated_at         |        completed_at        | bill_address_id | ship_address_id | payment_total | shipment_state | payment_state |              email               | special_instructions | distributor_id | currency | last_ip_address | order_cycle_id | customer_id | created_by_id | included_tax_total | additional_tax_total 
--------+------------+------------+-------+----------+------------------+---------+----------------------------+----------------------------+----------------------------+-----------------+-----------------+---------------+----------------+---------------+----------------------------------+----------------------+----------------+----------+-----------------+----------------+-------------+---------------+--------------------+----------------------
 717290 | R001760052 |      15.00 | 15.00 | complete |             0.00 |  208036 | 2021-04-07 15:18:22.607755 | 2021-04-07 15:18:58.546236 | 2021-04-07 15:18:58.368436 |          427886 |          427887 |          0.00 | pending        | balance_due   | [email protected] |                      |         201402 | GBP      |                 |         203946 |        7419 |               |               0.00 |                 0.00

openfoodnetwork=> SELECT * FROM spree_shipments WHERE order_id='717290';

   id   | tracking |    number    | cost | shipped_at | order_id | address_id |         created_at         |         updated_at         |  state  | stock_location_id | included_tax_total | additional_tax_total | adjustment_total 
--------+----------+--------------+------+------------+----------+------------+----------------------------+----------------------------+---------+-------------------+--------------------+----------------------+------------------
 237251 |          | H87668074776 | 0.00 |            |   717290 |            | 2021-04-07 15:18:48.682889 | 2021-04-07 15:18:58.530957 | pending |                 1 |               0.00 |                 0.00 |             0.00
(1 row)

[filipefurtad0]

In fact, it looks like there are only 8 (!!!) shipment entries in this table - there are 4790 orders in state='complete':

   id   | tracking |    number    | cost |         shipped_at         | order_id | address_id |         created_at         |         updated_at         |  state  | stock_location_id | included_tax_total | additional_tax_total | adjustment_total 
--------+----------+--------------+------+----------------------------+----------+------------+----------------------------+----------------------------+---------+-------------------+--------------------+----------------------+------------------
 237243 |          | H31508587085 | 2.00 |                            |   716878 |            | 2021-04-06 16:19:37.632    | 2021-04-06 16:19:39.600556 | pending |                 1 |               0.00 |                 0.00 |             2.00
 237249 |          | H84481367523 | 0.00 |                            |   717254 |            | 2021-04-07 11:12:04.162771 | 2021-04-07 11:13:38.530774 | ready   |                 1 |               0.00 |                 0.00 |             0.00
 237248 |          | H24502310831 | 0.00 |                            |   716365 |            | 2021-04-07 11:08:09.151637 | 2021-04-07 11:13:39.418452 | ready   |                 1 |               0.00 |                 0.00 |             0.00
 237244 |          | H27245082033 | 2.00 |                            |   717107 |            | 2021-04-06 16:21:24.981968 | 2021-04-06 16:21:26.886761 | pending |                 1 |               0.00 |                 0.00 |             2.00
 237245 |          | H66232126841 | 2.00 |                            |   717108 |            | 2021-04-06 16:25:56.263444 | 2021-04-06 16:25:57.90475  | pending |                 1 |               0.40 |                 0.00 |             2.00
 237251 |          | H87668074776 | 0.00 | 2021-04-07 15:51:00.741154 |   717290 |            | 2021-04-07 15:18:48.682889 | 2021-04-07 15:51:00.741154 | shipped |                 1 |               0.00 |                 0.00 |             0.00
 237247 |          | H32435180545 | 2.00 |                            |   716334 |            | 2021-04-06 16:36:19.619541 | 2021-04-06 16:36:34.94745  | pending |                 1 |               0.00 |                 0.00 |             2.00
 237246 |          | H65754004576 | 2.00 |                            |   717109 |            | 2021-04-06 16:31:51.417766 | 2021-04-06 18:03:18.498538 | pending |                 1 |               0.40 |                 0.00 |             2.00
(8 rows)

The last one is from 2021-04-06 16:19:37. This would match with the date and time of deployment of PR #6924 on staging-UK. But this PR was staged/tested in other servers, and the orders seem not to be missing there... I'm puzzled here. Ping @Matt-Yorkley.

[Matt-Yorkley]

I think I was trying some things out on UK Staging the other day before 6924 was deployed, there's a good chance it was me that deleted the shipments there. Sorry! I'll take a look at restoring a backup. I think it's separate from this issue in UK Production though. Deploying PRs to staging that were not merged before the last release can't be the cause of the issue in UK Prod, right?

[Matt-Yorkley]

Going back to this comment: #6924 (comment)

I also manually replicated something like this the first time it came up. Switching the toggle and restarting unicorn made the shipment section re-appear on the order I was looking at (in staging), but it didn't really make sense.

[filipefurtad0]

Thanks @Matt-Yorkley an no worries on that - restoring the orders might be an idea, deleting them as well would be fine.

Deploying PRs to staging that were not merged before the last release can't be the cause of the issue in UK Prod, right?

Right 👍 It all matched with the time of the deployment of the patch, so for a moment I thought PR #6924 was in it (but it's not).

We should probably remove the default setting to enable unit prices (or features which are in development) from staging environments - I think this was a conclusion from our meeting on this matter (cant' find the notes now).

Update: submitted PR #7350

[andrewpbrett]

I was able to reproduce this issue by downloading the UK database and trying to place an order containing one of the subscription coffee products.

I'm not all that familiar with the inventory parts of the code base, but I was able to track this down and it was happening because it's saying there's no stock available for the item.

In the database dump that I have, that OrderCycle has the following products available:

["- New Dawn Traders / Yallah - Coffee", "- New Dawn Traders / Yallah - Coffee", "- New Dawn Traders / Yallah - Coffee", "- New Dawn Traders / Yallah - Coffee Subscription", "- New Dawn Traders / Yallah - Coffee Subscription", "- New Dawn Traders / Yallah - Coffee Subscription", "- New Dawn Traders / Yallah - Coffee Subscription", "- New Dawn Traders / Arhuaco - Panela", "- New Dawn Traders / Arhuaco - Panela", "- New Dawn Traders / Arhuaco - Panela", "- New Dawn Traders / Yallah - Coffee", "- New Dawn Traders / Yallah - Coffee", "- Gorreana - Green Tea Hysson", "- Gorreana - Green Tea Hysson", "- Gorreana - Black Tea Pekoe", "- Gorreana - Black Tea Pekoe", "- Atlantic Brewery - Azores Pale Ale -  4.2%", "- Atlantic Brewery - Azores Pale Ale -  4.2%"] 

But when I look at the inventory for New Dawn, none of those products appear. Again, this might be me misunderstanding what @lbwright22 mentions about:

Product stock is overridden in inventory but inventory settings do not necessitate products being in the inventory for them to be added to an order cycle.
and
Products added to backoffice orders are in the corresponding OC and are in stock in inventory.

But from what I'm looking at, it does look like something isn't right with how inventory is working for this distributor.

I also tested creating an order for another distributor/order cycle and was able to move the order to the payment state after entering customer details.

We could probably downgrade this from an S2 given that it's apparently limited to just this shop and might be fixed by checking their setup, depending on what @lbwright22 thinks.

In any case, though, we could look into making the error message more informative - right now, we expect that entering customer details should always advance the order state to payment, and don't indicate why if that doesn't happen.

[andrewpbrett]

Actually, it looks like quite a few of these products in the order cycle - everything supplied by New Dawn traders in fact - has 0 on hand in the product list, and does not show up in the inventory.

When creating a backoffice order, these products show up in the dropdown search as being able to add to the order. I don't know if that's a recent change/regression, but the immediate workaround would be to either add the product to inventory or change its quantity on hand to be > 0.

[lbwright22]

Hi @andrewpbrett all of New Dawn Traders products are in the New dawn Traders Inventory with stock level over-rides. It just takes ages for them to load and show. They are already in stock in the inventory. Sorry...

I have just tested creating a back office order. The issue remains.
The products are visible on the shop front. It is a problem with back office orders for this enterprise

[lin-d-hop]

This is an S2. It would be an S1 with a report from another user. No backoffice orders. I have successfully placed a backoffice order on a different OC for this user but not with this OC. It seems something specific to the OC but I can't figure out why that might be...

I just want to add to the description:

Normal Behaviour:

1. Create order in back office for enterprise 201078 using OC 207544 (also tested for OC 207889)
2. Add product in 'Order Details'
3. Visit 'Customer details' and add address
4. click update
5. Add shipping method in 'Order Details'

On an order with these products for this enterprise in this order cycle you do not have the option to add the Shipping Method. And the line items do not display correctly as Louise described.

In the below image NORMALLY i would see line items and the option to choose a Shipping Method. Why can't I choose a shipping method? I get blocked by Order State 'Address'. Why does this state transition occur?

[andrewpbrett]

Thanks @lin-d-hop and @lbwright22 for clarifying.

I'm going to put some notes here on what I've discovered so far, since I'm scratching my head and might need to explain it to a rubber duck.

The first-level reason that we can't access the payments screen is that we assume that filling in customer details will transition the order from the address to payment state. This isn't happening in this case.

Okay, so why isn't it happening? We call OrderWorkflow.new(@order).complete after the customer details are filled in. This attempts to move the order to the payment state. In the process it checks how many of each line item's variant is on hand:

openfoodnetwork/app/models/concerns/variant_stock.rb

Lines 91 to 101 in aca19ed

	def fill_status(quantity)
	on_hand = if total_on_hand >= quantity || on_demand
	quantity
	else
	[0, total_on_hand].max
	end
	backordered = 0
	[on_hand, backordered]
	end

In this case, total_on_hand is returning 0.

There's a bit of a red flag here because on Line 26 of the VariantStock module, we define a method called on_hand, and here we use a local variable with the same name.

There are actually four different places we define a method called total_on_hand. The one in ScopeVariantToHub looks for the presence of a VariantOverride; the others do not. When I put a debugger in each of them, I found that we call the total_on_hand method in Spree::Variant, which then uses the one in Spree::Stock::Quantifier, to determine if there's enough stock available.

When creating the BO order, however, the dropdown uses the API::Variant::Serializer, which uses the total_on_hand method in ScopeVariantToHub.

So basically, the variant override is being ignored here. I can't imagine that this we changed something such that suddenly all variant overrides are being ignored, or we'd be hearing about it from more than just this shop.

I'm not all that familiar with the inventory/variant override parts of the code base (although I'm becoming more familiar by the hour...). I'm going to hit publish on this comment in case someone else wants to pick up the trail from here but I'll also continue to work on it.

[Matt-Yorkley]

🦆💯

[Matt-Yorkley]

Inventory / VariantOverrides / "scoping" variants is crazy and head-scratching is 100% expected 👌

So to continue the rubber-ducking; I think when that dropdown looks for variants, it's hitting Admin::VariantsController#search:

openfoodnetwork/app/controllers/spree/admin/variants_controller.rb

Lines 56 to 60 in 479897f

	def search
	scoper = OpenFoodNetwork::ScopeVariantsForSearch.new(variant_search_params)
	@variants = scoper.search
	render json: @variants, each_serializer: ::Api::Admin::VariantSerializer
	end

Which essentially finds variants and then in theory "overrides" them here before returning the results:

openfoodnetwork/lib/open_food_network/scope_variants_for_search.rb

Lines 69 to 74 in 479897f

	def scope_variants_to_distributor(variants, distributor)
	scoper = OpenFoodNetwork::ScopeVariantToHub.new(distributor)
	# Perform scoping after all filtering is done.
	# Filtering could be a problem on scoped variants.
	variants.each { |v| scoper.scope(v) }
	end

The override process is a bit crazy but essentially it overwrites the attributes of the Variant object in memory with a different set of attributes from a corresponding VariantOverride, so by the time the Api::Variant::Serializer asks what the object's on_hand count is, it's basically not the same object. In theory it will respond with the stock level of the variant override and not the base variant...

I suspect this part is actually working as intended, but I could be wrong. The next step after selecting a product via the dropdown is a POST request to /api/shipments, and I'd probably have a look at what happens there for more clues...

[andrewpbrett]

Also worth mentioning here: I can reproduce this in development using the default seed data (Freddy's Farm etc) by doing the following:

• Set a product (Tomatoes) to have 0 on hand and "on demand?" unchecked in the product list
• Add Tomatoes to Inventory and set On Hand to 10 and On Demand to No
• Add Tomatoes to a back office order
• Enter customer details
• Get stuck at "Address" state

So this isn't anything specific to the hub, or the order cycle; the variant override is simply being ignored when we go to check if there's available inventory in this way.

I've confirmed that a VariantOverride exists for the Tomatoes variant I'm trying to add.

This is starting to be one of those "how did this ever work" bugs... based on what we do in the shipments controller, (scoping the variant to take into account overrides) I made a change to Stock::Packer to do the same and.... it works???

I'll send a PR for others to review.