wrong status code when using selenium + rspec #178

Closed
wilkerlucio opened this Issue Nov 1, 2010 · 44 comments

Comments

Projects
None yet
8 participants

When some specs using Selenium fails, the runner don't return 1 as status code, it returns 0 (but some test failed, it should return 1).

I confirmed with a little application, I will post here the used files to reproduce the bug:

Gemfile
source 'http://rubygems.org'

gem 'rails', '3.0.1'
gem 'sqlite3-ruby', :require => 'sqlite3'

group :test do
  gem 'rspec-rails', '>=2.0.1'
  gem 'capybara'
end

spec/spec_helper.rb
ENV["RAILS_ENV"] ||= 'test'
require File.expand_path("../../config/environment", FILE)
require 'rspec/rails'
require 'capybara'
require 'capybara/dsl'

Capybara.default_driver = :selenium

Dir[Rails.root.join("spec/support/**/*.rb")].each {|f| require f}

RSpec.configure do |config|
  config.mock_with :rspec
  config.fixture_path = "#{::Rails.root}/spec/fixtures"
  config.use_transactional_fixtures = true
end

spec/failed_spec.rb
require File.expand_path("../spec_helper", FILE)

describe "testing" do
  include Capybara

  it "will fail" do
    visit '/'
    page.should have_content("im a failing one")
  end
end

try to run:
RAILS_ENV=test rspec spec/failing_spec.rb

them:
echo $?

the result should be 1, but returns 0.
It only happens when using Selenium driver, if change to default driver (config on spec_helper) it returns 1, as it should.

Collaborator

jnicklas commented Nov 1, 2010

That's very odd, unfortunately I know next to nothing about the RSpec internals and have no idea what could be causing this :S

maybe the opening of firefox is causing the selenium to return the exit code of firefox (which should be 0) and replacing the exit code of program.

maybe Im totally wrong too... its just a theory...

Collaborator

jnicklas commented Nov 9, 2010

That's not entirely unreasonable. It might have something to do with threading issues as well, since we're launching the Rails app on a separate thread. Any chance you could investigate this further?

paneq commented Dec 10, 2010

I have the same issue but using test::unit

File test/capybara_helper.rb :

require File.expand_path(File.join(File.dirname(__FILE__), "test_helper"))

require 'capybara/rails'
require "selenium-webdriver"
require 'capybara/dsl'

class CapybaraTest < ActionController::IntegrationTest
  include ActionController::RecordIdentifier
  include Capybara
  Capybara.default_driver = :selenium
  Capybara.default_selector = :css
  Capybara.default_wait_time = 5

  self.use_transactional_fixtures = false

  def login
    visit(new_user_session_path)

    within("#user_new") do
      fill_in 'Login', :with => 'a'
      fill_in 'Password', :with => 'b'
    end
  end
end

File: test/integration/login_test.rb

require 'capybara_helper'

class LoginTest < CapybaraTest

  test "I can login and log out" do
    login() # Comment and uncomment to see the difference in runner exit code
    assert_equal 1,2
  end

end

Commenting calling the "login()" method in the test leads to runner returning 1 which means error. Running selenium however (uncommmented line) leads to returning 0.

paneq commented Dec 10, 2010

I checked that using selenium webdriver without capybara does not cause this problem. Oh and btw I'm using capybara 0.3.9

This works fine:

test/capybara_helper.rb :

require File.expand_path(File.join(File.dirname(__FILE__), "test_helper"))

require "selenium-webdriver"

class CapybaraTest < ActionController::IntegrationTest
  self.use_transactional_fixtures = false
  def login
    f = Selenium::WebDriver.for(:firefox)
    f.navigate.to("http://google.com")
    f.close
  end
end

test/integration/login_test.rb :

require 'capybara_helper'
class LoginTest < CapybaraTest
  test "I can login and log out" do
    login
    assert_equal 1,2
  end
end

paneq commented Dec 10, 2010

Running this way:

require 'capybara_helper'
class LoginTest < CapybaraTest
  before do
    @f = Selenium::WebDriver.for(:firefox)
  end

  test "I can login and log out" do
    @f.navigate.to("http://google.com")
    assert_equal 1,2
  end

  after do
    @f.close
  end
end

also returns proper error code (1) so probably it is a capybara bug.

paneq commented Dec 10, 2010

I looked at capybara/driver/selenium_driver.rb :

  def self.driver
    unless @driver
      @driver = Selenium::WebDriver.for :firefox
      at_exit do
        @driver.quit
      end
    end
    @driver
  end

and was able to reproduce the bug:

require 'capybara_helper'

class LoginTest < CapybaraTest

  test "I can login and log out" do
    @driver = Selenium::WebDriver.for :firefox
    at_exit do
      @driver.quit
    end
    @driver.navigate.to("http://google.com")
    assert_equal 1,2
  end
end

This is more or less what capybara does, doesn't it ?

I hope it will be useful for you.

paneq commented Dec 11, 2010

Running it with minitest returns wrong exit code:

require 'rubygems'
require 'selenium-webdriver'
require 'minitest/autorun'
class TestMeme < MiniTest::Unit::TestCase
  def test_flunk
    @driver = Selenium::WebDriver.for :firefox
    at_exit do
     @driver.quit
    end
    @driver.navigate.to("http://google.com")

    flunk("no reason")
  end
end

17:00  ~/develop/gavdihrpif (masterpatch) > ruby x.rb 
Loaded suite x
Started
F
Finished in 5.544404 seconds.
  1) Failure:
test_flunk(TestMeme) [x.rb:15]:
no reason

1 tests, 1 assertions, 1 failures, 0 errors, 0 skips
17:01  ~/develop/gavdihrpif (masterpatch) > echo $?
0

paneq commented Dec 11, 2010

Selenium webdriver starts a new firefox process using ChildProcess gem. Using it we can reporoduce the bug:

require 'minitest/autorun'

require 'rubygems'
require 'childprocess'

class TestMeme < MiniTest::Unit::TestCase

  def test_flunk
    @process = ChildProcess.build("sleep 100")
    @process.start

    at_exit do
      begin
        @process.poll_for_exit 5
      rescue ChildProcess::TimeoutError
        @process.stop 5
      end
    end
    flunk("no reason")
  end
end

If we lower the sleep time of subprocess to 0 then the return code is 1 which is ok. When it sleeps for 100 second then there is timeout after 5 seconds and the return code of the whole programm is unfortunately 0.

Collaborator

jnicklas commented Dec 11, 2010

Wow, what a weird bug. This is all a bit over my head, do you have a suggestion how we can get this fixed?

paneq commented Dec 11, 2010

I'm going to create a bug for minitest. I'm not sure we can fix this easily unless there is some hook in testing framework that is run after all tests are finished. That could be used instead of at_exit(){}. Let's see what people from ruby think about it. Maybe it is even deeper bug in ruby that the error code is returned wrongly when another subprocess is closed in at_exit hook. Who knows... :-)

This is a bug in selenium or capybara calling exit in an at_exit handler (I haven't tracked it down, but above it looks like @driver.quit prolly does it). Libraries shouldn't do that 99% of the time (test runner frameworks being an obvious exception). I have a workaround for minitest that I'm testing, but you'll have this problem with all testing frameworks out there that don't anticipate bugs like this.

I just committed a fix to minitest. Please test.

This still won't change things with rspec and others. I suggest you track down the real problem and fix it too.

paneq commented Dec 13, 2010

I would be glad to test it however i do not know where to find your patch.

All our stuff is in our seattlerb group.

https://github.com/seattlerb/minitest

paneq commented Dec 13, 2010

Wow! This magic really works. Could you tell what should I do to start using this patch across all computers right now ? Is there an easy way to use minitest from gem or git instead of minitest included with ruby 1.9.2 ? I'm not sure how to do that ? I tested the fix using monkey-patching but I do not want to relay on that in the long term.

paneq commented Dec 13, 2010

MiniTest has been fixed and I created the ticket for rspec runner with links to this discussion and the solution that they could use to fix the same issue. https://github.com/dchelimsky/rspec/issues/issue/12

Guys... the bug is in capybara or selenium. Don't push this out on all the testing frameworks out there. It doesn't scale. Please identify the root cause and fix it.

paneq: you can use minitest as a gem by activating it using the 'gem' method before you require minitest.

paneq commented Dec 13, 2010

I have trouble finding an error in capybara/selenium with that. As you can see at : https://github.com/jnicklas/capybara/issues#issue/178/comment/605003 new process is spawned and then kill at at_exit hook. I could not find any code calling exit from the same process. I'm trying to reproduce the bug without using 'childprocess' library (which is used by selenium).

paneq commented Dec 13, 2010

This is getting stranger with every minute.

This works fine:

class TestMeme < MiniTest::Unit::TestCase
  def test_flunk

    pid = fork do
      exec("sleep 100") # firefox in reality
    end
   
    at_exit do
        ::Process.kill "TERM", pid
        sleep 2
        ::Process.kill "KILL", pid
        sleep 2
    end

    flunk("no reason")
  end
end

This not:

class TestMeme < MiniTest::Unit::TestCase
  def test_flunk
    pid = fork do
      exec("sleep 100") # firefox in reality
    end
   
    at_exit do
      begin
        ::Process.kill "TERM", pid
        raise "blah"
      rescue
        sleep 2
        ::Process.kill "KILL", pid
        sleep 2
      end
    end

    flunk("no reason")
  end
end

Ruby bug?

paneq commented Dec 13, 2010

And capybara => selenium-driver => childprocess uses this version with begin/rescue/end block under the hood to manage firefox process of courese.

paneq commented Dec 13, 2010

My previous example was tested on the unpatched minitest. It works fine with the patched version.

paneq commented Dec 13, 2010

@zenspider - Do you still think that this is a bug in capybara/selenium ? Because i think is more ruby/minitest thing. Your patch is fine. I do not think that we do something wrong here that could be patched in capybara/selenium. And i have no idea why begin/rescue/end block makes the difference.

paneq commented Dec 13, 2010

@zenspider - how to bundle 'minitest' ?

Updating https://github.com/seattlerb/minitest.git
Fetching source index for http://rubygems.org/
Could not find gem 'minitest (>= 0, runtime)' in https://github.com/seattlerb/minitest.git (at master).
Source does not contain any versions of 'minitest (>= 0, runtime)'

sunaku commented Jan 6, 2011

I added the following debugging code at the top of my test/test_helper.rb in my Rails app:

module Kernel
  alias __at_exit__ at_exit
  def at_exit(&b)
    p :registering_at_exit => b
    puts caller, nil
    __at_exit__ { p :calling_at_exit => b; b.call }
  end
end

This showed me that:

  1. Minitest registers its at_exit hook.

  2. Minitest's at_exit hook is triggered, causing all tests to be run.

  3. When the first page.visit() call occurs in my capybara test, the selenium webdriver is activated. As part of this activation, the following new at_exit hooks are registered:

    #Proc:0x00000003eb1510@/home/sunny/.rvm/gems/ruby-1.9.2-p136@rails3/gems/selenium-webdriver-0.1.0/lib/selenium/webdriver/common/file_reaper.rb:38

    #Proc:0x00000005314bd8@/home/sunny/.rvm/gems/ruby-1.9.2-p136@rails3/gems/capybara-0.4.0/lib/capybara/driver/selenium_driver.rb:87

  4. My capybara test and all other tests finish running.

  5. Minitest's at_exit hook finishes, setting the proper value for Ruby's exit status.

  6. The new at_exit hooks (registered in step #3) are run in the following order. They screw up Ruby's exit status that was set by Minitest in step #5.

    #Proc:0x00000005314bd8@/home/sunny/.rvm/gems/ruby-1.9.2-p136@rails3/gems/capybara-0.4.0/lib/capybara/driver/selenium_driver.rb:87

    #Proc:0x00000003eb1510@/home/sunny/.rvm/gems/ruby-1.9.2-p136@rails3/gems/selenium-webdriver-0.1.0/lib/selenium/webdriver/common/file_reaper.rb:38

In summary, I observed that child at_exit hooks registered within the execution of a parent at_exit hook are executed after the parent and all of its siblings are executed. Perhaps this is a bug in Ruby? (I would expect all child hooks to be executed just before their parent returns.)

For the time being, the workaround seems to be to force capybara's at_exit hooks (see step #3) to be registered just after step #1 and before step #2. Is this possible?

sunaku commented Feb 15, 2011

I reported the issue of nested at_exit hooks running in strange order on the Ruby issue tracker.

sunaku commented Feb 15, 2011

Matz just approved a fix for the nested at_exit execution order issue, so we'll be seeing a fix for this problem in Ruby itself in the near future. Hurray!

Collaborator

joliss commented Mar 10, 2011

It seems to me that if there should be an interim fix to support Ruby <1.9.3, that fix should probably be in the testing frameworks, not in Capybara (unless someone wants to submit a patch). May I suggest that we close this issue?

paneq commented Mar 10, 2011

I think we can. It was fixed in other libraries.

sunaku commented Mar 10, 2011

@paneq what "other libraries" are you referring to?

paneq commented Mar 10, 2011

I just meant ruby and minitest :-)

Collaborator

jnicklas commented Mar 10, 2011

Closing this.

dblock commented Jun 22, 2011

Workaround in rspec-core, rspec/rspec-core#410.

paneq commented Jun 22, 2011

@dblock:

In your Gemfile:

  gem 'minitest', '~> 2.0.2'
end

dblock commented Jun 22, 2011

@paneq: i am not using minitest, made a pull request in rspec-core copying from minitest tho - thanks.

paneq commented Jun 22, 2011

@dblock - sorry, I didn't notice that the original bug is about rspec. Do you use 1.9.2 ? Does the problem occur on patchlevel 180 ?

dblock commented Jun 22, 2011

@paneq: yes to both

paneq commented Jun 22, 2011

Unfortunately 1.9.2.p180 does not contain the fix for nested at_exit execution :-(

The workaround could be to use 1.9.2.p180 as a base and cherry-pick this commit : ruby/ruby@36a0a1a but I don't know if it applies cleanly.

If it does then installing such custom ruby build with rvm should not be that hard.

dblock commented Jun 22, 2011

@paneq: or take my pull request! rspec/rspec-core#410
I think it's innocent as far as rspec goes, no?

paneq commented Jun 22, 2011

@dblock - innocent as lamb :-)

dblock commented Aug 23, 2011

The workaround in RSpec is having other ugly consequences. Looks like jnicklas#463 might fix this, please consider merging.

Contributor

jarib commented Sep 25, 2011

I'm late to the game, but the problem boils down to this - a begin/rescue inside the at_exit resets $! from SystemExit to nil. ChildProcess doesn't mess with the process' exit codes, but it does have inevitable begin/rescue blocks as part of reliably killing the child.

$ cat at_exit_test.rb
at_exit do
  at_exit do
    begin
      raise "blah"
    rescue
      # ignore
    end
  end

  exit 1
end
$ ruby -v at_exit_test.rb; echo $?
ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin10.8.0]
0

1.8.7 gets it right (IMHO):

$ ruby -v at_exit_test.rb; echo $?
ruby 1.8.7 (2009-06-12 patchlevel 174) [universal-darwin10.0]
1

But even after @sunaku's issue fixed at_exit ordering, the begin/rescue issue is still in 1.9.3:

$ ruby -v at_exit_test.rb; echo $?
ruby 1.9.3dev (2011-07-31 revision 32789) [x86_64-darwin10.8.0]
0

Rubinius gets it right:

$ ruby -v at_exit_test.rb; echo $?
rubinius 2.0.0dev (1.8.7 dded6b24 yyyy-mm-dd JI) [x86_64-apple-darwin10.8.0]
1

$ ruby -X19 -v at_exit_test.rb; echo $?
rubinius 2.0.0dev (1.9.2 dded6b24 yyyy-mm-dd JI) [x86_64-apple-darwin10.8.0]
1

As does JRuby:

$ ruby -v at_exit_test.rb; echo $?      
jruby 1.6.4 (ruby-1.8.7-p330) (2011-08-23 17ea768) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_26) [darwin-x86_64-java]
1
$ ruby --1.9 -v at_exit_test.rb; echo $?
jruby 1.6.4 (ruby-1.9.2-p136) (2011-08-23 17ea768) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_26) [darwin-x86_64-java]
1
$ 

This is a nasty one for sure. I'm tempted to file it as a bug in 1.9.

cc: @dchelimsky, @paneq

Contributor

jarib commented Sep 25, 2011

Looks like it was already filed against 1.9 here

This issue was closed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment