Commit callbacks for the same AR model are not all executed

[agrobbin]

Steps to reproduce

If you are interacting with 2 instances of the same AR model in a transaction, Active Record only executes commit callbacks for the first instance of the model, not any others.

This is not a super-common real-world scenario, though I'm sure it does happen! For us, it has come up a few times in our system tests, when we have a controller action updating an AR model, then enqueuing a background job, which does further updates to that same model. With system tests executing background jobs inline, those 2 updates to the same AR model occur within the same transaction.

Here is a reproducible test case:

require "bundler/inline"

gemfile(true) do
  source "https://rubygems.org"

  git_source(:github) { |repo| "https://github.com/#{repo}.git" }

  # Activate the gem you are reporting the issue against.
  gem "activerecord", "6.0.3"
  gem "sqlite3"
end

require "active_record"
require "minitest/autorun"
require "logger"

# This connection will do for database-independent bug reports.
ActiveRecord::Base.establish_connection(adapter: "sqlite3", database: ":memory:")
ActiveRecord::Base.logger = Logger.new(STDOUT)

ActiveRecord::Schema.define do
  create_table :companies, force: true do |t|
    t.string :name, null: false
  end
end

$actual_after_commit_call_objects = []

class Company < ActiveRecord::Base
  after_commit { $actual_after_commit_call_objects << object_id }
end

class BugTest < ActiveSupport::TestCase
  include ActiveRecord::TestFixtures

  self.use_transactional_tests = true

  def test_commit_callbacks_for_identical_ar_model
    expected_after_commit_call_objects = []

    Company.transaction do
      Company.new(name: 'Test 1').tap do |company| # object A
        expected_after_commit_call_objects << company.object_id

        company.save!
      end

      Company.new(name: 'Test 2').tap do |company| # object B
        expected_after_commit_call_objects << company.object_id

        company.save!
      end

      Company.find_by!(name: 'Test 1').tap do |company| # object C
        expected_after_commit_call_objects << company.object_id

        company.update!(name: 'Test 1A')
      end
    end

    assert_equal expected_after_commit_call_objects, $actual_after_commit_call_objects
  end
end

I believe this is due to the internals of AR's commit callback management tracking the callbacks to be executed based on the AR model, which implements ==/eql? like this:

rails/activerecord/lib/active_record/core.rb

Lines 428 to 443 in 34991a6

	# Returns true if +comparison_object+ is the same exact object, or +comparison_object+
	# is of the same type and +self+ has an ID and it is equal to +comparison_object.id+.
	#
	# Note that new records are different from any other record by definition, unless the
	# other record is the receiver itself. Besides, if you fetch existing records with
	# +select+ and leave the ID out, you're on your own, this predicate will return false.
	#
	# Note also that destroying a record preserves its ID in the model instance, so deleted
	# models are still comparable.
	def ==(comparison_object)
	super ||
	comparison_object.instance_of?(self.class) &&
	!id.nil? &&
	comparison_object.id == id
	end
	alias :eql? :==

I'd love to fix this myself, but have been unable to track down the precise area in AR's transaction/callback internals.

Expected behavior

after_commit is called 3 times, once for each Company instance.

Actual behavior

after_commit is only called 2 times, for object A and B.

System configuration

Rails version: 6.0.3.1

Ruby version: 2.6.6

[evgeniy-r]

It seems that callbacks run at the end of

Company.transaction do
.................
end

block.

I added some puts statements before each save!/update! (also replaced after_commit block with puts) and got this test output:

Started

Before save A object_id is 87954160
Before save B object_id is 88282580
Before save C object_id is 88329780
AFTER COMMIT: Test 1 87954160
AFTER COMMIT: Test 2 88282580
Finished in 0.09801s

[evgeniy-r]

Therefore, I’m not sure that calling callbacks on all records would be appropriate.

[evgeniy-r]

In activerecord/lib/active_record/connection_adapters/abstract/transaction.rb there is the method commit_records:

      def commit_records
        ite = records.uniq(&:__id__)
        already_run_callbacks = {}
        while record = ite.shift
          if @run_commit_callbacks
            trigger_callbacks = record.trigger_transactional_callbacks?
            should_run_callbacks = !already_run_callbacks[record] && trigger_callbacks
            already_run_callbacks[record] ||= trigger_callbacks
            record.committed!(should_run_callbacks: should_run_callbacks)
          else
            # if not running callbacks, only adds the record to the parent transaction
            connection.add_transaction_record(record)
          end
        end
      ensure
        ite.each { |i| i.committed!(should_run_callbacks: false) }
      end

If we replace

            should_run_callbacks = !already_run_callbacks[record] && trigger_callbacks
            already_run_callbacks[record] ||= trigger_callbacks

with

            should_run_callbacks = !already_run_callbacks[record.object_id] && trigger_callbacks
            already_run_callbacks[record.object_id] ||= trigger_callbacks

we will get the desired behavior (we can also use __id__ instead of object_id).

Link to this file in rails repo:

rails/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb

Line 119 in 39de115

def commit_records

[evgeniy-r]

Test output (after suggested change):

Started

Before save A object_id is 85576140
Before save B object_id is 85755080
Before save C object_id is 85714040
AFTER COMMIT: Test 1 85576140
AFTER COMMIT: Test 2 85755080
AFTER COMMIT: Test 1A 85714040
Finished in 0.08800s

[evgeniy-r]

But, again, I'm not sure that this change should be commited.

[agrobbin]

@evgeniy-r ahh nice find! That definitely seems to be the right place, along with rollback_records just above it.

I do still think this is a bug, though. Just because the objects happen to be the same AR model type + ID, I don't think that means AR should be skipping the callbacks of all but the first occurrence of it in a transaction. That definitely feels a little surprising!

If the Rails Core team agrees, I'd be happy to issue a PR to fix {rollback,commit}_records!

[evgeniy-r]

I agree that we need the opinion of some member of the core team.

[kamipo]

I had found the same thing in #36190, and that is the reason to introduce already_run_callbacks to maintain the original behavior (committed! should be called for all records, but should be run commit callbacks only for the first one).

Practically the enrollment same records (but different object_id) in a transaction easily happens if manipulate an association records and save in callbacks (e.g. after_save). In that case, people had relied on the original behavior for a long time.

So if we will change the behavior, it is considered as a breaking change which will break existing apps.

[agrobbin]

That's some awesome context @kamipo, thanks! I've been experiencing it with Active Storage's after_commit callbacks (Attachment, has_one_attached and has_many_attached) not firing.

And totally agree, if we change the behavior, it should be considered a breaking change and potentially should be done behind a framework configuration that can be turned on by default in new apps while leaving existing apps with the current behavior.

[rails-bot]

This issue has been automatically marked as stale because it has not been commented on for at least three months.
The resources of the Rails team are limited, and so we are asking for your help.
If you can still reproduce this error on the 6-0-stable branch or on master, please reply with all of the information you have about it in order to keep the issue open.
Thank you for all your contributions.

[agrobbin]

I do still think this is a bug, but I haven't been able to circle back and make the appropriate change to AR. I will try and get back to it soon!

[rails-bot]

This issue has been automatically marked as stale because it has not been commented on for at least three months.
The resources of the Rails team are limited, and so we are asking for your help.
If you can still reproduce this error on the 6-0-stable branch or on master, please reply with all of the information you have about it in order to keep the issue open.
Thank you for all your contributions.

[kchasel]

I've just encountered this bug in Rails 6.1.4.7 – same issue! Only the first instance of a given record in a transaction block has the after_commit callbacks triggered on it. Definitely has led to some confusion on our end. I feel like this is not the behavior I would expect? I would assume that each instance of a record would have all of its lifecycle callbacks triggered as-needed every time (save, commit, etc.). Any updates here?

[wkirby]

@agrobbin this seems to still be popping up on Rails 7.1 — for us it's around active storage. A much simplified example of the issue:

class Post
  has_many :comments
end

class Comment
  has_one_attached :avatar
  has_one_attached :screenshot
end

Post.transaction do
  post.comments.each do |comment|
    comment.avatar.attach(avatar_file)
  end
  
  # some other code
  
  post.comments.each do |comment|
    comment.screenshot.attach(screenshot_file)
  end
end

Because we end up with different object ID references to the Comment in the above example, we get a really pernicious bug: the ActiveStorage::Attachment and ActiveStorage::Blob are created for both the avatar and screenshot — but the after-commit hook, responsible for uploading the file to the active storage service, is only called for the first one. This results in records in the database, but no file being persisted.

I see that a note was added to the active record callbacks guide in #49831, but seems like the same warning should be applied to active storage.

[agrobbin]

Ah yes, that definitely makes sense @wkirby! I can't be sure, but I'd imagine the Rails core team would accept a PR similar to #49831 that mentions the same behavior in the Active Storage guide.