Reasons for spontaneously authenticity token rejection on production site

Question

My Rails application throws an ActionController::InvalidAuthenticityToken from time to time. It occurs spontaneously once a month or so. As I don't think that there is some other site trying a CSRF attack, I started to make my thoughts about this rare events. My conclusion so far:

• Random robots?
• People waiting too long to send the form so that it expires on the server?

Are there other reasons for such false positive rejections?

And please don't explain what CSRF is ;-)

Here are some logs...

F, [2016-12-06T16:03:59.050673 #15136] FATAL -- : 
ActionController::InvalidAuthenticityToken (ActionController::InvalidAuthenticityToken):
  actionpack (4.2.7) lib/action_controller/metal/request_forgery_protection.rb:181:in `handle_unverified_request'
  actionpack (4.2.7) lib/action_controller/metal/request_forgery_protection.rb:209:in `handle_unverified_request'
  devise (4.2.0) lib/devise/controllers/helpers.rb:253:in `handle_unverified_request'
  actionpack (4.2.7) lib/action_controller/metal/request_forgery_protection.rb:204:in `verify_authenticity_token'
  activesupport (4.2.7) lib/active_support/callbacks.rb:432:in `block in make_lambda'
  activesupport (4.2.7) lib/active_support/callbacks.rb:164:in `block in halting'
  activesupport (4.2.7) lib/active_support/callbacks.rb:504:in `block in call'
  activesupport (4.2.7) lib/active_support/callbacks.rb:504:in `each'
  activesupport (4.2.7) lib/active_support/callbacks.rb:504:in `call'
  activesupport (4.2.7) lib/active_support/callbacks.rb:92:in `__run_callbacks__'
  activesupport (4.2.7) lib/active_support/callbacks.rb:778:in `_run_process_action_callbacks'
  activesupport (4.2.7) lib/active_support/callbacks.rb:81:in `run_callbacks'
  actionpack (4.2.7) lib/abstract_controller/callbacks.rb:19:in `process_action'
  actionpack (4.2.7) lib/action_controller/metal/rescue.rb:29:in `process_action'
  actionpack (4.2.7) lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
  activesupport (4.2.7) lib/active_support/notifications.rb:164:in `block in instrument'
  activesupport (4.2.7) lib/active_support/notifications/instrumenter.rb:20:in `instrument'
  activesupport (4.2.7) lib/active_support/notifications.rb:164:in `instrument'
  actionpack (4.2.7) lib/action_controller/metal/instrumentation.rb:30:in `process_action'
  actionpack (4.2.7) lib/action_controller/metal/params_wrapper.rb:250:in `process_action'
  actionpack (4.2.7) lib/abstract_controller/base.rb:137:in `process'
  actionview (4.2.7) lib/action_view/rendering.rb:30:in `process'
  actionpack (4.2.7) lib/action_controller/metal.rb:196:in `dispatch'
  actionpack (4.2.7) lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
  actionpack (4.2.7) lib/action_controller/metal.rb:237:in `block in action'
  actionpack (4.2.7) lib/action_dispatch/routing/route_set.rb:74:in `dispatch'
  actionpack (4.2.7) lib/action_dispatch/routing/route_set.rb:43:in `serve'
  actionpack (4.2.7) lib/action_dispatch/routing/mapper.rb:49:in `serve'
  actionpack (4.2.7) lib/action_dispatch/journey/router.rb:43:in `block in serve'
  actionpack (4.2.7) lib/action_dispatch/journey/router.rb:30:in `each'
  actionpack (4.2.7) lib/action_dispatch/journey/router.rb:30:in `serve'
  actionpack (4.2.7) lib/action_dispatch/routing/route_set.rb:817:in `call'
  turnout (2.3.1) lib/rack/turnout.rb:25:in `call'
  omniauth (1.3.1) lib/omniauth/strategy.rb:186:in `call!'
  omniauth (1.3.1) lib/omniauth/strategy.rb:164:in `call'
  omniauth (1.3.1) lib/omniauth/strategy.rb:186:in `call!'
  omniauth (1.3.1) lib/omniauth/strategy.rb:164:in `call'
  rack-attack (4.4.1) lib/rack/attack.rb:107:in `call'
  exception_notification (4.2.1) lib/exception_notification/rack.rb:32: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 `catch'
  warden (1.2.6) lib/warden/manager.rb:34:in `call'
  rack (1.6.4) lib/rack/etag.rb:24:in `call'
  rack (1.6.4) lib/rack/conditionalget.rb:38:in `call'
  rack (1.6.4) lib/rack/head.rb:13:in `call'
  actionpack (4.2.7) lib/action_dispatch/middleware/params_parser.rb:27:in `call'
  actionpack (4.2.7) lib/action_dispatch/middleware/flash.rb:260: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'
  actionpack (4.2.7) lib/action_dispatch/middleware/cookies.rb:560:in `call'
  actionpack (4.2.7) lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
  activesupport (4.2.7) lib/active_support/callbacks.rb:88:in `__run_callbacks__'
  activesupport (4.2.7) lib/active_support/callbacks.rb:778:in `_run_call_callbacks'
  activesupport (4.2.7) lib/active_support/callbacks.rb:81:in `run_callbacks'
  actionpack (4.2.7) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  actionpack (4.2.7) lib/action_dispatch/middleware/remote_ip.rb:78:in `call'
  actionpack (4.2.7) lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
  actionpack (4.2.7) lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
  railties (4.2.7) lib/rails/rack/logger.rb:38:in `call_app'
  railties (4.2.7) lib/rails/rack/logger.rb:20:in `block in call'
  activesupport (4.2.7) lib/active_support/tagged_logging.rb:68:in `block in tagged'
  activesupport (4.2.7) lib/active_support/tagged_logging.rb:26:in `tagged'
  activesupport (4.2.7) lib/active_support/tagged_logging.rb:68:in `tagged'
  railties (4.2.7) lib/rails/rack/logger.rb:20:in `call'
  ahoy_matey (1.4.2) lib/ahoy/engine.rb:22:in `call_with_quiet_ahoy'
  request_store (1.3.1) lib/request_store/middleware.rb:9:in `call'
  actionpack (4.2.7) lib/action_dispatch/middleware/request_id.rb:21:in `call'
  rack (1.6.4) lib/rack/methodoverride.rb:22:in `call'
  rack (1.6.4) lib/rack/runtime.rb:18:in `call'
  activesupport (4.2.7) lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
  rack (1.6.4) lib/rack/sendfile.rb:113:in `call'
  actionpack (4.2.7) lib/action_dispatch/middleware/ssl.rb:24:in `call'
  railties (4.2.7) lib/rails/engine.rb:518:in `call'
  railties (4.2.7) lib/rails/application.rb:165:in `call'
  /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:97:in `process_request'
  /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:160:in `accept_and_process_next_request'
  /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:113:in `main_loop'
  /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:416:in `block (3 levels) in start_threads'
  /usr/lib/ruby/vendor_ruby/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'

Ragi

There are multiple reasons. One is explained in this question #39055980 – Ichthyology

Question linked from @Ichthyology seems to be a severe issue. But my observations of this is very rare. So I guess it is more a timing and caching issue as described here github.com/rails/rails/issues/21948 – Ragi

I'm curious, did you find out? I'm seeing also some of this occasional errors and I'm digging it further. – Inexertion

No, sorry I had no time to investigate it in more details, it also seem not a problem in production. No one ever complained about this so far. – Ragi

Have any logs from you server to give a bit of details/context to what/when it happens ? – Rabjohn

I added some logs I found in a recent exception. – Ragi

Have you logged the details of the request that caused the exception? If you use something like Rollbar, you'll get more information on the actual request. – Hhd

Answer 1

I am with Dorian on this one as for the solution.

If you're looking to the cause I'm fairly positive that this issue report in rails github hits true, especially this little section:

# Browser quits, clearing session cookies

# Browser re-opens, reloads the page from cache without doing a request

This is especially true since by defualt Rails uses turbolinks which encourages caching (by default 10 pages if I recall).

Another way this can be potentially replicated is by having a user load your DOM (and thus your cookies / session) and then having them manually destroy their session or cookies through the browser management tools (e.g: chrome://settings). This should also reproduce the error since you will have the hidden tag for csrf in the form, but not the session cookie... and you need both.

Baccate

Thanks, I think that could be the case. – Ragi

@MarkusGraf I am curious to know if this ended up actually being the problem. Do you have any feedback on testing the issue? – Baccate

Answer 2

You should probably null the session in your production environment instead of throwing an exception:

In you ApplicationController (or any controller you are concerned about) add:

protect_from_forgery with: :null_session

If you are really worried about it, my advice would be to log to error to Bugsnag for instance and there you will be able to review the request and understand why it happened.

Seriema