Thursday, June 4, 2009

How to Find Errors in Your Test When Rake Eats the Error (Using JRuby)

I scratched my head a good while because rake was not outputting much useful except for the file it was dying on in a rack-test test for a Sinatra application using JRuby and Rake.

One trick to get the error is to do the following in the very top of the test rb file (even above requires, etc. since one of them was the culprit in this case):

log = File.new("tests.log", "w")
STDOUT.reopen(log)
STDERR.reopen(log)
Then again I run jruby -S rake test and get the same useless error:
$ jr rake test --trace
(in /path/to/projectname)
** Invoke test (first_time)
** Invoke test:units (first_time)
** Execute test:units
rake aborted!
Command failed with status (1): [/path/to/jruby/bin/jruby -I"lib" "/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake/rake_test_loader.rb" "test/unit/my_controller_test.rb" ]
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:995:in `sh'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:1010:in `call'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:1010:in `sh'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:1098:in `sh'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:1029:in `ruby'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:1098:in `ruby'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake/testtask.rb:117:in `define'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:1112:in `verbose'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake/testtask.rb:102:in `define'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:636:in `call'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:636:in `execute'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:631:in `each'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:631:in `execute'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:597:in `invoke_with_call_chain'
/path/to/jruby/lib/ruby/1.8/monitor.rb:191:in `mon_synchronize'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:590:in `invoke_with_call_chain'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:607:in `invoke_prerequisites'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:604:in `each'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:604:in `invoke_prerequisites'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:596:in `invoke_with_call_chain'
/path/to/jruby/lib/ruby/1.8/monitor.rb:191:in `mon_synchronize'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:590:in `invoke_with_call_chain'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:583:in `invoke'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2051:in `invoke_task'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2029:in `top_level'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2029:in `each'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2029:in `top_level'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2068:in `standard_exception_handling'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2023:in `top_level'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2001:in `run'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2068:in `standard_exception_handling'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:1998:in `run'
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/bin/rake:31
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/bin/rake:19:in `load'
/path/to/jruby/bin/rake:19
But, now I have a tests.log containing the error causing this mess!:
test/unit/my_controller_test.rb:5:in `require': no such file to load -- my_controller (LoadError)
        from test/unit/my_controller_test.rb:5
        from test/unit/my_controller_test.rb:5:in `load'
        from /path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake/rake_test_loader.rb:5
        from /path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake/rake_test_loader.rb:5:in `each'
        from /path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake/rake_test_loader.rb:5
If you do this, you might want to capture all tests output into the same log, because the overall summary goes into the last file that it was redirected into.

Note, according to Nick and Charlie this is fixed in 1.3.1:

Yeah, I think this is the issue. In some cases it seems like stderr is
silenced and in other cases it's not. We could probably go ahead and
apply this patch to master, since it was only to eliminate an annoying
stderr output in the spec run.

On Tue, Jul 14, 2009 at 11:10 AM, Nick Sieger wrote:
> > I noticed this problem as well. I think this was a bug in 1.3.0 that
> > we fixed for 1.3.1. The commit is here:
> >
> > http://github.com/jruby/jruby/commit/2fd6c3d9018ba3d1e3e80f280d04f94c14351eaa
> >
> > /Nick

No comments: