has_many :through join model created twice in after_create in Rails 3.1.3 #3798

Closed
robmckinnon opened this Issue Nov 29, 2011 · 6 comments

Comments

Projects
None yet
7 participants
@robmckinnon

When new has_many :through join model created from after_create filter, the SQL to create join model is executed twice.

The correct behaviour is that it should be executed once.

This problem only occurs when join model created in an after_create filter. When created from a after_save filter, the SQL to create join model is executed only once, which is the correct behaviour.

class User < ActiveRecord::Base

  has_many :user_groups
  has_many :groups, :through => :user_groups

  after_create :assign_role

  def assign_role
    Rails.logger.info "User assign_role called with: #{group_name}"
    self.groups << Group.find_by_name(group_name)
    Rails.logger.info "Finished user assign_role called with: #{group_name}"
  end
end

For example, when new User created the SQL to create UserGroup is executed twice, when it should be executed once.

From the log:

(0.5ms) BEGIN

(0.6ms) SELECT 1 FROM "user" WHERE "user"."username" = 'u' LIMIT 1
SQL (0.7ms) INSERT INTO "user" ("algorithm", "created_at", "is_active", "is_super_admin", ...

User assign_role called with: Borrowers

Group Load (0.5ms) SELECT "group".* FROM "group" WHERE "group"."name" = 'Borrowers' LIMIT 1

User Load (0.8ms) SELECT "user".* FROM "user" WHERE "user"."id" = 10336 LIMIT 1

SQL (0.8ms) INSERT INTO "user_group" ("created_at", "group_id", "updated_at", "user_id") VALUES ($1, $2, $3, $4) RETURNING "user_id" [["created_at", Tue, 29 Nov 2011 11:44:57 UTC +00:00], ["group_id", 1], ["updated_at", Tue, 29 Nov 2011 11:44:57 UTC +00:00], ["user_id", 10336]]

Finished user assign_role called with: Borrowers

User Load (0.5ms) SELECT "user".* FROM "user" WHERE "user"."id" = 10336 LIMIT 1
SQL (0.9ms) INSERT INTO "user_group" ("created_at", "group_id", "updated_at", "user_id") VALUES ($1, $2, $3, $4) RETURNING "user_id" [["created_at", Tue, 29 Nov 2011 11:44:57 UTC +00:00], ["group_id", 1], ["updated_at", Tue, 29 Nov 2011 11:44:57 UTC +00:00], ["user_id", 10336]]

PGError: ERROR: duplicate key value violates unique constraint "user_group_pkey"

DETAIL: Key (user_id, group_id)=(10336, 1) already exists.

: INSERT INTO "user_group" ("created_at", "group_id", "updated_at", "user_id") VALUES ($1, $2, $3, $4) RETURNING "user_id"
(0.3ms) ROLLBACK

@ghost ghost assigned jonleighton Nov 29, 2011

@jonleighton

This comment has been minimized.

Show comment Hide comment
@jonleighton

jonleighton Dec 15, 2011

Member

I have tried to reproduce with this script:

require 'active_record'
require 'logger'

ActiveRecord::Base.establish_connection(adapter: 'sqlite3', database: ':memory:')

ActiveRecord::Schema.define do
  create_table :users do
  end

  create_table :user_groups do |t|
    t.integer :user_id
    t.integer :group_id
  end

  create_table :groups do
  end
end

class User < ActiveRecord::Base
  has_many :user_groups
  has_many :groups, :through => :user_groups

  after_create :assign_role

  def assign_role
    puts "start"
    self.groups << Group.first
    puts "finish"
  end
end

class UserGroup < ActiveRecord::Base
  belongs_to :user
  belongs_to :group
end

class Group < ActiveRecord::Base
end

ActiveRecord::Base.logger = Logger.new(STDERR)

Group.create
User.create

It doesn't show any problem on master or 3-1-stable:

$ bundle exec ruby ~/Desktop/bug3798.rb 
-- create_table(:users)
   -> 0.0063s
-- create_table(:user_groups)
   -> 0.0009s
-- create_table(:groups)
   -> 0.0006s
D, [2011-12-15T14:06:07.378011 #6175] DEBUG -- :   SQL (1.3ms)  INSERT INTO "groups" VALUES(NULL)
D, [2011-12-15T14:06:07.382452 #6175] DEBUG -- :   SQL (0.1ms)  INSERT INTO "users" VALUES(NULL)
start
D, [2011-12-15T14:06:07.426012 #6175] DEBUG -- :   Group Load (0.2ms)  SELECT "groups".* FROM "groups" LIMIT 1
D, [2011-12-15T14:06:07.470699 #6175] DEBUG -- :   SQL (8.0ms)  INSERT INTO "user_groups" ("group_id", "user_id") VALUES (?, ?)  [["group_id", 1], ["user_id", 1]]
finish

Please could you confirm if you still experience the problem? If you do, please modify the script such that it reproduces the bug. I'll close this for now but feel free to reopen if necessary.

Member

jonleighton commented Dec 15, 2011

I have tried to reproduce with this script:

require 'active_record'
require 'logger'

ActiveRecord::Base.establish_connection(adapter: 'sqlite3', database: ':memory:')

ActiveRecord::Schema.define do
  create_table :users do
  end

  create_table :user_groups do |t|
    t.integer :user_id
    t.integer :group_id
  end

  create_table :groups do
  end
end

class User < ActiveRecord::Base
  has_many :user_groups
  has_many :groups, :through => :user_groups

  after_create :assign_role

  def assign_role
    puts "start"
    self.groups << Group.first
    puts "finish"
  end
end

class UserGroup < ActiveRecord::Base
  belongs_to :user
  belongs_to :group
end

class Group < ActiveRecord::Base
end

ActiveRecord::Base.logger = Logger.new(STDERR)

Group.create
User.create

It doesn't show any problem on master or 3-1-stable:

$ bundle exec ruby ~/Desktop/bug3798.rb 
-- create_table(:users)
   -> 0.0063s
-- create_table(:user_groups)
   -> 0.0009s
-- create_table(:groups)
   -> 0.0006s
D, [2011-12-15T14:06:07.378011 #6175] DEBUG -- :   SQL (1.3ms)  INSERT INTO "groups" VALUES(NULL)
D, [2011-12-15T14:06:07.382452 #6175] DEBUG -- :   SQL (0.1ms)  INSERT INTO "users" VALUES(NULL)
start
D, [2011-12-15T14:06:07.426012 #6175] DEBUG -- :   Group Load (0.2ms)  SELECT "groups".* FROM "groups" LIMIT 1
D, [2011-12-15T14:06:07.470699 #6175] DEBUG -- :   SQL (8.0ms)  INSERT INTO "user_groups" ("group_id", "user_id") VALUES (?, ?)  [["group_id", 1], ["user_id", 1]]
finish

Please could you confirm if you still experience the problem? If you do, please modify the script such that it reproduces the bug. I'll close this for now but feel free to reopen if necessary.

@jacksmith117

This comment has been minimized.

Show comment Hide comment
@jacksmith117

jacksmith117 Sep 5, 2013

Hello, this issue is still alive, you were unable to reproduce it 'cause you placed after_create after "has_many" definition. If you place it before, it double-inserts (rails 4)

https://gist.github.com/daekrist/6447563

Hello, this issue is still alive, you were unable to reproduce it 'cause you placed after_create after "has_many" definition. If you place it before, it double-inserts (rails 4)

https://gist.github.com/daekrist/6447563

@jonahbron

This comment has been minimized.

Show comment Hide comment
@jonahbron

jonahbron Apr 25, 2014

👍 This is still a problem for me as well, Rails 4.1.0.beta1. I did as @daekrist suggested and placed it after the has_many definition, and it worked correctly after that.

👍 This is still a problem for me as well, Rails 4.1.0.beta1. I did as @daekrist suggested and placed it after the has_many definition, and it worked correctly after that.

@robin850

This comment has been minimized.

Show comment Hide comment
@robin850

robin850 Apr 28, 2014

Member

I can reproduce this as well with 4.0.4 and 4.1.0. I'm not comfortable with Active Record stuff but at least this seems a bit unexpected. I take the liberty to reopen this.

Member

robin850 commented Apr 28, 2014

I can reproduce this as well with 4.0.4 and 4.1.0. I'm not comfortable with Active Record stuff but at least this seems a bit unexpected. I take the liberty to reopen this.

@robin850 robin850 reopened this Apr 28, 2014

@robin850 robin850 modified the milestones: 4.0.6, 3.1.4 Apr 28, 2014

@sgrif sgrif assigned sgrif and unassigned jonleighton Jun 14, 2014

sgrif added a commit to sgrif/rails that referenced this issue Jun 14, 2014

Don't save through associations twice (4-0-stable)
If the through record gets created in an after_create hook that is
defined before the association is defined (therefore after its
after_create hook) get saved twice. This ensures that the through
records are created only once, regardless of the order of the hooks.

Backports the fix for #3798 to 4.1. Slightly more conservative on the
callback order since it's a patch version, and required an additional
special case for HABTM
@sgrif

This comment has been minimized.

Show comment Hide comment
@sgrif

sgrif Jun 14, 2014

Member

Reproduced, #15728 will fix this on master, and I have also backported to 4.0.x and 4.1.x.

Member

sgrif commented Jun 14, 2014

Reproduced, #15728 will fix this on master, and I have also backported to 4.0.x and 4.1.x.

@rafaelfranca

This comment has been minimized.

Show comment Hide comment
@rafaelfranca

rafaelfranca Sep 5, 2014

Member

I don't think this is an issue. Associations defines callbacks. Callback order is important since they are executed in the correct order. That said you should not place callbacks before the associations. This is even documented

Member

rafaelfranca commented Sep 5, 2014

I don't think this is an issue. Associations defines callbacks. Callback order is important since they are executed in the correct order. That said you should not place callbacks before the associations. This is even documented

rafaelfranca added a commit that referenced this issue Sep 5, 2014

Do not mark object as persisted after an association is saved
Callback order in Active Record objects are important. Users should not
define callbacks before the association definition or surprising
behaviours like the described at #3798 will happen. This callback order
dependency is documented at https://github.com/rails/rails/blob/31bfcdc77ca0d8cec9b5fe513bdc6f05814dd4f1/activerecord/lib/active_record/associations.rb#L1222-1227.

This reverts #15728.

Fixes #16620.

rafaelfranca added a commit that referenced this issue Sep 5, 2014

Do not mark object as persisted after an association is saved
Callback order in Active Record objects are important. Users should not
define callbacks before the association definition or surprising
behaviours like the described at #3798 will happen. This callback order
dependency is documented at https://github.com/rails/rails/blob/31bfcdc77ca0d8cec9b5fe513bdc6f05814dd4f1/activerecord/lib/active_record/associations.rb#L1222-1227.

This reverts #15728.

Fixes #16620.

Conflicts:
	activerecord/test/cases/associations/has_many_associations_test.rb

rafaelfranca added a commit that referenced this issue Sep 5, 2014

Do not mark object as persisted after an association is saved
Callback order in Active Record objects are important. Users should not
define callbacks before the association definition or surprising
behaviours like the described at #3798 will happen. This callback order
dependency is documented at https://github.com/rails/rails/blob/31bfcdc77ca0d8cec9b5fe513bdc6f05814dd4f1/activerecord/lib/active_record/associations.rb#L1222-1227.

This reverts #15728.

Fixes #16620.

Conflicts:
	activerecord/test/cases/associations/has_many_associations_test.rb

rafaelfranca added a commit that referenced this issue Sep 8, 2014

Do not mark object as persisted after an association is saved
Callback order in Active Record objects are important. Users should not
define callbacks before the association definition or surprising
behaviours like the described at #3798 will happen. This callback order
dependency is documented at https://github.com/rails/rails/blob/31bfcdc77ca0d8cec9b5fe513bdc6f05814dd4f1/activerecord/lib/active_record/associations.rb#L1222-1227.

This reverts #15728.

Fixes #16620.

Conflicts:
	activerecord/lib/active_record/autosave_association.rb
	activerecord/test/cases/associations/has_many_associations_test.rb

rafaelfranca added a commit that referenced this issue Sep 8, 2014

Do not mark object as persisted after an association is saved
Callback order in Active Record objects are important. Users should not
define callbacks before the association definition or surprising
behaviours like the described at #3798 will happen. This callback order
dependency is documented at https://github.com/rails/rails/blob/31bfcdc77ca0d8cec9b5fe513bdc6f05814dd4f1/activerecord/lib/active_record/associations.rb#L1222-1227.

This reverts #15728.

Fixes #16620.

Conflicts:
	activerecord/lib/active_record/autosave_association.rb
	activerecord/test/cases/associations/has_many_associations_test.rb

trungpham added a commit to trungpham/rails that referenced this issue Sep 18, 2014

Do not mark object as persisted after an association is saved
Callback order in Active Record objects are important. Users should not
define callbacks before the association definition or surprising
behaviours like the described at #3798 will happen. This callback order
dependency is documented at https://github.com/rails/rails/blob/31bfcdc77ca0d8cec9b5fe513bdc6f05814dd4f1/activerecord/lib/active_record/associations.rb#L1222-1227.

This reverts #15728.

Fixes #16620.

sachin004 added a commit to sachin004/rails that referenced this issue Dec 13, 2014

Do not mark object as persisted after an association is saved
Callback order in Active Record objects are important. Users should not
define callbacks before the association definition or surprising
behaviours like the described at #3798 will happen. This callback order
dependency is documented at https://github.com/rails/rails/blob/31bfcdc77ca0d8cec9b5fe513bdc6f05814dd4f1/activerecord/lib/active_record/associations.rb#L1222-1227.

This reverts #15728.

Fixes #16620.

tarasmatsyk added a commit to tarasmatsyk/rails that referenced this issue Dec 30, 2015

Fixes the issue of creating record twice
If the issue was registered in after_create callback, a record will be created twice.
For more information see issues #17599 and #3798
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment