error in sessions_controller.rb:42 - on sign_in after application restart

[gibo]

I have a farily standard token auth app running on Rails 5 in production mode.

Main changes are:

• Using 'Profile' model instead of 'Users'
• Have set the token to expire in 1 year
• Token does not refresh

Currently sign_in and sign_up work fine (with DB Seeds), however, it seems after the application is stopped and restarted, I get a 500.

Logs below.

[2017-08-21T13:48:00.164957 #4] FATAL -- : [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/devise_token_auth-0.1.42/app/controllers/devise_token_auth/sessions_controller.rb:42:in `[]='
2017-08-21T13:48:00.165035+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/activesupport-5.1.3/lib/active_support/notifications.rb:166:in `block in instrument'
2017-08-21T13:48:00.165029+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/devise_token_auth-0.1.42/app/controllers/devise_token_auth/sessions_controller.rb:42:in `create'

Larger stack trace below...

2017-08-21T13:47:59.917645+00:00 app[web.1]: I, [2017-08-21T13:47:59.917547 #4]  INFO -- : [8f6962a7-f07c-4754-959c-c51dafa37d76] Started POST "/auth/sign_in" for 82.163.112.30 at 2017-08-21 13:47:59 +0000
2017-08-21T13:48:00.165030+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/actionpack-5.1.3/lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'
2017-08-21T13:48:00.165036+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/activesupport-5.1.3/lib/active_support/notifications.rb:166:in `instrument'
2017-08-21T13:47:59.925118+00:00 app[web.1]: I, [2017-08-21T13:47:59.925047 #4]  INFO -- : [8f6962a7-f07c-4754-959c-c51dafa37d76] Processing by DeviseTokenAuth::SessionsController#create as */*
2017-08-21T13:48:00.165031+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/actionpack-5.1.3/lib/abstract_controller/base.rb:186:in `process_action'
2017-08-21T13:48:00.165036+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/actionpack-5.1.3/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
2017-08-21T13:47:59.925184+00:00 app[web.1]: I, [2017-08-21T13:47:59.925134 #4]  INFO -- : [8f6962a7-f07c-4754-959c-c51dafa37d76]   Parameters: {"email"=>"[email protected]", "password"=>"[FILTERED]", "session"=>{"email"=>"[email protected]", "password"=>"[FILTERED]"}}
2017-08-21T13:48:00.165032+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/actionpack-5.1.3/lib/action_controller/metal/rendering.rb:30:in `process_action'
2017-08-21T13:48:00.165036+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/actionpack-5.1.3/lib/action_controller/metal/params_wrapper.rb:252:in `process_action'
2017-08-21T13:47:59.976389+00:00 app[web.1]: D, [2017-08-21T13:47:59.976252 #4] DEBUG -- : [8f6962a7-f07c-4754-959c-c51dafa37d76]   Profile Load (2.1ms)  SELECT  "profiles".* FROM "profiles" WHERE (email = '[email protected]' AND provider='email') ORDER BY "profiles"."id" ASC LIMIT $1  [["LIMIT", 1]]
2017-08-21T13:48:00.165032+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/actionpack-5.1.3/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
2017-08-21T13:48:00.165037+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/activerecord-5.1.3/lib/active_record/railties/controller_runtime.rb:22:in `process_action'
2017-08-21T13:48:00.163017+00:00 app[web.1]: I, [2017-08-21T13:48:00.162930 #4]  INFO -- : [8f6962a7-f07c-4754-959c-c51dafa37d76] Completed 500 Internal Server Error in 238ms (ActiveRecord: 19.2ms)
2017-08-21T13:48:00.165033+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:131:in `run_callbacks'
2017-08-21T13:48:00.164815+00:00 app[web.1]: F, [2017-08-21T13:48:00.164748 #4] FATAL -- : [8f6962a7-f07c-4754-959c-c51dafa37d76]   
2017-08-21T13:48:00.165033+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/actionpack-5.1.3/lib/abstract_controller/callbacks.rb:19:in `process_action'
2017-08-21T13:48:00.164880+00:00 app[web.1]: F, [2017-08-21T13:48:00.164820 #4] FATAL -- : [8f6962a7-f07c-4754-959c-c51dafa37d76] IndexError (string not matched):
2017-08-21T13:48:00.165034+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/actionpack-5.1.3/lib/action_controller/metal/rescue.rb:20:in `process_action'
2017-08-21T13:48:00.164933+00:00 app[web.1]: F, [2017-08-21T13:48:00.164884 #4] FATAL -- : [8f6962a7-f07c-4754-959c-c51dafa37d76]   
2017-08-21T13:48:00.165034+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/actionpack-5.1.3/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
2017-08-21T13:48:00.165028+00:00 app[web.1]: F, [2017-08-21T13:48:00.164957 #4] FATAL -- : [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/devise_token_auth-0.1.42/app/controllers/devise_token_auth/sessions_controller.rb:42:in `[]='
2017-08-21T13:48:00.165035+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/activesupport-5.1.3/lib/active_support/notifications.rb:166:in `block in instrument'
2017-08-21T13:48:00.165029+00:00 app[web.1]: [8f6962a7-f07c-4754-959c-c51dafa37d76] vendor/bundle/ruby/2.3.0/gems/devise_token_auth-0.1.42/app/controllers/devise_token_auth/sessions_controller.rb:42:in `create'

[claycarpenter]

I just encountered this error as well, running on Rails 5 on Heroku w/ Postgres.

Somehow the tokens value of Users are being converted to strings (rather than remaining hashes). For instance, user bsadm has a string tokens value, but bo-1 is fine:

  1 | [email protected]             | "{\"cnMIHqHJ139gYUbtchCWvQ\":{\"token\":\"$2a$10$3Fu.pkibJtB7NcMKhAOBRecvSJtczsnOZl83.2clQ6X0K8LMdKxzO\",\"expiry\":1507074478},\"CTz71XHn843a3H9ym_QcOQ\":{\"token\":\"$2a$10$GFqYS5GRqpDWQevAtm7TJuMaGRZUtuMkxLyzT1ODifgOPHWYs.N1y\",\"expiry\":1507125400},\"00cfkGpBVitMSY-djeKBMA\":{\"token\":\"$2a$10$QD9fknLe34ASSKN.rRQMcuOfVienS/BXkYeFUX286sqNNmjLHRKC2\",\"expiry\":1507146371}}"
  2 | [email protected]              | {"FYfJ2gn_CZn5z9O4z3XlkA":{"token":"$2a$10$lXROnqDl31TWdVHmVNk/z.tC0zNZMF9ZoD.5C2XPtHDOSDOl/Kr4q","expiry":1507227527}}

Not sure how that's happening; the only way I was able to replicate it locally was by bypassing DTA's callbacks when pushing a string into a User's tokens property (e.g., user.update_column(:tokens, "{}").

I was able to workaround this by adding a small cleanup routine to the create sessions controller:

# ......

if (
      @resource and
      valid_params?(:email, resource_params[:email]) and
      @resource.valid_password?(resource_params[:password]) and
      @resource.confirmed? and
      [email protected]?
    )
      # Clean up tokens value, if necessary
      if @resource.tokens.class == String
        @resource.update(
          tokens: JSON.parse(@resource.tokens),
        )
      end

      # create client id
      @client_id = SecureRandom.urlsafe_base64(nil, false)
      @token     = SecureRandom.urlsafe_base64(nil, false)

      # .........

That works well but ideally I'd like to prevent those tokens values from ever being strings in the first place.

[lynndylanhurley]

Can someone that's having this problem provide steps to reproduce the issue? Please include anything about your setup that's different from the example app.

I am unable to reproduce this issue by stopping and restarting the app as @gibo described.

[norbajunior]

Suddenly I also started to have this issue. But my problem was that my user object was invalid in reason of a uniqueness validation checked before the gem update the tokens. Take a look if you guys has the same problem.

[gibo]

@lynndylanhurley It's an absolutely standard set up..

however I did fix it by adding this to my migration

reversible do |direction|       
  direction.up do  
    User.find_each do |user|  
      user.tokens = nil  
      user.save! 
    end  
  end  
end  

[natefoundry]

I'm specifically only running into this issue when deploying my rails app to Heroku.

I noticed my local Postgres version is 9.6.2 and Heroku's is 9.6.4, but I'm not certain that is affecting anything.

For me, this seems to happen after my initial User creation in my seed file when setting up the database. The workaround provided by @gibo fixes the issue, and the gem no longer creates string values for the tokens after signing into the app.

Hopefully this helps track down the root cause.

[MaicolBen]

Closing since it's a duplicated of #681 and #121. @claycarpenter solution could be better than the migration solution, so maybe we can implement it here (but it's an ugly solution)