Autosaving associations twice in Rails 6.0.3 violates uniqueness

[geoffharcourt]

Steps to reproduce

This behavior is new as of Rails 6.0.3.

If you updated a just-created record with a has_many through association where the join table has a uniqueness constraint on the two foreign keys the associations get saved twice, resulting in a uniqueness violation:

class Team < ApplicationRecord
  has_many :memberships
  has_many :players, through: :memberships
end

class Player < ApplicationRecord
  has_many :memberships
  has_many :teams, through: :memberships
end

class Membership < ApplicationRecord
  # memberships has a unique index on player_id and team_id
  belongs_to :player
  belongs_to :team 
end

player = Player.create!(teams: team])
player.update!(updated_at: Time.current)

Expected behavior

In Rails 6.0.2.2, this would save a new Player and a Membership linking the Player to the Team successfully. The subsequent update would be successful.

Actual behavior

An ActiveRecord::RecordNotUnique exception is raised when a second Membership is written at the time of the #update!.

I think the issue is related to this change: #39124. This can be worked around, but it's an unexpected change from prior behavior in Rails.

System configuration

Rails version: 6.0.3

Ruby version: 6.0.2.2

[rafaelfranca]

@eugeneius can you take a look?

[eugeneius]

I couldn't reproduce the issue:

# frozen_string_literal: true

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 :memberships, force: true do |t|
    t.integer :player_id
    t.integer :team_id
    t.index [:player_id, :team_id], unique: true
  end

  create_table :players, force: true do |t|
    t.timestamps
  end

  create_table :teams, force: true do |t|
  end
end

class Team < ActiveRecord::Base
  has_many :memberships
  has_many :players, through: :memberships
end

class Player < ActiveRecord::Base
  has_many :memberships
  has_many :teams, through: :memberships
end

class Membership < ActiveRecord::Base
  belongs_to :player
  belongs_to :team 
end

class BugTest < Minitest::Test
  def test_association_stuff
    team = Team.create!
    player = Player.create!(teams: [team])
    player.update!(updated_at: Time.current)
  end
end

@geoffharcourt could you try to modify the script above to demonstrate your problem? It looks like there's something going on that isn't captured in the bug report. Thanks!

[adipasquale]

hi! I'm also getting a new error with 6.0.3 in one of my specs. It's very similar to this case, the record won't save because of a postgres uniqueviolation error:

       PG::UniqueViolation: ERROR:  duplicate key value violates unique constraint "index_organisations_users_on_organisation_id_and_user_id"
       DETAIL:  Key (organisation_id, user_id)=(1, 2) already exists.

I double checked, in my case it's the initial save (not a second one like @geoffharcourt) that causes this error. The record that I'm trying to save looks good, and there is no duplicate entry in the join table right before the save.

[adipasquale]

I've tried reproducing with your script by switching to pg, and using something close to my case (setting team_ids instead of teams) but it still does not reproduce :/ I'll let you know if I manage to reproduce.

[geoffharcourt]

Hi @eugeneius I'm looking now. We're using Postgres, not sqlite, in case that's relevant. The test script from your snippet didn't have a uniqueness constraint on the join table.

[geoffharcourt]

I'm having trouble reproducing this in a simple test case. I'm working to figure out what other factors from our application beyond Postgres are different from the test script.

[geoffharcourt]

OK, I figured out what causes this. If you have a callback such as after_create that re-saves the record (we do this because we have some attributes that are built from the record's ID), the uniqueness constraint is violated when the callback calls #save!.

[adipasquale]

yes @geoffharcourt I'm also narrowing it down to after_create callbacks but haven't yet managed to reproduce in a short example.
I'm using HATBM relations in my case, are you too?
here's my current script, unfortunately not reproducing yet:

# frozen_string_literal: true

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 "pg"
end

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

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

ActiveRecord::Schema.define do
  create_table :players_teams, id: false, force: true do |t|
    t.integer :player_id
    t.integer :team_id
    t.index [:player_id, :team_id], unique: true
  end

  create_table :players, force: true do |t|
    t.timestamps
    t.string :name
  end

  create_table :teams, force: true do |t|
  end
end

class Team < ActiveRecord::Base
  has_and_belongs_to_many :players, -> { distinct }
end

class Player < ActiveRecord::Base
  after_create :resave
  has_and_belongs_to_many :teams, -> { distinct }

  def resave
    self.name = 'test'
    save!
  end
end


class BugTest < Minitest::Test
  def test_association_stuff
    team = Team.create!
    p1 = Player.new(team_ids: [team.id])
    p1.save
    p2 = Player.new(team_ids: [team.id])
    p2.save
  end
end

[geoffharcourt]

I'm unfortunately terrible at minitest and had trouble doing this in an inline script. I created an app with rails new and made the minimum number of changes to get here (join table/model with uniqueness constraint, after_create callback that re-saves one of the models).

https://github.com/geoffharcourt/rails_6_0_3_uniqueness

Here's the most relevant commit:
geoffharcourt/rails_6_0_3_uniqueness@4b47016

[adipasquale]

great @geoffharcourt 👍 it reproduces very well. I was able to reproduce after setting up the app by running this in the console:

team = Team.create!
Player.new(team_ids: [team.id]).save

so it does not seem linked to HABTM relations, and for some reason it does not reproduce in the very contained ruby script @eugeneius . Do you have any suggestion on what could differ when running a full-blown rails app?

[yosiat]

hi @adipasquale !

I am seeing the same issue in my rails app, when upgrading to rails 6.0.3, If I do an extra save! in after_create I will get the same record being written twice.
But If I change the after_create to be after_commit on create it will solve the issue for me.

Wrote reproduction script with failing test on rails 6.0.3 but passing on 6.0.2:

# frozen_string_literal: true

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 :users, force: true do |t|
  end

  create_table :posts, force: true do |t|
    t.timestamp :last_post_creation_time
  end

  create_join_table :posts, :users
end

class User < ActiveRecord::Base
  has_and_belongs_to_many :posts
end

class Post < ActiveRecord::Base
  has_and_belongs_to_many :users

  after_create :post_process

  def post_process
    self.last_post_creation_time = Time.now
    self.save!
  end
end

class BugTest < Minitest::Test
  def test_association_stuff
    user = User.create!

    post = Post.create(
      users: [user]
    )

    user.reload
    post.reload

    assert_equal [user.id], dbs.users.ids
    assert_equal [post.id], user.posts.ids
  end
end

[eugeneius]

Thanks for the reproduction steps! Both bisect to #38166. I'll take a closer look later this evening.

[maxvlc]

hi! I'm also getting a this error with 6.0.3 in one of my rspecs with rspec.

 # --- Caused by: ---
 # PG::UniqueViolation:
#   ERROR:  llave duplicada viola restricción de unicidad «index_cocinas_productos_on_cocina_id_and_producto_id»
#   DETAIL:  Ya existe la llave (cocina_id, producto_id)=(9, 1).

Are you saying that with after_commit could fix the error?

Thanks in advance

[yosiat]

@maxvlc for my application, changing to after_commit on: :create fixed the issue.
You can try this on your app, it might work for you use case.

[maxvlc]

Thanks @yosiat I'll wait for a new Rails version with the bug fixed.

[jules2689]

This is being caused by a documented limitation of the Rails system. On associations, there exist 2 callbacks in ActiveRecord for associations:

rails/activerecord/lib/active_record/autosave_association.rb

Lines 367 to 373 in 0571da9

	def before_save_collection_association
	@new_record_before_save ||= new_record?
	end
	def after_save_collection_association
	@new_record_before_save = false
	end

What this means is that before_save we tell ActiveRecord that we are a new record (this means we should create the association), and in the after_save we reset that to false.

after_create happens before after_save, so we aren't set to false yet by after_save_collection_association. By defining a method that updates the model with callbacks (e.g. update, save, save!, etc) you are invoking the callbacks with @new_record_before_save set to true still. This will save the record twice.

This is why @yosiat had luck using after_commit because that happens after after_save.

There is a warning in the ActiveRecord documentation that states:

Care should be taken in callbacks to avoid updating attributes. For example, avoid running update(attribute: "value") and similar code (like saves) during callbacks. This can alter the state of the model and may result in unexpected side effects during commit. Instead, you should try to assign values in the before_create or earlier callbacks.

While this probably shouldn't cause issues, it is still not advisable to run methods with callbacks in callbacks.

In the bug report here (#39173 (comment)), the after_create should be changed to a before_save or before_validation to be something like self.last_post_creation_time = Time.now and let the normal save callbacks work (bonus is a saved SQL query!)

Unfortunately undoing some recent changes re-introduces a different bug of a similar nature that causes children records to not be saved if added to an unsaved parent that is subsequently saved (e.g. comment = Comment.create!; post = Post.new(comments: [comment]); post.save; # comment does not have "post_id" assigned).

I'll leave the ultimate decision of which bug is worse up to the Rails team, but this could be fixed with this diff, which would re-introduce the bug that introduced this one 🙃

index 96a3effcf9..84274bef8a 100644
--- a/activerecord/lib/active_record/autosave_association.rb
+++ b/activerecord/lib/active_record/autosave_association.rb
@@ -365,7 +365,7 @@ def normalize_reflection_attribute(indexed_attribute, reflection, index, attribu
       # Is used as a before_save callback to check while saving a collection
       # association whether or not the parent was a new record before saving.
       def before_save_collection_association
-        @new_record_before_save ||= new_record?
+        @new_record_before_save = new_record?
       end
 
       def after_save_collection_association

[jules2689]

Thinking this through a bit more, I think we would ideally be able to handle all of these edge cases but since the autosave and callback system relies on instance variables on the model instance, we're probably going to end up playing a long winded game of whack of mole for all eternity as these callbacks can logically collide with one another in many ways (since they work on the instance variables on the same instance and assume some level of isolation).

Therefore, I'd propose:

1. Revert the bug fix I originally submitted
2. Change it to a warning:

index 96a3effcf9..56f32f91bb 100644
--- a/activerecord/lib/active_record/autosave_association.rb
+++ b/activerecord/lib/active_record/autosave_association.rb
@@ -365,7 +365,10 @@ def normalize_reflection_attribute(indexed_attribute, reflection, index, attribu
       # Is used as a before_save callback to check while saving a collection
       # association whether or not the parent was a new record before saving.
       def before_save_collection_association
-        @new_record_before_save ||= new_record?
+        if defined?(@new_record_before_save)
+          logger.warn "Calling a method that emits callbacks in a callback is not supported. Please blah blah change blah blah ... doc link"
+        end
+        @new_record_before_save = new_record?
       end

3. Keep the warning in the ActiveRecord docs
4. In Rails 6.1, change it to a raise ActiveRecord::NestedCallback error (or similar)

This will make sure that we help people remove problemsome code (nested callbacks) while giving them time to act on the warnings.

[doits]

👍 not breaking existing apps on a minor update but giving a warning instead, so users can fix it until 6.1, is the best approach imo.

[jules2689]

One thing to note is that having callbacks in callbacks may subtly break expectations in other ways and is contrary to documented active record limitations (that is getting improved wording in #39433).

I'd highly recommend everyone work to remove these callbacks now for the 6.0.3 update regardless of it it's a warning or explicit exception as you may not know what's up if you have callbacks in callbacks.

[danielricecodes]

I think this is an issue is Rails 5.2.4.3 as well. I just updated an older app from 5.2.3 to 5.2.4.3 and my tests are throwing this exact same error.

Failure/Error: resource.addresses << FactoryBot.create_list(:address, 3, user_id: resource.user_id)
     
     ActiveRecord::RecordNotUnique:
       PG::UniqueViolation: ERROR:  duplicate key value violates unique constraint "service_request_addresses_unique_idx"
       DETAIL:  Key (service_request_id, address_id)=(1, 1) already exists.
       : INSERT INTO "service_request_addresses" ("service_request_id", "address_id", "position") VALUES ($1, $2, $3) RETURNING "id"
     # ./spec/factories/service_requests.rb:83:in `block (4 levels) in <top (required)>'

When I set my Gemfile back to rails 5.2.3, the tests all pass 100%.

[hashwin]

Any update on this? There were security updates bundled into 6.0.3.1 that I can't update to because of this issue. Any chance of pushing forward @jules2689 proposition?

I understand that we should be trying to remove nested callbacks, but when dealing with large apps, it is very difficult to track them all down. I have tried deploying the update a couple of times, every time running into this problem in a subtly new scenario.

We really shouldn't have to be playing games with our apps' existing functionality and security so I humbly request that this be pushed out with urgency.

[mdworken]

Hi all - bumping the request here. Since 'callbacks within callbacks' is part of the public API (even if it's heavily discouraged) it's really frustrating that this occurred during a patch update. Are there are any updates on when this might be fixed? Like @hashwin mentions above, having to choose between security compliance and existing functionality is not a fun place to suddenly be.

[eugeneius]

I believe #39771 fixes the problem reported here. @geoffharcourt (or anyone else affected): would you mind testing it against your application? https://github.com/eugeneius/rails/tree/6_0_stable_autosave_exactly_once is a branch containing that commit on top of 6-0-stable, in case that makes it easier.

@danielricecodes: #38166 wasn't backported to Rails 5.2, so I don't think you're seeing the same problem as the other reports here, despite the similar-looking error. Rails 5.2 is no longer supported for bug fixes, but if you can reproduce your problem in a sample application or an executable test case that uses the 6-0-stable or master branch, please do open a new issue.

[hashwin]

@eugeneius can confirm that branch works for my test cases 👍

[geoffharcourt]

Hi @eugeneius I haven't been at a computer in a day, but I should be able to test this later today. Thank you for your work to help resolve!

[danielricecodes]

@danielricecodes: #38166 wasn't backported to Rails 5.2 ...

Thanks @eugeneius. It sounds like I must upgrade my 5.2 app to 6.0+latest patch after the branch mentioned in this Issue is formally merged and has made it into a 6.0 patch release.

[geoffharcourt]

@eugeneius I confirmed that your fix resolves the issue for us where it fails in 6.0.3.

[doits]

I can confirm #39771 fixes it for me, too.

[adeeb1]

Hello, I'm experiencing this issue after upgrading to Rails 6.1.0-alpha. Has this fix been reverted?

[eugeneius]

No, the fix is still present on the master branch. Please open a new issue with an executable test case.