Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Already on GitHub? Sign in to your account

Race condition: test_mode! intermittent failures (rails 3.2) #44

Closed
sarmiena opened this Issue Apr 2, 2012 · 0 comments

Comments

Projects
None yet
2 participants
Contributor

sarmiena commented Apr 2, 2012

Easiest to spot using the following stack

Rails 3.2, Devise, RSpec2, Capybara, Selenium

What's going on

_on_next_request is being dequeued on asset requests. This results in unintended results when you do subsequent requests.

Investigation

I modified lib/warden.rb #test_mode! to log what's going on

  def self.test_mode!
    unless Warden::Test::WardenHelpers === Warden
      Warden.extend Warden::Test::WardenHelpers
      Warden::Manager.on_request do |proxy|
        # Begin logger
          ::Rails.logger.info ">>>>> LOGGING Warden: Queue size #{_on_next_request.size} <<<<<<<"
        # End logger

        while blk = Warden._on_next_request.shift
          blk.call(proxy)
        end
      end
    end
    true
  end

Example of offending test

it "should show the login/register page if the user's session timed out" do
    user = FactoryGirl.create(:user)
    login_as(user, scope: :user)
    visit(admin_path)

    logout(:user) # User was logged in when page first loaded, but then got logged out

    click_link('Admin Home')
    page.should have_content('Login')
    page.should have_content('Register')
end

test.log (Shows cause & symptoms)

Started GET "/admin" for 127.0.0.1 at 2012-04-02 12:33:11 -0700
>>>>> LOGGING Warden: in queue 1 <<<<<<<
   (0.1ms)  SAVEPOINT active_record_1
   (0.2ms)  UPDATE "contact_users" SET "last_sign_in_at" = '2012-04-02 19:33:11.543532', "current_sign_in_at" = '2012-04-02 19:33:11.543532', "last_sign_in_ip" = '127.0.0.1', "current_sign_in_ip" = '127.0.0.1', "sign_in_count" = 1, "updated_at" = '2012-04-02 19:33:11.544275' WHERE "contact_users"."id" = 1
. . .
Completed 200 OK in 80ms (Views: 59.7ms | ActiveRecord: 3.2ms)

Started GET "/assets/application.js" for 127.0.0.1 at 2012-04-02 12:33:11 -0700
>>>>> LOGGING Warden: in queue 0 <<<<<<<
Served asset /application.js - 200 OK (0ms)
.
.
.
Started GET "/assets/classic-loader.gif" for 127.0.0.1 at 2012-04-02 12:33:12 -0700
>>>>> LOGGING Warden: in queue 1 <<<<<<< 
Served asset /classic-loader.gif - 200 OK (0ms)
.
.
.
Started GET "/admin" for 127.0.0.1 at 2012-04-02 12:33:11 -0700
>>>>> LOGGING Warden: in queue 0 <<<<<<<
. . .
Completed 200 OK in 80ms (Views: 59.7ms | ActiveRecord: 3.2ms)

Conclusion

The _on_next_request block won't honor logout (and most likely login_as) if it's an asset request. I propose that we don't run the callback if it's an asset request, but add a way to opt out of this behavior.

@hassox hassox closed this in e67abc7 Apr 11, 2012

driedtoast pushed a commit to nodedef/warden that referenced this issue Mar 7, 2013

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