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

Announcement (2017-05-07): www.ruby-forum.com is now read-only since I unfortunately do not have the time to support and maintain the forum any more. Please see rubyonrails.org/community and ruby-lang.org/en/community for other Rails- und Ruby-related community platforms.
Gary W. (Guest)
on 2009-06-04 20:43
(Received via mailing list)
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 unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email
Charles Oliver N. (Guest)
on 2009-06-05 20:42
(Received via mailing list)
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: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'
...
> 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
Gary W. (Guest)
on 2009-06-05 21:10
(Received via mailing list)
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:

1. 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---

2. Create the path "test/unit"

3. 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--

4. 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
Jay McGaffigan (Guest)
on 2009-06-05 22:15
(Received via mailing list)
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. <removed_email_address@domain.invalid>
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
Charles Oliver N. (Guest)
on 2009-06-05 22:27
(Received via mailing list)
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
Gary W. (Guest)
on 2009-06-08 17:56
(Received via mailing list)
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
Charles Oliver N. (Guest)
on 2009-06-09 06:08
(Received via mailing list)
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
Tal R. (Guest)
on 2009-06-22 05:21
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
This topic is locked and can not be replied to.