Instance Methods Disappearing

I have experienced this same problem on Rails 1.2 RC1 and can't pin down what is wrong. On the second request after a server restart, instance methods seem to disappear with no explanation. Even the association-based instance methods are not working. This effectively breaks my application because only one page loads before everything throws a NoMethodError or TemplateError. Strangely, I can't reproduce it in unit tests -- so all the models must be fine.

After rolling back to Rails 1.1.6, everything works just fine.

Tried using both Ruby 1.8.4 and 1.8.5 on Ubuntu Linux with the same result.

Development log:

ActionView::TemplateError (undefined method `containers' for #<HomePage:0xb724649c>) on line #1 of app/views/shared/page_of_wamlets.rhtml:
1: <%= render :partial => 'container/container', :collection => @page.containers %>
2: <%= javascript_tag "Droppables.add(\"canvas\", {
3:       onDrop: function(element){#{remote_function(:url => {:controller => 'container', :action => 'move'},
4:         :with => "'id=' + getContainerId(element.id) + '&xpos=' + parseInt(Element.getStyle(element,'left') || '0') + '&ypos=' +
parseInt(Element.getStyle(element,'top') || '0')",
/usr/local/lib/ruby/gems/1.8/gems/activerecord-1.14.4.5618/lib/active_record/associations/association_proxy.rb:123:in `send'
/usr/local/lib/ruby/gems/1.8/gems/activerecord-1.14.4.5618/lib/active_record/associations/association_proxy.rb:123:in `method_missing'
#{RAILS_ROOT}/app/views/shared/page_of_wamlets.rhtml:1:in `_run_rhtml_47app47views47shared47page_of_wamlets46rhtml'
#...

Here, in fact 'containers' is defined as an association in my app:

class Page < ActiveRecord::Base
  has_many :containers
  # ...
end

class HomePage < Page ; end

Also some strange output from Mongrel that I have never seen before:

#<NameError: cannot remove Object::LOCALIZED_STRINGS>
/usr/local/lib/ruby/gems/1.8/gems/activesupport-1.3.1.5618/lib/active_support/dependencies.rb:416:in `remove_const'
/usr/local/lib/ruby/gems/1.8/gems/activesupport-1.3.1.5618/lib/active_support/dependencies.rb:416:in `send'
/usr/local/lib/ruby/gems/1.8/gems/activesupport-1.3.1.5618/lib/active_support/dependencies.rb:416:in `remove_constant'
/usr/local/lib/ruby/gems/1.8/gems/activesupport-1.3.1.5618/lib/active_support/dependencies.rb:270:in `remove_unloadable_constants!'
/usr/local/lib/ruby/gems/1.8/gems/activesupport-1.3.1.5618/lib/active_support/dependencies.rb:270:in `each'
/usr/local/lib/ruby/gems/1.8/gems/activesupport-1.3.1.5618/lib/active_support/dependencies.rb:270:in `remove_unloadable_constants!'
/usr/local/lib/ruby/gems/1.8/gems/activesupport-1.3.1.5618/lib/active_support/dependencies.rb:73:in `clear'
/usr/local/lib/ruby/gems/1.8/gems/rails-1.1.6.5618/lib/dispatcher.rb:63:in `reset_application!'
/usr/local/lib/ruby/gems/1.8/gems/rails-1.1.6.5618/lib/dispatcher.rb:115:in `reset_after_dispatch'
/usr/local/lib/ruby/gems/1.8/gems/rails-1.1.6.5618/lib/dispatcher.rb:51:in `dispatch'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/rails.rb:84:in `process'
/usr/local/lib/ruby/1.8/sync.rb:229:in `synchronize'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/rails.rb:83:in `process'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:580:in `process_client'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:579:in `each'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:579:in `process_client'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:686:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:686:in `initialize'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:686:in `new'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:686:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:673:in `initialize'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:673:in `new'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:673:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/configurator.rb:267:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/configurator.rb:266:in `each'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/configurator.rb:266:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/bin/mongrel_rails:127:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/command.rb:211:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/bin/mongrel_rails:231
/usr/local/bin/mongrel_rails:18:in `load'
/usr/local/bin/mongrel_rails:18 

This may be related to the stricter autoloading of dependencies in 1.2. Make sure you have one class per file and that all the files are named correctly, eg: MyClass => my_class.rb. Also, remove any unnecessary require statements that load classes that could be autoloaded, or if an explicit require is necessary, change them to require_dependency.

After nearly an entire day trying to debug this, I discovered this in app/config/environments/development.rb

# In the development environment your application's code is reloaded on
# every request.  This slows down response time but is perfect for development
# since you don't have to restart the webserver when you make code changes.
config.cache_classes     = false

I changed it to

config.cache_classes     = true

... and it works again! No more strange NoMethodErrors on any request.

Now can somebody explain to me what has changed in 1.2 that requires this?

caching classes isn't really a solution unless you are accepting to restart your development server after each change ;-(

I had similar problems and found by activating debug output in activesupport/lib/active_support/dependencies.rb and studying the output that it had to do (in my case) with the inclusion of Magick (that is, I had require "RMagick' and include Magick in my controllers).

The (new) dependency code seems to have a problem when one loaded and included a c module. When I changed my code to leave out the `include Magick' (which means to use apropriate module prefixes when using RMagick-Classes), everything was fine again.

The problem can be seen by a test application with some model defining some function eg. class Item < ActiveRecord::Base def foo

'foo'

end

end

and a controller require 'RMagick' include Magick

class ItemsController < ApplicationController

def list

@item = Item.new

end

end

and a view accessing @item.foo.

The first request will be ok (no unloding so far), the second fails (undefined method `foo' for #<Item:0x40f784d4>).

See also my mail to the rails mailing list, e.g. http://comments.gmane.org/gmane.comp.lang.ruby.rails/109534

I guess it would be helpful if the other having this problem could check if they load and include c modules as well (doesn't need to be RMagick).

regards

Morus

Morus, thanks for your suggestion.

I am using RMagick in my app, and I removed all includes like you suggested. I think the problem is not with RMagick though, but the Localization module in my case. I have include Localization at the top of application_helper.rb.

When I remove it, the localization method l doesn't work in my models anymore. I couldn't get it to work by including the module prefixes either. I'm not sure why.

I think this is a bug that the Localization module is not being unloaded if cached classes are off. Evidenced by my Mongrel log included in my first comment of this ticket.

For now, I am working around this problem by just turning on cached classes.

Ok, so probably I'm wrong blaming just c modules for that. Probably any included module breaks the dependency code.

I took a second look at dependencies.rb. One can fix the symptoms of the problem (though I doubt that this is a good fix) by catching errors in dependencies.rb method remove_constant (~line 405). If you change

  def remove_constant(const)
    return false unless qualified_const_defined? const
    
    names = const.split('::')
    if names.size == 1 || names.first.empty? # It's under Object
      parent = Object
    else
      parent = (names[0..-2] * '::').constantize
    end
    
    log "removing constant #{const}"
    parent.send :remove_const, names.last
    return true
  end

to

 def remove_constant(const)
    return false unless qualified_const_defined? const
    begin
      names = const.split('::')
      if names.size == 1 || names.first.empty? # It's under Object
        parent = Object
      else
        parent = (names[0..-2] * '::').constantize
      end
      
      log "removing constant #{const}"
      parent.send :remove_const, names.last
    rescue => err
      log err.inspect
    end
    return true
  end

the problem goes away (for me). The error catched (and ignored) is something like #<NameError: cannot remove Object::OrQuantumOperator> which is understandable, since OrQuantumOperator is a constant in the Magick module, not in object.

But I guess the deeper cause of this problem is somewhere in the object loading logic, where these constants are tracked and added to the autoloaded_constants array. I don't understand enough of that. I hope some dependecy guru will have a look at this and fix it properly.

I changed the component to 'ActiveResource', since I'm pretty sure, that the problems arise there.

regards

Morus

(In [5710]) Fix remove_constant to correctly handle constant names of the form "::A::...". References #6720.

The above change might have solved your issue Morus. Please let me know if so. If the issue remains, then I'm going to need some more help in tracking it down. Perhaps one of you could set Dependencies.log_activity = true to provide more information to guide me?

Thanks, Ulysses

log file with dependices - requested by Ulysses

Ulysses,

I turned on Dependencies logging, and uploaded my log file as an attachment .

Let me know if I can help any more.

Nate

Hmm, I still haven't been able to reproduce. Any chance you could apply this patch and paste the logs again?

Index: activesupport/lib/active_support/dependencies.rb
===================================================================
--- activesupport/lib/active_support/dependencies.rb	(revision 5710)
+++ activesupport/lib/active_support/dependencies.rb	(working copy)
@@ -403,7 +403,11 @@
   end
   
   def remove_constant(const)
-    return false unless qualified_const_defined? const
+    log_call(const)
+    unless qualified_const_defined? const
+      log "qualified_const_defined? #{const.inspect} => false"
+      return false
+    end
     
     const = $1 if /\A::(.*)\Z/ =~ const.to_s
     names = const.split('::')
@@ -413,7 +417,7 @@
       parent = (names[0..-2] * '::').constantize
     end
     
-    log "removing constant #{const}"
+    log "removing constant #{const} from #{parent}"
     parent.send :remove_const, names.last
     return true
   end

Thanks! :-)

development log - after patch applied

Ulysses,

I applied the patch and uploaded the newest log here This is the full detail log of two GET requests, both to HomeController#index. The first request runs fine, but the second request quickly fails. I hope this is enough detail to pin down the problem.

My workaround has been to keep cached classes turned on, then the problem goes away.

Replying to ulysses:

Hmm, I still haven't been able to reproduce. Any chance you could apply this patch and paste the logs again?

Unfortunately it does not help. The remove constant is called with a simple name, no prefix. E.g. SubtractCompositeOp. So there is no chance to see if that's a constant in object or not at this point (at least not from the name).

Adding your changes and extending the last log in remove_constant a bit further (original name is a copy of the argument to remove_constanct) I get

Dependencies: called remove_constant("SubtractCompositeOp")

Dependencies: removing constant SubtractCompositeOp from Object (original name SubtractCompositeOp)

(If you think another full log would be helpful let me know)

If I look at the problem in irb doing a

require 'RMagick'
include Magick

Object has a constant 'SubtractCompositeOp':

Object.constants.index('SubtractCompositeOp')
=> 176
Object.const_defined? 'SubtractCompositeOp'
=> true

But I cannot unload it:

Object.send :remove_const, "SubtractCompositeOp"
NameError: cannot remove Object::SubtractCompositeOp
        from (irb):4:in `remove_const'
        from (irb):4:in `send'
        from (irb):4

If I try to unload it from magick, it works:

Magick.send :remove_const, "SubtractCompositeOp"
=> SubtractComposit=50
Object.constants.index('SubtractCompositeOp')
=> nil

Unfortunately I don't know how to tell, whether some constant stems from an included module or not. Except looking through all included modules and looking at the constants defined there:

      parent.included_modules.each do | mod |
        mod.send :remove_const, names.last if mod.const_defined? names.last
      end
      parent.send :remove_const, names.last if parent.const_defined? names.last

instead of

parent.send :remove_const, names.last

does work for me. Don't know what the performance impact is (probably one could return on the first constant removed).

(In [5782]) Update load once paths to prevent nested once constants from being detected and claimed by an external non-once load. References #6720

This is not fixed for me. If I turn cached classes off in development mode, I am still getting the exact same behavior as stated before.

I am now running on Edge rails revision 5874

Replying to supernate:

This is not fixed for me. If I turn cached classes off in development mode, I am still getting the exact same behavior as stated before. I am now running on Edge rails revision 5874

I can confirm that. My testcase in comment #5 still fails.

Closing since this is a different issue and deserves a new ticket. (And I'm tired of scrolling.)

Please see #6951 -- is that an accurate description?