From 75aa16e4e2879003b4aee3268ea8a6782eed2e4a Mon Sep 17 00:00:00 2001 From: "Sure Admin (bot)" Date: Sun, 16 Aug 2026 00:36:43 +0200 Subject: [PATCH] Log async rule run failures to debug log (#3045) * Log async rule run failures to debug log * Propagate auto-categorize provider failures --- app/jobs/auto_categorize_job.rb | 9 ++- app/models/family/auto_categorizer.rb | 3 +- app/models/rule_run.rb | 48 ++++++++++-- test/jobs/auto_categorize_job_test.rb | 84 ++++++++++++++++++++ test/models/family/auto_categorizer_test.rb | 16 +++- test/models/rule_run_test.rb | 85 +++++++++++++++++++++ 6 files changed, 233 insertions(+), 12 deletions(-) create mode 100644 test/jobs/auto_categorize_job_test.rb create mode 100644 test/models/rule_run_test.rb diff --git a/app/jobs/auto_categorize_job.rb b/app/jobs/auto_categorize_job.rb index f168351bd..5f82ff955 100644 --- a/app/jobs/auto_categorize_job.rb +++ b/app/jobs/auto_categorize_job.rb @@ -2,12 +2,13 @@ class AutoCategorizeJob < ApplicationJob queue_as :medium_priority def perform(family, transaction_ids: [], rule_run_id: nil) + rule_run = RuleRun.find_by(id: rule_run_id) if rule_run_id.present? modified_count = family.auto_categorize_transactions(transaction_ids) # If this job was part of a rule run, report back the modified count - if rule_run_id.present? - rule_run = RuleRun.find_by(id: rule_run_id) - rule_run&.complete_job!(modified_count: modified_count) - end + rule_run&.complete_job!(modified_count: modified_count) + rescue => e + rule_run&.fail_job!(error: e, source: self.class.name, transaction_ids: transaction_ids) + raise end end diff --git a/app/models/family/auto_categorizer.rb b/app/models/family/auto_categorizer.rb index de56e18d5..fb7d15aa7 100644 --- a/app/models/family/auto_categorizer.rb +++ b/app/models/family/auto_categorizer.rb @@ -30,8 +30,7 @@ class Family::AutoCategorizer ) unless result.success? - Rails.logger.error("Failed to auto-categorize transactions for family #{family.id}: #{result.error.message}") - return 0 + raise Error, "Failed to auto-categorize transactions: #{result.error.message}" end modified_count = 0 diff --git a/app/models/rule_run.rb b/app/models/rule_run.rb index 3028de44a..935b790e8 100644 --- a/app/models/rule_run.rb +++ b/app/models/rule_run.rb @@ -34,13 +34,51 @@ class RuleRun < ApplicationRecord # Thread-safe method to complete a job and update the run def complete_job!(modified_count: 0) with_lock do - increment!(:transactions_modified, modified_count) - decrement!(:pending_jobs_count) + self.transactions_modified += modified_count + self.pending_jobs_count = [ pending_jobs_count - 1, 0 ].max # If all jobs are done, mark as success - if pending_jobs_count <= 0 - update!(status: "success") - end + self.status = "success" if pending_jobs_count <= 0 && !failed? + + save! end end + + def fail_job!(error:, source:, transaction_ids: []) + should_log = false + + with_lock do + should_log = !failed? + + self.pending_jobs_count = [ pending_jobs_count - 1, 0 ].max + self.status = "failed" + self.error_message = "#{error.class}: #{error.message}" + + save! + end + + capture_failure_debug_log(error:, source:, transaction_ids:) if should_log + end + + private + def capture_failure_debug_log(error:, source:, transaction_ids:) + DebugLogEntry.capture( + category: "rule_run", + level: "error", + message: "Rule run failed: #{error.class}: #{error.message}", + source: source, + family: rule.family, + metadata: { + rule_run_id: id, + rule_id: rule_id, + rule_name: rule_name, + execution_type: execution_type, + error_class: error.class.name, + error_message: error.message, + transaction_count: transaction_ids.size, + transaction_ids: transaction_ids, + backtrace: Array(error.backtrace).first(10) + } + ) + end end diff --git a/test/jobs/auto_categorize_job_test.rb b/test/jobs/auto_categorize_job_test.rb new file mode 100644 index 000000000..573339503 --- /dev/null +++ b/test/jobs/auto_categorize_job_test.rb @@ -0,0 +1,84 @@ +require "test_helper" + +class AutoCategorizeJobTest < ActiveJob::TestCase + include EntriesTestHelper, ProviderTestHelper + + setup do + @family = families(:empty) + @account = @family.accounts.create!(name: "Rule test", balance: 100, currency: "USD", accountable: Depository.new) + @family.categories.create!(name: "Food") + @rule = @family.rules.create!( + name: "AI category rule", + resource_type: "transaction", + effective_date: 1.year.ago.to_date, + conditions: [ + Rule::Condition.new(condition_type: "transaction_name", operator: "like", value: "coffee") + ], + actions: [ + Rule::Action.new(action_type: "auto_categorize") + ] + ) + @rule_run = @rule.rule_runs.create!( + rule_name: @rule.name, + execution_type: "manual", + status: "pending", + transactions_queued: 20, + transactions_processed: 20, + transactions_modified: 0, + pending_jobs_count: 1, + executed_at: Time.current + ) + end + + test "records rule run failure debug log before reraising categorization errors" do + error = RuntimeError.new("Fixed prompt tokens exceed context budget") + transaction_ids = [ SecureRandom.uuid ] + + @family.stubs(:auto_categorize_transactions).with(transaction_ids).raises(error) + + assert_difference "DebugLogEntry.count", 1 do + assert_raises(RuntimeError) do + AutoCategorizeJob.perform_now(@family, transaction_ids: transaction_ids, rule_run_id: @rule_run.id) + end + end + + @rule_run.reload + assert_equal "failed", @rule_run.status + assert_equal "RuntimeError: Fixed prompt tokens exceed context budget", @rule_run.error_message + assert_equal 0, @rule_run.pending_jobs_count + + entry = DebugLogEntry.order(:created_at).last + assert_equal "rule_run", entry.category + assert_equal "error", entry.level + assert_equal "AutoCategorizeJob", entry.source + assert_equal @family, entry.family + assert_equal @rule_run.id, entry.metadata["rule_run_id"] + assert_equal transaction_ids, entry.metadata["transaction_ids"] + end + + test "records unsuccessful provider responses as rule run failures" do + transaction = create_transaction(account: @account, name: "Coffee shop").transaction + provider = mock + provider_error = Provider::Error.new("Fixed prompt tokens exceed context budget") + + Provider::Registry.stubs(:preferred_llm_provider).returns(provider) + provider.expects(:auto_categorize).returns(provider_error_response(provider_error)) + + assert_difference "DebugLogEntry.count", 1 do + assert_raises(Family::AutoCategorizer::Error) do + AutoCategorizeJob.perform_now(@family, transaction_ids: [ transaction.id ], rule_run_id: @rule_run.id) + end + end + + @rule_run.reload + assert_equal "failed", @rule_run.status + assert_equal "Family::AutoCategorizer::Error: Failed to auto-categorize transactions: Fixed prompt tokens exceed context budget", @rule_run.error_message + assert_equal 0, @rule_run.pending_jobs_count + + entry = DebugLogEntry.order(:created_at).last + assert_equal "rule_run", entry.category + assert_equal "Family::AutoCategorizer::Error", entry.metadata["error_class"] + assert_equal "Failed to auto-categorize transactions: Fixed prompt tokens exceed context budget", entry.metadata["error_message"] + assert_equal [ transaction.id ], entry.metadata["transaction_ids"] + end +end diff --git a/test/models/family/auto_categorizer_test.rb b/test/models/family/auto_categorizer_test.rb index 296ac8e93..4c83feb76 100644 --- a/test/models/family/auto_categorizer_test.rb +++ b/test/models/family/auto_categorizer_test.rb @@ -7,7 +7,7 @@ class Family::AutoCategorizerTest < ActiveSupport::TestCase @family = families(:dylan_family) @account = @family.accounts.create!(name: "Rule test", balance: 100, currency: "USD", accountable: Depository.new) @llm_provider = mock - Provider::Registry.stubs(:get_provider).with(:openai).returns(@llm_provider) + Provider::Registry.stubs(:preferred_llm_provider).returns(@llm_provider) end test "auto-categorizes transactions" do @@ -38,6 +38,20 @@ class Family::AutoCategorizerTest < ActiveSupport::TestCase assert_equal 1, @account.transactions.reload.enrichable(:category_id).count end + test "raises when provider returns an unsuccessful response" do + txn = create_transaction(account: @account, name: "Coffee shop").transaction + @family.categories.create!(name: "Coffee") + + @llm_provider.expects(:auto_categorize) + .returns(provider_error_response(Provider::Error.new("Fixed prompt tokens exceed context budget"))) + + error = assert_raises(Family::AutoCategorizer::Error) do + Family::AutoCategorizer.new(@family, transaction_ids: [ txn.id ]).auto_categorize + end + + assert_equal "Failed to auto-categorize transactions: Fixed prompt tokens exceed context budget", error.message + end + private AutoCategorization = Provider::LlmConcept::AutoCategorization end diff --git a/test/models/rule_run_test.rb b/test/models/rule_run_test.rb new file mode 100644 index 000000000..fd0fb8e5a --- /dev/null +++ b/test/models/rule_run_test.rb @@ -0,0 +1,85 @@ +require "test_helper" + +class RuleRunTest < ActiveSupport::TestCase + setup do + @family = families(:empty) + @rule = @family.rules.create!( + name: "AI category rule", + resource_type: "transaction", + effective_date: 1.year.ago.to_date, + conditions: [ + Rule::Condition.new(condition_type: "transaction_name", operator: "like", value: "coffee") + ], + actions: [ + Rule::Action.new(action_type: "auto_categorize") + ] + ) + end + + test "fail_job marks run failed and captures debug log entry" do + rule_run = create_rule_run(pending_jobs_count: 2) + error = RuntimeError.new("Fixed prompt tokens exceed context budget") + transaction_id = SecureRandom.uuid + + assert_difference "DebugLogEntry.count", 1 do + rule_run.fail_job!(error: error, source: "AutoCategorizeJob", transaction_ids: [ transaction_id ]) + end + + rule_run.reload + assert_equal "failed", rule_run.status + assert_equal "RuntimeError: Fixed prompt tokens exceed context budget", rule_run.error_message + assert_equal 1, rule_run.pending_jobs_count + + entry = DebugLogEntry.order(:created_at).last + assert_equal "rule_run", entry.category + assert_equal "error", entry.level + assert_equal "AutoCategorizeJob", entry.source + assert_equal @family, entry.family + assert_equal rule_run.id, entry.metadata["rule_run_id"] + assert_equal @rule.id, entry.metadata["rule_id"] + assert_equal @rule.name, entry.metadata["rule_name"] + assert_equal "RuntimeError", entry.metadata["error_class"] + assert_equal "Fixed prompt tokens exceed context budget", entry.metadata["error_message"] + assert_equal 1, entry.metadata["transaction_count"] + assert_equal [ transaction_id ], entry.metadata["transaction_ids"] + end + + test "fail_job is retry-safe for pending count and debug logging" do + rule_run = create_rule_run(pending_jobs_count: 1) + error = RuntimeError.new("retrying same failed batch") + + assert_difference "DebugLogEntry.count", 1 do + rule_run.fail_job!(error: error, source: "AutoCategorizeJob") + rule_run.fail_job!(error: error, source: "AutoCategorizeJob") + end + + rule_run.reload + assert_equal "failed", rule_run.status + assert_equal 0, rule_run.pending_jobs_count + end + + test "complete_job does not overwrite failed status" do + rule_run = create_rule_run(status: "failed", pending_jobs_count: 0) + + rule_run.complete_job!(modified_count: 3) + + rule_run.reload + assert_equal "failed", rule_run.status + assert_equal 0, rule_run.pending_jobs_count + assert_equal 3, rule_run.transactions_modified + end + + private + def create_rule_run(status: "pending", pending_jobs_count: 1) + @rule.rule_runs.create!( + rule_name: @rule.name, + execution_type: "manual", + status: status, + transactions_queued: 20, + transactions_processed: 20, + transactions_modified: 0, + pending_jobs_count: pending_jobs_count, + executed_at: Time.current + ) + end +end