From 9627a6bf6fb69e5f54df5ab24c6b67596f6666ed Mon Sep 17 00:00:00 2001 From: Zach Gollwitzer Date: Wed, 5 Mar 2025 15:38:31 -0500 Subject: [PATCH] Add tagged logging to sync process (#1956) * Add tagged logging to sync process * Reduce logging in syncer * Typo --- app/models/account/balance_calculator.rb | 15 +++++---- app/models/account/holding_calculator.rb | 11 +++++-- app/models/account/syncer.rb | 39 ++++++++++++++++-------- app/models/plaid_item.rb | 20 ++++++++++-- app/models/sync.rb | 33 ++++++++++++-------- config/environments/production.rb | 7 +++-- 6 files changed, 86 insertions(+), 39 deletions(-) diff --git a/app/models/account/balance_calculator.rb b/app/models/account/balance_calculator.rb index d5b3b3d1..ca292dc5 100644 --- a/app/models/account/balance_calculator.rb +++ b/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 diff --git a/app/models/account/holding_calculator.rb b/app/models/account/holding_calculator.rb index c9327daa..edb55acf 100644 --- a/app/models/account/holding_calculator.rb +++ b/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 diff --git a/app/models/account/syncer.rb b/app/models/account/syncer.rb index cd664e66..d664b8f1 100644 --- a/app/models/account/syncer.rb +++ b/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? diff --git a/app/models/plaid_item.rb b/app/models/plaid_item.rb index 1a49675b..c76af8aa 100644 --- a/app/models/plaid_item.rb +++ b/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 } diff --git a/app/models/sync.rb b/app/models/sync.rb index 65e474d7..64446cdd 100644 --- a/app/models/sync.rb +++ b/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 diff --git a/config/environments/production.rb b/config/environments/production.rb index fba29091..4670492d 100644 --- a/config/environments/production.rb +++ b/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 ]