Tweak exception logging, sync stale behavior

app/models/concerns/syncable.rb

@@ -11,17 +11,18 @@ module Syncable
 
   def sync_later(parent_sync: nil, window_start_date: nil, window_end_date: nil)
     Sync.transaction do
-      # Expire any previous in-flight syncs for this record that exceeded the
-      # global staleness window.
-      syncs.stale_candidates.find_each(&:mark_stale!)
+      # Since we're scheduling a new sync, mark old syncs for this syncable as stale
+      self.syncs.incomplete.find_each(&:mark_stale!)
 
-      new_sync = syncs.create!(
+      new_sync = self.syncs.create!(
         parent: parent_sync,
         window_start_date: window_start_date,
         window_end_date: window_end_date
       )
 
       SyncJob.perform_later(new_sync)
+
+      new_sync
     end
   end
 

app/models/provider/synth.rb

@@ -71,9 +71,11 @@ class Provider::Synth < Provider
         rate = rate.dig("rates", to)
 
         if date.nil? || rate.nil?
-          message = "#{self.class.name} returned invalid rate data for pair from: #{from} to: #{to} on: #{date}.  Rate data: #{rate.inspect}"
-          Rails.logger.warn(message)
-          Sentry.capture_exception(InvalidExchangeRateError.new(message), level: :warning)
+          Rails.logger.warn("#{self.class.name} returned invalid rate data for pair from: #{from} to: #{to} on: #{date}.  Rate data: #{rate.inspect}")
+          Sentry.capture_exception(InvalidExchangeRateError.new("#{self.class.name} returned invalid rate data"), level: :warning) do |scope|
+            scope.set_context("rate", { from: from, to: to, date: date })
+          end
+
           next
         end
 
@@ -162,9 +164,11 @@ class Provider::Synth < Provider
         price = price.dig("close") || price.dig("open")
 
         if date.nil? || price.nil?
-          message = "#{self.class.name} returned invalid price data for security #{symbol} on: #{date}.  Price data: #{price.inspect}"
-          Rails.logger.warn(message)
-          Sentry.capture_exception(InvalidSecurityPriceError.new(message), level: :warning)
+          Rails.logger.warn("#{self.class.name} returned invalid price data for security #{symbol} on: #{date}.  Price data: #{price.inspect}")
+          Sentry.capture_exception(InvalidSecurityPriceError.new("#{self.class.name} returned invalid security price data"), level: :warning) do |scope|
+            scope.set_context("security", { symbol: symbol, date: date })
+          end
+
           next
         end
 

app/models/security/price/importer.rb

@@ -26,9 +26,16 @@ class Security::Price::Importer
     prev_price_value = start_price_value
 
     unless prev_price_value.present?
-      error = MissingStartPriceError.new("Could not find a start price for #{security.ticker} on or before #{start_date}")
-      Rails.logger.error(error.message)
-      Sentry.capture_exception(error)
+      Rails.logger.error("Could not find a start price for #{security.ticker} on or before #{start_date}")
+
+      Sentry.capture_exception(MissingStartPriceError.new("Could not determine start price for ticker")) do |scope|
+        scope.set_tags(security_id: security.id)
+        scope.set_context("security", {
+          id: security.id,
+          start_date: start_date
+        })
+      end
+
       return 0
     end
 
@@ -75,9 +82,12 @@ class Security::Price::Importer
         if response.success?
           response.data.index_by(&:date)
         else
-          msg = "#{security_provider.class.name} could not fetch prices for #{security.ticker} between #{provider_fetch_start_date} and #{end_date}. Provider error: #{response.error.message}"
-          Rails.logger.warn(msg)
-          Sentry.capture_exception(MissingSecurityPriceError.new(msg), level: :warning)
+          Rails.logger.warn("#{security_provider.class.name} could not fetch prices for #{security.ticker} between #{provider_fetch_start_date} and #{end_date}. Provider error: #{response.error.message}")
+          Sentry.capture_exception(MissingSecurityPriceError.new("Could not fetch prices for ticker"), level: :warning) do |scope|
+            scope.set_tags(security_id: security.id)
+            scope.set_context("security", { id: security.id, start_date: start_date, end_date: end_date })
+          end
+
           {}
         end
       end

app/models/sync.rb

@@ -1,7 +1,7 @@
 class Sync < ApplicationRecord
-  # We run a cron that marks any syncs that have been running > 2 hours as "stale"
+  # We run a cron that marks any syncs that have not been resolved in 24 hours as "stale"
   # Syncs often become stale when new code is deployed and the worker restarts
-  STALE_AFTER = 2.hours
+  STALE_AFTER = 24.hours
 
   # The max time that a sync will show in the UI (after 5 minutes)
   VISIBLE_FOR = 5.minutes
@@ -19,9 +19,6 @@ class Sync < ApplicationRecord
   scope :incomplete, -> { where("syncs.status IN (?)", %w[pending syncing]) }
   scope :visible, -> { incomplete.where("syncs.created_at > ?", VISIBLE_FOR.ago) }
 
-  # In-flight records that have exceeded the allowed runtime
-  scope :stale_candidates, -> { incomplete.where("syncs.created_at < ?", STALE_AFTER.ago) }
-
   validate :window_valid
 
   # Sync state machine
@@ -54,7 +51,7 @@ class Sync < ApplicationRecord
 
   class << self
     def clean
-      stale_candidates.find_each(&:mark_stale!)
+      incomplete.where("syncs.created_at < ?", STALE_AFTER.ago).find_each(&:mark_stale!)
     end
   end
 

test/interfaces/syncable_interface_test.rb

@@ -17,4 +17,12 @@ module SyncableInterfaceTest
     @syncable.class.any_instance.expects(:perform_sync).with(mock_sync).once
     @syncable.perform_sync(mock_sync)
   end
+
+  test "any prior syncs for the same syncable entity are marked stale when new sync is requested" do
+    stale_sync = @syncable.sync_later
+    new_sync = @syncable.sync_later
+
+    assert_equal "stale", stale_sync.reload.status
+    assert_equal "pending", new_sync.reload.status
+  end
 end

test/models/sync_test.rb

@@ -172,15 +172,15 @@ class SyncTest < ActiveSupport::TestCase
     stale_pending = Sync.create!(
       syncable: accounts(:depository),
       status: :pending,
-      created_at: 3.hours.ago
+      created_at: 25.hours.ago
     )
 
     stale_syncing = Sync.create!(
       syncable: accounts(:depository),
       status: :syncing,
-      created_at: 3.hours.ago,
-      pending_at: 3.hours.ago,
-      syncing_at: 2.hours.ago
+      created_at: 25.hours.ago,
+      pending_at: 24.hours.ago,
+      syncing_at: 23.hours.ago
     )
 
     Sync.clean