after_create callback not working as it should

I moved to sqlite3 for easy testing and added a simple backtrace for all queries. My results are attached.

My modified testapp2, for anyone who wants it.

are there no rails team members interested in looking at this? i think this issue is due to a bug in the callback routines somewhere (at least in 2.2.2)..

fyi, just checked, the bug still exists in 2.3.2, and it only appears if you use the after_create callback, (using the after_save callback works as expected).

Can you provide us with a failing test in the activerecord test suite rather than a stand alone app? That'd make it much easier to reproduce and verify

This is not a bug. You're getting two Linkage records added to the database because when you create a Foo model with an associated Bar model Rails creates the join model for you. Your after_create explicitly creates a second, unnecessary, join model, so you end up with two.

Automatically creating an association between a newly created Foo and Bar.last makes no sense. Trying creating a Foo model with no bars in the database. You'll find you code creates a join model to nothing, which is clearly incorrect.

In short, delete your after_create callback method and everything will work as expected.

After a little more investigation I take back my previous comment. Something very odd is happening here.

Glad others are seeing the strange behavior here as well :)

Michael, I think I've found where to add to the AR test suite to show the same behavior as my example app, but I'm not totally sure where to put the test, how to submit a patch to the test suite, or how best to run one particular test from the suite. If you've got tips on that, it would save me a bunch of time trying to look things up :) I am including inline here what test needs to be added and how I expect to recreate the failing behavior:

In my example app I have:
-- Foo has_many :linkages -- Foo has_many :bars, :through => :linkages, :source => :thing, :source_type => 'Bar' -- Bar has_many :linkages, :as => :thing -- Linkage belongs_to :foo -- Linkage belongs_to :thing, :polymorphic => true

The equivalent setup in the AR test suite seems to be:
-- Tag has_many :taggings -- Tag has_many :tagged_posts, :through => :taggings, :source => :taggable, :source_type => 'Post' -- Post has_many :taggings, :as => :taggable -- Tagging belongs_to :tag -- Tagging belongs_to :taggables, :polymorphic => true

SO, to repeat my test we would need to:

(1) ADD the following to the "Tag" model:

after_create :link_tag_to_last_post
def link_tag_to_last_post
  if p = Post.last
    Tagging.create!(:tag => self, :taggable => p)
  end
end

(2) Add a test where we: (a) create a post; (b) create a tag; (c) see how many new taggable items are created via the callback

If this mimics my test app, you'll see that two taggable items are created via the after_create callback instead of just one.

Sounds good, can you attach that as a diff (assuming it's failing
:)). If it doesn't fail then we have a whole other problem :)

[Apologies for the delayed reply]

I duplicated the failing case from my test app in the AR test suite and it didn't fail!
The AR test suite setup has a lot of extra complexities that I've stripped out in my super-simple test app, so it's a bit hard to know exactly which of those complexities is making the difference.

I'm not sure what the best way is to create a diff file, as I've never used one, but here are the very simple changes to the AR test suite that produce a non-failing test case that I expected to fail:

INSERT THIS AT END OF test/model/tag.rb

after_create :link_tag_to_last_post

def link_tag_to_last_post

if p = Post.last
  Tagging.create!(:tag => self, :taggable => p)
end
puts "\ntagged_posts count: #{tagged_posts.count}\n"

end

INSERT THIS AT END OF test/cases/associations/has_many_through_associations_test.rb

def test_after_create_callback_that_creates_a_link_between_two_objects_that_have_a_polymorphic_has_many_through_association

author = authors(:mary)
post = Post.create!(:author => author, :title => "TITLE", :body => "BODY")
tag = Tag.create!
assert_equal tag.taggings.length, 1

end

An additional piece of information that might help narrow down what's going on here:

In my test app, if I return 'false' from my callback, a duplicate association is not created
If I return something that evaluates to true, a duplicate association is created

I've tried recreating those conditions in the AR test suite, but without success.

+1 This ticket is still valid in 2.3.2 and returning false as the last argument doesn't duplicate the record in the db, as barunio points out.

This many to many relations does create two records. However, the test suite, as barunio says, doesn't test a model specifically for after_create callbacks at all in activerecord/test/models/*.rb, let alone a simple polymorphic relationship and a many to many relationship. (or that i can find).

When you use after_save :blah, in the same way you would after_create, which is executed after an after_create call according to the comments in callbacks.rb, This test case does not duplicate, so everything is fine.

Are we using after_create wrong here? is this why it would duplicate?

I'm not sure, but it doesn't appear that any of these callbacks are tested against a polymorphic relationship in the test suite.

Also: This snippet of commentary from Active record intrigues me too... is count an indexer? is that what is meant?

  # ---  From Active Record -----
  # After Create Is called after <tt>Base.save</tt> on new objects that haven't been saved yet (no record exists).
  # Note that this callback is still wrapped in the transaction around +save+. For example, if you
  # invoke an external indexer at this point it won't see the changes in the database.

+1 verified that this occurs and that I'm not able to reproduce in the active record test suite.

-1 I added the after_create callback and test barurio suggested on August 4th, 2009 @ 03:42 AM and tests passed.

I don't think this is a bug.

Didn't he say that the test would pass, but incorrectly: it produces "a non-failing test case that I expected to fail"? That's a strange way to do things, though, if that's what he meant. Shouldn't a bug make a test fail?

Also the code he suggested produced print debugging information in the test output, which is his style, but I doubt is the preferred method in general.

Dan, I think you might have misunderstood what I wrote in my earlier notes (some were a bit confusing), as Rebecca pointed out. To clarify:

I have not been able to reproduce the error in the ActiveRecord test suite. My attempt to do so (via the code that I described in my first comment on Aug 4) did not work.

But, this doesn't imply that there isn't a bug -- only that it isn't obvious to me how to reproduce it in the AR test suite. I haven't had any time to familiarize myself further with the test suite and augment the models in it to the point where I can reproduce the bug.

But my test app is trivially simple, and since there's nothing there that seems like it should cause the duplicate-record-creation behavior, I'm leaning strongly toward thinking this is an AR bug.

Also, re: Rebecca's point about the puts statement -- I included the print debugging in example code only because when I first opened this ticket I noticed that whether or not I included the puts statement affected whether or not the bug occurred. This didn't make any sense to me until my most recent comment (on Aug 4) when I realized that the puts statement was just affecting the return value of the callback method and that's why the duplicate-error-creation was being affected. So you should be able to get rid of the puts statement, but in order to reproduce the bug the callback will need to return something that evaluates to true.

I am totally mixed up, test SHOULD or SHOULDN'T be expected pass with the patch?

Elad -- I have been unable to duplicate the conditions leading to this bug using the AR test suite. To see the failure, see the very small test app at start of the thread.

The patch is an unsuccessful attempt to duplicate the bug in the AR test suite -- so, one might expect the test in the patch to fail but it does not; which perhaps isn't very helpful but at least it might narrow down some possible sources of the problem.

(btw, thanks for making the patch, Rebecca)

so.. did the bugmash result in any better understanding of this issue?

There were a few red herrings in the earlier messages. The root of the problem seems to be that in the after_create callback in the Foo model there is a call to "bars.count". This somehow triggers an internal ActiveRecord callback, to a method named (in Rails 2.3.5) "autosave_associated_records_for_bars", which creates the second Linkage object.

I've included an updated version of the test app that demonstrates this, and sets the rails environment to 2.3.5.

I re-tested this as well. As barunio pointed out, the bug only occurs when calling "bars.count" and then you must also return true from the callback. (Returning false will halt the internal callback where the bug occurs.)

The internal callback which creates the second Linkage model is part of the autosave_association library - the "save_collection_association" method. By creating the Linkage and then calling "bars.count", it seems that the Bar object gets added to the association, and is then returned by "associated_records_to_validate_or_save".

You can see the queries going through the autosave_association library in the query backtraces (attached).

Hopefully someone who is intimately familiar (or wrote) the autosave_association code will be able to help.

[bulk edit]

@Grant I am not able to reproduce it in rails master. This is what I did.

ActiveRecord::Schema.define(:version => 20100717210126) do

  create_table "bars", :force => true do |t|
    t.string   "name"
    t.datetime "created_at"
    t.datetime "updated_at"
  end

  create_table "foos", :force => true do |t|
    t.string   "name"
    t.datetime "created_at"
    t.datetime "updated_at"
  end

  create_table "linkages", :force => true do |t|
    t.integer  "foo_id"
    t.integer  "thing_id"
    t.string   "thing_type"
    t.datetime "created_at"
    t.datetime "updated_at"
  end

end
class Bar < ActiveRecord::Base
  has_many :linkages, :as => :thing
end
class Foo < ActiveRecord::Base
  after_create  :blah
  has_many  :linkages
  has_many  :bars, :through => :linkages, :source => :thing, :source_type => 'Bar'

  def blah
    b = Bar.last
    Linkage.create!(:foo => self, :thing => b)
    bars.count
  end

  def self.lab
    Foo.delete_all
    Linkage.delete_all
    Bar.delete_all
    Foo.create
    puts Foo.count
    puts Linkage.count
  end

end

class Linkage < ActiveRecord::Base

  belongs_to :foo
  belongs_to :thing, :polymorphic => true

end

ree-1.8.7-2010.01 > Foo.lab
  SQL (1.4ms)  DELETE FROM "foos" WHERE 1=1
  SQL (0.7ms)  DELETE FROM "linkages" WHERE 1=1
  SQL (2.4ms)  DELETE FROM "bars" WHERE 1=1
  SQL (0.5ms)  INSERT INTO "foos" ("created_at", "name", "updated_at") VALUES ('2010-07-17 21:12:05.125673', NULL, '2010-07-17 21:12:05.125673')
  Bar Load (0.2ms)  SELECT "bars".* FROM "bars" ORDER BY bars.id DESC LIMIT 1
  SQL (0.1ms)  INSERT INTO "linkages" ("created_at", "foo_id", "thing_id", "thing_type", "updated_at") VALUES ('2010-07-17 21:12:05.160847', 1, NULL, NULL, '2010-07-17 21:12:05.160847')
  SQL (0.1ms)  SELECT COUNT(*) AS count_id FROM "bars" INNER JOIN "linkages" ON "bars".id = "linkages".thing_id AND "linkages".thing_type = 'Bar' WHERE (("linkages".foo_id = 1))
  Bar Load (0.1ms)  SELECT "bars".* FROM "bars" INNER JOIN "linkages" ON "bars".id = "linkages".thing_id AND "linkages".thing_type = 'Bar' WHERE (("linkages".foo_id = 1))
  SQL (0.2ms)  SELECT COUNT(*) AS count_id FROM "foos"
1
  SQL (0.2ms)  SELECT COUNT(*) AS count_id FROM "linkages"
1
 => nil

As you can see the count of number of records in Linkage is 1.

@Neeraj, Your test will pass because you are not creating any Bars.

You should see the bug present itself if you change your self.lab function to this:

  def self.lab
    Foo.delete_all
    Linkage.delete_all
    Bar.delete_all
    Bar.create
    Foo.create
    puts Foo.count
    puts Linkage.count
  end

This bug is a real head scratcher. I added a test case to ActiveRecord that follows the exact same formula to replicate the bug, and yet, it works perfectly. Basically I just changed the names of things:

Foo -> Author
Bar -> Etch
Linkage -> Scribbling

Neeraj (or someone else), can you apply my patch and figure out why my test is passing? I can't figure out what the difference is between a contrived rails app that DOES demonstrate the bug, and an ActiveRecord test case that does NOT. It's very odd!

The patch is for rails master.

Grant, I would reference my post about bars.count causing the issue (it invokes the autosave association code). You are calling self.etches which I'm guessing does not have the same effect - try self.etches.count.

@jdance, All you need to do is call self.etches or self.bars to replicate the bug. Adding count is unnecessary.

I dig deep into the code and this is what I found. First how to recreate the problem.

class Linkage < ActiveRecord::Base
  belongs_to :foo
  belongs_to :bar
end

class Bar < ActiveRecord::Base
  has_many :linkages
end

class Foo < ActiveRecord::Base

  after_create  :doit

  has_many  :linkages

  has_many  :bars, :through => :linkages

  def doit
    Linkage.create!(:foo => self, :bar => Bar.last)
    bars.count
  end

  def self.lab
    Foo.delete_all
    Linkage.delete_all
    Bar.delete_all
    puts Foo.count     #=> 0
    puts Linkage.count #=> 0

    Bar.create
    Foo.create
    puts Foo.count     #=> 1
    puts Linkage.count #=> 2
  end

end

Notice that the output of Linkage.count is 2.

ActiveRecord set ups autosave callback for every has_many association. In this case after doit is executed, ActiveRecord goes through the has_many callback for linkage. There is nothing to be done. Then ActiveRecord goes through the has_many callbacks for bars. In this case in the association is blank initially. So AR creates an instance of the association. Since method doit invokes bars.count the result of association = association_instance_get(reflection.name) is an association that has one bar record. Now as part of the has_many callbacks in autosave following condition is evaluated.

autosave != false && (@new_record_before_save || record.new_record?)

that condition turns out to be true because of @new_record_before_save . And then following method is invoked

association.send(:insert_record, record)

Above method gets invoked on HasManyThroughAssociation class and the end result is that another record gets inserted in the linkage table.

The fix is to move doit callback at the end so that has_many callbacks happen before doit is called. Here is the fixed version

class Linkage < ActiveRecord::Base
  belongs_to :foo
  belongs_to :bar
end

class Bar < ActiveRecord::Base
  has_many :linkages
end

class Foo < ActiveRecord::Base

  has_many  :linkages

  has_many  :bars, :through => :linkages

  after_create  :doit

  def doit
    Linkage.create!(:foo => self, :bar => Bar.last)
    bars.count
  end

  def self.lab
    Foo.delete_all
    Linkage.delete_all
    Bar.delete_all
    puts Foo.count     #=> 0
    puts Linkage.count #=> 0

    Bar.create
    Foo.create
    puts Foo.count     #=> 1
    puts Linkage.count #=> 1
  end

end

After looking at the code for a while I could not find any decent way to fix this problem without changing the callbacks order. Callbacks order matter in other cases too for example #4386 .

Automatic cleanup of spam.