Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP

Loading…

Regression on failed runs outputting huge stack trace for rake itself. #198

Closed
zenspider opened this Issue · 14 comments

7 participants

@zenspider

using:

Rake::TestTask.new "testtask"

on ruby 2 with rake 0.9.x:

10016 % rake testtask
Run options: --seed 56356

# Running:

F

Finished in 0.000913s, 1095.2903 runs/s, 1095.2903 assertions/s.

  1) Failure:
woot#test_0001_should die [/Users/ryan/Work/p4/zss/src/minitest/dev/test/test_fail.rb:5]:
no

1 runs, 1 assertions, 1 failures, 0 errors, 0 skips
rake aborted!
Command failed with status (1): [ruby -I"lib" -I"/Library/Ruby/Gems/1.8/gems/rake-0.9.6/lib" "/Library/Ruby/Gems/1.8/gems/rake-0.9.6/lib/rake/rake_test_loader.rb" "test/test*.rb" ]

Tasks: TOP => testtask
(See full trace by running task with --trace)

on ruby 2.0 with rake 10.0.4:

10017 % GEM_PATH=xxx rake20 testtask
Run options: --seed 14367

# Running:

F

Finished in 0.000754s, 1326.2599 runs/s, 1326.2599 assertions/s.

  1) Failure:
woot#test_0001_should die [/Users/ryan/Work/p4/zss/src/minitest/dev/test/test_fail.rb:5]:
no

1 runs, 1 assertions, 1 failures, 0 errors, 0 skips
rake aborted!
Command failed with status (1): [ruby -I"lib" -I"/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib" "/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/rake_test_loader.rb" "test/test*.rb" ]
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/testtask.rb:104:in `block (3 levels) in define'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/file_utils.rb:45:in `call'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/file_utils.rb:45:in `sh'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/file_utils_ext.rb:37:in `sh'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/file_utils.rb:82:in `ruby'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/file_utils_ext.rb:37:in `ruby'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/testtask.rb:100:in `block (2 levels) in define'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/file_utils_ext.rb:58:in `verbose'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/testtask.rb:98:in `block in define'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/task.rb:246:in `call'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/task.rb:246:in `block in execute'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/task.rb:241:in `each'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/task.rb:241:in `execute'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/task.rb:184:in `block in invoke_with_call_chain'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/task.rb:177:in `invoke_with_call_chain'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/task.rb:170:in `invoke'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/application.rb:143:in `invoke_task'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/application.rb:101:in `block (2 levels) in top_level'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/application.rb:101:in `each'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/application.rb:101:in `block in top_level'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/application.rb:110:in `run_with_threads'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/application.rb:95:in `top_level'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/application.rb:73:in `block in run'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/application.rb:160:in `standard_exception_handling'
/Users/ryan/Work/p4/zss/src/minitest/dev/xxx/gems/rake-10.0.4/lib/rake/application.rb:70:in `run'
Tasks: TOP => testtask
(See full trace by running task with --trace)
@jimweirich
Owner

Can I see the code for the failing test (having difficulty replicating your exact results).

@zenspider
@zenspider

rake demo to show the problem. I'm using ruby 2.0:

# -*- ruby -*-

require "rake/testtask"

Rake::TestTask.new "testtask"

task :default => :demo

task :demo => :setup do
  puts "good:"
  system "ruby -S gem list rake"
  output = `ruby -S rake testtask 2>&1`
  puts output
  puts "Lines = #{output.lines.size}"

  puts "bad:"
  ENV["GEM_PATH"] = "tmp"
  system "ruby -S gem list rake"
  output = `ruby -S rake testtask 2>&1`
  puts output
  puts "Lines = #{output.lines.size}"
end

task :setup do
  unless File.directory? "tmp" then
    ruby "-S gem i -i tmp rake --no-rdoc --no-ri"
  end

  unless File.file? "test/test_bug.rb" then
    mkdir_p "test"

    File.open "test/test_bug.rb", "w" do |f|
      f.puts "exit 1"
    end
  end
end

task :clean do
  rm_rf Dir["test", "tmp", "*~"]
end

output:

10067 % rake demo
rake demo
good:

*** LOCAL GEMS ***

rake (0.9.6)
rake aborted!
Command failed with status (1): [ruby -I"lib" -I"/Users/ryan/.rbenv/versions/2.0.0-p0/lib/ruby/2.0.0" "/Users/ryan/.rbenv/versions/2.0.0-p0/lib/ruby/2.0.0/rake/rake_test_loader.rb" "test/test*.rb" ]

Tasks: TOP => testtask
(See full trace by running task with --trace)
Lines = 5
bad:

*** LOCAL GEMS ***

rake (10.0.4, 0.9.6)
rake aborted!
Command failed with status (1): [ruby -I"lib" -I"/Users/ryan/regression/tmp/gems/rake-10.0.4/lib" "/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/rake_test_loader.rb" "test/test*.rb" ]
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/testtask.rb:104:in `block (3 levels) in define'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/file_utils.rb:45:in `call'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/file_utils.rb:45:in `sh'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/file_utils_ext.rb:37:in `sh'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/file_utils.rb:82:in `ruby'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/file_utils_ext.rb:37:in `ruby'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/testtask.rb:100:in `block (2 levels) in define'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/file_utils_ext.rb:58:in `verbose'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/testtask.rb:98:in `block in define'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/task.rb:246:in `call'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/task.rb:246:in `block in execute'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/task.rb:241:in `each'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/task.rb:241:in `execute'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/task.rb:184:in `block in invoke_with_call_chain'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/task.rb:177:in `invoke_with_call_chain'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/task.rb:170:in `invoke'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/application.rb:143:in `invoke_task'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/application.rb:101:in `block (2 levels) in top_level'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/application.rb:101:in `each'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/application.rb:101:in `block in top_level'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/application.rb:110:in `run_with_threads'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/application.rb:95:in `top_level'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/application.rb:73:in `block in run'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/application.rb:160:in `standard_exception_handling'
/Users/ryan/regression/tmp/gems/rake-10.0.4/lib/rake/application.rb:70:in `run'
Tasks: TOP => testtask
(See full trace by running task with --trace)
Lines = 29
@zenspider

Looks like the problem is "fixed" by changing display_error_message from:

        trace Backtrace.collapse(ex.backtrace).join("\n")

to:

        trace Backtrace.collapse(ex.backtrace).first

and the real problem is in Backtrace.collapse.

@jimweirich
Owner

Yes. Backtrace.collapse needed some cleanup. See #193 for details.

In your particular case, the patch for switching \'s to /'s runs after the Regexp quote and screws up the patterns.

There is a 10.1.0.beta.3 on Rubygems.org with that fix, see if that works for you.

@zenspider

Looks good to me as confirmed by adding --pre to the setup task. Thanks.

@jimweirich
Owner

Great.

@jimweirich jimweirich closed this
@bitencode

Thanks @jimweirich. I ran into this problem today on a new project using ruby 2, minitest and rake. 10.1.0.beta.3 fixed it for me (with the exception of the ruby_noexec_wrapper that appear to be coming from RVM - as referenced in #193).

@jkanywhere

@jimweirich I ran into this problem and 10.1.0.beta.3 shortens but does not entirely remove the stack trace.

I'm new to ruby and rake so I hope this is enough information for you to diagnose. Thanks!

My Rakefile

require "bundler/gem_tasks"
require 'rake/testtask'

Rake::TestTask.new do |t| 
  t.libs << "test"
  # OK to use default patter 'test/test*.rb' for now 

  trace = false
end

desc "Run tests"
task :default => :test

ruby info

$ which ruby
/home/jkanywhere/.rvm/rubies/ruby-1.9.3-p392/bin/ruby

$ ruby --version
ruby 1.9.3p392 (2013-02-22 revision 39386) [x86_64-linux]

rake version 10.0.4

produced long stack trace

$ rake --version
rake, version 10.0.4

$ rake test
Run options:

# Running tests:

F.

Finished tests in 0.000392s, 5099.9072 tests/s, 5099.9072 assertions/s.

  1) Failure:
test_that_fails(CredsTest) [/home/jkanywhere/Documents/projects/lolruby/spice-creds-aws/test/test_test.rb:9]:
Failed assertion, no message given.

2 tests, 2 assertions, 1 failures, 0 errors, 0 skips
rake aborted!
Command failed with status (1): [ruby -I"lib:test" -I"/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib" "/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/rake_test_loader.rb" "test/test*.rb" ]
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/testtask.rb:104:in `block (3 levels) in define'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/file_utils.rb:45:in `call'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/file_utils.rb:45:in `sh'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/file_utils_ext.rb:37:in `sh'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/file_utils.rb:82:in `ruby'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/file_utils_ext.rb:37:in `ruby'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/testtask.rb:100:in `block (2 levels) in define'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/file_utils_ext.rb:58:in `verbose'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/testtask.rb:98:in `block in define'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/task.rb:246:in `call'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/task.rb:246:in `block in execute'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/task.rb:241:in `each'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/task.rb:241:in `execute'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/task.rb:184:in `block in invoke_with_call_chain'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/task.rb:177:in `invoke_with_call_chain'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/task.rb:170:in `invoke'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/application.rb:143:in `invoke_task'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/application.rb:101:in `block (2 levels) in top_level'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/application.rb:101:in `each'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/application.rb:101:in `block in top_level'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/application.rb:110:in `run_with_threads'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/application.rb:95:in `top_level'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/application.rb:73:in `block in run'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/application.rb:160:in `standard_exception_handling'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392@global/gems/rake-10.0.4/lib/rake/application.rb:70:in `run'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392/bin/ruby_noexec_wrapper:14:in `eval'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392/bin/ruby_noexec_wrapper:14:in `<main>'
Tasks: TOP => test
(See full trace by running task with --trace)

rake version 10.1.0.beta.3

produced short stack trace

$ rake --version
rake, version 10.1.0.beta.3

$ rake test
Run options:

# Running tests:

F.

Finished tests in 0.000390s, 5134.6564 tests/s, 5134.6564 assertions/s.

  1) Failure:
test_that_fails(CredsTest) [/home/jkanywhere/Documents/projects/lolruby/spice-creds-aws/test/test_test.rb:9]:
Failed assertion, no message given.

2 tests, 2 assertions, 1 failures, 0 errors, 0 skips
rake aborted!
Command failed with status (1): [ruby -I"lib:test" -I"/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392/gems/rake-10.1.0.beta.3/lib" "/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392/gems/rake-10.1.0.beta.3/lib/rake/rake_test_loader.rb" "test/test*.rb" ]
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392/bin/ruby_noexec_wrapper:14:in `eval'
/home/jkanywhere/.rvm/gems/ruby-1.9.3-p392/bin/ruby_noexec_wrapper:14:in `<main>'
Tasks: TOP => test
(See full trace by running task with --trace)
@jimweirich
Owner

I think the ruby_noexec_wrapper stack entries are coming from RVM. Rake is cleaning up its own stack, I'm not sure that it should be messing with stack entries from arbitrary software.

@perlun

FWIW, 10.0.4 has (on Linux with MRI 1.9.3p194) similar issues as this gist reported... (which is also a bit similar to this issue in question).

Switching to rake-10.1.0.beta.3 worked great to fix that regression also.

@effkay

FYI, had the same issue here. Running the same test suite without rvm seemed to do the trick.

@digitalWestie

Same here as with @jkanywhere

@jimweirich
Owner

Fixed in 10.1.0.

@jkline-okta jkline-okta referenced this issue from a commit
Commit has since been removed from the repository and is no longer available.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.