#<IndexError: string not matched> after second sign_in request with postgres

[dikey94]

Hello everyone,
I'm new in devise + token auth solution so please bear with me.

I noticed a strange behavior - the second sign_in request gives me 500 Internal Server Error - "#<IndexError: string not matched>". When I manually update tokens column and set it to null everything works fine.

Full response:

{
"status": 500,
"error": "Internal Server Error",
"exception": "#<IndexError: string not matched>",
"traces": {
"Application Trace": [],
"Framework Trace": [
{
"id": 0,
"trace": "devise_token_auth (0.1.42controllers) devise_token_auth/sessions_controller.rb:42:in []='" }, { "id": 1, "trace": "devise_token_auth (0.1.42controllers) devise_token_auth/sessions_controller.rb:42:in create'"
},
{
"id": 2,
"trace": "actionpack (5.1.4) lib/action_controller/metal/basic_implicit_render.rb:4:in send_action'" }, { "id": 3, "trace": "actionpack (5.1.4) lib/abstract_controller/base.rb:186:in process_action'"
},
{
"id": 4,
"trace": "actionpack (5.1.4) lib/action_controller/metal/rendering.rb:30:in process_action'" }, { "id": 5, "trace": "actionpack (5.1.4) lib/abstract_controller/callbacks.rb:20:in block in process_action'"
},
{
"id": 6,
"trace": "activesupport (5.1.4) lib/active_support/callbacks.rb:131:in run_callbacks'" }, { "id": 7, "trace": "actionpack (5.1.4) lib/abstract_controller/callbacks.rb:19:in process_action'"
},
{
"id": 8,
"trace": "actionpack (5.1.4) lib/action_controller/metal/rescue.rb:20:in process_action'" }, { "id": 9, "trace": "actionpack (5.1.4) lib/action_controller/metal/instrumentation.rb:32:in block in process_action'"
},
{
"id": 10,
"trace": "activesupport (5.1.4) lib/active_support/notifications.rb:166:in block in instrument'" }, { "id": 11, "trace": "activesupport (5.1.4) lib/active_support/notifications/instrumenter.rb:21:in instrument'"
},
{
"id": 12,
"trace": "activesupport (5.1.4) lib/active_support/notifications.rb:166:in instrument'" }, { "id": 13, "trace": "actionpack (5.1.4) lib/action_controller/metal/instrumentation.rb:30:in process_action'"
},
{
"id": 14,
"trace": "actionpack (5.1.4) lib/action_controller/metal/params_wrapper.rb:252:in process_action'" }, { "id": 15, "trace": "activerecord (5.1.4) lib/active_record/railties/controller_runtime.rb:22:in process_action'"
},
{
"id": 16,
"trace": "actionpack (5.1.4) lib/abstract_controller/base.rb:124:in process'" }, { "id": 17, "trace": "actionview (5.1.4) lib/action_view/rendering.rb:30:in process'"
},
{
"id": 18,
"trace": "actionpack (5.1.4) lib/action_controller/metal.rb:189:in dispatch'" }, { "id": 19, "trace": "actionpack (5.1.4) lib/action_controller/metal.rb:253:in dispatch'"
},
{
"id": 20,
"trace": "actionpack (5.1.4) lib/action_dispatch/routing/route_set.rb:49:in dispatch'" }, { "id": 21, "trace": "actionpack (5.1.4) lib/action_dispatch/routing/route_set.rb:31:in serve'"
},
{
"id": 22,
"trace": "actionpack (5.1.4) lib/action_dispatch/routing/mapper.rb:16:in block in <class:Constraints>'" }, { "id": 23, "trace": "actionpack (5.1.4) lib/action_dispatch/routing/mapper.rb:46:in serve'"
},
{
"id": 24,
"trace": "actionpack (5.1.4) lib/action_dispatch/journey/router.rb:50:in block in serve'" }, { "id": 25, "trace": "actionpack (5.1.4) lib/action_dispatch/journey/router.rb:33:in each'"
},
{
"id": 26,
"trace": "actionpack (5.1.4) lib/action_dispatch/journey/router.rb:33:in serve'" }, { "id": 27, "trace": "actionpack (5.1.4) lib/action_dispatch/routing/route_set.rb:834:in call'"
},
{
"id": 28,
"trace": "rack-cors (1.0.2) lib/rack/cors.rb:97:in call'" }, { "id": 29, "trace": "rack (2.0.3) lib/rack/session/abstract/id.rb:232:in context'"
},
{
"id": 30,
"trace": "rack (2.0.3) lib/rack/session/abstract/id.rb:226:in call'" }, { "id": 31, "trace": "actionpack (5.1.4) lib/action_dispatch/middleware/cookies.rb:613:in call'"
},
{
"id": 32,
"trace": "warden (1.2.7) lib/warden/manager.rb:36:in block in call'" }, { "id": 33, "trace": "warden (1.2.7) lib/warden/manager.rb:35:in catch'"
},
{
"id": 34,
"trace": "warden (1.2.7) lib/warden/manager.rb:35:in call'" }, { "id": 35, "trace": "rack (2.0.3) lib/rack/etag.rb:25:in call'"
},
{
"id": 36,
"trace": "rack (2.0.3) lib/rack/conditional_get.rb:38:in call'" }, { "id": 37, "trace": "rack (2.0.3) lib/rack/head.rb:12:in call'"
},
{
"id": 38,
"trace": "rack (2.0.3) lib/rack/session/abstract/id.rb:232:in context'" }, { "id": 39, "trace": "rack (2.0.3) lib/rack/session/abstract/id.rb:226:in call'"
},
{
"id": 40,
"trace": "actionpack (5.1.4) lib/action_dispatch/middleware/cookies.rb:613:in call'" }, { "id": 41, "trace": "activerecord (5.1.4) lib/active_record/migration.rb:556:in call'"
},
{
"id": 42,
"trace": "actionpack (5.1.4) lib/action_dispatch/middleware/callbacks.rb:26:in block in call'" }, { "id": 43, "trace": "activesupport (5.1.4) lib/active_support/callbacks.rb:97:in run_callbacks'"
},
{
"id": 44,
"trace": "actionpack (5.1.4) lib/action_dispatch/middleware/callbacks.rb:24:in call'" }, { "id": 45, "trace": "actionpack (5.1.4) lib/action_dispatch/middleware/executor.rb:12:in call'"
},
{
"id": 46,
"trace": "actionpack (5.1.4) lib/action_dispatch/middleware/debug_exceptions.rb:59:in call'" }, { "id": 47, "trace": "web-console (3.5.1) lib/web_console/middleware.rb:135:in call_app'"
},
{
"id": 48,
"trace": "web-console (3.5.1) lib/web_console/middleware.rb:20:in block in call'" }, { "id": 49, "trace": "web-console (3.5.1) lib/web_console/middleware.rb:18:in catch'"
},
{
"id": 50,
"trace": "web-console (3.5.1) lib/web_console/middleware.rb:18:in call'" }, { "id": 51, "trace": "actionpack (5.1.4) lib/action_dispatch/middleware/show_exceptions.rb:31:in call'"
},
{
"id": 52,
"trace": "railties (5.1.4) lib/rails/rack/logger.rb:36:in call_app'" }, { "id": 53, "trace": "railties (5.1.4) lib/rails/rack/logger.rb:24:in block in call'"
},
{
"id": 54,
"trace": "activesupport (5.1.4) lib/active_support/tagged_logging.rb:69:in block in tagged'" }, { "id": 55, "trace": "activesupport (5.1.4) lib/active_support/tagged_logging.rb:26:in tagged'"
},
{
"id": 56,
"trace": "activesupport (5.1.4) lib/active_support/tagged_logging.rb:69:in tagged'" }, { "id": 57, "trace": "railties (5.1.4) lib/rails/rack/logger.rb:24:in call'"
},
{
"id": 58,
"trace": "sprockets-rails (3.2.1) lib/sprockets/rails/quiet_assets.rb:13:in call'" }, { "id": 59, "trace": "actionpack (5.1.4) lib/action_dispatch/middleware/remote_ip.rb:79:in call'"
},
{
"id": 60,
"trace": "actionpack (5.1.4) lib/action_dispatch/middleware/request_id.rb:25:in call'" }, { "id": 61, "trace": "rack (2.0.3) lib/rack/method_override.rb:22:in call'"
},
{
"id": 62,
"trace": "rack (2.0.3) lib/rack/runtime.rb:22:in call'" }, { "id": 63, "trace": "activesupport (5.1.4) lib/active_support/cache/strategy/local_cache_middleware.rb:27:in call'"
},
{
"id": 64,
"trace": "actionpack (5.1.4) lib/action_dispatch/middleware/executor.rb:12:in call'" }, { "id": 65, "trace": "actionpack (5.1.4) lib/action_dispatch/middleware/static.rb:125:in call'"
},
{
"id": 66,
"trace": "rack (2.0.3) lib/rack/sendfile.rb:111:in call'" }, { "id": 67, "trace": "railties (5.1.4) lib/rails/engine.rb:522:in call'"
},
{
"id": 68,
"trace": "puma (3.11.0) lib/puma/configuration.rb:225:in call'" }, { "id": 69, "trace": "puma (3.11.0) lib/puma/server.rb:624:in handle_request'"
},
{
"id": 70,
"trace": "puma (3.11.0) lib/puma/server.rb:438:in process_client'" }, { "id": 71, "trace": "puma (3.11.0) lib/puma/server.rb:302:in block in run'"
},
{
"id": 72,
"trace": "puma (3.11.0) lib/puma/thread_pool.rb:120:in block in spawn_thread'" } ], "Full Trace": [ { "id": 0, "trace": "devise_token_auth (0.1.42controllers) devise_token_auth/sessions_controller.rb:42:in []='"
},
{
"id": 1,
"trace": "devise_token_auth (0.1.42controllers) devise_token_auth/sessions_controller.rb:42:in create'" }, { "id": 2, "trace": "actionpack (5.1.4) lib/action_controller/metal/basic_implicit_render.rb:4:in send_action'"
},
{
"id": 3,
"trace": "actionpack (5.1.4) lib/abstract_controller/base.rb:186:in process_action'" }, { "id": 4, "trace": "actionpack (5.1.4) lib/action_controller/metal/rendering.rb:30:in process_action'"
},
{
"id": 5,
"trace": "actionpack (5.1.4) lib/abstract_controller/callbacks.rb:20:in block in process_action'" }, { "id": 6, "trace": "activesupport (5.1.4) lib/active_support/callbacks.rb:131:in run_callbacks'"
},
{
"id": 7,
"trace": "actionpack (5.1.4) lib/abstract_controller/callbacks.rb:19:in process_action'" }, { "id": 8, "trace": "actionpack (5.1.4) lib/action_controller/metal/rescue.rb:20:in process_action'"
},
{
"id": 9,
"trace": "actionpack (5.1.4) lib/action_controller/metal/instrumentation.rb:32:in block in process_action'" }, { "id": 10, "trace": "activesupport (5.1.4) lib/active_support/notifications.rb:166:in block in instrument'"
},
{
"id": 11,
"trace": "activesupport (5.1.4) lib/active_support/notifications/instrumenter.rb:21:in instrument'" }, { "id": 12, "trace": "activesupport (5.1.4) lib/active_support/notifications.rb:166:in instrument'"
},
{
"id": 13,
"trace": "actionpack (5.1.4) lib/action_controller/metal/instrumentation.rb:30:in process_action'" }, { "id": 14, "trace": "actionpack (5.1.4) lib/action_controller/metal/params_wrapper.rb:252:in process_action'"
},
{
"id": 15,
"trace": "activerecord (5.1.4) lib/active_record/railties/controller_runtime.rb:22:in process_action'" }, { "id": 16, "trace": "actionpack (5.1.4) lib/abstract_controller/base.rb:124:in process'"
},
{
"id": 17,
"trace": "actionview (5.1.4) lib/action_view/rendering.rb:30:in process'" }, { "id": 18, "trace": "actionpack (5.1.4) lib/action_controller/metal.rb:189:in dispatch'"
},
{
"id": 19,
"trace": "actionpack (5.1.4) lib/action_controller/metal.rb:253:in dispatch'" }, { "id": 20, "trace": "actionpack (5.1.4) lib/action_dispatch/routing/route_set.rb:49:in dispatch'"
},
{
"id": 21,
"trace": "actionpack (5.1.4) lib/action_dispatch/routing/route_set.rb:31:in serve'" }, { "id": 22, "trace": "actionpack (5.1.4) lib/action_dispatch/routing/mapper.rb:16:in block in class:Constraints'"
},
{
"id": 23,
"trace": "actionpack (5.1.4) lib/action_dispatch/routing/mapper.rb:46:in serve'" }, { "id": 24, "trace": "actionpack (5.1.4) lib/action_dispatch/journey/router.rb:50:in block in serve'"
},
{
"id": 25,
"trace": "actionpack (5.1.4) lib/action_dispatch/journey/router.rb:33:in each'" }, { "id": 26, "trace": "actionpack (5.1.4) lib/action_dispatch/journey/router.rb:33:in serve'"
},
{
"id": 27,
"trace": "actionpack (5.1.4) lib/action_dispatch/routing/route_set.rb:834:in call'" }, { "id": 28, "trace": "rack-cors (1.0.2) lib/rack/cors.rb:97:in call'"
},
{
"id": 29,
"trace": "rack (2.0.3) lib/rack/session/abstract/id.rb:232:in context'" }, { "id": 30, "trace": "rack (2.0.3) lib/rack/session/abstract/id.rb:226:in call'"
},
{
"id": 31,
"trace": "actionpack (5.1.4) lib/action_dispatch/middleware/cookies.rb:613:in call'" }, { "id": 32, "trace": "warden (1.2.7) lib/warden/manager.rb:36:in block in call'"
},
{
"id": 33,
"trace": "warden (1.2.7) lib/warden/manager.rb:35:in catch'" }, { "id": 34, "trace": "warden (1.2.7) lib/warden/manager.rb:35:in call'"
},
{
"id": 35,
"trace": "rack (2.0.3) lib/rack/etag.rb:25:in call'" }, { "id": 36, "trace": "rack (2.0.3) lib/rack/conditional_get.rb:38:in call'"
},
{
"id": 37,
"trace": "rack (2.0.3) lib/rack/head.rb:12:in call'" }, { "id": 38, "trace": "rack (2.0.3) lib/rack/session/abstract/id.rb:232:in context'"
},
{
"id": 39,
"trace": "rack (2.0.3) lib/rack/session/abstract/id.rb:226:in call'" }, { "id": 40, "trace": "actionpack (5.1.4) lib/action_dispatch/middleware/cookies.rb:613:in call'"
},
{
"id": 41,
"trace": "activerecord (5.1.4) lib/active_record/migration.rb:556:in call'" }, { "id": 42, "trace": "actionpack (5.1.4) lib/action_dispatch/middleware/callbacks.rb:26:in block in call'"
},
{
"id": 43,
"trace": "activesupport (5.1.4) lib/active_support/callbacks.rb:97:in run_callbacks'" }, { "id": 44, "trace": "actionpack (5.1.4) lib/action_dispatch/middleware/callbacks.rb:24:in call'"
},
{
"id": 45,
"trace": "actionpack (5.1.4) lib/action_dispatch/middleware/executor.rb:12:in call'" }, { "id": 46, "trace": "actionpack (5.1.4) lib/action_dispatch/middleware/debug_exceptions.rb:59:in call'"
},
{
"id": 47,
"trace": "web-console (3.5.1) lib/web_console/middleware.rb:135:in call_app'" }, { "id": 48, "trace": "web-console (3.5.1) lib/web_console/middleware.rb:20:in block in call'"
},
{
"id": 49,
"trace": "web-console (3.5.1) lib/web_console/middleware.rb:18:in catch'" }, { "id": 50, "trace": "web-console (3.5.1) lib/web_console/middleware.rb:18:in call'"
},
{
"id": 51,
"trace": "actionpack (5.1.4) lib/action_dispatch/middleware/show_exceptions.rb:31:in call'" }, { "id": 52, "trace": "railties (5.1.4) lib/rails/rack/logger.rb:36:in call_app'"
},
{
"id": 53,
"trace": "railties (5.1.4) lib/rails/rack/logger.rb:24:in block in call'" }, { "id": 54, "trace": "activesupport (5.1.4) lib/active_support/tagged_logging.rb:69:in block in tagged'"
},
{
"id": 55,
"trace": "activesupport (5.1.4) lib/active_support/tagged_logging.rb:26:in tagged'" }, { "id": 56, "trace": "activesupport (5.1.4) lib/active_support/tagged_logging.rb:69:in tagged'"
},
{
"id": 57,
"trace": "railties (5.1.4) lib/rails/rack/logger.rb:24:in call'" }, { "id": 58, "trace": "sprockets-rails (3.2.1) lib/sprockets/rails/quiet_assets.rb:13:in call'"
},
{
"id": 59,
"trace": "actionpack (5.1.4) lib/action_dispatch/middleware/remote_ip.rb:79:in call'" }, { "id": 60, "trace": "actionpack (5.1.4) lib/action_dispatch/middleware/request_id.rb:25:in call'"
},
{
"id": 61,
"trace": "rack (2.0.3) lib/rack/method_override.rb:22:in call'" }, { "id": 62, "trace": "rack (2.0.3) lib/rack/runtime.rb:22:in call'"
},
{
"id": 63,
"trace": "activesupport (5.1.4) lib/active_support/cache/strategy/local_cache_middleware.rb:27:in call'" }, { "id": 64, "trace": "actionpack (5.1.4) lib/action_dispatch/middleware/executor.rb:12:in call'"
},
{
"id": 65,
"trace": "actionpack (5.1.4) lib/action_dispatch/middleware/static.rb:125:in call'" }, { "id": 66, "trace": "rack (2.0.3) lib/rack/sendfile.rb:111:in call'"
},
{
"id": 67,
"trace": "railties (5.1.4) lib/rails/engine.rb:522:in call'" }, { "id": 68, "trace": "puma (3.11.0) lib/puma/configuration.rb:225:in call'"
},
{
"id": 69,
"trace": "puma (3.11.0) lib/puma/server.rb:624:in handle_request'" }, { "id": 70, "trace": "puma (3.11.0) lib/puma/server.rb:438:in process_client'"
},
{
"id": 71,
"trace": "puma (3.11.0) lib/puma/server.rb:302:in block in run'" }, { "id": 72, "trace": "puma (3.11.0) lib/puma/thread_pool.rb:120:in block in spawn_thread'"
}
]
}
}

Gemfile:

source 'https://rubygems.org'

git_source(:github) do |repo_name|
repo_name = "#{repo_name}/#{repo_name}" unless repo_name.include?("/")
"https://github.com/#{repo_name}.git"
end

gem 'rails', '> 5.1.4'
gem 'pg', '> 0.18'
gem 'puma', '> 3.7'
gem 'sass-rails', '> 5.0'
gem 'uglifier', '>= 1.3.0'
gem 'coffee-rails', '> 4.2'
gem 'turbolinks', '> 5'
gem 'jbuilder', '> 2.5'
gem 'devise'
gem 'devise_token_auth'
gem 'omniauth'
gem 'rack-cors', :require => 'rack/cors'
gem 'cancancan', '> 2.0'
gem 'bcrypt', '> 3.1.7'
gem 'rack'
gem 'rack-test', require: 'rack/test'
gem 'activeadmin', '> 1.1.0'
gem 'active_skin'
gem 'rails-i18n'
gem 'ckeditor'
gem 'paperclip'
gem 'friendly_id', '> 5.1.0'
gem 'active_model_serializers', '> 0.10.7'

group :development, :test do
gem 'byebug', platforms: [:mri, :mingw, :x64_mingw]
gem 'capybara', '~> 2.13'
gem 'selenium-webdriver'
end

group :development do
gem 'web-console', '>= 3.3.0'
gem 'listen', '>= 3.0.5', '< 3.2'
gem 'spring'
gem 'spring-watcher-listen', '~> 2.0.0'
gem 'capistrano', require: false
gem 'capistrano-rvm', require: false
gem 'capistrano-rails', require: false
gem 'capistrano-bundler', require: false
gem 'capistrano3-puma', require: false
end

gem 'tzinfo-data', platforms: [:mingw, :mswin, :x64_mingw, :jruby]

Thanks for any support.

[zachfeldman]

@dikey94 are you sure that your tokens column is JSON? See this search result:
https://stackoverflow.com/questions/2072283/rails-strange-error-indexerror-string-not-matched

Sounds like maybe you have a column that's the wrong type?

[dikey94]

I'm sure.

Here is a simple users table preview:

> `id	bigint
> provider	character varying
> uid	character varying
> encrypted_password	character varying
> reset_password_token	character varying
> reset_password_sent_at	timestamp without time zone
> remember_created_at	timestamp without time zone
> sign_in_count	integer
> current_sign_in_at	timestamp without time zone
> last_sign_in_at	timestamp without time zone
> current_sign_in_ip	character varying
> last_sign_in_ip	character varying
> confirmation_token	character varying
> confirmed_at	timestamp without time zone
> confirmation_sent_at	timestamp without time zone
> unconfirmed_email	character varying
> name	character varying
> nickname	character varying
> image	character varying
> email	character varying
> first_name	character varying
> last_name	character varying
> tokens	json
> created_at	timestamp without time zone
> updated_at	timestamp without time zone
> `

[zachfeldman]

@dikey94 what database are you using to back your project?

[zachfeldman]

Also see:
rootstrap/rails_api_base#73
rootstrap/rails_api_base#85

[dikey94]

It's a docker version of postgres:10.1

[MaicolBen]

It's a duplicate of #121