Adding devise async causes order dependent spec failures

[tak1n]

Adding devise-async to our user model leads to generation of wrong SQL when devise does an auto update on login for request specs. For more details see:

rails/rails#26038
http://stackoverflow.com/questions/38635739/request-spec-order-dependent-failure-wrong-sql-created-for-devise-user-update-o

A minimal rails reproduction app is available at https://github.com/tak1n/reproduction (Just run something_test.rb)

[swapnilchincholkar]

@tak1n

I checked your application, it has errors in it as below.

• you have hard-coded db configs
• your route "/something" doesn't match to any route
• I tried to pass test requests to "/" & ran "rake test", everything is passing....

Can you put more details in app or test cases to reproduce the issue?

[tak1n]

@swapnilchincholkar removed hard coded db configs (using peer authentication now)

The route /something does not exist like it is stated in the integration test.
The problem is not that it is failing, the problem is the reason why it is failing.

benny@benny-Lenovo-Y50-70:~/dev/ruby/reproduction$ rake test TEST="test/integration/something_test.rb"
Run options: --seed 46122

# Running:

EE

Finished in 0.056048s, 35.6836 runs/s, 0.0000 assertions/s.

  1) Error:
SomethingTest#test_returns_smth_#1:
NameError: undefined local variable or method `paramst' for #<SomethingTest:0x0055e97ba92e68>
Did you mean?  parameterize
    test/integration/something_test.rb:22:in `block in <class:SomethingTest>'


  2) Error:
SomethingTest#test_returns_smth_#2:
ActiveRecord::StatementInvalid: PG::NotNullViolation: ERROR:  null value in column "created_at" violates not-null constraint
DETAIL:  Failing row contains (61, , , null, null, null, 1, 2016-10-04 13:49:54.344217, 2016-10-04 13:49:54.344217, 127.0.0.1, 127.0.0.1, null, null).
: INSERT INTO "users" ("last_sign_in_at", "current_sign_in_at", "last_sign_in_ip", "current_sign_in_ip", "sign_in_count") VALUES ($1, $2, $3, $4, $5) RETURNING "id"
    test/integration/something_test.rb:31:in `block in <class:SomethingTest>'

2 runs, 0 assertions, 0 failures, 2 errors, 0 skips
benny@benny-Lenovo-Y50-70:~/dev/ruby/reproduction$

The first test should fail (because of the typo), the second test should also fail (route not found), but it fails because of a invalid sql statement. It tries to insert instead of updating it.

When removing devise-async from user model following happens:

benny@benny-Lenovo-Y50-70:~/dev/ruby/reproduction$ rake test TEST="test/integration/something_test.rb"
Run options: --seed 14090

# Running:

EE

Finished in 0.064535s, 30.9907 runs/s, 0.0000 assertions/s.

  1) Error:
SomethingTest#test_returns_smth_#1:
NameError: undefined local variable or method `paramst' for #<SomethingTest:0x0055f6f9fead80>
Did you mean?  parameterize
    test/integration/something_test.rb:22:in `block in <class:SomethingTest>'


  2) Error:
SomethingTest#test_returns_smth_#2:
ActionController::RoutingError: No route matches [GET] "/something.json"
    test/integration/something_test.rb:31:in `block in <class:SomethingTest>'

2 runs, 0 assertions, 0 failures, 2 errors, 0 skips

[swapnilchincholkar]

FYI I am using ruby 2.3.0. Sent pull request for what exactly I am executing at my end. In both situations, keeping :async & removing it from User model, nothing changes to me.

I changed tests as below.
From

get '/something.json', params

to

get '/', params

And did execution as below,

SwapnilChincholkar: devise-aync-issue96 (fixes) $rake db:create
testapp_test already exists
SwapnilChincholkar: devise-aync-issue96 (fixes) $rake db:migrate
== 20160728102607 DeviseCreateUsers: migrating ================================
-- create_table(:users)
   -> 0.0118s
-- add_index(:users, :email, {:unique=>true})
   -> 0.0035s
-- add_index(:users, :reset_password_token, {:unique=>true})
   -> 0.0041s
== 20160728102607 DeviseCreateUsers: migrated (0.0198s) =======================

SwapnilChincholkar: devise-aync-issue96 (fixes) $rake test TEST="test/integration/something_test.rb"
Run options: --seed 64609

# Running:

..

Finished in 0.231163s, 8.6519 runs/s, 0.0000 assertions/s.

2 runs, 0 assertions, 0 failures, 0 errors, 0 skips

Now commenting :async from User model

SwapnilChincholkar: devise-aync-issue96 (fixes) $vi app/models/user.rb 
SwapnilChincholkar: devise-aync-issue96 (fixes) $rake test TEST="test/integration/something_test.rb"
Run options: --seed 54957

# Running:

..

Finished in 0.231773s, 8.6291 runs/s, 0.0000 assertions/s.

2 runs, 0 assertions, 0 failures, 0 errors, 0 skips

[tak1n]

@swapnilchincholkar thx for the pull request, but as said it needs to fail to reproduce it.

I understand that when changing the test (proper route) everything works.

But as we do TDD and tests often fail until we implement the code for it etc its not helpful to see a failing test/spec because a wrong SQL statement was created when including devise :async.

As I said when everything is passing there is no problem at all, the problem occurrs when theres a error in an example/test case.

I mean its clearly that the integration test will fail, but it should fail for these 2 reasons:

1.) The first testcase fails because of a typo (paramst)
2.) The second testcase fails because of a testrequest to a non existing route

which is not the case if you include devise async in the model.

My problem is not how to fix these failures, the problem is the differing behaviour when u include devise async in a model and you have failing tests/specs.

[swapnilchincholkar]

@tak1n I got it, I even got the errors you are facing.

One thing surprises me is, if I keep :async in User model as is & fix 1st error i.e convert "paramst" to "params" in test case 1 i.e

test 'returns smth #1'

that turns 2nd test case's error "PG::NotNullViolation" to "No route matches error". Looking into it, will get back soon.

[tak1n]

@swapnilchincholkar cool thx, appreciate it! 😄

[swapnilchincholkar]

As you commented looks like #2608 is causing this. In my debugging it I got in similar situation. Will keep updating.

[tak1n]

@swapnilchincholkar maybe this issue comment is helping somehow: rails/rails#26038 (comment)

One reason that @new_record can become true because the test failed is that an exception may be causing DatabaseCleaner for example to rollback an transaciton and the recorded state of the model before the transaction was open was a non persisted method

As we proved DatabaseCleaner (transaction strategy) had nothing todo with it, it is also appearing with transactional fixtures comming from rails itself.

In your debugging gist there is this:

    515: def sync_with_transaction_state
    516:   #binding.pry
 => 517:   update_attributes_from_transaction_state(@transaction_state, 0)
    518: end

I'm not sure (as I'm not that experienced with active record transactions) but I think somehow devise-async uses such a method like described above and when rolling back the transaction it updates the attributes to a non persisted state?

[swapnilchincholkar]

@tak1n

Looks like issue is with Warden. Considering integration tests doc & signing in user via request, changing

login_as(user, scope: :user)

to

post_via_redirect user_session_path, user: {email: user.email, password: user.password}

Works everything fine.
(Note: Just "*.js" un-availablity causes a trouble, so clearing require statements from application.js makes everything fall in place correctly)

[tak1n]

@swapnilchincholkar thx for digging further into this.

I will try to see what exactly warden is doing here and why it's causing this behaviour when I got some time again.