devise_token_auth: not working with latest version of active_model_serializers

Logins produce an error with version 0.10.0.rc5 of active_model_serializers. I’ve also filed an issue there, because I can’t figure out where the root cause is.

With version 0.10.0.rc4 ASM is not serializing the response from devise_token_auth, so sign_in succeeds:

Started POST "/api/v1/auth/sign_in" for 127.0.0.1 at 2016-04-06 11:55:32 -0400
  ActiveRecord::SchemaMigration Load (0.9ms)  SELECT "schema_migrations".* FROM "schema_migrations"
Processing by DeviseTokenAuth::SessionsController#create as JSON
  Parameters: {"email"=>"EMAIL", "password"=>"[FILTERED]"}
Can't verify CSRF token authenticity
  User Load (3.4ms)  SELECT  "users".* FROM "users" WHERE (email = 'EMAIL' AND provider='email')  ORDER BY "users"."id" ASC LIMIT 1
   (1.0ms)  BEGIN
  SQL (2.2ms)  UPDATE "users" SET "tokens" = $1, "updated_at" = $2 WHERE "users"."id" = $3  [
  ["tokens", "{\"KEY\":{\"token\":\"VALUE\",\"expiry\":1460489763}}"], ["updated_at", "2016-04-06 15:55:32.864239"], ["id", 1]]
   (1.2ms)  COMMIT
   (0.8ms)  BEGIN
  SQL (1.4ms)  UPDATE "users" SET "last_sign_in_at" = $1, "current_sign_in_at" = $2, "sign_in_count" = $3, "updated_at" = $4 WHERE "users"."id" = $5  [["last_sign_in_at", "2016-04-06 15:53:07.210140"], ["current_sign_in_at", "2016-04-06 15:55:32.887707"], ["sign_in_count", 33], ["updated_at", "2016-04-06 15:55:32.889785"], ["id", 1]]
   (1.2ms)  COMMIT
Completed 200 OK in 212ms (Views: 5.4ms | ActiveRecord: 13.1ms)

With version 0.10.0.rc5 ASM is attempting to serialize the response from devise_token_auth, so sign_in fails:

Started POST "/api/v1/auth/sign_in" for 127.0.0.1 at 2016-04-06 11:57:45 -0400
  ActiveRecord::SchemaMigration Load (1.0ms)  SELECT "schema_migrations".* FROM "schema_migrations"
Processing by DeviseTokenAuth::SessionsController#create as JSON
  Parameters: {"email"=>"EMAIL", "password"=>"[FILTERED]"}
Can't verify CSRF token authenticity
  User Load (2.3ms)  SELECT  "users".* FROM "users" WHERE (email = 'EMAIL' AND provider='email')  ORDER BY "users"."id" ASC LIMIT 1
   (1.1ms)  BEGIN
  SQL (1.8ms)  UPDATE "users" SET "tokens" = $1, "updated_at" = $2 WHERE "users"."id" = $3  [["tokens", "{\"KEY\":{\"token\":\"VALUE\",\"expiry\":1460489763}}"], ["updated_at", "2016-04-06 15:57:45.253067"], ["id", 1]]
   (1.2ms)  COMMIT
   (0.9ms)  BEGIN
  SQL (1.3ms)  UPDATE "users" SET "last_sign_in_at" = $1, "current_sign_in_at" = $2, "sign_in_count" = $3, "updated_at" = $4 WHERE "users"."id" = $5  [["last_sign_in_at", "2016-04-06 15:55:32.887707"], ["current_sign_in_at", "2016-04-06 15:57:45.271287"], ["sign_in_count", 34], ["updated_at", "2016-04-06 15:57:45.273380"], ["id", 1]]
   (1.1ms)  COMMIT
[active_model_serializers] Rendered ActiveModel::Serializer::Null with Hash (0.14ms)
Completed 500 Internal Server Error in 207ms (Views: 7.5ms | ActiveRecord: 10.9ms)

I’m not sure if the fix will ultimately reside in active_model_serializers or here.

The error & backtrace is:

> undefined method `[]' for nil:NilClass

devise_token_auth (0.1.37) app/models/devise_token_auth/concerns/user.rb, line 202
----------------------------------------------------------------------------------

  197     def build_auth_header(token, client_id='default')
  198       client_id ||= 'default'
  199   
  200       # client may use expiry to prevent validation request if expired
  201       # must be cast as string or headers will break
> 202       expiry = self.tokens[client_id]['expiry'] || self.tokens[client_id][:expiry]
  203   
  204       return {
  205         "access-token" => token,
  206         "token-type"   => "Bearer",
  207         "client"       => client_id,

NoMethodError - undefined method `[]' for nil:NilClass:
  devise_token_auth (0.1.37) app/models/devise_token_auth/concerns/user.rb:202:in `build_auth_header'
  devise_token_auth (0.1.37) app/controllers/devise_token_auth/concerns/set_user_by_token.rb:77:in `update_auth_header'
  activesupport (4.2.6) lib/active_support/callbacks.rb:432:in `block in make_lambda'
  activesupport (4.2.6) lib/active_support/callbacks.rb:239:in `block in halting'
  activesupport (4.2.6) lib/active_support/callbacks.rb:506:in `block in call'
  activesupport (4.2.6) lib/active_support/callbacks.rb:506:in `call'
  activesupport (4.2.6) lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
  activesupport (4.2.6) lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
  rails-observers (0.1.2) lib/rails/observers/action_controller/caching/sweeping.rb:73:in `around'
  activesupport (4.2.6) lib/active_support/callbacks.rb:455:in `block in make_lambda'
  activesupport (4.2.6) lib/active_support/callbacks.rb:312:in `block in halting'
  activesupport (4.2.6) lib/active_support/callbacks.rb:497:in `block in around'
  activesupport (4.2.6) lib/active_support/callbacks.rb:505:in `call'
  activesupport (4.2.6) lib/active_support/callbacks.rb:92:in `__run_callbacks__'
  activesupport (4.2.6) lib/active_support/callbacks.rb:778:in `_run_process_action_callbacks'
  activesupport (4.2.6) lib/active_support/callbacks.rb:81:in `run_callbacks'
  actionpack (4.2.6) lib/abstract_controller/callbacks.rb:19:in `process_action'
  actionpack (4.2.6) lib/action_controller/metal/rescue.rb:29:in `process_action'
  actionpack (4.2.6) lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
  activesupport (4.2.6) lib/active_support/notifications.rb:164:in `block in instrument'
  activesupport (4.2.6) lib/active_support/notifications/instrumenter.rb:20:in `instrument'
  activesupport (4.2.6) lib/active_support/notifications.rb:164:in `instrument'
  actionpack (4.2.6) lib/action_controller/metal/instrumentation.rb:30:in `process_action'
  actionpack (4.2.6) lib/action_controller/metal/params_wrapper.rb:250:in `process_action'
  activerecord (4.2.6) lib/active_record/railties/controller_runtime.rb:18:in `process_action'
  actionpack (4.2.6) lib/abstract_controller/base.rb:137:in `process'
  actionview (4.2.6) lib/action_view/rendering.rb:30:in `process'
  rack-mini-profiler (0.9.9.2) lib/mini_profiler/profiling_methods.rb:102:in `block in profile_method'
  actionpack (4.2.6) lib/action_controller/metal.rb:196:in `dispatch'
  actionpack (4.2.6) lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
  actionpack (4.2.6) lib/action_controller/metal.rb:237:in `block in action'
  actionpack (4.2.6) lib/action_dispatch/routing/route_set.rb:74:in `dispatch'
  actionpack (4.2.6) lib/action_dispatch/routing/route_set.rb:43:in `serve'
  actionpack (4.2.6) lib/action_dispatch/routing/mapper.rb:49:in `serve'
  actionpack (4.2.6) lib/action_dispatch/journey/router.rb:43:in `block in serve'
  actionpack (4.2.6) lib/action_dispatch/journey/router.rb:30:in `serve'
  actionpack (4.2.6) lib/action_dispatch/routing/route_set.rb:817:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  bullet (5.0.0) lib/bullet/rack.rb:12:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/rack/agent_hooks.rb:30:in `traced_call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/rack/browser_monitoring.rb:32:in `traced_call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/rack/developer_mode.rb:48:in `traced_call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  warden (1.2.6) lib/warden/manager.rb:35:in `block in call'
  warden (1.2.6) lib/warden/manager.rb:34:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  rack (1.6.4) lib/rack/etag.rb:24:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  rack (1.6.4) lib/rack/conditionalget.rb:38:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  rack (1.6.4) lib/rack/head.rb:13:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  actionpack (4.2.6) lib/action_dispatch/middleware/params_parser.rb:27:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  actionpack (4.2.6) lib/action_dispatch/middleware/flash.rb:260:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  rack (1.6.4) lib/rack/session/abstract/id.rb:225:in `context'
  rack (1.6.4) lib/rack/session/abstract/id.rb:220:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  actionpack (4.2.6) lib/action_dispatch/middleware/cookies.rb:560:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  activerecord (4.2.6) lib/active_record/query_cache.rb:36:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  activerecord (4.2.6) lib/active_record/connection_adapters/abstract/connection_pool.rb:653:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  activerecord (4.2.6) lib/active_record/migration.rb:377:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  actionpack (4.2.6) lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
  activesupport (4.2.6) lib/active_support/callbacks.rb:88:in `__run_callbacks__'
  activesupport (4.2.6) lib/active_support/callbacks.rb:778:in `_run_call_callbacks'
  activesupport (4.2.6) lib/active_support/callbacks.rb:81:in `run_callbacks'
  actionpack (4.2.6) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  actionpack (4.2.6) lib/action_dispatch/middleware/reloader.rb:73:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  actionpack (4.2.6) lib/action_dispatch/middleware/remote_ip.rb:78:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  rollbar (2.8.3) lib/rollbar/middleware/rails/rollbar.rb:24:in `block in call'
  rollbar (2.8.3) lib/rollbar.rb:948:in `scoped'
  rollbar (2.8.3) lib/rollbar/middleware/rails/rollbar.rb:22:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  better_errors (2.1.1) lib/better_errors/middleware.rb:84:in `protected_app_call'
  better_errors (2.1.1) lib/better_errors/middleware.rb:79:in `better_errors_call'
  better_errors (2.1.1) lib/better_errors/middleware.rb:57:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  actionpack (4.2.6) lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
  rollbar (2.8.3) lib/rollbar/middleware/rails/show_exceptions.rb:22:in `call_with_rollbar'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  web-console (2.3.0) lib/web_console/middleware.rb:28:in `block in call'
  web-console (2.3.0) lib/web_console/middleware.rb:18:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  actionpack (4.2.6) lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  railties (4.2.6) lib/rails/rack/logger.rb:38:in `call_app'
  railties (4.2.6) lib/rails/rack/logger.rb:20:in `block in call'
  activesupport (4.2.6) lib/active_support/tagged_logging.rb:68:in `block in tagged'
  activesupport (4.2.6) lib/active_support/tagged_logging.rb:26:in `tagged'
  activesupport (4.2.6) lib/active_support/tagged_logging.rb:68:in `tagged'
  railties (4.2.6) lib/rails/rack/logger.rb:20:in `call'
  quiet_assets (1.1.0) lib/quiet_assets.rb:27:in `call_with_quiet_assets'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  actionpack (4.2.6) lib/action_dispatch/middleware/request_id.rb:21:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  rack (1.6.4) lib/rack/methodoverride.rb:22:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  rack (1.6.4) lib/rack/runtime.rb:18:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  activesupport (4.2.6) lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  rack (1.6.4) lib/rack/lock.rb:17:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  actionpack (4.2.6) lib/action_dispatch/middleware/static.rb:120:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  rack (1.6.4) lib/rack/sendfile.rb:113:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  rack-cors (0.4.0) lib/rack/cors.rb:80:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  rack-mini-profiler (0.9.9.2) lib/mini_profiler/profiler.rb:281:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  railties (4.2.6) lib/rails/engine.rb:518:in `call'
  railties (4.2.6) lib/rails/application.rb:165:in `call'
  newrelic_rpm (3.15.1.316) lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
  rack (1.6.4) lib/rack/content_length.rb:15:in `call'
  thin (1.6.4) lib/thin/connection.rb:86:in `block in pre_process'
  thin (1.6.4) lib/thin/connection.rb:84:in `pre_process'
  thin (1.6.4) lib/thin/connection.rb:53:in `process'
  thin (1.6.4) lib/thin/connection.rb:39:in `receive_data'
  eventmachine (1.2.0.1) lib/eventmachine.rb:194:in `run'
  thin (1.6.4) lib/thin/backends/base.rb:73:in `start'
  thin (1.6.4) lib/thin/server.rb:162:in `start'
  rack (1.6.4) lib/rack/handler/thin.rb:19:in `run'
  rack (1.6.4) lib/rack/server.rb:286:in `start'
  railties (4.2.6) lib/rails/commands/server.rb:80:in `start'
  railties (4.2.6) lib/rails/commands/commands_tasks.rb:80:in `block in server'
  railties (4.2.6) lib/rails/commands/commands_tasks.rb:75:in `server'
  railties (4.2.6) lib/rails/commands/commands_tasks.rb:39:in `run_command!'
  railties (4.2.6) lib/rails/commands.rb:17:in `<top (required)>'
  bin/rails:4:in `<main>'

I do have a serializer for User, but it looks like devise_token_auth isn’t using it. The rc5 output at the top of this issue included this line: [active_model_serializers] Rendered ActiveModel::Serializer::Null with Hash (0.14ms) … The Null in there seems odd.

With rc4, the client_id is making it into the build_auth_header method. With rc5, it is not (it exists as default).

I’ve been trying to trace back that client_id value, but I haven’t been successful in finding where it gets unset.

Can you provide any insight on when the client_id value would be unset, or the order of methods that are called during sign_in?

About this issue

Original URL
State: closed
Created 8 years ago
Reactions: 8
Comments: 20 (1 by maintainers)

Commits related to this issue

Fix for issue #600 Method set_user_by_token is called(from current_user) after SessionController create action and @client_id was set to nil. — committed to milep/devise_token_auth by deleted user 8 years ago
Merge pull request #674 from milep/master Fix for issue #600 — committed to lynndylanhurley/devise_token_auth by booleanbetrayal 8 years ago

Most upvoted comments

I’m facing the same issue with (devise_token_auth 0.1.39), (devise 4.2.0) and (active_model_serializers to 0.10.2), I downgraded to 0.1.38 as per @JamesChevalier comment but still the same!

Rendered ActiveModel::Serializer::Null with Hash

AbdullahAs on Oct 19, 2016

I advise you to use active model serializer v0.9

omar28 on Apr 18, 2016

Downgrading to version 0.10.0.rc4 fixes the issue

Indicate this in your gemfile:

gem ‘active_model_serializers’, ‘0.10.0.rc4’

augustosamame on May 21, 2016

Hi @brunowego , I found a workaround in this stackoverflow post . I just added:

serialization_scope :view_context

To the base controller I’m using for my api (for you it might be ApplicationController) and it worked.

This is my ApiController just in case:

class ApiController < ActionController::Base

      include DeviseTokenAuth::Concerns::SetUserByToken
      protect_from_forgery with: :null_session, only: Proc.new { |c| c.request.format.json? }
      serialization_scope :view_context

end

I really hope this is helpfull to you.

godinezb on Dec 9, 2016

Facing same problem with ‘devise_token_auth’, ‘0.1.39’ and ‘active_model_serializers’, '0.10.3’, I have downgraded to 0.1.38 but the problem it’s still there. I’m getting:

AppUser Load (0.3ms)  SELECT  "app_users".* FROM "app_users" WHERE "app_users"."uid" = $1 LIMIT 1  [["uid", "somemail@mymail.mx"]]
Completed 500 Internal Server Error in 117ms (ActiveRecord: 1.2ms)
NoMethodError (undefined method `find_by_uid' for #<Class:0x007f9db45a8fa8>
Did you mean?  find_by
               find_by!
               find_by_sql)

Is this issue gonna be re-open?

godinezb on Dec 1, 2016

@AbdullahAs +1

BrahimDahmani on Nov 11, 2016

Hi @augustosamame thanks for trying to help out on this issue! Unfortunately, this task covers the fact that rc4 is functional and downgrading to resolve the problem is a workaround not a fix.

Development is going to continue over at active_model_serializers (they’ve already moved past the release candidate stage for the 0.10.0 version that we’re discussing here), so pinning that to an older release candidate version is only going to cause more problems down the road.

The good news is that there have been improvements in the level of functionality. This issue was originally reporting that the whole response was bad, but now the issue is with two particular header values not making their way out.

Thanks again!

JamesChevalier on May 21, 2016

@brunowego I’m using postman as well. I have used devise token auth in two similar projects, with the same gem sets and only in one of them I faces this issue. I’d be lost if I hand’t find that stackoverflow post.

godinezb on Jul 11, 2017

Just curious if there’s been any updates on this? We’re running into this issue as well when DTA is configured not to change tokens on each request.

config.change_headers_on_each_request = false

We got around this by implementing support for changing tokens in the client, which is fine.

However, we’ve now discovered a much more serious issue (introduced when using AMS 0.10.0.rc5 and later) that introduces a security hole.

If you post to /auth/sign_in with a valid email, but incorrect password, you get a 401 (expected), but you also get a valid auth header (access-token, client, uid, expiry) (definitely not expected!).

Rolling back to AMS 0.10.0.rc4 appears to fix it, but as suggested above, this is only a workaround, not a solution.

steveclarkin on Jun 9, 2016