This project is archived and is in readonly mode.

#5074 ✓resolved
Kevin Wang

observer bug

Reported by Kevin Wang | July 8th, 2010 @ 09:52 PM | in 3.0.2

I am using Ruby 1.8.7 and Rails 3 Beta4

Steps to recreate this bug

1) rails new ./foo
2) rails generate model bar
3) rails generate observer bar
4) rake db:migrate
5) in config/application.rb file,

config.active_record.observers = :bar_observer

6) rails console
7) Bar.create

I get the error message below... however if I do Bar.create again it works.

irb(main):001:0> Bar.create
LoadError: Expected /Users/kevin/rails/foo3/app/models/bar.rb to define Bar

from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies.rb:456:in `load_missing_constant'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies.rb:156:in `const_missing'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies.rb:154:in `each'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies.rb:154:in `const_missing'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/inflector/methods.rb:103:in `constantize'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/inflector/methods.rb:102:in `each'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/inflector/methods.rb:102:in `constantize'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/core_ext/string/conversions.rb:59:in `constantize'
from /opt/local/lib/ruby/gems/1.8/gems/activemodel-3.0.0.beta4/lib/active_model/observing.rb:177:in `observed_class'
from /opt/local/lib/ruby/gems/1.8/gems/activemodel-3.0.0.beta4/lib/active_model/observing.rb:170:in `observed_classes'
from /opt/local/lib/ruby/gems/1.8/gems/activemodel-3.0.0.beta4/lib/active_model/observing.rb:190:in `observed_classes'
from /opt/local/lib/ruby/gems/1.8/gems/activemodel-3.0.0.beta4/lib/active_model/observing.rb:186:in `initialize'
from /opt/local/lib/ruby/gems/1.8/gems/activerecord-3.0.0.beta4/lib/active_record/observer.rb:94:in `initialize'
from /opt/local/lib/ruby/1.8/singleton.rb:94:in `new'
from /opt/local/lib/ruby/1.8/singleton.rb:94:in `instance'
from /opt/local/lib/ruby/gems/1.8/gems/activemodel-3.0.0.beta4/lib/active_model/observing.rb:64:in `instantiate_observer'

... 5 levels...

from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/lazy_load_hooks.rb:17:in `execute_hook'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/lazy_load_hooks.rb:24:in `run_load_hooks'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/lazy_load_hooks.rb:23:in `each'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/lazy_load_hooks.rb:23:in `run_load_hooks'
from /opt/local/lib/ruby/gems/1.8/gems/activerecord-3.0.0.beta4/lib/active_record/base.rb:1937
from /Users/kevin/rails/foo3/app/models/bar.rb:1
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies.rb:418:in `load'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies.rb:418:in `load_file'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies.rb:554:in `new_constants_in'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies.rb:417:in `load_file'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies.rb:313:in `require_or_load'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies.rb:455:in `load_missing_constant'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies.rb:156:in `const_missing'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies.rb:154:in `each'
from /opt/local/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies.rb:154:in `const_missing'

Comments and changes to this ticket

  • Rohit Arondekar

    Rohit Arondekar July 9th, 2010 @ 02:46 AM

    • Milestone cleared.
    • State changed from “new” to “open”
    • Tag set to rails 3, activerecord, loaderror, observer
    • Importance changed from “” to “Low”

    Confirmed on Rails master on 1.9.2-RC1 too.

  • Rohit Arondekar

    Rohit Arondekar July 9th, 2010 @ 03:09 AM

    This is a strange bug.

    I added the following just before the exception is raised in activesupport/lib/active_support/dependencies.rb : 465

      puts "For #{const_name}"
      puts "#{file_path}"
      puts "Loaded #{const_name}" if local_const_defined?(from_mod, const_name)
      puts "END"
    

    I get the following output in the console (truncated for clarity):

    First Try:

    ruby-1.9.2-rc1 > Bar
    For BarObserver
    /home/rohit/bugmash/newapp/app/models/bar_observer.rb
    Loaded BarObserver
    END
    For Bar
    /home/rohit/bugmash/newapp/app/models/bar.rb
    END
    LoadError: Expected /home/rohit/bugmash/newapp/app/models/bar.rb to define Bar
    

    Second Try:

    ruby-1.9.2-rc1 > Bar
    For Bar
    /home/rohit/bugmash/newapp/app/models/bar.rb
    Loaded Bar
    END
     => Bar(id: integer, created_at: datetime, updated_at: datetime)
    

    So there must be something going on in require_or_load method. Could it be that it thinks Bar is already loaded because of BarObserver? Will take a look later but I thought I should put what I found in here, in case somebody else wants to take a crack at it.

  • Rohit Arondekar

    Rohit Arondekar July 9th, 2010 @ 11:02 AM

    • Assigned user set to “José Valim”
  • José Valim

    José Valim July 9th, 2010 @ 11:08 AM

    Rohit put a puts caller at the beginning of load_missing_constant error and it returned this: http://pastie.org/1037235

    By looking at this caller stack trace, is easier to grasp what is going on:

    1) When you invoke Bar, it will trigger load_missing_constant(Bar);

    2) Once Bar file is loaded, it will find and load ActiveRecord::Base, triggering a few hooks;

    3) One of these ActiveRecord hooks is called instantiate_observer and it will cause BarObserver to be loaded through load_missing_constant(BarObserver);

    4) BarObserver is then loaded and it will try to apply its hooks to the Bar class. We already asked Bar class to be loaded, but it hasn't happened yet, because we started to load ActiveRecord::Base, which loaded BarObserver which wants to load Bar once again. What happens at this point, is that Bar is loaded again by AS::Dependencies, causing for us to have two Bar references, but one of them is obviously invalid;

    I'm not sure what is the proper fix here. By doing things lazy is stepping on our toes once again. :(

  • José Valim

    José Valim July 9th, 2010 @ 11:15 AM

    The issue could be easily avoided by forcing ActiveRecord::Base to be loaded before loading Bar:

    irb > ActiveRecord::Base
    irb > Bar.create #=> works

  • Xavier Noria

    Xavier Noria July 9th, 2010 @ 12:54 PM

    A minimal example that depicts the circularity involved:

    fxn@rails:~/tmp/h$ cat app/models/foo.rb
    class Foo < Bar
    end
    
    fxn@rails:~/tmp/h$ cat app/models/bar.rb 
    class Bar
    end
    
    Foo
    
    fxn@rails:~/tmp/h$ script/rails runner Foo
    /home/fxn/rails/railties/lib/rails/commands/runner.rb:50: /home/fxn/rails/activesupport/lib/active_support/dependencies.rb:465:in `load_missing_constant': Expected /home/fxn/tmp/h/app/models/foo.rb to define Foo (LoadError)
    
  • Xavier Noria

    Xavier Noria July 9th, 2010 @ 01:29 PM

    The issue is not a deadlock, that would work in MRI, but it implies two executions of foo.rb:

    halmos:tmp fxn$ cat test_const_missing.rb
    def Object.const_missing(name)
      case name.to_s
      when 'Foo'
        load 'foo.rb'
        Foo
      when 'Bar'
        load 'bar.rb'
        Bar
      end
    end
    
    Foo
    halmos:tmp fxn$ cat foo.rb
    puts "in foo.rb"
    class Foo < Bar
      puts "defining Foo"
    end
    
    halmos:tmp fxn$ cat bar.rb 
    puts "in bar.rb"
    class Bar
      puts "defining Bar"
    end
    
    Foo
    
    halmos:tmp fxn$ ruby test_const_missing.rb 
    in foo.rb
    in bar.rb
    defining Bar
    in foo.rb
    defining Foo
    defining Foo
    

    Which is not good anyway (perhaps dependencies is complaining to prevent that issue?).

    I wonder if this justifies not lazy loading Active Record, looks like this loop is unsolvable.

  • José Valim
  • Jeremy Kemper

    Jeremy Kemper October 15th, 2010 @ 11:01 PM

    • Milestone set to 3.0.2

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>

Referenced by

Pages