Report subscription failures #7207

andrewpbrett · 2021-03-24T20:19:15Z

What? Why?

Addresses #7063

What should we test?

We're not sure how this is actually happening in production... one way to get to this branch of the code, though, is by trying to place an order for a subscription that contains a variant with a nil price should report the failure in the summary email.

I think this might be dev-test or no-test, actually.

Release notes

Fixed a bug where some subscriptions that failed to create orders would not appear in the summary email.

Changelog Category: User facing changes

Dependencies

Documentation updates

engines/order_management/spec/services/order_management/subscriptions/summary_spec.rb

app/jobs/subscription_placement_job.rb

spec/jobs/subscription_placement_job_spec.rb

sauloperez · 2021-03-29T15:00:04Z

spec/jobs/subscription_placement_job_spec.rb

+      it "records an error " do
+        expect(job).to receive(:record_subscription_issue)
+        expect(job).to_not receive(:place_order)
+        job.send(:place_proxy_order, proxy_order)


weird, I tried to execute this test and I get "NoMethodError: undefined method `place_proxy_order' for #SubscriptionPlacementJob:0x000055d45d802fa0"

besides, something is wrong if need to unit test a private method. IMO this is a clear symptom that the existing design doesn't allow for proper testing and should be improved.

sauloperez · 2021-03-29T15:11:41Z

I offer myself ☝️ if you think I can be of any help getting this sorted out.

andrewpbrett · 2021-03-29T23:14:00Z

Thanks for the review @sauloperez. I made a couple changes that are marginal improvements, but agree that there's quite a bit that could still be improved about subscriptions. I didn't change the spec that tests the private method, however; we test other private methods in the same spec file, was my thinking with that, and to call perform would make the spec far too complex.

What do you think about these changes? Would you want to proceed with the PR, or wait until we can do some more refactoring on subscriptions? I don't know where that would fit in a priority list.

sauloperez · 2021-03-30T08:06:16Z

IMO given we've introduced a new feature (yes, rather small but still a new feature) it's on us to adequate the underlying OOP design to better fit this new requirement so we keep things changeable. It's part of the job and the more we neglect it that it'll get overtime. In any case, this is not fixing the specific user error on #7063 but improves the experience if this were to happen again, right? so we're not rushing.

So, there are various code smells that lead me to think that we need to extract a class and move there the private methods that we're testing. A simple case of Extract Class. As a result, tests will probably require less setup and become easier to read, which is always good. The code smells that come to mind are:

This job class has many responsibilities: on one hand what is expected from an ActiveJob class, being the entry point for a background worker, and on the other, all the business logic related to placing subs. orders. IMO it's very similar to a controller. We'd likely extract private methods to a service so HTTP-related logic is separate from the business logic. Here is more or less the same: job logic vs business logic.
Related to this, 90% of the times we change this file (totally biased personal perception 😂 ), it's because the logic to treat a proxy order needed to change but not the data-fetching or anything related to the job class. So, separating the things that change more frequently from the things that don't would result in smaller and less risky changes.
Most of the private methods take either a proxy order or an order as an argument. Therefore, it feels a lot like Feature Envy.
The tests are considerably complex and cumbersome thus, the class is way too coupled with too many things.

For the record, I used reek and churn to assess the situation.

sauloperez · 2021-03-30T08:13:26Z

engines/order_management/spec/services/order_management/subscriptions/summary_spec.rb

@@ -56,6 +56,15 @@ module Subscriptions
        end
      end

+      describe "record_subscription_issue" do
+        let(:subscription) { double(:subscription, id: 101) }


we should rely on an RSpec's verifying double such as https://relishapp.com/rspec/rspec-mocks/docs/verifying-doubles/using-an-instance-double to avoid the double drifting away from Susbcription's interface.

Is it worth it if the only method being used is #id?

sauloperez · 2021-03-30T08:13:50Z

engines/order_management/spec/services/order_management/subscriptions/summary_spec.rb

@@ -81,6 +90,21 @@ module Subscriptions
          summary.instance_variable_set(:@success_ids, success_ids)
          expect(summary.issue_count).to be 2 # 7 & 9
        end
+
+        context "when there are also subscription issues" do
+          let(:subscription) { double(:subscription, id: 101) }


here as well

app/jobs/subscription_placement_job.rb

sauloperez · 2021-03-30T08:18:23Z

engines/order_management/spec/services/order_management/subscriptions/summary_spec.rb

+
+        context "when there are also subscription issues" do
+          let(:subscription) { double(:subscription, id: 101) }
+          let(:order) { double(:order, id: 1) }


and the same happens with the order. We must ensure we don't diverge from Spree::Order's public API.

sauloperez · 2021-03-30T08:34:49Z

Sorry for the wall of text, but I wanted to stress the need to improve subs. I'm sorry you're paying the price 😅

I have an attempt halfway through at #7281. What do you think?

sauloperez · 2021-03-31T16:22:49Z

I think we can move forward with this while we finish off #7281. Then that'll be just a refactoring which will ease reviews.

codecov · 2021-04-04T19:42:12Z

Codecov Report

❗ No coverage uploaded for pull request base (master@4bddc59). Click here to learn what that means.
The diff coverage is n/a.

@@            Coverage Diff            @@
##             master    #7207   +/-   ##
=========================================
  Coverage          ?   89.69%           
=========================================
  Files             ?      648           
  Lines             ?    18857           
  Branches          ?        0           
=========================================
  Hits              ?    16913           
  Misses            ?     1944           
  Partials          ?        0

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 4bddc59...c30ced2. Read the comment docs.

filipefurtad0 · 2021-04-09T14:42:29Z

Hey @andrewpbrett ,

Not sure what to test here.

I looked at the original issue, which seems to relate to situations where:
i) an item is out of stock
ii) possibly related with #6680 (now closed)

Looking at your code:

you seem to test for the recording of issues - :record_subscription_issue
after this PR :subscription_issues will be included into the body of the sent emails (was this not the case, before? - sorry, my rails is a bit rusty 😅 )

I tried to reproduce the bug with the hints from the issue, but wasn't really successful.

Did a brief sanity check, around:

subs which should go through - all good
some stock, but not all to cover the originally placed order -> order is created with item's amount limited by stock - OK
subs which have no stock at all, for the order - order is not created -> there's no stock - OK (pic below)

While I think these are valid tests, it probably would be interesting to test the changes this PR introduces on the email. We'd need to reproduce the bug for this. What do you think?

Other than this, I guess we can merge.

filipefurtad0 · 2021-04-09T14:53:33Z

What about:

manually changing Price to nil in the DB, for a variant on the subscription
running the placement/confirmation jobs for that sub

Maybe worth a try...

andrewpbrett · 2021-04-09T14:59:15Z

@filipefurtad0 - yes, if you manually set the price to nil on a variant in a subscription, you should see an example of the changes in the emails that go out. That was what I did as a dev-test; I think what you already did (making sure there weren't any big changes to existing behavior) was a good general test and we could probably go ahead and merge with just that. But if you did want to see it in action, manually setting a price to nil should do it.

filipefurtad0 · 2021-04-09T15:35:10Z

That was what I did as a dev-test;

Ok, I was not aware you've tested this scenario before, I just gave it a try on staging-UK.

I just made these changes on the relevant variant:

Before staging this PR - Running the placement job command:
bundle exec rake ofn:subs:test:repeat_placement_job
triggers:
https://app.bugsnag.com/yaycode/openfoodnetwork-uk/errors/607070a04fe96f00078f837b?event_id=607070a0007713303b760000&i=sk&m=nw

After staging this PR - Running the placement job command:
bundle exec rake ofn:subs:test:repeat_placement_job
triggers:

https://app.bugsnag.com/yaycode/openfoodnetwork-uk/errors/60422eda3c3c6600182214fd?event_id=607070a100773cb863810000&i=sk&m=nw

this seems to point to the code introduced, on engines/order_management/app/services/order_management/subscriptions/summarizer.rb:26

The order confirmation email does not arrive, in this case. Any thoughts on this?

andrewpbrett · 2021-04-09T17:11:30Z

Something strange is going on here. When I look at the trace for the bugsnag triggered after this PR is staged, I see this code:

def place_order_for(proxy_order)
  JobLogger.logger.info("Placing Order for Proxy Order #{proxy_order.id}")
  initialise_order(proxy_order)
  place_order(proxy_order.order)
end

But this PR has those lines as:

def place_order_for(proxy_order)
  JobLogger.logger.info("Placing Order for Proxy Order #{proxy_order.id}")
  initialise_order(proxy_order)
  return unless proxy_order.order.present?

  proxy_order.update_column(:placed_at, Time.zone.now)
  place_order(proxy_order.order)
end

I double checked the notifications channel and I don't see this PR as being deployed to the UK - maybe there was an error deploying it?

filipefurtad0 · 2021-04-09T18:59:22Z

Thanks @andrewpbrett ,
It seems the PR really wasn't deployed - my bad, sorry.

I've tried it again - now the deploy appears on the logs - and repeated the procedure.

Changing the price to nil and running the subscription jobs now triggers this bugsnag:
https://app.bugsnag.com/yaycode/openfoodnetwork-uk/errors/60709c1622b3e30007d0c099?event_id=60709c16007709f7fc120000&i=sk&m=nw

This error is new, I can't find it on Slack nor on bugsnag (the code is also new, so that's ok I think). It seems to break subs as well (when compared to the case before staging) - no emails arrive in this case.

We should perhaps consider that this does not seem reproduce what was reported on issue #7063 (NaN), namely on the UI. The price for that item appears in /subscriptions, although it is set to zero.

So maybe it is price_estimate from table subscription_line_items which needs to be set to NULL to reproduce the issue?

 id  | subscription_id | variant_id | quantity |         created_at         |         updated_at         | price_estimate 
-----+-----------------+------------+----------+----------------------------+----------------------------+----------------
 285 |             167 |     235225 |        5 | 2021-04-09 18:37:28.171287 | 2021-04-09 18:37:28.171287 |          12.00

Ok, I've tried this as well, with:
UPDATE subscription_line_items SET price_estimate=NULL WHERE id='285';

and now it does look like #7063 🎉

What's interesting is that, despite seeing the NaN on the screen, the subscription runs as normal, at least in testing, in which one places and confirms the jobs manually... all 6 emails arrive, everything seemingly normal, despite the NaN and having this in the DB:

 id  | subscription_id | variant_id | quantity |         created_at         |         updated_at         | price_estimate 
-----+-----------------+------------+----------+----------------------------+----------------------------+----------------
 285 |             167 |     235225 |        5 | 2021-04-09 18:37:28.171287 | 2021-04-09 18:37:28.171287 |

So - long story short - this PR seems to introduce no regression. It's difficult to check the change in the email, but I guess we are good to merge? I'll probably have yet another look during release testing.

andrewpbrett · 2021-04-09T19:13:08Z

Thanks again @filipefurtad0. I'm going to merge since we also have some work coming that builds on it in #7281 that should improve things further.

andrewpbrett mentioned this pull request Mar 24, 2021

Subscriptions Failing to Generate and products within them with NaN prices #7063

Closed

andrewpbrett self-assigned this Mar 24, 2021

sauloperez reviewed Mar 29, 2021

View reviewed changes

engines/order_management/spec/services/order_management/subscriptions/summary_spec.rb Outdated Show resolved Hide resolved

app/jobs/subscription_placement_job.rb Show resolved Hide resolved

sauloperez reviewed Mar 29, 2021

View reviewed changes

spec/jobs/subscription_placement_job_spec.rb Outdated Show resolved Hide resolved

sauloperez suggested changes Mar 29, 2021

View reviewed changes

andrewpbrett added 4 commits March 29, 2021 14:53

record subscription issue if no order is generated

9d2fd37

add specs

d0d3b73

ignore long module in rubocop

3664b86

refactor responsibilities and order of operations

8867f1e

andrewpbrett force-pushed the fix-nil-price-subs branch from 15d21e2 to 5c94095 Compare March 29, 2021 23:08

improve specs

61a3931

andrewpbrett force-pushed the fix-nil-price-subs branch from 5c94095 to 61a3931 Compare March 30, 2021 05:51

andrewpbrett requested a review from sauloperez March 30, 2021 05:51

sauloperez reviewed Mar 30, 2021

View reviewed changes

app/jobs/subscription_placement_job.rb Outdated Show resolved Hide resolved

sauloperez reviewed Mar 30, 2021

View reviewed changes

sauloperez approved these changes Mar 31, 2021

View reviewed changes

put Time.zone back

c30ced2

Matt-Yorkley approved these changes Apr 4, 2021

View reviewed changes

filipefurtad0 self-assigned this Apr 9, 2021

filipefurtad0 added pr-staged-uk staging.openfoodnetwork.org.uk and removed pr-staged-uk staging.openfoodnetwork.org.uk labels Apr 9, 2021

filipefurtad0 removed the pr-staged-uk staging.openfoodnetwork.org.uk label Apr 9, 2021

filipefurtad0 added the pr-staged-uk staging.openfoodnetwork.org.uk label Apr 9, 2021

filipefurtad0 removed the pr-staged-uk staging.openfoodnetwork.org.uk label Apr 9, 2021

filipefurtad0 added the pr-staged-uk staging.openfoodnetwork.org.uk label Apr 9, 2021

filipefurtad0 removed the pr-staged-uk staging.openfoodnetwork.org.uk label Apr 9, 2021

andrewpbrett merged commit d00970e into openfoodfoundation:master Apr 9, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Report subscription failures #7207

Report subscription failures #7207

andrewpbrett commented Mar 24, 2021 •

edited

Loading

sauloperez Mar 29, 2021

sauloperez Mar 29, 2021

sauloperez commented Mar 29, 2021 •

edited

Loading

andrewpbrett commented Mar 29, 2021

sauloperez commented Mar 30, 2021 •

edited

Loading

sauloperez Mar 30, 2021

Matt-Yorkley Apr 4, 2021

sauloperez Mar 30, 2021

sauloperez Mar 30, 2021

sauloperez commented Mar 30, 2021 •

edited

Loading

sauloperez commented Mar 31, 2021

codecov bot commented Apr 4, 2021 •

edited

Loading

filipefurtad0 commented Apr 9, 2021 •

edited

Loading

filipefurtad0 commented Apr 9, 2021 •

edited

Loading

andrewpbrett commented Apr 9, 2021

filipefurtad0 commented Apr 9, 2021 •

edited

Loading

andrewpbrett commented Apr 9, 2021

filipefurtad0 commented Apr 9, 2021 •

edited

Loading

andrewpbrett commented Apr 9, 2021

Report subscription failures #7207

Report subscription failures #7207

Conversation

andrewpbrett commented Mar 24, 2021 • edited Loading

What? Why?

What should we test?

Release notes

Dependencies

Documentation updates

sauloperez Mar 29, 2021

Choose a reason for hiding this comment

sauloperez Mar 29, 2021

Choose a reason for hiding this comment

sauloperez commented Mar 29, 2021 • edited Loading

andrewpbrett commented Mar 29, 2021

sauloperez commented Mar 30, 2021 • edited Loading

sauloperez Mar 30, 2021

Choose a reason for hiding this comment

Matt-Yorkley Apr 4, 2021

Choose a reason for hiding this comment

sauloperez Mar 30, 2021

Choose a reason for hiding this comment

sauloperez Mar 30, 2021

Choose a reason for hiding this comment

sauloperez commented Mar 30, 2021 • edited Loading

sauloperez commented Mar 31, 2021

codecov bot commented Apr 4, 2021 • edited Loading

Codecov Report

filipefurtad0 commented Apr 9, 2021 • edited Loading

filipefurtad0 commented Apr 9, 2021 • edited Loading

andrewpbrett commented Apr 9, 2021

filipefurtad0 commented Apr 9, 2021 • edited Loading

andrewpbrett commented Apr 9, 2021

filipefurtad0 commented Apr 9, 2021 • edited Loading

andrewpbrett commented Apr 9, 2021

andrewpbrett commented Mar 24, 2021 •

edited

Loading

sauloperez commented Mar 29, 2021 •

edited

Loading

sauloperez commented Mar 30, 2021 •

edited

Loading

sauloperez commented Mar 30, 2021 •

edited

Loading

codecov bot commented Apr 4, 2021 •

edited

Loading

filipefurtad0 commented Apr 9, 2021 •

edited

Loading

filipefurtad0 commented Apr 9, 2021 •

edited

Loading

filipefurtad0 commented Apr 9, 2021 •

edited

Loading

filipefurtad0 commented Apr 9, 2021 •

edited

Loading