v4.6.0 breaks rspec controller tests

[philayres]

Environment

• Ruby 2.4.5
• Rails 4.2.7
• Devise 4.6.0

Current behavior

I just updated to 4.6.0 (no other changes were made) and the rspec controller tests now return undefined method root_path after running a sign_in.

4.5.0 does not exhibit this behaviour.

Expected behavior

root_path should return a value.

[feliperenan]

Hi @philayres, thanks for the issue.

Could you provide more info about what is happening in your application? It could be an application that reproduces this issue in isolation or just the stacktrace.

[philayres]

This is the rspec example:

  describe "GET #new" do
    before_each_login_user

    it "assigns a new item as @var" do
      master_id = create_master.id
      get :new, {master_id: master_id}
      expect(assigns(object_symbol)).to be_a_new(object_class)
    end
  end

The error is:

  6) AddressesController behaves like a standard user controller GET #new assigns a new item as @var
     Failure/Error: get :new, {master_id: master_id}
     
     NoMethodError:
       undefined method `root_path' for #<Module:0x000055bff178b7f0>
     Shared Example Group: "a standard user controller" called from ./spec/controllers/addresses_controller_spec.rb:20
     # ./spec/support/standard_user_controller.rb:53:in `block (3 levels) in <top (required)>'

That error aligns with the rspec example. But in reality every similar example like this fails.

As soon as I rolled back to 4.5.0 the error went away.

[philayres]

Oh, and the method for logging in

  def before_each_login_user
    before(:each) do

      user, pw = ControllerMacros.create_user
      @request.env["devise.mapping"] = Devise.mappings[:user]

      res = sign_in user
      @user = user
    end
  end

I have both a user and admin entity working independently.

[feliperenan]

Could you also send the backtrace? that would help find where it's breaking inside Devise.

[philayres]

That's the strange thing. In the console you have the full error that I have in the comment above (which is strangely short). In the test log, despite having changed logging level to :debug it still doesn't give me the error or any stack trace.

I'm assuming that there is something nasty happening low down the stack that is getting swallowed up without logging. I'll keep digging to see if I can find more info.

[philayres]

I have stepped through in a debugger and have narrowed it down to:

gems/devise-4.6.0/lib/devise/test/controller_helpers.rb around line 140:

def _process_unauthenticated(env, options = {})
        options[:action] ||= :unauthenticated
        proxy = request.env['warden']
        result = options[:result] || proxy.result

        ret = case result
        when :redirect
          body = proxy.message || "You are being redirected to #{proxy.headers['Location']}"
          [proxy.status, proxy.headers, [body]]
        when :custom
          proxy.custom_response
        else
          request.env["PATH_INFO"] = "/#{options[:action]}"
          request.env["warden.options"] = options
          Warden::Manager._run_callbacks(:before_failure, env, options)

          status, headers, response = Devise.warden_config[:failure_app].call(env).to_a

This final line is where it dies.

My guess, not knowing the internals of the code, is that this is forcing a redirection when a user is not logged in? But in previous versions my user would have been successfully logged in prior to this point. So I don't really understand either this error, or why I would have arrived here unauthenticated.

Of course, it is possible that I'm not understanding what is going on here.

[feliperenan]

Are you using Rails engine? The only this that I can think now that was released and could break the root_path is this PR: #4700 (comment)

We came up with this solution to check if the root_path is defined. Not sure if could be something here.

Are you able to reproduce this issue in new app?

EDIT

I'm already able to reproduce the issue.

[feliperenan]

Just to make sure, have you the root_path defined in your routes?

[tegon]

@philayres We were able to reproduce the issue with the following scenario: a Rails application that doesn't have a root defined and after an unsuccessful login attempt.

After the commit mentioned by @feliperenan, we started calling url_helpers.root_path, which is causing the failure now. We tried to prevent this by using #present? by now it's clear that it should have been a #respond_to? instead.

This is definitely a regression and we're going to push a fix as soon as we can. But, what concerns me the most about your report is that in your tests you're expecting the user to be logged in successfully, but right now the authentication is failing.

Can you point your application to the let-fix-root-path branch and test it again? This way we can remove this error and see whether there's another issue happening there.

[philayres]

Ok, I just checked out the branch you suggested. As you guessed, this helped, but did not solve all the problems. The following steps through where I have looked to identify the root cause. Sorry if some of it is irrelevant; I just want to make sure I don't miss something that could be meaningful.

Running the spec again I'm now getting different errors:

  1) AddressesController behaves like a standard user controller Ensure authentication returns a result
     Failure/Error: expect(response).to have_http_status(200), "Attempting #{@user}"
       Attempting ctestuser-tester-443@testing.com
     Shared Example Group: "a standard user controller" called from ./spec/controllers/addresses_controller_spec.rb:20
     # ./spec/support/standard_user_controller.rb:21:in `block (3 levels) in <top (required)>'

  2) AddressesController behaves like a standard user controller GET #index assigns all items as @vars
     Failure/Error: expect(assigns(objects_symbol)).to eq([item])
     
       expected: [#<Address id: 127, master_id: 1233, street: "7708 main st", street2: "apt #14", street3: "(rear of b...19-02-09 11:25:05", updated_at: "2019-02-09 11:25:05", country: nil, postal_code: nil, region: nil>]
            got: nil
     
       (compared using ==)
     Shared Example Group: "a standard user controller" called from ./spec/controllers/addresses_controller_spec.rb:20
     # ./spec/support/standard_user_controller.rb:32:in `block (3 levels) in <top (required)>'

Stepping through an authentication reveals an issue with the authentication.

Where I call sign_in user in the before block, the authentication doesn't work as expected (but does not fail with an exception). Stepping through, where I hit

`lib/devise.rb`
   480:         warden_config.serialize_into_session(mapping.name) do |record|
=> 481:           mapping.to.serialize_into_session(record)
   482:         end

and subsequently lib/devise/models/authenticatable.rb

   233:         def serialize_into_session(record)
=> 234:           [record.to_key, record.authenticatable_salt]
   235:         end

... I spot a problem. The record.authenticatable_salt returns nil, because record.encrypted_password is empty.

If I force a value with record.password = 'some password that works' and allow the rest of the example to run, it passes, where previously it was redirecting due to a lack of authentication.

Something must have changed in this area, where the encrypted_password was not previously required. I have recently added some code to my user model that nils the plain text password attribute after saving. This has the side effect it seems of making the encrypted_password attribute nil too. So either the test code around serialize_into_session is working differently in this version, or the encrypted_password is being cleared where it wasn't before.

It feels to me that it is the test code that has changed, since human testing in development runs fine.

I will keep digging to see if I can spot what has changed and where.

[philayres]

OK, easier to find than I expected.

Blame database_authenticatable.rb https://github.com/plataformatec/devise/blame/master/lib/devise/models/database_authenticatable.rb shows line 63 forces the encrypted_password to nil even when password is nil, which is a change from previously. This has the side effect I'm seeing that the spec test won't create the user session because my code has cleared the plain text password.

The reasoning for me clearing the plain text password after save in the user model is that I'm checking for actual password value change (encrypted_password_changed? doesn't work with BCrypt due to dynamic salts) and I was getting leakage of the plain text password into tests around this (among other things), and wanted belt and braces to avoid accidentally showing the password where I shouldn't... Or something like that anyway.

So from the point of view of Devise, the above change broke my tests (and maybe others will experience this). For now I'm going to dig some more to decide whether I adapt my code or propose a change in Devise.

[philayres]

Referencing #4245 / #4261 so I don't have to keep digging around to find out what broke things.

[philayres]

@tegon I didn't answer your previous question about the root_path. No, my application does not have it set. I have relied on an application_controller to redirect to specific paths under certain conditions. No reason why I couldn't set the root_path as a fallback though.

[tegon]

@philayres The root_path issue was regression so we're going to release it soon in the version 4.6.1.

About the encrypted_password being set to nil, we did it to keep it in sync with the password field and prevent possible security issues - e.g. before valid_password? would return true for a cleaned password.

As for your concern of leaking the password, Rails already replaces it with the value "[FILTERED]" in the logs via the config.filter_parameters option and we hide it when #inspect is called so that it's not presented on exceptions, for example.

irb(main):007:0> u = User.first
  User Load (0.4ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1  [["LIMIT", 1]]
=> #<User id: 2, email: "bruce@wayne.com", created_at: "2019-01-30 12:50:45", updated_at: "2019-01-30 13:03:57">
irb(main):008:0> u.password = '123'
=> "123"
irb(main):009:0> p u
#<User id: 2, email: "bruce@wayne.com", created_at: "2019-01-30 12:50:45", updated_at: "2019-01-30 13:03:57">
=> #<User id: 2, email: "bruce@wayne.com", created_at: "2019-01-30 12:50:45", updated_at: "2019-01-30 13:03:57">
irb(main):010:0> puts u
#<User:0x00007fe579b64f20>
=> nil

Also, Rails 6 will come with a feature called inspection_masks which will do a similar thing for models.

I'm not sure if those cover the cases you're worried about. If they don't, please let me know the exceptions.

Thanks.

[philayres]

The actual challenge I had was that my model forces password changes after first sign in, and these were breaking specs. For example, if I am running a series of controller tests like this:

• a user / password is created
• sign in is successful
• the user is forced to change password (and the password is not the same as before)
• perform some meaningful action that requires me to be authenticated
• sign out

I have many combinations of these types of things to ensure the implementation in my application actually does both what Devise claims and what the auditors might check for.

The challenge was that in these series of model tests was that holding the plain text password between the steps above wouldn't allow for sensible checking whether a new password had been provided for sign in or to update the record, etc. My model code never knew if the password had changed (possibly a convoluted set of checks going on in my implementation) and could not fire callbacks consistently. Basically having the ability to clear the plain text password attribute automatically on save allowed complex test sequences to run without having to constantly reload the user record at every step, or worry that the password was being extracted from the user record in some other unrelated chunk of code. This is the leakage I mean; the password was leaking from one mode of use (creating the user) to another (testing authentication, checking for password change, validating password age, viewing user details etc)

Anyway, I can make the changes to allow my specs to run without clearing the password attribute after save, by reloading user records representing more how a series of web requests would actually run. It breaks things from previously, but maybe I can accept that.

I'm still not happy that the controller tests fail so obscurely when password is set to nil. The controller sign_in appears to work fine, but when it comes to actually using the authenticated controller you find out that actually you weren't signed in. Sign in doesn't provide any meaningful information in this regard. That could mean I have obscure tests that are looking to check that a sign_in where a user record has been manipulated will just fail without warning. Is this expected behaviour? Presumably it needs a separate issue to address it, which I'd be happy to create if you believe it is not expected behaviour.

Thoughts?

[rodrigo-puente]

By looking at this thread, I'm also having similar issues with v6.4.1

undefined method `root_path' for #<Module:0x007fb3415f0e50>

which points to this:

def root_path_defined?(context)
    defined?(context.routes) && context.routes.url_helpers.root_path.present?
end

I don't have a root_path defined. Will having a root_path defined will be something necessary from now on?

[tegon]

@rodrigo-puente Nope, that was fixed in version 4.6.1. Can you try to update and see if the error is gone?

[tegon]

@philayres I don't get exactly what the issues were to create your specs - if you want to create a sample application I can take a look at them and see if I can think of another solution. But when you said:

I can make the changes to allow my specs to run without clearing the password attribute after save, by reloading user records representing more how a series of web requests would actually run.

I understood that this issue is only for your test environment - please correct me if I got it wrong - when you test it manually in a browser everything works correctly? If that's the case, I'd say it's better to keep the specs as close to the reality as possible. It's a bummer when the tests are failing but the system is working fine due to differences from environments.

It breaks things from previously, but maybe I can accept that.

I know this is bad but the reason we released this change in a minor version is that we consider the old behavior a bug. We fixed and thought it wouldn't have those kinds of issues but it's hard to know how the code is being used throughout applications out there. We are sorry it's going to cause you trouble to update but we think it's the best way to go.

[philayres]

@tegon this is probably a good time for me to go back and DRY up my tests anyway. Things have got messy over time. Thanks for you thoughts and rapid response to this issue. I'll close it now.

[erich-team]

Regarding nilifying #encrypted_password, I may missing something, but if, when I load a user model, #password is blank(as it's defined merely by attr_reader), won't any subsequent save of the user model cause encrypted_password to be cleared and persisted?

[tegon]

@erich-team Not sure if I understood correctly, is this what you mean?

❯ rails c
Running via Spring preloader in process 35300
Loading development environment (Rails 5.2.2)
irb(main):001:0> u = User.first
  User Load (0.5ms)  SELECT  "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1  [["LIMIT", 1]]
=> #<User id: 1, email: "bruce@wayne.com", created_at: "2019-02-21 19:05:54", updated_at: "2019-02-22 19:01:31">
irb(main):002:0> u.password
=> nil
irb(main):003:0> u.encrypted_password
=> "$2a$11$rHW3mrrB6nzBIjueG1rSgOy2Dt4vStVk.3QLA4yWJS8yR0/Y1Jjym"
irb(main):004:0> u.save # encrypted_password is not updated to nil here
   (0.3ms)  BEGIN
   (0.3ms)  COMMIT
=> true
irb(main):005:0> u.password
=> nil
irb(main):006:0> u.encrypted_password
=> "$2a$11$rHW3mrrB6nzBIjueG1rSgOy2Dt4vStVk.3QLA4yWJS8yR0/Y1Jjym"
irb(main):007:0>

The encrypted_password will only be set to nil after password is by calling password= directly, and not on initialization.

[erich-team]

The issue appears to be with strip_whitespace_keys.

This...

config.strip_whitespace_keys = [:email, :password, :password_confirmation]

... in config/initializers/devise.rb, results in password= being called on every validation.

Obviously, the simplest solution is to not include password and password_confirmation, but it seems like this might be less than ideal. I have a user base that isn't necessarily... adept ...adept at typing and have to do things like strip white-space from these attributes.

[tegon]

@erich-team I see 🤔

I'm not familiar with your user base or your application at all, but it seems to me that it's dangerous to change the password input in any way. I mean, theoretically, one could choose to deliberately include a white space on their password.

If you want to prevent them from including those spaces as mistakes, I think it would be better to add a validation for this and let them know that they've typed their password with an extra whitespace so that they can fix it. Does that make sense to you?

[erich-team]

My user base is truck drivers. :) Good people, not always the most accomplished typists. That said, we do have a work around.

…

On Thu, Feb 28, 2019 at 8:33 AM Leonardo Tegon ***@***.***> wrote: @erich-team <https://github.com/erich-team> I see 🤔 I'm not familiar with your user base or your application at all, but it seems to me that it's dangerous to change the password input in any way. I mean, theoretically, one could choose to deliberately include a white space on their password. If you want to prevent them from including those spaces as mistakes, I think it would be better to add a validation for this and let them know that they've typed their password with an extra whitespace so that they can fix it. Does that make sense to you? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#5021 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AfbsCZvV9sMEeZc8lBtSU6ZVzOFCXpqVks5vR-iygaJpZM4awdbL> .

-- Erich L Timkar

[tegon]

@erich-team Since this broke a lot of existing applications like yours, we decided to roll back the original change. If you want to return to the original behavior you can update to version 4.6.2.

Thanks!