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

@@ -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

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

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

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

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

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