Openfoodnetwork: [Subs] Wrong Shipping Method Applied to Subscriptions

[lin-d-hop]

Description

One specific user has reported that their Subscriptions are being generated with the same Shipping Method, regardless of the shipping method assigned in the Subscription.

This seems to be somehow related to the fact that the user uses tags to make some shipping methods available to some users and not to others. This might be a red herring, but would be my starting point as we are not having this reported by other subs users.

This is an S1 issue as it is costing the user money. The first occurrence resulted in a discounted shipping method being applied meaning that the customer lost 30% of the sale price. We are working to minimise the issue by removing the discounted shipping method, but still delivery charges are being missed.

UK have agreed to credit the user.

Expected Behavior

When subscription orders are created the correct shipping method is applied.

Actual Behaviour

Subscriptions are being generated with incorrect shipping methods. The same Shipping method is being applied to all subscription orders in the OC.

Steps to Reproduce

Chat to Lynne on Slack and I'll give you specific user details. I suspect a dev will want to try and recreate the bug using production data as it will be a little curly.

Animated Gif/Screenshot

Context

This bug is costing us money. Literal actual money. Automatic orders are generated with incorrect value due to the incorrect application of the Shipping Method.

Severity

bug-s1: a critical feature is broken: checkout, payments, signup, login

Your Environment

• Version used:
• Browser name and version:
• Operating System and version (desktop or mobile):
• OFN Platform instance where you discovered the bug, and which version of the software they are using.

Possible Fix

I suspect this is something curly in the application of Tagging to Subscriptions.
Part of this fix, I suspect, is improving our release and unit testing of tagging.

[kristinalim]

Leaving some findings here.

No error in Bugsnag stands out.

This doesn't seem to be related to tag rules.

I checked the code for TagRuleApplicator. This is only used in customer pages for shopping and checkout, so I don't see why this issue would be related to tag rules.

This is not because a shipping method used by a subscription got deleted.

I was wondering if the shipping method of some problem subs were deleted, leaving the subs with no shipping method.

But there are no deleted shipping methods that were associated with the hub before they got deleted:

deleted_shipping_methods = Spree::ShippingMethod.unscoped.where("deleted_at IS NOT NULL")
deleted_shipping_methods.select { |shipping_method| shipping_method.distributors.include?(hub) }
# => []

There's nothing obvious when I looked for an invalid associated record.

With sample problem order, the order, line items, line item variants, proxy order, subscription, and order cycle records are all valid.

Were we not able to set the order's shipping method?

In the order's shipping rates, the wrongly assigned shipping method was created first. This supports the idea that we were just not able to successfully set the shipping method for the subscription.

first_shipping_rate = order.shipment.shipping_rates.order(:id).first
first_shipping_rate.shipping_method
# => wrong shipping method that the orders ended up using

Did setting up the order for the subscription fail so we weren't able to set the shipping method?

The shipping method is set in OrderFactory#set_shipping_method, and this happens shortly after we create the subscription's order. This is called after #create_shipments and before #create_payments.

The payment was successfully created shortly after the order was created, so #set_shipping_method should have been called without error. But I don't know why created_at of the shipment is ~before~ after that of the payment for this order. (?)

order.created_at
# => Thu, 15 Aug 2019 23:48:32 BST +01:00
order.shipment.created_at
# => Thu, 15 Aug 2019 23:48:38 BST +01:00
order.shipment.shipping_rates.first.created_at
# => Wed, 21 Aug 2019 20:23:23 BST +01:00
order.shipment.shipping_rates.first.updated_at
# => Wed, 21 Aug 2019 20:23:23 BST +01:00
order.payments.first.created_at
# => Thu, 15 Aug 2019 23:48:36 BST +01:00

[lin-d-hop]

Great investigations @kristinalim!

[mkllnk]

Gathering more context. There are 47 subscriptions and five of them should get the volunteer discount.

Subscription.where(shop_id: hub.id).count
=> 47

shipping_method = Spree::ShippingMethod.where(name: "volunteer discount").first
Subscription.where(shipping_method_id: shipping_method.id).map(&:customer).map(&:email)

I tried to find all affected subscriptions but this query returns an empty array because the orders don't have a shipping method:

Subscription.where(shop_id: hub.id).select { |sub| sub.orders.complete.present? && sub.shipping_method_id != sub.orders.complete.last.shipping_method_id && sub.orders.complete.last.shipping_method_id.present? }
# []

Now I understand why Kristina looked for reasons for a failed association of shipping methods. To find affected orders, I looked for the people who are volunteers and then for the people who received volunteer discounts. Apparently there are four volunteers but six people received discounts. One of them only has a cancelled order without subscription. That leaves two people (in the current database) who have orders with the volunteer shipping even though it's not in their subscription.

Subscription.where(shipping_method_id: shipping_method.id).map(&:customer).map(&:email).uniq.sort
Spree::Order.where(shipping_method_id: shipping_method).pluck(:email).uniq.sort

But then there are a lot of orders without shipping method. This is really confusing. So here are all orders with a volunteer discount. Only half of them still have that shipping method associated:

Spree::Order.joins(:adjustments).where("spree_adjustments.originator_id = ?", 200471)

Spree::Order.joins(:adjustments).where("spree_adjustments.originator_id = ?", 200471).where("spree_orders.email not in (?)", volunteers).pluck(:email).sort.uniq.count
# 25 people affected

Looking at the affected orders, only 29 of 54 orders came from a subscription. It might be that it's not a subscription bug but can also happen during normal checkout. Maybe not all volunteers have subscriptions. Here is a better way to find volunteers:

volunteers = hub.customers.tagged_with("vol").pluck(:email)

Spree::Order.joins(:adjustments).where("spree_adjustments.originator_id = ?", 200471).where("spree_orders.email not in (?)", volunteers).pluck(:email).sort.uniq.count
# 25 people affected

Spree::Order.joins(:adjustments).where("spree_adjustments.originator_id = ?", 200471).where("spree_orders.email not in (?)", volunteers).count
# 39

Spree::Order.joins(:adjustments).where("spree_adjustments.originator_id = ?", 200471).where("spree_orders.email not in (?)", volunteers).map(&:subscription).select(&:present?).count
=> 39

Okay, this confirms that all affected orders were generated by a subscription.

Now that I know which data is affected, I will try to re-produce it.

[mkllnk]

Steps trying to reproduce as dev:

Make the next order cycle open today.

Go through the logic of the SubscriptionPlacementJob:

proxy_orders = ProxyOrder.not_canceled.where(placed_at: nil).joins(:order_cycle).merge(OrderCycle.active).joins(:subscription).merge(Subscription.not_canceled.not_paused)
# 20 records

non_vol_proxy_orders = proxy_orders.where("subscriptions.shipping_method_id != 200471")
# 16 records

po = non_vol_proxy_orders.first
factory = OrderFactory.new(po.send(:order_attrs), skip_stock_check: true)
# factory to create order with "1 HOME DELIVERY" shipping method
order = factory.create

This order has the right shipping method and the right adjustment. But shipping_method_id is nil. It turns out we override the access to shipping method:
https://github.com/openfoodfoundation/openfoodnetwork/blob/34ed86cf2dd7c6ed5ad18e15ec6936d6d5010c3a/app/models/concerns/order_shipment.rb#L21-L24

The newest order with a shipping_method_id on UK production was created on 28 July. We upgrade from v2.2.0 to v2.2.1 on 29 July. There could have been a related code change. But the missing id may not be related to this at all.

Back to the reproducing. I tried to initialise orders but I found that they were all good:

bad_proxy_orders = non_vol_proxy_orders.select { |po| po = ProxyOrder.find(po.id); po.initialise_order!; po.subscription.shipping_method_id != po.order.adjustments.where(label: "Shipping").first.originator_id }
# []  empty array

These orders are now in cart stage. The next step is processing them.

po.order.next! # => state: address, shipping fee: home delivery
po.order.next!
po.order.state
# => "delivery"
po.order.adjustments.where(label: "Shipping").first.originator.name
# => "volunteer discount"

:dart: In the transition from address to delivery the shipping fee is replaced. :boom:

The shipment was replaced as well.

[mkllnk]

I found this odd code: https://github.com/openfoodfoundation/spree/blob/8a8585a43cd04d1a50dc65227f337a91b18d66d5/core/app/models/spree/order.rb#L334-L336

    def remove_invalid_shipments!
      shipments.each { |s| s.destroy unless s.shipping_method.available_to_order?(self) }
    end

But it seems to be unused. No reference to remove_invalid_shipments! and the available_to_order? method doesn't exist.

Looking further: https://github.com/openfoodfoundation/spree/blob/8a8585a43cd04d1a50dc65227f337a91b18d66d5/core/app/models/spree/order/checkout.rb#L72-L73

              before_transition :to => :delivery, :do => :create_proposed_shipments
              before_transition :to => :delivery, :do => :ensure_available_shipping_rates

https://github.com/openfoodfoundation/spree/blob/8a8585a43cd04d1a50dc65227f337a91b18d66d5/core/app/models/spree/order.rb#L539

    def create_proposed_shipments
      shipments.destroy_all


      packages = Spree::Stock::Coordinator.new(self).packages
      packages.each do |package|
        shipments << package.to_shipment
      end


      shipments
    end

So we destroy all shipments. But since we didn't save the shipping_method_id on the order, there is no knowledge about which shipping method to select. I tried to assigning the id but it doesn't help, probably because we ignore the id anyway. Our override would just return nil when calling order.shipping_method.

I tried to patch Order#shipping_method to use the shipping_method_id if no shipments are there and then set the id before transitioning but it didn't work. I still got the volunteer discount.

Spree code looks at all available shipping rates and chooses the cheapest one:
https://github.com/openfoodfoundation/spree/blob/8a8585a43cd04d1a50dc65227f337a91b18d66d5/core/app/models/spree/stock/estimator.rb#L11-L34

      def shipping_rates(package, frontend_only = true)
        shipping_rates = Array.new
        shipping_methods = shipping_methods(package)
        return [] unless shipping_methods


        shipping_methods.each do |shipping_method|
          cost = calculate_cost(shipping_method, package)
          shipping_rates << shipping_method.shipping_rates.new(:cost => cost)
        end


        shipping_rates.sort_by! { |r| r.cost || 0 }


        unless shipping_rates.empty?
          if frontend_only
            shipping_rates.each do |rate|
              rate.selected = true and break if rate.shipping_method.frontend?
            end
          else
            shipping_rates.first.selected = true
          end
        end


        shipping_rates
      end

I think we have several options from here:

• Don't delete and rebuild shipments if shipments are already present. Patch Spree::Order#create_proposed_shipments.
• In subscriptions, rebuild the desired shipment after we reached the delivery state of the order. Patch SubscriptionPlacementJob.
• Make SpreeStockEstimator (which is a shipping rate selector) look into pre-existing shipping method selections.

I'm not sure how many side effects option 1 has. It could be the best solution but needs a bit more thinking through and thorough testing. Option 2 seems to be the most obvious solution with no other impact. It makes the code more complex. It's a workaround but should work. Option 3 is introducing too much complexity. I would forget about that one.

[kristinalim]

Nice investigation, @mkllnk.

About Spree::Order.create_proposed_shipments, I forgot that we regenerate not just the shipping rates but the shipment themselves too. :+1: The timestamps now make sense.

On calling order.next! on the orders directly, in #3560 we introduced AdvanceOrderService which less obtrusively wraps order.next with OFN-specific logic such as retaining the shipping method when the order is transitioned to delivery.

It appears that I missed to do this for SubscriptionPlacementJob in #3560. :disappointed: Subscriptions were not testable in v2 yet at that time, so we did not have manual testing for this. This in SubscriptionPlacementJob is not covered by our specs either so there was no spec failure. I guess manual testing for subscriptions also either had only one available shipping method for the shop or accidentally picked the correct shipping method.

I'll submit a PR fixing this later.

[lin-d-hop]

Amazing! Thanks @kristinalim! Definitely not your fault that this was missed.

So would be great to get some code reviews on this. @mkllnk obvs.
What should we do without the lack of other devs for the code review?

Go team!

[sigmundpetersen]

I think it was agreed to reduce the code review requirement to 1 approval in this transitional period until more devs are back next week 👍

[lin-d-hop]

Banc - Shipping Method Issues

[lin-d-hop]

@mkllnk or @kristinalim Would you confirm something for me....?

Can I check if the probem occurs when Subs Orders are created (-> order cycle opens) or when the Orders are confirmed (-> order cycle closes)?

I'm going to manually correct the subscriptions for this user so just checking which day I need to block a bit of time out.

Thanks!!

[mkllnk]

When the order cycles are opened, @lin-d-hop!

The SubscriptionPlacementJob runs every five minutes. So roughly within five minutes of the order cycle opening, it creates orders and places them. It sends emails out to tell people that their orders have been placed, probably with the wrong amount. You can then change it, yes. Sounds reasonable. "Sorry, technical error, we applied the wrong shipping rate." I guess buyers will understand that for a week or maybe two?