Add tagged logging to sync process (#1956)

* Add tagged logging to sync process

* Reduce logging in syncer

* Typo

app/models/account/balance_calculator.rb

@@ -5,13 +5,16 @@ class Account::BalanceCalculator
   end
 
   def calculate(reverse: false, start_date: nil)
-    cash_balances = reverse ? reverse_cash_balances : forward_cash_balances
+    Rails.logger.tagged("Account::BalanceCalculator") do
+      Rails.logger.info("Calculating cash balances with strategy: #{reverse ? "reverse sync" : "forward sync"}")
+      cash_balances = reverse ? reverse_cash_balances : forward_cash_balances
 
-    cash_balances.map do |balance|
-      holdings_value = converted_holdings.select { |h| h.date == balance.date }.sum(&:amount)
-      balance.balance = balance.balance + holdings_value
-      balance
-    end.compact
+      cash_balances.map do |balance|
+        holdings_value = converted_holdings.select { |h| h.date == balance.date }.sum(&:amount)
+        balance.balance = balance.balance + holdings_value
+        balance
+      end.compact
+    end
   end
 
   private

app/models/account/holding_calculator.rb

@@ -5,9 +5,14 @@ class Account::HoldingCalculator
   end
 
   def calculate(reverse: false)
-    preload_securities
-    calculated_holdings = reverse ? reverse_holdings : forward_holdings
-    gapfill_holdings(calculated_holdings)
+    Rails.logger.tagged("Account::HoldingCalculator") do
+      preload_securities
+
+      Rails.logger.info("Calculating holdings with strategy: #{reverse ? "reverse sync" : "forward sync"}")
+      calculated_holdings = reverse ? reverse_holdings : forward_holdings
+
+      gapfill_holdings(calculated_holdings)
+    end
   end
 
   private

app/models/account/syncer.rb

@@ -5,19 +5,34 @@ class Account::Syncer
   end
 
   def run
-    account.family.auto_match_transfers!
+    Rails.logger.tagged("Account::Syncer") do
+      Rails.logger.info("Finding potential transfers to auto-match")
+      account.family.auto_match_transfers!
 
-    holdings = sync_holdings
-    balances = sync_balances(holdings)
-    account.reload
-    update_account_info(balances, holdings) unless plaid_sync?
-    convert_records_to_family_currency(balances, holdings) unless account.currency == account.family.currency
+      holdings = sync_holdings
+      Rails.logger.info("Calculated #{holdings.size} holdings")
 
-    # Enrich if user opted in or if we're syncing transactions from a Plaid account on the hosted app
-    if account.family.data_enrichment_enabled? || (plaid_sync? && Rails.application.config.app_mode.hosted?)
-      account.enrich_data
-    else
-      Rails.logger.info("Data enrichment is disabled, skipping enrichment for account #{account.id}")
+      balances = sync_balances(holdings)
+      Rails.logger.info("Calculated #{balances.size} balances")
+
+      account.reload
+
+      unless plaid_sync?
+        update_account_info(balances, holdings)
+      end
+
+      unless account.currency == account.family.currency
+        Rails.logger.info("Converting #{balances.size} balances and #{holdings.size} holdings from #{account.currency} to #{account.family.currency}")
+        convert_records_to_family_currency(balances, holdings)
+      end
+
+      # Enrich if user opted in or if we're syncing transactions from a Plaid account on the hosted app
+      if account.family.data_enrichment_enabled? || (plaid_sync? && Rails.application.config.app_mode.hosted?)
+        Rails.logger.info("Enriching transaction data for account #{account.name}")
+        account.enrich_data
+      else
+        Rails.logger.info("Data enrichment disabled for account #{account.name}")
+      end
     end
   end
 
@@ -43,8 +58,6 @@ class Account::Syncer
       calculator = Account::HoldingCalculator.new(account)
       calculated_holdings = calculator.calculate(reverse: plaid_sync?)
 
-      current_time = Time.now
-
       Account.transaction do
         load_holdings(calculated_holdings)
         purge_outdated_holdings unless plaid_sync?

app/models/plaid_item.rb

@@ -41,8 +41,11 @@ class PlaidItem < ApplicationRecord
     update!(last_synced_at: Time.current)
 
     begin
+      Rails.logger.info("Fetching and loading Plaid data")
       plaid_data = fetch_and_load_plaid_data
       update!(status: :good) if requires_update?
+
+      Rails.logger.info("Plaid data fetched and loaded")
       plaid_data
     rescue Plaid::ApiError => e
       handle_plaid_error(e)
@@ -83,12 +86,17 @@ class PlaidItem < ApplicationRecord
   private
     def fetch_and_load_plaid_data
       data = {}
+
+      # Log what we're about to fetch
+      Rails.logger.info "Starting Plaid data fetch (accounts, transactions, investments, liabilities)"
+
       item = plaid_provider.get_item(access_token).item
       update!(available_products: item.available_products, billed_products: item.billed_products)
 
-      # Fetch and store institution details
+      # Institution details
       if item.institution_id.present?
         begin
+          Rails.logger.info "Fetching Plaid institution details for #{item.institution_id}"
           institution = plaid_provider.get_institution(item.institution_id)
           update!(
             institution_id: item.institution_id,
@@ -96,12 +104,14 @@ class PlaidItem < ApplicationRecord
             institution_color: institution.institution.primary_color
           )
         rescue Plaid::ApiError => e
-          Rails.logger.warn("Error fetching institution details for item #{id}: #{e.message}")
+          Rails.logger.warn "Failed to fetch Plaid institution details: #{e.message}"
         end
       end
 
+      # Accounts
       fetched_accounts = plaid_provider.get_item_accounts(self).accounts
       data[:accounts] = fetched_accounts || []
+      Rails.logger.info "Processing Plaid accounts (count: #{fetched_accounts.size})"
 
       internal_plaid_accounts = fetched_accounts.map do |account|
         internal_plaid_account = plaid_accounts.find_or_create_from_plaid_data!(account, family)
@@ -109,10 +119,12 @@ class PlaidItem < ApplicationRecord
         internal_plaid_account
       end
 
+      # Transactions
       fetched_transactions = safe_fetch_plaid_data(:get_item_transactions)
       data[:transactions] = fetched_transactions || []
 
       if fetched_transactions
+        Rails.logger.info "Processing Plaid transactions (added: #{fetched_transactions.added.size}, modified: #{fetched_transactions.modified.size}, removed: #{fetched_transactions.removed.size})"
         transaction do
           internal_plaid_accounts.each do |internal_plaid_account|
             added = fetched_transactions.added.select { |t| t.account_id == internal_plaid_account.plaid_id }
@@ -126,10 +138,12 @@ class PlaidItem < ApplicationRecord
         end
       end
 
+      # Investments
       fetched_investments = safe_fetch_plaid_data(:get_item_investments)
       data[:investments] = fetched_investments || []
 
       if fetched_investments
+        Rails.logger.info "Processing Plaid investments (transactions: #{fetched_investments.transactions.size}, holdings: #{fetched_investments.holdings.size}, securities: #{fetched_investments.securities.size})"
         transaction do
           internal_plaid_accounts.each do |internal_plaid_account|
             transactions = fetched_investments.transactions.select { |t| t.account_id == internal_plaid_account.plaid_id }
@@ -141,10 +155,12 @@ class PlaidItem < ApplicationRecord
         end
       end
 
+      # Liabilities
       fetched_liabilities = safe_fetch_plaid_data(:get_item_liabilities)
       data[:liabilities] = fetched_liabilities || []
 
       if fetched_liabilities
+        Rails.logger.info "Processing Plaid liabilities (credit: #{fetched_liabilities.credit&.size || 0}, mortgage: #{fetched_liabilities.mortgage&.size || 0}, student: #{fetched_liabilities.student&.size || 0})"
         transaction do
           internal_plaid_accounts.each do |internal_plaid_account|
             credit = fetched_liabilities.credit&.find { |l| l.account_id == internal_plaid_account.plaid_id }

app/models/sync.rb

@@ -6,38 +6,47 @@ class Sync < ApplicationRecord
   scope :ordered, -> { order(created_at: :desc) }
 
   def perform
-    start!
+    Rails.logger.tagged("Sync", id, syncable_type, syncable_id) do
+      start!
 
-    begin
-      data = syncable.sync_data(start_date: start_date)
-      update!(data: data) if data
-      complete!
-    rescue StandardError => error
-      fail! error
-      raise error if Rails.env.development?
-    ensure
-      syncable.post_sync
+      begin
+        data = syncable.sync_data(start_date: start_date)
+        update!(data: data) if data
+        complete!
+      rescue StandardError => error
+        fail! error
+        raise error if Rails.env.development?
+      ensure
+        Rails.logger.info("Sync completed, starting post-sync")
+
+        syncable.post_sync
+
+        Rails.logger.info("Post-sync completed")
+      end
     end
   end
 
   private
     def start!
+      Rails.logger.info("Starting sync")
       update! status: :syncing
     end
 
     def complete!
+      Rails.logger.info("Sync completed")
       update! status: :completed, last_ran_at: Time.current
     end
 
     def fail!(error)
+      Rails.logger.error("Sync failed: #{error.message}")
+
       Sentry.capture_exception(error) do |scope|
-        scope.set_context("sync", { id: id })
+        scope.set_context("sync", { id: id, syncable_type: syncable_type, syncable_id: syncable_id })
       end
 
       update!(
         status: :failed,
         error: error.message,
-        error_backtrace: error.backtrace&.first(10),
         last_ran_at: Time.current
       )
     end

config/environments/production.rb

@@ -49,17 +49,18 @@ Rails.application.configure do
   config.assume_ssl = ActiveModel::Type::Boolean.new.cast(ENV.fetch("RAILS_ASSUME_SSL", true))
 
   # Log to Logtail if API key is present, otherwise log to STDOUT
-  config.logger = if ENV["LOGTAIL_API_KEY"].present?
+  base_logger = if ENV["LOGTAIL_API_KEY"].present?
     Logtail::Logger.create_default_logger(
       ENV["LOGTAIL_API_KEY"],
       telemetry_host: "in.logs.betterstack.com"
     )
   else
     ActiveSupport::Logger.new(STDOUT)
-      .tap  { |logger| logger.formatter = ::Logger::Formatter.new }
-      .then { |logger| ActiveSupport::TaggedLogging.new(logger) }
+      .tap { |logger| logger.formatter = ::Logger::Formatter.new }
   end
 
+  config.logger = ActiveSupport::TaggedLogging.new(base_logger)
+
   # Prepend all log lines with the following tags.
   config.log_tags = [ :request_id ]