Topic: Self-modifying models... Very weird.

Dear forum readers,

i have a very simple set of models, and i'm facing two rather weird problems. i have discovered the second problem while investigating the first, so they might be related (i posted here about the first http://railsforum.com/viewtopic.php?id=49557 but had no joy yet, so i give a shot here with the new problems).

Basically, i'm having a set of very simple models. The problem appears after a while, when a minimum of two clients are connected to the server, and after they reset their coolies / empty their cache.

For the explaination of my problems, let's assume i only have two models: Person and Role. a Person HABTM Roles, and a Role HABTM Persons. The intermediate database table that holds the foreign links is named people_roles, and has a migration like follows:

class CreatePeopleRoles < ActiveRecord::Migration
  def change
    create_table :people_roles, id: false, timestamps: false do |t|
      t.references    :person
      t.references    :role
    end
    add_index :people_roles, [:person_id, :role_id], unique: true
  end
end

The 1st problem.

The Person model is as follows:

require 'habtm_extensions'
require 'model_metadata'
require 'is_hierarchy_node'
require 'addressable'
require 'annotable'
require 'searchable'

class Person < ActiveRecord::Base
  has_secure_password
  attr_protected          :password_digest
  attr_accessible         :company, :email, :first_name, :last_name, :password, :password_confirmation
  attr_accessible         :role_ids
  # Relationships.
  belongs_to              :company
  has_and_belongs_to_many :roles, uniq: true
  has_many                :model_rights,  through: :roles
  is_addressable
  is_annotable
  # Mark company_id as the ancestor chain endpoint.
  provides_ancestor_key   :company_id
  # Enable search on first / last / email fields.
  is_searchable_on        :first_name, :last_name, :email

  before_save             { email.downcase! }

  # Exclude password info from json output.
  def as_json (opts=nil)
    binding.pry
    super (opts||{}).merge({except:[:password, :password_confirmation, :password_digest]})
  end
end

Note the binding.pry statement in the as_json definition, it is very important for later.

Now, as you can see at the very begining of the file, this model uses a few plugins i've made, like addressable, annotable, etc. The most important one, is the habtm_extensions:

module HabtmExtensions
  # Declare instance methods.
  def self.included (base)
    puts 'Patching ActiveRecord::Base so accessible "*_ids" fields are included in as_json...'
    def as_json (opts=nil)
      @@methods     ||= self.class.accessible_attributes.to_a.keep_if { |a| a.end_with?('_ids') }
      super (opts||{}).merge({methods:@@methods})
    end
  end
end
ActiveRecord::Base.send :include, HabtmExtensions

This piece of code, for the Person model, will automatically append a role_ids field containing an array of Roles IDs when outputing an object as JSON.

The problem i have is very, very, very weird. For a while, everything works. In the /people.json output, i have role_ids. i'm able as well as posting a new person, or updating an existing person. the role_ids field gets sent to the browser, and is properly handled when received. And both binding.pry are correctly handled, the debugger fires up. However, for a reason i don't understand yet, after using the server with 2 clients and at some random point, role_ids field disappear from the JSON, and the excluded JSON fields (password etc) are in the JSON! The pry breakpoints are not reached anymore, like if the Person model was re-parsed without the extensions and overrides...

Note that, the inclusion of habtm_extension wasn't in the Person model, i added it to see if it would change anything, but it doesnt. In my initializers, i have a file that is properly parsed at startup, that reads:

# Require any patch / extension that is custom and in lib/.
require 'habtm_extensions.rb'
require 'model_metadata.rb'
require 'forced_models_parsing.rb'

Any idea why the as_json seems to be back to the default rails implementation after a while?


The 2nd problem.
The Role model looks like this:

require 'habtm_extensions'
require 'model_metadata'

class Role < ActiveRecord::Base
  attr_accessible         :name, :read, :write, :cross_company
  # Relationships.
  has_and_belongs_to_many :people, uniq: true
  has_many                :model_rights
end

Very simple. However, using an ExtJS application, i'm having another random behavior:
From the console:

Person.first.role_ids = [1, 2, 3]

works as expected.
However, when the rails server has just started, and then when using the ExtJS application (Which really only does RESTFUL calls), i get this error:

Started PUT "/people/2?_dc=1352161436125" for 127.0.0.1 at 2012-11-05 16:23:56 -0800
Processing by PeopleController#update as JSON
  Parameters: {"email"=>"jdoe@somewhere.com", "last_name"=>"DOE", "first_name"=>"John", "company_id"=>2, "created_at"=>"2012-11-06T00:23:28Z", "updated_at"=>"2012-11-06T00:23:28Z", "role_ids"=>[1, 2], "id"=>"2", "_dc"=>"1352161436125", "person"=>{"email"=>"jdoe@somewhere.com", "first_name"=>"John", "last_name"=>"DOE", "role_ids"=>[1, 2]}}
WARNING: Can't verify CSRF token authenticity
  Company Load (0.1ms)  SELECT "companies".* FROM "companies" WHERE "companies"."id" = ? LIMIT 1  [["id", 2]]
  Person Load (0.2ms)  SELECT "people".* FROM "people" WHERE "people"."company_id" = 2 AND "people"."id" = ? LIMIT 1  [["id", "2"]]
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
Completed 500 Internal Server Error in 10ms
NoMethodError (undefined method `type_cast' for nil:NilClass):
  app/controllers/people_controller.rb:19:in `update'
  Rendered /Volumes/Data/Users/hickscorp/.rvm/gems/ruby-1.9.3-p286@wid_grinder/gems/actionpack-3.2.6/lib/action_dispatch/middleware/templates/rescues/_trace.erb (5.1ms)
  Rendered /Volumes/Data/Users/hickscorp/.rvm/gems/ruby-1.9.3-p286@wid_grinder/gems/actionpack-3.2.6/lib/action_dispatch/middleware/templates/rescues/_request_and_response.erb (1.4ms)
  Rendered /Volumes/Data/Users/hickscorp/.rvm/gems/ruby-1.9.3-p286@wid_grinder/gems/actionpack-3.2.6/lib/action_dispatch/middleware/templates/rescues/diagnostics.erb within rescues/layout (15.3ms)

Hmm... Using pry, i was able to pinpoint that the exception was actually firing in collection_association.rb around line 69:

     def ids_writer(ids)
       pk_column = reflection.primary_key_column
       ids = Array.wrap(ids).reject { |id| id.blank? }
       ids.map! { |i| pk_column.type_cast(i) }
       replace(klass.find(ids).index_by { |r| r.id }.values_at(*ids))
     end

For some reason, at this point pk_column is nil when the method is called for the role_ids field... But hold on. Without restarting my browser, i just CTRL+C and restart my rails server... And issue the exact same request. Now look:

Started PUT "/people/2?_dc=1352161596579" for 127.0.0.1 at 2012-11-05 16:26:36 -0800
Processing by PeopleController#update as JSON
  Parameters: {"email"=>"jdoe@somewhere.com", "last_name"=>"DOE", "first_name"=>"John", "company_id"=>2, "created_at"=>"2012-11-06T00:23:28Z", "updated_at"=>"2012-11-06T00:23:28Z", "role_ids"=>[1, 2], "id"=>"2", "_dc"=>"1352161596579", "person"=>{"email"=>"jdoe@somewhere.com", "first_name"=>"John", "last_name"=>"DOE", "role_ids"=>[1, 2]}}
WARNING: Can't verify CSRF token authenticity
  Company Load (0.1ms)  SELECT "companies".* FROM "companies" WHERE "companies"."id" = ? LIMIT 1  [["id", 2]]
  Person Load (0.1ms)  SELECT "people".* FROM "people" WHERE "people"."company_id" = 2 AND "people"."id" = ? LIMIT 1  [["id", "2"]]
   (0.0ms)  begin transaction
  Role Load (0.1ms)  SELECT "roles".* FROM "roles" WHERE "roles"."id" IN (1, 2)
  Role Load (0.1ms)  SELECT DISTINCT "roles".* FROM "roles" INNER JOIN "people_roles" ON "roles"."id" = "people_roles"."role_id" WHERE "people_roles"."person_id" = 2
  Person Exists (0.1ms)  SELECT 1 AS one FROM "people" WHERE (LOWER("people"."email") = LOWER('jdoe@somewhere.com') AND "people"."id" != 2) LIMIT 1
   (0.1ms)  commit transaction
Completed 204 No Content in 36ms (ActiveRecord: 0.0ms)

Everything is just fine. And everything will be fine from now on, until the problem #1 arrives. Ouch.


Well...

i have to say, those two problems made me bang my head against the wall for maybe 2 weeks now... This is very odd, and i believe there might be something very silly i'm doing somewhere... But really, how can i diagnose / solve this kind of issue in the future?

For your time and expertise, i thank you.

Best to you,
Pierre.

Last edited by hickscorp (2012-11-05 20:41:29)

Re: Self-modifying models... Very weird.

Hmm... After testing, it appears that these two bugs are not showing up with Rails 3.1.8, only with 3.2.X (i tested from 3.2.4 to 3.2.8)... Do you guys think i should fill a bug report, or does it sound like it's a problem of mine?