Problem: Gem's version of require rescues all LoadErrors, and can cause files to be loaded twice
From WhyNotWiki
Contents |
[edit] Symptoms
When I would try to start up Webrick (to run a Rails app), I would get this warning and then it would exit Webrick and (inexplicably) try to start up mongrel, which would die with an error:
... /usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/commands/servers/webrick.rb:22: warning: already initialized constant OPTIONS => Booting Mongrel (use 'script/server webrick' to force WEBrick) => Rails application starting on http://0.0.0.0:3000 => Call with -d to detach => Ctrl-C to shutdown server ** Starting Mongrel listening at 0.0.0.0:3000 ** Starting Rails with development environment... Exiting /usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/commands/servers/mongrel.rb:15: warning: already initialized constant OPTIONS /usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/commands/servers/mongrel.rb:18: undefined method `options' for []:Array (NoMethodError) ...
as a result of /usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/commands/servers/webrick.rb being loaded twice.
[edit] What I found out
When I printed out the call stack from /usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/commands/servers/webrick.rb, I found that the call stacks were nearly identical, with the only difference that one showed a require from line 27 of rubygems/custom_require.rb and the other was from line 32 of the same file. These lines are shown below:
/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb
def require(path) # :nodoc:
gem_original_require path # 1st require (line 27)
rescue LoadError => load_error
begin
if spec = Gem.searcher.find(path)
Gem.activate(spec.name, false, "= #{spec.version}")
gem_original_require path # 2nd require (line 32)
else
raise load_error
end
end
end
It was quickly apparent that there was a LoadError (somewhere, somehow) that was being raised, which caused us to get into the rescue block, which caused the second require to occur.
What's disconcerting, however, is that the first require (line 27) actually succeeded, rendering the second require not only redundant but problematic.
What do I mean by "the first require succeeded"? Well, the require on line 27 succeeded. The requested path ('commands/servers/webrick.rb') was indeed found in the load path (/usr/lib/ruby/gems/1.8/gems/rails-1.2.3/) and loaded.
It was while commands/servers/webrick.rb was still being loaded that we had another LoadError. This LoadError had nothing to do with the require on custom_require.rb line 27 failing. The only reason the error was caught by that rescue block was because the LoadError wasn't rescued higher up in the call stack.
All right, what caused the LoadError then?
This is how I answered that question for myself:
/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb
def require(path) # :nodoc:
(puts "Trying to require '#{path}' from existing load_path") if path == 'commands/servers/webrick'
gem_original_require path
rescue LoadError => load_error
(pp load_error; pp load_error.backtrace) if path == 'commands/servers/webrick'
begin
if spec = Gem.searcher.find(path)
Gem.activate(spec.name, false, "= #{spec.version}")
(puts "Activating gem '#{spec.name}' in order to require '#{path}'") if path == 'commands/servers/webrick'
gem_original_require path
else
raise load_error
end
end
end
This is the output I got back:
=> Booting WEBrick... Trying to require 'commands/servers/webrick' from existing load_path --------------------------------------------------------------------------------------- In /usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/commands/servers/webrick.rb... #<MissingSourceFile: no such file to load -- loaded_plugins> ["/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:28:in `gem_original_require'", "/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:28:in `require'", "/usr/lib/ruby/gems/1.8/gems/activesupport-1.4.2/lib/active_support/dependencies.rb:495:in `require'", "/usr/lib/ruby/gems/1.8/gems/activesupport-1.4.2/lib/active_support/dependencies.rb:342:in `new_constants_in'", "/usr/lib/ruby/gems/1.8/gems/activesupport-1.4.2/lib/active_support/dependencies.rb:495:in `require'", "./script/../config/../vendor/plugins/plugin_migrations/lib/plugin_migrations.rb:1", "/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:28:in `gem_original_require'", "/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:28:in `require'", "/usr/lib/ruby/gems/1.8/gems/activesupport-1.4.2/lib/active_support/dependencies.rb:495:in `require'", "/usr/lib/ruby/gems/1.8/gems/activesupport-1.4.2/lib/active_support/dependencies.rb:342:in `new_constants_in'", "/usr/lib/ruby/gems/1.8/gems/activesupport-1.4.2/lib/active_support/dependencies.rb:495:in `require'", "script/../config/../vendor/plugins/plugin_migrations/init.rb:1:in `load_plugin'", "/usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/initializer.rb:401:in `load_plugin'", "/usr/lib/ruby/gems/1.8/gems/activesupport-1.4.2/lib/active_support/core_ext/kernel/reporting.rb:11:in `silence_warnings'", "/usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/initializer.rb:401:in `load_plugin'", "/usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/initializer.rb:185:in `load_plugins'", "/usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/initializer.rb:185:in `each'", "/usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/initializer.rb:185:in `load_plugins'", "/usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/initializer.rb:105:in `process'", "/usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/initializer.rb:43:in `send'", "/usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/initializer.rb:43:in `run'", "./script/../config/../config/environment.rb:13", "/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:28:in `gem_original_require'", "/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:28:in `require'", "/usr/lib/ruby/gems/1.8/gems/activesupport-1.4.2/lib/active_support/dependencies.rb:495:in `require'", "/usr/lib/ruby/gems/1.8/gems/activesupport-1.4.2/lib/active_support/dependencies.rb:342:in `new_constants_in'", "/usr/lib/ruby/gems/1.8/gems/activesupport-1.4.2/lib/active_support/dependencies.rb:495:in `require'", "/usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/commands/servers/webrick.rb:63", "/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:28:in `gem_original_require'", "/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:28:in `require'", "/usr/lib/ruby/gems/1.8/gems/activesupport-1.4.2/lib/active_support/dependencies.rb:495:in `require'", "/usr/lib/ruby/gems/1.8/gems/activesupport-1.4.2/lib/active_support/dependencies.rb:342:in `new_constants_in'", "/usr/lib/ruby/gems/1.8/gems/activesupport-1.4.2/lib/active_support/dependencies.rb:495:in `require'", "/usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/commands/server.rb:39", "/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:28:in `gem_original_require'", "/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:28:in `require'", "./script/server:3"] Activating gem 'rails' in order to require 'commands/servers/webrick' --------------------------------------------------------------------------------------- In /usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/commands/servers/webrick.rb... /usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/commands/servers/webrick.rb:22: warning: already initialized constant OPTIONS
So you can see that the actual LoadError was MissingSourceFile: no such file to load -- loaded_plugins, which was caused by ./script/../config/../vendor/plugins/plugin_migrations/lib/plugin_migrations.rb:1:
require 'loaded_plugins'
As you can see, this failure had nothing to do with RubyGems not being able to require commands/servers/webrick.rb. So why does RubyGems determine that it needs to try activiting the 'rails' gem (which I'm pretty sure had already been activated, judging by the value of $LOAD_PATH) and trying the require commands/servers/webrick.rb again??
Not only does that fail to help resolve the actual LoadError that was raised; it causes commands/servers/webrick.rb to be loaded twice, which causes some unwanted side effects, as described under "Symptoms".
[edit] A more general test case
Download, package, and install this gem: http://svn.tylerrick.com/public/ruby/examples/should_only_be_loaded_once/
Get this code:
svn export http://svn.tylerrick.com/public/ruby/examples/expose_rubygems_load_error_double_require_bug
And read http://svn.tylerrick.com/public/ruby/examples/expose_rubygems_load_error_double_require_bug/Readme
When run (before applying the patch), you will see this output:
ruby main.rb
Successfully loaded /usr/lib/ruby/gems/1.8/gems/should_only_be_loaded_once-0.0.1/lib/should_only_be_loaded_once.rb (1th time)
Successfully loaded /usr/lib/ruby/gems/1.8/gems/should_only_be_loaded_once-0.0.1/lib/should_only_be_loaded_once.rb (2th time)
/usr/lib/ruby/gems/1.8/gems/should_only_be_loaded_once-0.0.1/lib/should_only_be_loaded_once.rb:4: YOU WEREN'T SUPPOSED TO LOAD THIS FILE MORE THAN ONCE! YOU JUST BLEW UP THE UNIVERSE! (RuntimeError)
from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:37:in `gem_original_require'
from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:37:in `require'
from main.rb:4
Or, with this debug code in place:
def require(path) # :nodoc:
puts "Trying to require '#{path}' from existing load_path"
gem_original_require path
rescue LoadError => load_error
puts "Rescued #{load_error.inspect}"
begin
if spec = Gem.searcher.find(path)
Gem.activate(spec.name, false, "= #{spec.version}")
puts "Activating gem '#{spec.name}' in order to require '#{path}'"
gem_original_require path
else
puts "Re-raising #{load_error.inspect}"
raise load_error
end
end
end
, we see this output:
Trying to require 'should_only_be_loaded_once' from existing load_path Successfully loaded /usr/lib/ruby/gems/1.8/gems/should_only_be_loaded_once-0.0.1/lib/should_only_be_loaded_once.rb (1th time) Trying to require 'some_non-existent_file' from existing load_path Rescued #<LoadError: no such file to load -- some_non-existent_file> Re-raising #<LoadError: no such file to load -- some_non-existent_file> Rescued #<LoadError: no such file to load -- some_non-existent_file> Activating gem 'should_only_be_loaded_once' in order to require 'should_only_be_loaded_once' Successfully loaded /usr/lib/ruby/gems/1.8/gems/should_only_be_loaded_once-0.0.1/lib/should_only_be_loaded_once.rb (2th time) /usr/lib/ruby/gems/1.8/gems/should_only_be_loaded_once-0.0.1/lib/should_only_be_loaded_once.rb:4: YOU WEREN'T SUPPOSED TO LOAD THIS FILE MORE THAN ONCE! YOU JUST BLEW UP THE UNIVERSE! (RuntimeError)
[edit] A solution (patch)
http://svn.tylerrick.com/public/ruby/examples/expose_rubygems_load_error_double_require_bug/patch/patch (the contents thereof will be automatically included, as soon as that becomes possible)
diff -u /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb.orig /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb
def require(path) # :nodoc:
gem_original_require path
rescue LoadError => load_error
- begin
- if spec = Gem.searcher.find(path)
- Gem.activate(spec.name, false, "= #{spec.version}")
- gem_original_require path
- else
- raise load_error
+ if load_error.message == "no such file to load -- #{path}"
+ begin
+ if spec = Gem.searcher.find(path)
+ Gem.activate(spec.name, false, "= #{spec.version}")
+ gem_original_require path
+ else
+ raise load_error
+ end
end
+ else
+ # This isn't our error. Re-raise it!
+ raise
end
end
end # module Kernel
When I run my test case again, I get this output:
Successfully loaded /usr/lib/ruby/gems/1.8/gems/should_only_be_loaded_once-0.0.1/lib/should_only_be_loaded_once.rb (1th time)
/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in `gem_original_require': no such file to load -- some_non-existent_file (LoadError)
from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in `require'
from /usr/lib/ruby/gems/1.8/gems/should_only_be_loaded_once-0.0.1/lib/should_only_be_loaded_once.rb:5
from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in `gem_original_require'
from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in `require'
from lib/main.rb:4
Much better! We actually see the load error for some_non-existent_file.rb. We actually find out about it now! (Before the patch, this error would be silently rescued and we wouldn't even find out about -- instead, we would end up getting other side effects or errors that resulted from loading should_only_be_loaded_once.rb a second time!)
It is much better / more helpful to get this error:
./script/../config/../vendor/plugins/plugin_dependencies/lib/plugin_dependencies/extensions/kernel.rb:14:in `gem_original_require_without_plugins': no such file to load -- loaded_plugins (MissingSourceFile)
than to get this error, which tells us nothing about what actually went wrong (and actually makes it appear that the error is somewhere else):
/usr/lib/ruby/gems/1.8/gems/rails-1.2.3/lib/commands/servers/mongrel.rb:18: undefined method `options' for []:Array (NoMethodError)
Ticket/Bug tracker: http://rubyforge.org/tracker/index.php?func=detail&aid=10677&group_id=126&atid=575
[edit] Another, superfluous and extra and extraneous (but still rather good :) ) explanation
Tyler on http://rubyforge.org/tracker/index.php?func=detail&aid=10677&group_id=126&atid=575
The problem was that require() was rescuing all
LoadErrors, evenLoadErrors that had nothing to do with the failure of the gem_original_require call that was attempted within this method.The problem is that Ruby's exception handling mechanism only lets you specify the *class* of the exception that you want to rescue:
rescue LoadError => load_errorBut in this particular case, that is too broad a category of errors to rescue.
Because what if, after it successfully finds and starts loading the required file, it hits another (unrelated)
LoadError(for "file_B") while still in the process of loading the first file ("file_A")?The current behavior -- which is to rescue the
LoadErrorfor file_B, and then attempt to activate a gem that contains the path "file_A", and then attempt to load file_A again -- does not make any sense.It would be far better, I feel, to have RubyGems actually check if the
LoadErrorwas raised by RubyGems or not, and only rescue the error and do all that stuff in the case that it WAS an error that was raised as a result of something RubyGems was doing.Fortunately, Ruby makes it very easy to inspect the details of the error after you've rescued it and to "change your mind" and re-raise the error if you decide you're not interested in rescuing it.
So my solution is simple: We just check if the
LoadErroris actually for thepaththat was passed in torequire(), and if not, we re-raise it:rescue LoadError => load_error + if load_error.message == "no such file to load -- #{path}" ... + else + # This isn't our error. Re-raise it! + raise endNow, instead of seeing an error that is completely unrelated to the actual source of the error -- for example:
.../rails-1.2.3/lib/commands/servers/mongrel.rb:18: undefined method `options' for []:Array (NoMethodError)-- RubyGems will let the
LoadErrorpercolate up the call stack unhandled so that it actually reaches its intended destination: the developer!.../plugin_dependencies/extensions/kernel.rb:14:in `gem_original_require_without_plugins': no such file to load -- loaded_plugins (MissingSourceFile)
Categories: Gems | Ruby | Ruby problems | Rails | Rails problems
