devise_token_auth icon indicating copy to clipboard operation
devise_token_auth copied to clipboard
verified publisher icon lynndylanhurley

ArgumentError: Argument Out of Range when authorizing via token

Open TruRooms opened this issue 6 years ago • 2 comments

Authentication via the new user session path is working as expected. When a call is made to any controller that calls authenticate_user! returns the following error log.

  • Version: Devise Token Auth => 1.1.3, Postman => 7.7.3, Ruby => 2.6.0, Rails => 5.2.3, Devise => 4.7.1

  • Request and response headers:

Request Headers

Content-Type: Application/json
access-token: QCsBbXZ96ugarGsuwLPupQ
token-type: Bearer
expiry: 1575572963
uid: [email protected]
client: 81zmic27JPNh5WNhi9DL3Q

Response Headers

Date: Thu, 21 Nov 2019 19:44:12 GMT
Server: Apache/2.4.38 (Unix) OpenSSL/1.0.2s PHP/7.2.24 Phusion_Passenger/6.0.2
Vary: Origin
X-Runtime: 0.319028
X-Request-Id: bd5d8844-29f9-4a84-b41b-1229b6c71222
X-Powered-By: Phusion Passenger 6.0.2
Content-Length: 110718
Status: 500 Internal Server Error
Connection: close
Content-Type: text/html; charset=UTF-8
  • Rails Stacktrace:
Processing by Api::HomesController#index as JSON
  Parameters: {"subdomain"=>"api", "home"=>{}}
  User Load (0.7ms)  SELECT  "users".* FROM "users" WHERE "users"."uid" = $1 LIMIT $2  [["uid", "[email protected]"], ["LIMIT", 1]]
  ↳ /usr/local/Cellar/passenger/6.0.2_1/libexec/src/ruby_supportlib/phusion_passenger/rack/thread_handler_extension.rb:97
  Rendering api/homes/index.json.jbuilder
  Home Load (0.4ms)  SELECT "homes".* FROM "homes"
  ↳ app/views/api/homes/index.json.jbuilder:1
  Rendered api/homes/index.json.jbuilder (6.7ms)
  User Load (0.3ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = $1 LIMIT $2  [["id", 1], ["LIMIT", 1]]
  ↳ /usr/local/Cellar/passenger/6.0.2_1/libexec/src/ruby_supportlib/phusion_passenger/rack/thread_handler_extension.rb:97
   (0.1ms)  BEGIN
  ↳ /usr/local/Cellar/passenger/6.0.2_1/libexec/src/ruby_supportlib/phusion_passenger/rack/thread_handler_extension.rb:97
  User Load (1.1ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = $1 LIMIT $2 FOR UPDATE  [["id", 1], ["LIMIT", 1]]
  ↳ /usr/local/Cellar/passenger/6.0.2_1/libexec/src/ruby_supportlib/phusion_passenger/rack/thread_handler_extension.rb:97
   (0.2ms)  ROLLBACK
  ↳ /usr/local/Cellar/passenger/6.0.2_1/libexec/src/ruby_supportlib/phusion_passenger/rack/thread_handler_extension.rb:97
Completed 500 Internal Server Error in 124ms (Views: 6.0ms | ActiveRecord: 13.0ms)


  
ArgumentError (argument out of range):
  
activesupport (5.2.3) lib/active_support/core_ext/string/conversions.rb:27:in `initialize'
activesupport (5.2.3) lib/active_support/core_ext/string/conversions.rb:27:in `new'
activesupport (5.2.3) lib/active_support/core_ext/string/conversions.rb:27:in `to_time'
devise_token_auth (1.1.3) app/controllers/devise_token_auth/concerns/set_user_by_token.rb:135:in `is_batch_request?'
devise_token_auth (1.1.3) app/controllers/devise_token_auth/concerns/set_user_by_token.rb:141:in `auth_header_from_batch_request'
devise_token_auth (1.1.3) app/controllers/devise_token_auth/concerns/set_user_by_token.rb:127:in `block in refresh_headers'
activerecord (5.2.3) lib/active_record/locking/pessimistic.rb:84:in `block in with_lock'
activerecord (5.2.3) lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `block in transaction'
activerecord (5.2.3) lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
/Users/noname/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/monitor.rb:230:in `mon_synchronize'
activerecord (5.2.3) lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
activerecord (5.2.3) lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `transaction'
activerecord (5.2.3) lib/active_record/transactions.rb:212:in `transaction'
activerecord (5.2.3) lib/active_record/transactions.rb:301:in `transaction'
activerecord (5.2.3) lib/active_record/locking/pessimistic.rb:82:in `with_lock'
devise_token_auth (1.1.3) app/controllers/devise_token_auth/concerns/set_user_by_token.rb:121:in `refresh_headers'
devise_token_auth (1.1.3) app/controllers/devise_token_auth/concerns/set_user_by_token.rb:112:in `update_auth_header'
activesupport (5.2.3) lib/active_support/callbacks.rb:426:in `block in make_lambda'
activesupport (5.2.3) lib/active_support/callbacks.rb:247:in `block in halting'
activesupport (5.2.3) lib/active_support/callbacks.rb:517:in `block in invoke_after'
activesupport (5.2.3) lib/active_support/callbacks.rb:517:in `each'
activesupport (5.2.3) lib/active_support/callbacks.rb:517:in `invoke_after'
activesupport (5.2.3) lib/active_support/callbacks.rb:133:in `run_callbacks'
actionpack (5.2.3) lib/abstract_controller/callbacks.rb:41:in `process_action'
actionpack (5.2.3) lib/action_controller/metal/rescue.rb:22:in `process_action'
actionpack (5.2.3) lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
activesupport (5.2.3) lib/active_support/notifications.rb:168:in `block in instrument'
activesupport (5.2.3) lib/active_support/notifications/instrumenter.rb:23:in `instrument'
activesupport (5.2.3) lib/active_support/notifications.rb:168:in `instrument'
actionpack (5.2.3) lib/action_controller/metal/instrumentation.rb:32:in `process_action'
actionpack (5.2.3) lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
activerecord (5.2.3) lib/active_record/railties/controller_runtime.rb:24:in `process_action'
actionpack (5.2.3) lib/abstract_controller/base.rb:134:in `process'
actionview (5.2.3) lib/action_view/rendering.rb:32:in `process'
actionpack (5.2.3) lib/action_controller/metal.rb:191:in `dispatch'
actionpack (5.2.3) lib/action_controller/metal.rb:252:in `dispatch'
actionpack (5.2.3) lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
actionpack (5.2.3) lib/action_dispatch/routing/route_set.rb:34:in `serve'
actionpack (5.2.3) lib/action_dispatch/journey/router.rb:52:in `block in serve'
actionpack (5.2.3) lib/action_dispatch/journey/router.rb:35:in `each'
actionpack (5.2.3) lib/action_dispatch/journey/router.rb:35:in `serve'
actionpack (5.2.3) lib/action_dispatch/routing/route_set.rb:840:in `call'
warden-jwt_auth (0.3.6) lib/warden/jwt_auth/middleware/token_dispatcher.rb:20:in `call'
warden-jwt_auth (0.3.6) lib/warden/jwt_auth/middleware/revocation_manager.rb:21:in `call'
rack (2.0.7) lib/rack/builder.rb:153:in `call'
warden-jwt_auth (0.3.6) lib/warden/jwt_auth/middleware.rb:23:in `call'
warden (1.2.8) lib/warden/manager.rb:36:in `block in call'
warden (1.2.8) lib/warden/manager.rb:34:in `catch'
warden (1.2.8) lib/warden/manager.rb:34:in `call'
rack (2.0.7) lib/rack/tempfile_reaper.rb:15:in `call'
rack (2.0.7) lib/rack/etag.rb:25:in `call'
rack (2.0.7) lib/rack/conditional_get.rb:25:in `call'
rack (2.0.7) lib/rack/head.rb:12:in `call'
actionpack (5.2.3) lib/action_dispatch/http/content_security_policy.rb:18:in `call'
rack (2.0.7) lib/rack/session/abstract/id.rb:232:in `context'
rack (2.0.7) lib/rack/session/abstract/id.rb:226:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/cookies.rb:670:in `call'
activerecord (5.2.3) lib/active_record/migration.rb:559:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
activesupport (5.2.3) lib/active_support/callbacks.rb:98:in `run_callbacks'
actionpack (5.2.3) lib/action_dispatch/middleware/callbacks.rb:26:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/executor.rb:14:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
web-console (3.7.0) lib/web_console/middleware.rb:135:in `call_app'
web-console (3.7.0) lib/web_console/middleware.rb:22:in `block in call'
web-console (3.7.0) lib/web_console/middleware.rb:20:in `catch'
web-console (3.7.0) lib/web_console/middleware.rb:20:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
railties (5.2.3) lib/rails/rack/logger.rb:38:in `call_app'
railties (5.2.3) lib/rails/rack/logger.rb:26:in `block in call'
activesupport (5.2.3) lib/active_support/tagged_logging.rb:71:in `block in tagged'
activesupport (5.2.3) lib/active_support/tagged_logging.rb:28:in `tagged'
activesupport (5.2.3) lib/active_support/tagged_logging.rb:71:in `tagged'
railties (5.2.3) lib/rails/rack/logger.rb:26:in `call'
sprockets-rails (3.2.1) lib/sprockets/rails/quiet_assets.rb:13:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/request_id.rb:27:in `call'
rack (2.0.7) lib/rack/method_override.rb:22:in `call'
rack (2.0.7) lib/rack/runtime.rb:22:in `call'
activesupport (5.2.3) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/executor.rb:14:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/static.rb:127:in `call'
rack (2.0.7) lib/rack/sendfile.rb:111:in `call'
rack-cors (1.0.3) lib/rack/cors.rb:95:in `call'
railties (5.2.3) lib/rails/engine.rb:524:in `call'
/usr/local/Cellar/passenger/6.0.2_1/libexec/src/ruby_supportlib/phusion_passenger/rack/thread_handler_extension.rb:97:in `process_request'
/usr/local/Cellar/passenger/6.0.2_1/libexec/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:149:in `accept_and_process_next_request'
/usr/local/Cellar/passenger/6.0.2_1/libexec/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:110:in `main_loop'
/usr/local/Cellar/passenger/6.0.2_1/libexec/src/ruby_supportlib/phusion_passenger/request_handler.rb:415:in `block (3 levels) in start_threads'
/usr/local/Cellar/passenger/6.0.2_1/libexec/src/ruby_supportlib/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'
  • Environmental Info:
    • Routes: Routes are mounted in the api constraint.
    • Gems:
gem 'rack-cors-proxy'
gem 'devise_token_auth'
gem 'omniauth'
gem 'devise'

  • Custom Overrides: Devise Token Auth is alongside a standard Devise configuration. They operate on the same model, but Devise is mounted in the root, where Devise Token Auth is mounted in the 'api'. Initializer option config.enable_standard_devise_support is set to true.

  • Custom Frontend: This is base testing using Postman

  • Install Change: Given the base install of Devise, the migrations for the creation of the User model by Devise Token Auth was amended to the below to account for already existing schema:

class DeviseTokenAuthCreateUsers < ActiveRecord::Migration[5.2]
  def change

    add_column :users, :provider, :string, null: false, default: 'email'
    add_column :users, :uid, :string, null: false, default: ''
    add_column :users, :allow_password_change, :boolean, default: false

    add_column :users, :confirmation_token, :string
    add_column :users, :confirmed_at, :datetime
    add_column :users, :confirmation_sent_at, :datetime
    add_column :users, :unconfirmed_email, :string

    add_column :users, :sign_in_count, :integer, default: 0
    add_column :users, :current_sign_in_at, :datetime
    add_column :users, :last_sign_in_at, :datetime
    add_column :users, :current_sign_in_ip, :string
    add_column :users, :last_sign_in_ip, :string

    add_column :users, :name, :string
    add_column :users, :nickname, :string
    
    add_column :users, :tokens, :json

    add_index :users, :confirmation_token,   unique: true

  end
end

Digging deeper, it may have to do with the data store used tokens. to_time(String) can not parse the string "11/21/2019 8:14pm" , which is how it is stored in the DB.

Per the install generator, I created the column tokens as a json column. The reference app has a type of text instead.

TruRooms avatar Nov 21 '19 20:11 TruRooms

Cause found.

I had overrode the default time format in an initializer:

Time::DATE_FORMATS[:default] = '%-m/%-d/%Y %l:%M%P'.

This led to a poor format being used on generation.

I would propose maybe changing the token generation at user.rb to be updated to explicitly set a format instead of relying on the system defaults.

TruRooms avatar Nov 21 '19 20:11 TruRooms

I believe https://github.com/lynndylanhurley/devise_token_auth/pull/1423 will fix this issue, I prefer iso8601 over rfc822 as it's more widely used

MaicolBen avatar Oct 04 '20 19:10 MaicolBen