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'

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.