Merge pull request #4527 from luisramos0/subs_logs

Improve Subscriptions logging

.rubocop_manual_todo.yml

@@ -386,7 +386,6 @@ Metrics/AbcSize:
   - app/helpers/spree/admin/base_helper.rb
   - app/helpers/spree/admin/zones_helper.rb
   - app/helpers/spree/orders_helper.rb
-  - app/jobs/subscription_placement_job.rb
   - app/mailers/producer_mailer.rb
   - app/models/calculator/flat_percent_per_item.rb
   - app/models/column_preference.rb

app/jobs/subscription_confirm_job.rb

@@ -6,6 +6,7 @@ class SubscriptionConfirmJob
     ids = proxy_orders.pluck(:id)
     proxy_orders.update_all(confirmed_at: Time.zone.now)
     ProxyOrder.where(id: ids).each do |proxy_order|
+      Rails.logger.info "Confirming Order for Proxy Order #{proxy_order.id}"
       @order = proxy_order.order
       process!
     end

app/jobs/subscription_placement_job.rb

@@ -5,8 +5,7 @@ class SubscriptionPlacementJob
     ids = proxy_orders.pluck(:id)
     proxy_orders.update_all(placed_at: Time.zone.now)
     ProxyOrder.where(id: ids).each do |proxy_order|
-      proxy_order.initialise_order!
-      process(proxy_order.order)
+      place_order_for(proxy_order)
     end
 
     send_placement_summary_emails
@@ -28,16 +27,18 @@ class SubscriptionPlacementJob
       .joins(:subscription).merge(Subscription.not_canceled.not_paused)
   end
 
-  def process(order)
+  def place_order_for(proxy_order)
+    Rails.logger.info "Placing Order for Proxy Order #{proxy_order.id}"
+    proxy_order.initialise_order!
+    place_order(proxy_order.order)
+  end
+
+  def place_order(order)
     record_order(order)
     return record_issue(:complete, order) if order.completed?
 
     changes = cap_quantity_and_store_changes(order)
-    if order.line_items.where('quantity > 0').empty?
-      order.reload.adjustments.destroy_all
-      order.update!
-      return send_empty_email(order, changes)
-    end
+    return handle_empty_order(order, changes) if order.line_items.where('quantity > 0').empty?
 
     move_to_completion(order)
     send_placement_email(order, changes)
@@ -58,6 +59,12 @@ class SubscriptionPlacementJob
     changes
   end
 
+  def handle_empty_order(order, changes)
+    order.reload.adjustments.destroy_all
+    order.update!
+    send_empty_email(order, changes)
+  end
+
   def move_to_completion(order)
     AdvanceOrderService.new(order).call!
   end

app/models/order_cycle.rb

@@ -17,6 +17,7 @@ class OrderCycle < ActiveRecord::Base
   has_many :distributors, source: :receiver, through: :cached_outgoing_exchanges, uniq: true
 
   has_and_belongs_to_many :schedules, join_table: 'order_cycle_schedules'
+  has_paper_trail meta: { custom_data: :schedule_ids }
 
   attr_accessor :incoming_exchanges, :outgoing_exchanges
 

app/models/schedule.rb

@@ -1,5 +1,7 @@
 class Schedule < ActiveRecord::Base
   has_and_belongs_to_many :order_cycles, join_table: 'order_cycle_schedules'
+  has_paper_trail meta: { custom_data: :order_cycle_ids }
+
   has_many :coordinators, uniq: true, through: :order_cycles
 
   attr_accessible :name, :order_cycle_ids

config/initializers/paper_trail.rb

@@ -1 +1,7 @@
 PaperTrail.config.track_associations = false
+
+module PaperTrail
+  class Version < ActiveRecord::Base
+    attr_accessible :custom_data
+  end
+end

db/migrate/20191202165700_add_custom_data_to_versions.rb

@@ -0,0 +1,5 @@
+class AddCustomDataToVersions < ActiveRecord::Migration
+  def change
+    add_column :versions, :custom_data, :string
+  end
+end

db/schema.rb

@@ -11,7 +11,7 @@
 #
 # It's strongly recommended to check this file into your version control system.
 
-ActiveRecord::Schema.define(:version => 20191023172424) do
+ActiveRecord::Schema.define(:version => 20191202165700) do
 
   create_table "adjustment_metadata", :force => true do |t|
     t.integer "adjustment_id"
@@ -1196,12 +1196,13 @@ ActiveRecord::Schema.define(:version => 20191023172424) do
   add_index "variant_overrides", ["variant_id", "hub_id"], :name => "index_variant_overrides_on_variant_id_and_hub_id"
 
   create_table "versions", :force => true do |t|
-    t.string   "item_type",  :null => false
-    t.integer  "item_id",    :null => false
-    t.string   "event",      :null => false
+    t.string   "item_type",   :null => false
+    t.integer  "item_id",     :null => false
+    t.string   "event",       :null => false
     t.string   "whodunnit"
     t.text     "object"
     t.datetime "created_at"
+    t.string   "custom_data"
   end
 
   add_index "versions", ["item_type", "item_id"], :name => "index_versions_on_item_type_and_item_id"

lib/open_food_network/proxy_order_syncer.rb

@@ -17,29 +17,36 @@ module OpenFoodNetwork
     end
 
     def sync!
-      return sync_all! if @subscriptions
+      return sync_subscriptions! if @subscriptions
+
       return initialise_proxy_orders! unless @subscription.id
 
-      create_proxy_orders!
-      remove_orphaned_proxy_orders!
+      sync_subscription!
     end
 
     private
 
-    def sync_all!
+    def sync_subscriptions!
       @subscriptions.each do |subscription|
         @subscription = subscription
-        create_proxy_orders!
-        remove_orphaned_proxy_orders!
+        sync_subscription!
       end
     end
 
     def initialise_proxy_orders!
       uninitialised_order_cycle_ids.each do |order_cycle_id|
+        Rails.logger.info "Initializing Proxy Order " \
+          "of subscription #{@subscription.id} in order cycle #{order_cycle_id}"
         proxy_orders << ProxyOrder.new(subscription: subscription, order_cycle_id: order_cycle_id)
       end
     end
 
+    def sync_subscription!
+      Rails.logger.info "Syncing Proxy Orders of subscription #{@subscription.id}"
+      create_proxy_orders!
+      remove_orphaned_proxy_orders!
+    end
+
     def create_proxy_orders!
       return unless not_closed_in_range_order_cycles.any?
 
@@ -58,6 +65,8 @@ module OpenFoodNetwork
       orphaned_proxy_orders.scoped.delete_all
     end
 
+    # Remove Proxy Orders that have not been placed yet
+    #   and are in Order Cycles that are out of range
     def orphaned_proxy_orders
       orphaned = proxy_orders.where(placed_at: nil)
       order_cycle_ids = in_range_order_cycles.pluck(:id)

lib/open_food_network/subscription_summarizer.rb

@@ -17,6 +17,7 @@ module OpenFoodNetwork
     end
 
     def record_issue(type, order, message = nil)
+      Rails.logger.info "Issue in Subscription Order #{order.id}: #{type}"
       summary_for(order).record_issue(type, order, message)
     end
 

spec/jobs/subscription_placement_job_spec.rb

@@ -45,7 +45,7 @@ describe SubscriptionPlacementJob do
 
       before do
         allow(job).to receive(:proxy_orders) { ProxyOrder.where(id: proxy_order.id) }
-        allow(job).to receive(:process)
+        allow(job).to receive(:place_order)
       end
 
       it "marks placeable proxy_orders as processed by setting placed_at" do
@@ -55,7 +55,7 @@ describe SubscriptionPlacementJob do
 
       it "processes placeable proxy_orders" do
         job.perform
-        expect(job).to have_received(:process).with(proxy_order.reload.order)
+        expect(job).to have_received(:place_order).with(proxy_order.reload.order)
       end
     end
   end
@@ -143,7 +143,7 @@ describe SubscriptionPlacementJob do
       it "records an issue and ignores it" do
         ActionMailer::Base.deliveries.clear
         expect(job).to receive(:record_issue).with(:complete, order).once
-        expect{ job.send(:process, order) }.to_not change{ order.reload.state }
+        expect{ job.send(:place_order, order) }.to_not change{ order.reload.state }
         expect(order.payments.first.state).to eq "checkout"
         expect(ActionMailer::Base.deliveries.count).to be 0
       end
@@ -156,7 +156,7 @@ describe SubscriptionPlacementJob do
         end
 
         it "uses the same shipping method after advancing the order" do
-          job.send(:process, order)
+          job.send(:place_order, order)
           expect(order.state).to eq "complete"
           order.reload
           expect(order.shipping_method).to eq(shipping_method)
@@ -169,7 +169,7 @@ describe SubscriptionPlacementJob do
         end
 
         it "does not place the order, clears, all adjustments, and sends an empty_order email" do
-          expect{ job.send(:process, order) }.to_not change{ order.reload.completed_at }.from(nil)
+          expect{ job.send(:place_order, order) }.to_not change{ order.reload.completed_at }.from(nil)
           expect(order.adjustments).to be_empty
           expect(order.total).to eq 0
           expect(order.adjustment_total).to eq 0
@@ -182,13 +182,13 @@ describe SubscriptionPlacementJob do
         it "processes the order to completion, but does not process the payment" do
           # If this spec starts complaining about no shipping methods being available
           # on CI, there is probably another spec resetting the currency though Rails.cache.clear
-          expect{ job.send(:process, order) }.to change{ order.reload.completed_at }.from(nil)
+          expect{ job.send(:place_order, order) }.to change{ order.reload.completed_at }.from(nil)
           expect(order.completed_at).to be_within(5.seconds).of Time.zone.now
           expect(order.payments.first.state).to eq "checkout"
         end
 
         it "does not enqueue confirmation emails" do
-          expect{ job.send(:process, order) }.to_not enqueue_job ConfirmOrderJob
+          expect{ job.send(:place_order, order) }.to_not enqueue_job ConfirmOrderJob
           expect(job).to have_received(:send_placement_email).with(order, anything).once
         end
 
@@ -198,7 +198,7 @@ describe SubscriptionPlacementJob do
           it "records an error and does not attempt to send an email" do
             expect(job).to_not receive(:send_placement_email)
             expect(job).to receive(:record_and_log_error).once
-            job.send(:process, order)
+            job.send(:place_order, order)
           end
         end
       end

spec/lib/open_food_network/subscription_summarizer_spec.rb

@@ -1,3 +1,4 @@
+require 'spec_helper'
 require 'open_food_network/subscription_summarizer'
 
 module OpenFoodNetwork
@@ -5,6 +6,8 @@ module OpenFoodNetwork
     let(:order) { create(:order) }
     let(:summarizer) { OpenFoodNetwork::SubscriptionSummarizer.new }
 
+    before { allow(Rails.logger).to receive(:info) }
+
     describe "#summary_for" do
       let(:order) { double(:order, distributor_id: 123) }
 
@@ -53,6 +56,7 @@ module OpenFoodNetwork
 
       describe "#record_issue" do
         it "requests a summary for the order and calls #record_issue on it" do
+          expect(order).to receive(:id)
           expect(summary).to receive(:record_issue).with(:type, order, "message").once
           summarizer.record_issue(:type, order, "message")
         end
@@ -69,7 +73,6 @@ module OpenFoodNetwork
           end
 
           it "sends error info to the rails logger and calls #record_issue on itself with an error message" do
-            expect(Rails.logger).to receive(:info)
             expect(summarizer).to receive(:record_issue).with(:processing, order, "Errors: Some error")
             summarizer.record_and_log_error(:processing, order)
           end
@@ -81,7 +84,6 @@ module OpenFoodNetwork
           end
 
           it "falls back to calling record_issue" do
-            expect(Rails.logger).to_not receive(:info)
             expect(summarizer).to receive(:record_issue).with(:processing, order)
             summarizer.record_and_log_error(:processing, order)
           end