Rails Ruby on Rails → 3.x

Comments and changes to this ticket

• You flagged this item as spam.
  

  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.

  • query-backtrace.txt 23.7 KB

• You flagged this item as spam.
  

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

  My modified testapp2, for anyone who wants it.

  • testapp2.zip 28.7 KB

• You flagged this item as spam.
  

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

• You flagged this item as spam.
  

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

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

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

• You flagged this item as spam.
  

  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

• You flagged this item as spam.
  

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

• You flagged this item as spam.
  

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

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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-2765.diff 2 KB

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

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

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

• You flagged this item as spam.
  

  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)

• You flagged this item as spam.
  

  barunio August 23rd, 2009 @ 06:34 PM

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

• 

  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?

• You flagged this item as spam.
  

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

• You flagged this item as spam.
  

  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.

  • testapp.zip 56.4 KB

• You flagged this item as spam.
  

  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.

  • backtraces.txt 29.7 KB
• 

  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 May 16th, 2010 @ 02:41 AM

  [bulk edit]

• 

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

  • Milestone changed from “2.3.6” to “2.3.7”

  [bulk edit]

• 

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

  • Milestone changed from “2.3.7” to “2.3.8”

  [bulk edit]

• 

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

  • Milestone changed from “2.3.8” to “2.3.9”

  [bulk edit]

• You flagged this item as spam.
  

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

  • Importance changed from “” to “Medium”

  This issue also exists in rails master.

• 

  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.

• You flagged this item as spam.
  

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

• You flagged this item as spam.
  

  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.

  • 2765_test.patch 4.4 KB
• 

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

  • Assigned user set to “Neeraj Singh”

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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 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 August 9th, 2010 @ 10:04 PM

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

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

  • Tag cleared.

  Automatic cleanup of spam.

• 

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

  Automatic cleanup of spam.