18

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'
Markus Graf
  • 533
  • 3
  • 16
  • 1
    There are multiple reasons. One is explained in this question http://stackoverflow.com/questions/39055480/invalidauthenticitytoken-errors-in-mobile – slowjack2k Sep 23 '16 at 09:42
  • Question linked from @slowjack2k 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 https://github.com/rails/rails/issues/21948 – Markus Graf Sep 28 '16 at 12:10
  • I'm curious, did you find out? I'm seeing also some of this occasional errors and I'm digging it further. – dgilperez Oct 02 '16 at 14:38
  • 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. – Markus Graf Oct 03 '16 at 13:28
  • Have any logs from you server to give a bit of details/context to what/when it happens ? – gdurelle Dec 06 '16 at 16:06
  • I added some logs I found in a recent exception. – Markus Graf Dec 07 '16 at 12:08
  • 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. – Codebeef Dec 23 '16 at 10:12

2 Answers2

2

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.

Community
  • 1
  • 1
karnesJ.R
  • 326
  • 1
  • 11
0

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.

Dorian
  • 22,759
  • 8
  • 120
  • 116