jwood / tenacity

A database client independent way of managing relationships between models backed by different databases.
MIT License
118 stars 17 forks source link

t_has_many relationship nullifying child association fields on update (AR has_many Mongoid) #34

Closed abradner closed 12 years ago

abradner commented 12 years ago

I'm having trouble pinning down exactly what's causing it, but when I update an AR record, tenacity seems to be nullifying all of the id fields in a t_has_many related Mongoid model.

I've attached some large blobs of output below. As far as I can tell, tenacity seems to be calling

 Tenacity::Associations::HasMany::ClassMethods._t_clear_old_associations(record#StorageLocation(id: i...,...) 

for no reason (see frame 17 in the debug log at the bottom)

For context: app/controllers/management/storage_locations_controller.rb

class Management::StorageLocationsController < ApplicationController

  def update
    if @storage_location.update_attributes(params[:storage_location])
      redirect_to management_storage_locations_path, :notice => "The storage location  was successfully updated."
    else
      render :edit
    end
  end
end

app/models/storage_location.rb

class StorageLocation < ActiveRecord::Base
  include Tenacity
  belongs_to :system
  t_has_many :file_types, :dependent => :destroy

  #validations 
end

app/models/file_type.rb

class FileType
  include Mongoid::Document
  include Mongoid::Timestamps
  include Tenacity

  field :name, :type => String
  field :content, :type => String
  field :extensions, :type => String #change to array
  field :versioning, :type => Boolean

  t_belongs_to :system
  t_belongs_to :storage_location
  has_many :import_mappings
  has_many :raw_files
  embeds_many :file_metadata_schemas

  before_save :debugger

Logs:

Server Log

Started PUT "/management/storage_locations/1" for 127.0.0.1 at Tue Dec 06 12:20:49 +1100 2011
  Processing by Management::StorageLocationsController#update as HTML
  Parameters: {"commit"=>"Update Storage location", "authenticity_token"=>"H7X2Z/oV0m2Gt2Qro99xe0ZIXvTMQdTud+toEAx+YQA=", "utf8"=>"✓", "id"=>"1", "storage_location"=>{"name"=>"Raw Blob A", "location"=>"/tmp", "storage_type"=>"fs", "system_id"=>"1"}}
MONGODB webdb_development['system.namespaces'].find({})
  System Load (0.3ms)  SELECT "systems".* FROM "systems" ORDER BY name
  StorageLocation Load (0.2ms)  SELECT "storage_locations".* FROM "storage_locations" WHERE "storage_locations"."id" = ? LIMIT 1  [["id", "1"]]
   (0.2ms)  SELECT 1 FROM "storage_locations" WHERE (LOWER("storage_locations"."name") = LOWER('Raw Blob A') AND "storage_locations"."id" != 1 AND "storage_locations"."system_id" = 1) LIMIT 1
MONGODB webdb_development['system.namespaces'].find({})
MONGODB webdb_development['file_types'].find({"storage_location_id"=>1}).sort(_idasc)
MONGODB webdb_development['file_types'].find({"storage_location_id"=>1})
  System Load (0.2ms)  SELECT "systems".* FROM "systems" WHERE "systems"."id" = 1 LIMIT 1
MONGODB webdb_development['file_types'].update({"_id"=>BSON::ObjectId('4edd6948eb98e3f32f000007')}, {"$set"=>{"updated_at"=>Tue Dec 06 01:21:01 UTC 2011, "storage_location_id"=>nil}})
MONGODB webdb_development['file_types'].find({"storage_location_id"=>1})
Redirected to http://localhost:3000/management/storage_locations
Completed 302 Found in 21841ms

Debugger Trace. Top of the trace is the before_save in FileType, bottom is update_attributes in StorageLocationsController

--> #0 FileType._run_save_callbacks(key#NilClass) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activesupport-3.1.1/lib/active_support/callbacks.rb:416
    #1 Kernel.send(kind#Symbol) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activesupport-3.1.1/lib/active_support/callbacks.rb:81
    #2 ActiveSupport::Callbacks.to_s(kind#Symbol) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activesupport-3.1.1/lib/active_support/callbacks.rb:81
    #3 Proc.run_callbacks 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/mongoid-2.3.3/lib/mongoid/callbacks.rb:42
    #4 Mongoid::Callbacks.run_cascading_callbacks(children#Array, kind#Symbol) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/mongoid-2.3.3/lib/mongoid/callbacks.rb:67
    #5 Mongoid::Callbacks.run_callbacks(kind#Symbol) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/mongoid-2.3.3/lib/mongoid/callbacks.rb:41
    #6 Mongoid::Persistence::Modification.prepare 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/mongoid-2.3.3/lib/mongoid/persistence/modification.rb:23
    #7 Mongoid::Persistence::Operations::Update.persist 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/mongoid-2.3.3/lib/mongoid/persistence/operations/update.rb:43
    #8 Mongoid::Persistence.update(options#Hash) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/mongoid-2.3.3/lib/mongoid/persistence.rb:86
    #9 Mongoid::Persistence.save(options#Hash) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/mongoid-2.3.3/lib/mongoid/persistence.rb:151
    #10 Tenacity::OrmExt::Mongoid::InstanceMethods._t_save_if_dirty 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/tenacity-0.5.3/lib/tenacity/orm_ext/mongoid.rb:117
    #11 Tenacity::Associations::HasMany::ClassMethods.save_associate(associate#FileType,...) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/tenacity-0.5.3/lib/tenacity/associations/has_many.rb:122
    #12 Mongo::Cursor._t_clear_old_associations 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/tenacity-0.5.3/lib/tenacity/associations/has_many.rb:117
    #13 Mongoid::Cursor.each 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/mongoid-2.3.3/lib/mongoid/cursor.rb:48
    #14 Mongoid::Contexts::Mongo.iterate 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/mongoid-2.3.3/lib/mongoid/contexts/mongo.rb:212
    #15 Kernel.each 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/mongoid-2.3.3/lib/mongoid/criteria.rb:143
    #16 Mongoid::Criteria.each 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/mongoid-2.3.3/lib/mongoid/criteria.rb:143
    #17 Tenacity::Associations::HasMany::ClassMethods._t_clear_old_associations(record#StorageLocation(id: i...,...) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/tenacity-0.5.3/lib/tenacity/associations/has_many.rb:115
    #18 Tenacity::Associations::HasMany::ClassMethods._t_save_associates(record#StorageLocation(id: i...,...) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/tenacity-0.5.3/lib/tenacity/associations/has_many.rb:106
    #19 StorageLocation._callback_after_23973(key#NilClass) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/tenacity-0.5.3/lib/tenacity/orm_ext/activerecord.rb:90
    #20 StorageLocation._run_save_callbacks(key#NilClass) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activesupport-3.1.1/lib/active_support/callbacks.rb:413
    #21 Kernel.send(kind#Symbol) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activesupport-3.1.1/lib/active_support/callbacks.rb:81
    #22 ActiveSupport::Callbacks.to_s(kind#Symbol) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activesupport-3.1.1/lib/active_support/callbacks.rb:81
    #23 ActiveRecord::Callbacks.create_or_update 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activerecord-3.1.1/lib/active_record/callbacks.rb:264
    #24 ActiveRecord::Persistence.save 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activerecord-3.1.1/lib/active_record/persistence.rb:37
    #25 ActiveRecord::Validations.save(options#Hash) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activerecord-3.1.1/lib/active_record/validations.rb:50
    #26 ActiveRecord::AttributeMethods::Dirty.save 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activerecord-3.1.1/lib/active_record/attribute_methods/dirty.rb:22
    #27 ActiveRecord::ConnectionAdapters::DatabaseStatements.save(options#Hash) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activerecord-3.1.1/lib/active_record/transactions.rb:241
    #28 ActiveRecord::Transactions::ClassMethods.transaction(options#Hash) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activerecord-3.1.1/lib/active_record/transactions.rb:208
    #29 ActiveRecord::Transactions.with_transaction_returning_status 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activerecord-3.1.1/lib/active_record/transactions.rb:293
    #30 ActiveRecord::Transactions.save 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activerecord-3.1.1/lib/active_record/transactions.rb:241
    #31 ActiveRecord::Transactions.save 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activerecord-3.1.1/lib/active_record/transactions.rb:240
    #32 ActiveRecord::ConnectionAdapters::DatabaseStatements.update_attributes(options#Hash,...) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activerecord-3.1.1/lib/active_record/persistence.rb:163
    #33 ActiveRecord::Transactions::ClassMethods.transaction(options#Hash) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activerecord-3.1.1/lib/active_record/transactions.rb:208
    #34 ActiveRecord::Transactions.with_transaction_returning_status 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activerecord-3.1.1/lib/active_record/transactions.rb:293
    #35 ActiveRecord::Persistence.update_attributes(attributes#ActiveSupport::HashWi...,...) 
       at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/activerecord-3.1.1/lib/active_record/persistence.rb:161
    #36 Management::StorageLocationsController.[] 
       at line /Users/abradner/Dropbox/code/usyd/webdb/app/controllers/management/storage_locations_controller.rb:27
abradner commented 12 years ago

This seems to be affecting all of my AR>Mongoid t_has_many relationships, and is actually a really big problem

(NB: I don't have any Mongoid>AR relationships, nor any other ORM>ORM, I'm just specifying in case it is specific to AR>Mongoid)

jwood commented 12 years ago

Tenacity stores has_many associates in an instance variable on the object. When the object is saved, tenacity will

1) Clear out any old associations for that object from that database, by setting the foreign key to nil 2) Iterate through the associates stored in the instance variable, set the foreign key, and save the object

These two steps are being performed in lines 17 and 18 of your debugger trace. So, the clearing out is normal, but it appears that the setting of the new associates is not working.

#17 Tenacity::Associations::HasMany::ClassMethods._t_clear_old_associations(record#StorageLocation(id: i...,...) 
   at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/tenacity-0.5.3/lib/tenacity/associations/has_many.rb:115
#18 Tenacity::Associations::HasMany::ClassMethods._t_save_associates(record#StorageLocation(id: i...,...) 
   at line /Users/abradner/.rvm/gems/ree-1.8.7-2011.03@webdb/gems/tenacity-0.5.3/lib/tenacity/associations/has_many.rb:106

Can you check to see what @storage_location.file_types contains before calling @storage_location.update_attributes? It's possible that the associates were not loaded properly, the instance variable was not populated, and step 2 is not saving the re-saving the associates because it doesn't know about them.

jwood commented 12 years ago

I just reproduced the issue, and this is what is going on (and a bug in tenacity). This test case fails

    should "not lose the associated objects when the main object is updated" do
      active_record_object = ActiveRecordObject.create
      mongoid_objects = [MongoidHasManyTarget.create, MongoidHasManyTarget.create, MongoidHasManyTarget.create]
      active_record_object.mongoid_has_many_targets = mongoid_objects
      active_record_object.save
      assert_equal mongoid_objects, ActiveRecordObject.find(active_record_object.id).mongoid_has_many_targets

      active_record_object = ActiveRecordObject.find(active_record_object.id)
      active_record_object.update_attributes(:prop => "abc123")
      assert_equal mongoid_objects, ActiveRecordObject.find(active_record_object.id).mongoid_has_many_targets
    end

I'll start working on a fix.

jwood commented 12 years ago

I just pushed a fix for this to master. Would you mind testing it out before I publish a new version of the gem?

abradner commented 12 years ago

Sure, I'll be doing that today

abradner commented 12 years ago

It seems to no longer be destroying the associations, however there appears to be a deeper issue still: it still seems to be loading (and occasionally updating) the associated objects for no reason:

take this very simple association where a user owns many files:

class User < ActiveRecord::Base
  t_has_many :raw_files
end

class RawFile
  include CarrierWave::Mongoid
  include Mongoid::Document
  include Mongoid::Timestamps
  include Tenacity

  t_belongs_to :user
end

Simply updating my name in the user model causes it to load all related raw files:

Started PUT "/users" for 127.0.0.1 at Wed Dec 07 12:28:06 +1100 2011
  Processing by UserRegistersController#update as HTML
  Parameters: {"commit"=>"Update", "authenticity_token"=>"H7X2Z/oV0m2Gt2Qro99xe0ZIXvTMQdTud+toEAx+YQA=", "utf8"=>"✓", "user"=>{"last_name"=>"Bradner", "first_name"=>"Alex"}}
  User Load (0.2ms)  SELECT "users".* FROM "users" WHERE "users"."id" = 2 LIMIT 1
MONGODB webdb_development['system.namespaces'].find({})
MONGODB webdb_development['raw_files'].find({"user_id"=>2}, {"id"=>1})
MONGODB webdb_development['raw_files'].find({:_id=>nil})
MONGODB webdb_development['raw_files'].find({"user_id"=>2}).sort(_idasc)
MONGODB webdb_development['raw_files'].find({"user_id"=>2})
Redirected to http://localhost:3000/
Completed 302 Found in 385ms

Given that there are far more complicated t_has_many relationships, this will not scale at all!

A more complicated example from the same system:

class System < ActiveRecord::Base
  include Tenacity
  t_has_many :data_objects, :dependent => :destroy
  t_has_many :storage_locations, :dependent => :destroy
  t_has_many :file_types

  #snip
end

running

Rails.logger.debug "=======DEBUG: UPDATING SYSTEM=======\n"
@system.update_attributes(params[:system])  

causes this to happen (every mongo query below the debug line is unnecessary):

Started PUT "/management/systems/1" for 127.0.0.1 at Wed Dec 07 12:35:16 +1100 2011
  Processing by Management::SystemsController#update as HTML
  Parameters: {"commit"=>"Update System", "member"=>"", "system"=>{"schema_name"=>"system_a", "name"=>"First System", "code"=>"SYS0000", "colour_scheme_id"=>"1", "description"=>"First System Description"}, "authenticity_token"=>"H7X2Z/oV0m2Gt2Qro99xe0ZIXvTMQdTud+toEAx+YQA=", "utf8"=>"✓", "id"=>"1", "member_ids"=>["2", "1"]}
  User Load (0.1ms)  SELECT "users".* FROM "users" WHERE "users"."id" = 2 LIMIT 1
  Role Load (0.1ms)  SELECT "roles".* FROM "roles" WHERE "roles"."id" = 1 LIMIT 1
  System Load (0.1ms)  SELECT "systems".id FROM "systems" INNER JOIN "system_members" ON "systems"."id" = "system_members"."system_id" WHERE "system_members"."user_id" = 2 AND "system_members"."administrator" = 't'
  System Load (0.2ms)  SELECT "systems".id FROM "systems" INNER JOIN "system_members" ON "systems"."id" = "system_members"."system_id" WHERE "system_members"."user_id" = 2
  System Load (0.3ms)  SELECT "systems".* FROM "systems" INNER JOIN "system_members" ON "systems"."id" = "system_members"."system_id" WHERE "system_members"."user_id" = 2 AND "system_members"."administrator" = 't'
MONGODB webdb_development['system.namespaces'].find({})
MONGODB webdb_development['data_objects'].find({:system_id=>{"$in"=>[1]}}, {:_id=>1, :_type=>1})
  System Load (0.3ms)  SELECT "systems".* FROM "systems" INNER JOIN "system_members" ON "systems"."id" = "system_members"."system_id" WHERE "system_members"."user_id" = 2
MONGODB webdb_development['data_objects'].find({:system_id=>{"$in"=>[1]}}, {:_id=>1, :_type=>1})
  System Load (0.3ms)  SELECT "systems".* FROM "systems" ORDER BY name
  System Load (0.3ms)  SELECT "systems".* FROM "systems" WHERE "systems"."id" = ? LIMIT 1  [["id", "1"]]
New user_ids = 21
{"name"=>"First System", "schema_name"=>"system_a", "code"=>"SYS0000", "colour_scheme_id"=>"1", "description"=>"First System Description"}
=======DEBUG: UPDATING SYSTEM=======
  User Load (0.3ms)  SELECT "users".* FROM "users" WHERE "users"."id" IN (2, 1)
  User Load (0.2ms)  SELECT "users".* FROM "users" INNER JOIN "system_members" ON "users"."id" = "system_members"."user_id" WHERE "system_members"."system_id" = 1 AND "system_members"."administrator" = 't'
   (0.1ms)  SELECT 1 FROM "systems" WHERE (LOWER("systems"."name") = LOWER('First System') AND "systems"."id" != 1) LIMIT 1
MONGODB webdb_development['data_objects'].find({"system_id"=>1}, {"id"=>1})
MONGODB webdb_development['data_objects'].find({:_id=>nil})
MONGODB webdb_development['data_objects'].find({"system_id"=>1}).sort(_idasc)
MONGODB webdb_development['data_objects'].find({"system_id"=>1})
MONGODB webdb_development['data_objects'].find({"system_id"=>1})
MONGODB webdb_development['system.namespaces'].find({})
MONGODB webdb_development['storage_locations'].find({"system_id"=>1}, {"id"=>1})
MONGODB webdb_development['storage_locations'].find({:_id=>{"$in"=>[BSON::ObjectId('4edebf85eb98e33c38000003'), BSON::ObjectId('4edebfb3eb98e33c38000005')]}})
MONGODB webdb_development['storage_locations'].find({"system_id"=>1}).sort(_idasc)
MONGODB webdb_development['storage_locations'].find({"system_id"=>1})
MONGODB webdb_development['$cmd'].find({"count"=>"storage_locations", "query"=>{:_id=>{"$ne"=>BSON::ObjectId('4edebf85eb98e33c38000003')}, :name=>/^FS\ Blob$/i, :system_id=>nil}, "fields"=>nil})
MONGODB webdb_development['$cmd'].find({"count"=>"storage_locations", "query"=>{:_id=>{"$ne"=>BSON::ObjectId('4edebfb3eb98e33c38000005')}, :name=>/^DB\ Blob$/i, :system_id=>nil}, "fields"=>nil})
MONGODB webdb_development['storage_locations'].find({:_id=>BSON::ObjectId('4edebf85eb98e33c38000003')})
MONGODB webdb_development['storage_locations'].find({:_id=>BSON::ObjectId('4edebfb3eb98e33c38000005')})
MONGODB webdb_development['storage_locations'].find({"system_id"=>1})
MONGODB webdb_development['system.namespaces'].find({})
MONGODB webdb_development['file_types'].find({"system_id"=>1}, {"id"=>1})
MONGODB webdb_development['file_types'].find({:_id=>BSON::ObjectId('4edebfeeeb98e33c38000007')})
MONGODB webdb_development['file_types'].find({"system_id"=>1}).sort(_idasc)
MONGODB webdb_development['file_types'].find({"system_id"=>1})
MONGODB webdb_development['file_types'].update({"_id"=>BSON::ObjectId('4edebfeeeb98e33c38000007')}, {"$set"=>{"updated_at"=>Wed Dec 07 01:35:17 UTC 2011, "system_id"=>nil}})
MONGODB webdb_development['file_types'].find({:_id=>BSON::ObjectId('4edebfeeeb98e33c38000007')})
  System Load (0.2ms)  SELECT "systems".* FROM "systems" WHERE "systems"."id" = 1 LIMIT 1
MONGODB webdb_development['file_types'].update({"_id"=>BSON::ObjectId('4edebfeeeb98e33c38000007')}, {"$set"=>{"system_id"=>1}})
Redirected to http://localhost:3000/systems/1
Completed 302 Found in 874ms

Also note: the last query seems to be updating file_types even though it wasn't changed.

jwood commented 12 years ago

I made a change that should address the issue you describe above, and pushed it to master. Please let me know if it addresses your issue.

Also, I should warn you that Tenacity will not handle large collections of associated objects (via a t_has_many association) well. While it does lazily load the associated objects, when it does load them, it loads them all. There is currently no support for pagination, or anything else that will ease the pain of working with large collections of associated objects.

abradner commented 12 years ago

I haven't noticed any data loss issues since updating, and your subsequent update seems to have significantly reduced the number of queries. Thanks