"Can't verify CSRF token authenticity"

Question

"Can't verify CSRF token authenticity"

xmunoz opened this issue a year ago · 2 comments

I recently tried to log in on sandbox and hit a "422 Unprocessable Entity" error. Here is the backtrace from papertrail. Unfortunately the error does not appear to have been propagated to Sentry. I was eventually able to log in, so at worst it's intermittent. Until we can confirm that this won't be a problem on production, I don't think we should do any deploys.

heroku/router sock=client at=warning code=H27 desc="Client Request Interrupted" method=POST path="/users/sign_in?locale=es" host=sandbox.dariaservices.com request_id=b1d4d799-19a5-4f93-b1c4-317487ab7779 fwd="107.150.22.75,172.71.26.105" dyno=web.1 connect=0ms service=292ms status=499 bytes= protocol=https
app/web.1 I, [2023-05-10T21:37:08.883081 #11]  INFO -- : [b1d4d799-19a5-4f93-b1c4-317487ab7779] Redirected to https://sandbox.dariaservices.com/
app/web.1 I, [2023-05-10T21:37:08.883194 #11]  INFO -- : [b1d4d799-19a5-4f93-b1c4-317487ab7779] Completed 302 Found in 271ms (ActiveRecord: 17.1ms | Allocations: 16981)
app/web.1 I, [2023-05-10T21:37:25.404953 #8]  INFO -- : [390fc535-bb9b-456c-9eea-bb429b612b02] Started POST "/users/sign_in" for 172.71.26.105 at 2023-05-10 21:37:25 +0000
app/web.1 I, [2023-05-10T21:37:25.411357 #8]  INFO -- : [390fc535-bb9b-456c-9eea-bb429b612b02] Processing by Users::SessionsController#create as HTML
app/web.1 I, [2023-05-10T21:37:25.411408 #8]  INFO -- : [390fc535-bb9b-456c-9eea-bb429b612b02]   Parameters: {"authenticity_token"=>"[FILTERED]", "user"=>{"email"=>"[FILTERED]", "password"=>"[FILTERED]"}, "commit"=>"Sign in with password"}
app/web.1 W, [2023-05-10T21:37:25.478974 #8]  WARN -- : [390fc535-bb9b-456c-9eea-bb429b612b02] Can't verify CSRF token authenticity.
app/web.1 I, [2023-05-10T21:37:25.479456 #8]  INFO -- : [390fc535-bb9b-456c-9eea-bb429b612b02] Completed 422 Unprocessable Entity in 68ms (ActiveRecord: 25.6ms | Allocations: 10882)
app/web.1 F, [2023-05-10T21:37:25.481043 #8] FATAL -- : [390fc535-bb9b-456c-9eea-bb429b612b02]   
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] ActionController::InvalidAuthenticityToken (Can't verify CSRF token authenticity.):
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02]   
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_controller/metal/request_forgery_protection.rb:251:in `handle_unverified_request'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_controller/metal/request_forgery_protection.rb:284:in `handle_unverified_request'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] devise (4.9.2) lib/devise/controllers/helpers.rb:255:in `handle_unverified_request'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_controller/metal/request_forgery_protection.rb:273:in `verify_authenticity_token'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/callbacks.rb:400:in `block in make_lambda'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/callbacks.rb:199:in `block (2 levels) in halting'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/abstract_controller/callbacks.rb:34:in `block (2 levels) in <module:Callbacks>'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/callbacks.rb:200:in `block in halting'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/callbacks.rb:595:in `block in invoke_before'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/callbacks.rb:595:in `each'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/callbacks.rb:595:in `invoke_before'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/callbacks.rb:116:in `block in run_callbacks'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] sentry-rails (5.9.0) lib/sentry/rails/controller_transaction.rb:28:in `block in sentry_around_action'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] sentry-ruby (5.9.0) lib/sentry/hub.rb:102:in `with_child_span'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] sentry-ruby (5.9.0) lib/sentry-ruby.rb:456:in `with_child_span'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] sentry-rails (5.9.0) lib/sentry/rails/controller_transaction.rb:14:in `sentry_around_action'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/callbacks.rb:127:in `block in run_callbacks'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/callbacks.rb:138:in `run_callbacks'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/abstract_controller/callbacks.rb:233:in `process_action'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_controller/metal/rescue.rb:22:in `process_action'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_controller/metal/instrumentation.rb:67:in `block in process_action'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/notifications.rb:206:in `block in instrument'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/notifications/instrumenter.rb:24:in `instrument'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/notifications.rb:206:in `instrument'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_controller/metal/instrumentation.rb:66:in `process_action'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_controller/metal/params_wrapper.rb:259:in `process_action'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activerecord (7.0.4.3) lib/active_record/railties/controller_runtime.rb:27:in `process_action'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/abstract_controller/base.rb:151:in `process'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionview (7.0.4.3) lib/action_view/rendering.rb:39:in `process'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_controller/metal.rb:188:in `dispatch'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_controller/metal.rb:251:in `dispatch'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/routing/route_set.rb:32:in `serve'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/routing/mapper.rb:18:in `block in <class:Constraints>'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/routing/mapper.rb:48:in `serve'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/journey/router.rb:50:in `block in serve'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/journey/router.rb:32:in `each'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/journey/router.rb:32:in `serve'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/routing/route_set.rb:852:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] omniauth (2.1.1) lib/omniauth/strategy.rb:202:in `call!'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] omniauth (2.1.1) lib/omniauth/strategy.rb:169:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] rack-attack (6.6.1) lib/rack/attack.rb:103:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] rack-attack (6.6.1) lib/rack/attack.rb:127:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] warden (1.2.9) lib/warden/manager.rb:36:in `block in call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] warden (1.2.9) lib/warden/manager.rb:34:in `catch'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] warden (1.2.9) lib/warden/manager.rb:34:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] rack (2.2.6.4) lib/rack/tempfile_reaper.rb:15:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] rack (2.2.6.4) lib/rack/etag.rb:27:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] rack (2.2.6.4) lib/rack/conditional_get.rb:40:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] rack (2.2.6.4) lib/rack/head.rb:12:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/http/permissions_policy.rb:38:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/http/content_security_policy.rb:36:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] rack (2.2.6.4) lib/rack/session/abstract/id.rb:266:in `context'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] rack (2.2.6.4) lib/rack/session/abstract/id.rb:260:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/middleware/cookies.rb:704:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/callbacks.rb:99:in `run_callbacks'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/middleware/callbacks.rb:26:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] sentry-rails (5.9.0) lib/sentry/rails/rescued_exception_interceptor.rb:12:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/middleware/debug_exceptions.rb:28:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] sentry-ruby (5.9.0) lib/sentry/rack/capture_exceptions.rb:28:in `block (2 levels) in call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] sentry-ruby (5.9.0) lib/sentry/hub.rb:223:in `with_session_tracking'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] sentry-ruby (5.9.0) lib/sentry-ruby.rb:385:in `with_session_tracking'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] sentry-ruby (5.9.0) lib/sentry/rack/capture_exceptions.rb:19:in `block in call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] sentry-ruby (5.9.0) lib/sentry/hub.rb:59:in `with_scope'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] sentry-ruby (5.9.0) lib/sentry-ruby.rb:365:in `with_scope'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] sentry-ruby (5.9.0) lib/sentry/rack/capture_exceptions.rb:18:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/middleware/show_exceptions.rb:26:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] railties (7.0.4.3) lib/rails/rack/logger.rb:40:in `call_app'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] railties (7.0.4.3) lib/rails/rack/logger.rb:25:in `block in call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/tagged_logging.rb:99:in `block in tagged'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/tagged_logging.rb:37:in `tagged'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] activesupport (7.0.4.3) lib/active_support/tagged_logging.rb:99:in `tagged'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] railties (7.0.4.3) lib/rails/rack/logger.rb:25:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/middleware/remote_ip.rb:93:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] request_store (1.5.1) lib/request_store/middleware.rb:19:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/middleware/request_id.rb:26:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] rack (2.2.6.4) lib/rack/method_override.rb:24:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] rack (2.2.6.4) lib/rack/runtime.rb:22:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/middleware/executor.rb:14:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/middleware/static.rb:23:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] rack (2.2.6.4) lib/rack/sendfile.rb:110:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/middleware/ssl.rb:77:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] actionpack (7.0.4.3) lib/action_dispatch/middleware/host_authorization.rb:137:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] railties (7.0.4.3) lib/rails/engine.rb:530:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] puma (6.2.2) lib/puma/configuration.rb:270:in `call'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] puma (6.2.2) lib/puma/request.rb:98:in `block in handle_request'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] puma (6.2.2) lib/puma/thread_pool.rb:340:in `with_force_shutdown'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] puma (6.2.2) lib/puma/request.rb:97:in `handle_request'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] puma (6.2.2) lib/puma/server.rb:431:in `process_client'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] puma (6.2.2) lib/puma/server.rb:233:in `block in run'
app/web.1 [390fc535-bb9b-456c-9eea-bb429b612b02] puma (6.2.2) lib/puma/thread_pool.rb:147:in `block in spawn_thread'
app/web.1 I, [2023-05-10T21:37:25.482318 #8]  INFO -- : [390fc535-bb9b-456c-9eea-bb429b612b02] Processing by ErrorsController#error_422 as HTML

Answer 1 · 2023-06-03T13:21:57.000Z

I loaded this up to take a look and was able to log in with both password and oauth successfully on sandbox. I'll try to recreate this but I can think of a few reasons this would have plausibly happened:

server timing out of sync with reality, causing it to expire
a server restart meant the CSRF provided was no longer recognized
ghosts / other

I think by and large I'm not scared of this (I'd be most inclined to attribute it to the not-ghosts bullets), so I'll plan on doing a deploy tomorrow and seeing if it breaks something or other, and make sure I'm available to rollback if necessary.

PS: Most likely this didn't show up in sentry because it was a 422 and not a 5XX - maybe surprising but expected. If we want to log that we'd probably have to subclass a devise controller, although maybe devise has an '5xx on login failure' setting we can toggle or something.

Answer 2 · 2023-06-09T14:15:56.000Z

Unable to repro