This project is archived and is in readonly mode.

#2765 ✓wontfix
barunio

after_create callback not working as it should

Reported by barunio | June 5th, 2009 @ 03:55 AM | in 3.x

I'm seeing some really weird behavior when dealing with an after_create callback in the case of polymorphic associations. I've created a really trivial application that is as bare-bones as possible while still demonstrating the issue.

The example app is attached; to recreate the issue just run a "rake db:reset" and go into the console (there are no views or controllers).

There are three models: Foo, Bar, and Linkage. To see the issue, just run:

>> Bar.create
>> Foo.create

The Foo model has_many Bars via a polymorphic relationship through Linkages. The Foo model has an after_create callback that will automatically create a Linkage record with (Bar.last). The problem is that it in fact creates two Linkage records.

The weirder thing is that I can eliminate this bug if I either (a) name my callback method 'after_create' instead of naming it 'blah' and using 'after_create :blah' OR (b) remove a 'puts' statement from the end of the method.

I'm running Rails 2.2.2 and no plugins

Comments and changes to this ticket

  • Jonathan Dance

    Jonathan Dance June 5th, 2009 @ 09:36 PM

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

  • Jonathan Dance

    Jonathan Dance June 5th, 2009 @ 09:37 PM

    My modified testapp2, for anyone who wants it.

  • barunio

    barunio June 10th, 2009 @ 08:17 PM

    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)..

  • barunio

    barunio June 10th, 2009 @ 08:30 PM

    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).

  • Michael Koziarski

    Michael Koziarski July 4th, 2009 @ 02:20 AM

    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

  • Adam Milligan

    Adam Milligan July 4th, 2009 @ 07:47 PM

    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.

  • Adam Milligan

    Adam Milligan July 4th, 2009 @ 09:16 PM

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

  • barunio

    barunio July 5th, 2009 @ 05:21 PM

    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.

  • Michael Koziarski

    Michael Koziarski July 6th, 2009 @ 10:06 AM

    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 :)

  • barunio

    barunio August 4th, 2009 @ 03:42 AM

    [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

  • barunio

    barunio August 4th, 2009 @ 04:09 AM

    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.

  • Michael Koziarski

    Michael Koziarski August 5th, 2009 @ 06:44 AM

    • Tag changed from 2.2.2, after_create, callback, polymorphic to 2.2.2, after_create, bugmash, callback, polymorphic
  • pjammer

    pjammer August 8th, 2009 @ 05:50 PM

    +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.
    
  • Dan Pickett

    Dan Pickett August 8th, 2009 @ 08:36 PM

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

  • Dan Croak

    Dan Croak August 10th, 2009 @ 03:20 AM

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

  • Rebecca Frankel

    Rebecca Frankel August 10th, 2009 @ 04:21 AM

    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.

  • Rebecca Frankel

    Rebecca Frankel August 10th, 2009 @ 04:26 AM

    • Tag changed from 2.2.2, after_create, bugmash, callback, polymorphic to 2.2.3, after_create, bugmash, callback, polymorphic

    For discussion purposes, here is a patch of the code barunio suggested, minus the print statement. I used 'git format-patch 2-3-stable --stdout > barunio-2765.diff' to make it, which I hope was the right thing (the directions said to do it against master, but aren't we trying to fix 2-3-stable right now?)

    As Dan Croak said, after adding the code he suggested the tests passed for me, but I think he meant them to, if I read what he said correctly.

  • barunio

    barunio August 10th, 2009 @ 04:57 AM

    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.

  • Elad Meidar

    Elad Meidar August 10th, 2009 @ 04:57 AM

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

  • barunio

    barunio August 10th, 2009 @ 05:16 AM

    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)

  • barunio

    barunio August 23rd, 2009 @ 06:34 PM

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

  • Rizwan Reza

    Rizwan Reza January 20th, 2010 @ 11:43 AM

    • Tag changed from 2.2.3, after_create, bugmash, callback, polymorphic to 2.2.3, after_create, callback, polymorphic

    Is this still an issue?

  • barunio

    barunio January 25th, 2010 @ 12:15 AM

    • Tag changed from 2.2.3, after_create, callback, polymorphic to 2.2.3, 2.3.5, after_create, callback, polymorphic

    Yes, I can confirm that this is still happening as of Rails 2.3.5

  • Rizwan Reza

    Rizwan Reza January 25th, 2010 @ 12:51 AM

    • Tag changed from 2.2.3, 2.3.5, after_create, callback, polymorphic to 2.3.5, after_create, bug, callback, polymorphic
    • Milestone changed from 2.x to 2.3.6
  • barunio

    barunio January 25th, 2010 @ 01:33 AM

    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.

  • Jonathan Dance

    Jonathan Dance January 25th, 2010 @ 01:45 AM

    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.

  • Rizwan Reza

    Rizwan Reza May 16th, 2010 @ 02:30 AM

    • Tag changed from 2.3.5, after_create, bug, callback, polymorphic to 2.3.5, after_create, bug, bugmash, callback, polymorphic
  • Rizwan Reza
  • Jeremy Kemper

    Jeremy Kemper May 23rd, 2010 @ 05:54 PM

    • Milestone changed from 2.3.6 to 2.3.7
  • Jeremy Kemper

    Jeremy Kemper May 24th, 2010 @ 09:40 AM

    • Milestone changed from 2.3.7 to 2.3.8
  • Jeremy Kemper

    Jeremy Kemper May 25th, 2010 @ 11:45 PM

    • Milestone changed from 2.3.8 to 2.3.9
  • Grant Ammons

    Grant Ammons July 17th, 2010 @ 06:31 PM

    • Importance changed from “” to “Medium”

    This issue also exists in rails master.

  • Neeraj Singh

    Neeraj Singh July 17th, 2010 @ 10:16 PM

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

  • Grant Ammons

    Grant Ammons July 18th, 2010 @ 04:46 PM

    @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
    
  • Neeraj Singh

    Neeraj Singh July 18th, 2010 @ 09:27 PM

    • Milestone changed from 2.3.9 to 3.x
    • State changed from “new” to “open”
    • Tag changed from 2.3.5, after_create, bug, bugmash, callback, polymorphic to rails 3, after_create, bug, bugmash, callback, polymorphic

    @Grant thanks. I am able to reproduce the problem in rails master. I will look into this issue.

  • Grant Ammons

    Grant Ammons July 28th, 2010 @ 09:13 PM

    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.

  • Neeraj Singh

    Neeraj Singh July 28th, 2010 @ 09:18 PM

    • Assigned user set to “Neeraj Singh”
  • jdance

    jdance July 29th, 2010 @ 05:42 PM

    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.

  • Grant Ammons

    Grant Ammons July 29th, 2010 @ 09:31 PM

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

  • Neeraj Singh

    Neeraj Singh August 9th, 2010 @ 09:33 PM

    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 .

  • Neeraj Singh

    Neeraj Singh August 9th, 2010 @ 10:04 PM

    • State changed from “open” to “wontfix”
  • Ryan Bigg

    Ryan Bigg October 9th, 2010 @ 09:56 PM

    • Tag cleared.

    Automatic cleanup of spam.

  • Ryan Bigg

    Ryan Bigg November 8th, 2010 @ 01:52 AM

    Automatic cleanup of spam.

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile »

<h2 style="font-size: 14px">Tickets have moved to Github</h2>

The new ticket tracker is available at <a href="https://github.com/rails/rails/issues">https://github.com/rails/rails/issues</a>

Attachments

Referenced by

Pages