Workaround for rake (even with --trace) seemingly eating stdout and stderr in JRuby - is this ok, or

pfharlock · June 4, 2009, 6:43pm

For testing a JRuby + (Jruby) Rack + Sinatra app, in my Rakefile I have:

—start Rakefile—
raise “Rake must be called with JRuby: try again with `jruby -S rake’”
unless defined?(JRUBY_VERSION)
#raise “Read the README. You need to run runtests.sh to setup the
classpath” unless defined?(RUN_TESTS_CALLED)

Thanks to Nick S. for this line

Dir[“#{File.expand_path ‘lib’}/*.jar”].each {|j| $CLASSPATH << j }

require ‘rubygems’
require ‘rake’
require ‘rake/testtask’

desc “Default: run all tests”
task :default => :test

desc “Run tests”
task :test => %w(test:units test:acceptance)
namespace :test do

desc “Run unit tests”
Rake::TestTask.new(:units) do |t|
t.test_files = FileList[“test/unit/*_test.rb”]
end

desc “Run acceptance tests”
Rake::TestTask.new(:acceptance) do |t|
t.test_files = FileList[“test/acceptance/*_test.rb”]
end
end
—end Rakefile—

Then in test/unit/my_controller_test.rb I have:

—start test/unit/my_controller_test.rb—
log = File.new(“my_controller_test.log”, “w”)
STDOUT.reopen(log)
STDERR.reopen(log)

require ‘my_controller’
require ‘test/unit’
require ‘rack/test’

set :environment, :test

class DcControllerTest < Test::Unit::TestCase

include Rack::Test::Methods

def app
SomeModule::Controller
end
…

end
—end test/unit/my_controller_test.rb—

When the my_controller.rb file was missing (because I’d renamed it and
forgot to change the test) when I called jruby -S rake test I got:

$ 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/dmws_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’
/Users/garyweaver/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’
/Users/garyweaver/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

This wasn’t very useful, so I’d seen that others had a similar hack for
sinatra logging to go to a log, and decided to add the following above
the requires and everything else in my test file:

log = File.new(“name_of_my_test.log”, “w”)
STDOUT.reopen(log)
STDERR.reopen(log)

And now I have a name_of_my_test.log that contains 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

So the question is- shouldn’t rake be displaying this error when I run
it at command line without having to redirect stdout and stderr?

Using jruby from trunk from a few days ago +

jruby-openssl (0.5)
rack (1.0.0)
rack-test (0.3.0)
rake (0.8.7)
rest-client (1.0)
sinatra (0.9.2)
sources (0.0.1)
warbler (0.9.13)

Thanks in advance,

Gary

http://stufftohelpyouout.blogspot.com/2009/06/how-to-find-errors-in-your-test-when.html

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

pfharlock · June 5, 2009, 6:42pm

Gary W. wrote:

“/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake/rake_test_loader.rb”
“test/unit/dmws_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:incall’
/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:insh’
/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:inruby’
…
So the question is- shouldn’t rake be displaying this error when I run
it at command line without having to redirect stdout and stderr?

Well, that’s a good question. It should if running everything with
normal Ruby would do it, but I think this may be a quirk of the way Rake
runs the subprocess.

If you can confirm that we’re not showing something we should, we would
certainly want to fix that. I agree it’s annoying when it suppresses the
error output from running a subprocess.

It’s also possible that because we try to run it in the same JVM the
error output is suppressed incorrectly, but I thought we’d solved all
such issues.

Charlie

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

pfharlock · June 5, 2009, 7:10pm

Charles Oliver N. wrote:

Command failed with status (1): [/path/to/jruby/bin/jruby -I"lib"
`ruby’
If you can confirm that we’re not showing something we should, we
would certainly want to fix that. I agree it’s annoying when it
suppresses the error output from running a subprocess.

It’s also possible that because we try to run it in the same JVM the
error output is suppressed incorrectly, but I thought we’d solved all
such issues.

Charlie

It might have to do with the --trace flag not being set/interpreted
correctly also? Don’t know. I had to comment out the following line
(line 992 of (jruby)/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb) just
to get the command and rake stack trace to show up:

  #show_command = show_command[0,42] + "..." unless $trace

The way to reproduce it (for me at least) without even making any mods
to jruby and rake is to:

Create the file “Rakefile” in an empty dir:

—start Rakefile—
raise “Rake must be called with JRuby: try again with ‘jruby -S rake’”
unless defined?(JRUBY_VERSION)

require ‘rubygems’
require ‘rake’
require ‘rake/testtask’

desc “Default: run all tests”
task :default => :test

desc “Run tests”
task :test => %w(test:units test:acceptance)
namespace :test do

desc “Run unit tests”
Rake::TestTask.new(:units) do |t|
t.test_files = FileList[“test/unit/*_test.rb”]
end

desc “Run acceptance tests”
Rake::TestTask.new(:acceptance) do |t|
t.test_files = FileList[“test/acceptance/*_test.rb”]
end
end
— end Rakefile—

Create the path “test/unit”
Create the file “test/unit/example_test.rb”

–start test/unit/example_test.rb–
require ‘this/does/not/exist’
require ‘test/unit’

class ExampleTest < Test::Unit::TestCase

def test_not_equal
assert_equal ‘foo’, ‘bar’
end

end
–end test/unit/example_test.rb–

Execute: jruby -S rake test --trace

When I run that, I get no notification of the bad require, only a rake
error. If I comment the first bad require in the test, the test runs and
I get test output.

So is this a rake issue or a jruby issue? (I wish I could tell you, but
I don’t know.) If it is a rake issue, is it a rake running with jruby
issue, or should I post that to the rake list?

Thanks!
Gary

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

pfharlock · June 5, 2009, 8:15pm

I have seen this behavior too.
If you look at the line you commented out (BTW I’ve commented it out
on my machine too)
You see that the $trace flag either isn’t persisting or maybe rake is
sh ing another command and the flag isn’t passed through to the new
environment.

It seems to me to be more of a rake issue. When I was running 0.8.3
of rake I remember getting more informative messages.

It’s almost like 2 things are happening … the trace flag is failing
and the results of the “sh” command aren’t being properly piped back
to rake.

in my build I’ve commented out the line you’ve commented out. and when
I get a build I take the command that’s displayed and execute it for
myself. then (like you) I can see what’s wrong. I KNOW I didn’t have
to do this before upgrading Rake (and jruby).

Jay

On Fri, Jun 5, 2009 at 1:10 PM, Gary W. [email protected]
wrote:

** Invoke test:units (first_time)
/path/to/jruby/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:1029:in
Ruby would do it, but I think this may be a quirk of the way Rake runs the

jruby and rake is to:

end
3. Create the file “test/unit/example_test.rb”

don’t know.) If it is a rake issue, is it a rake running with jruby issue,
http://xircles.codehaus.org/manage_email

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

pfharlock · June 8, 2009, 3:56pm

Charles Oliver N. wrote:

happening.

Charlie

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

Created a Rake ticket: http://onestepback.org/redmine/issues/show/54
(feel free to comment if you are having this issue or a similar issue)

Wish I knew whether the bug was in JRuby, Rake, or something else before
filing anything, but perhaps they can assist us in figuring that out.

Thanks,

Gary

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

pfharlock · June 9, 2009, 4:08am

Gary W. wrote:

Created a Rake ticket: http://onestepback.org/redmine/issues/show/54
(feel free to comment if you are having this issue or a similar issue)

Wish I knew whether the bug was in JRuby, Rake, or something else before
filing anything, but perhaps they can assist us in figuring that out.

We’ll probably need to do some legwork ourselves. Maybe we can track it
down to what rake passes to the subprocess in both cruby and jruby and
see if there’s a difference there?

Charlie

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

pfharlock · June 22, 2009, 3:21am

I believe this bug is related:
http://jira.codehaus.org/browse/JRUBY-3520

I’m getting the same standard error swallowing behaviour with several
programs that use popen3.

Gary W. wrote:

Charles Oliver N. wrote:

happening.

Charlie

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

Created a Rake ticket: http://onestepback.org/redmine/issues/show/54
(feel free to comment if you are having this issue or a similar issue)

Wish I knew whether the bug was in JRuby, Rake, or something else before
filing anything, but perhaps they can assist us in figuring that out.

Thanks,

Gary

To unsubscribe from this list, please visit:
http://xircles.codehaus.org/manage_email

pfharlock · June 5, 2009, 8:27pm

Jay McGaffigan wrote:

It’s almost like 2 things are happening … the trace flag is failing
and the results of the “sh” command aren’t being properly piped back
to rake.

in my build I’ve commented out the line you’ve commented out. and when
I get a build I take the command that’s displayed and execute it for
myself. then (like you) I can see what’s wrong. I KNOW I didn’t have
to do this before upgrading Rake (and jruby).

That’s what I’ve been doing too I’d like to understand what’s
happening.

Charlie

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email