Rails 5.2 POST to 404 results in 500 due to missing CSRF token

[adrianhuna]

Hi, I found an issue with POST requests to non-existent endpoints in Rails 5.2 applications. Such requests should result in 404, however, 500 is returned. In Rails 5.1 it works as expected.

I couldn't reproduce it using rspec test, so I am attaching an example Rails application.

https://github.com/adrianhuna/rambulance_example

If you start the server and make request:
curl -X POST http://localhost:3000/foo

you get

500 Internal Server Error
If you are the administrator of this website, then please read this web application's log file and/or the web server's log file to find out what went wrong.

In server log you can see that it couldn't handle InvalidAuthenticityToken error. However, in an Rails 5.1 app (branch rails_5_1 in the example application), such request results in correct 404 response.

Started POST "/foo" for 127.0.0.1 at 2019-04-17 11:36:50 +0200
  
ActionController::RoutingError (No route matches [POST] "/foo"):
  
actionpack (5.2.3) lib/action_dispatch/middleware/debug_exceptions.rb:65:in `call'
web-console (3.7.0) lib/web_console/middleware.rb:135:in `call_app'
web-console (3.7.0) lib/web_console/middleware.rb:30:in `block in call'
web-console (3.7.0) lib/web_console/middleware.rb:20:in `catch'
web-console (3.7.0) lib/web_console/middleware.rb:20:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
railties (5.2.3) lib/rails/rack/logger.rb:38:in `call_app'
railties (5.2.3) lib/rails/rack/logger.rb:26:in `block in call'
activesupport (5.2.3) lib/active_support/tagged_logging.rb:71:in `block in tagged'
activesupport (5.2.3) lib/active_support/tagged_logging.rb:28:in `tagged'
activesupport (5.2.3) lib/active_support/tagged_logging.rb:71:in `tagged'
railties (5.2.3) lib/rails/rack/logger.rb:26:in `call'
sprockets-rails (3.2.1) lib/sprockets/rails/quiet_assets.rb:13:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/request_id.rb:27:in `call'
rack (2.0.7) lib/rack/method_override.rb:22:in `call'
rack (2.0.7) lib/rack/runtime.rb:22:in `call'
activesupport (5.2.3) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/executor.rb:14:in `call'
actionpack (5.2.3) lib/action_dispatch/middleware/static.rb:127:in `call'
rack (2.0.7) lib/rack/sendfile.rb:111:in `call'
railties (5.2.3) lib/rails/engine.rb:524:in `call'
puma (3.12.1) lib/puma/configuration.rb:227:in `call'
puma (3.12.1) lib/puma/server.rb:660:in `handle_request'
puma (3.12.1) lib/puma/server.rb:474:in `process_client'
puma (3.12.1) lib/puma/server.rb:334:in `block in run'
puma (3.12.1) lib/puma/thread_pool.rb:135:in `block in spawn_thread'
Processing by Rambulance::ExceptionsApp#not_found as */*
Can't verify CSRF token authenticity.
Completed 422 Unprocessable Entity in 1ms


Error during failsafe response: ActionController::InvalidAuthenticityToken
  /path/to/gems/actionpack-5.2.3/lib/action_controller/metal/request_forgery_protection.rb:211:in `handle_unverified_request'
  /path/to/gems/actionpack-5.2.3/lib/action_controller/metal/request_forgery_protection.rb:243:in `handle_unverified_request'
  /path/to/gems/actionpack-5.2.3/lib/action_controller/metal/request_forgery_protection.rb:238:in `verify_authenticity_token'
  /path/to/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:426:in `block in make_lambda'
  /path/to/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:198:in `block (2 levels) in halting'
  /path/to/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:34:in `block (2 levels) in <module:Callbacks>'
  /path/to/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:199:in `block in halting'
  /path/to/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:513:in `block in invoke_before'
  /path/to/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:513:in `each'
  /path/to/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:513:in `invoke_before'
  /path/to/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:131:in `run_callbacks'
  /path/to/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:41:in `process_action'
  /path/to/gems/actionpack-5.2.3/lib/action_controller/metal/rescue.rb:22:in `process_action'
  /path/to/gems/actionpack-5.2.3/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
  /path/to/gems/activesupport-5.2.3/lib/active_support/notifications.rb:168:in `block in instrument'
  /path/to/gems/activesupport-5.2.3/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
  /path/to/gems/activesupport-5.2.3/lib/active_support/notifications.rb:168:in `instrument'
  /path/to/gems/actionpack-5.2.3/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
  /path/to/gems/actionpack-5.2.3/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
  /path/to/gems/rambulance-0.6.0/lib/rambulance/exceptions_app.rb:78:in `process_action'
  /path/to/gems/actionpack-5.2.3/lib/abstract_controller/base.rb:134:in `process'
  /path/to/gems/actionview-5.2.3/lib/action_view/rendering.rb:32:in `process'
  /path/to/gems/rambulance-0.6.0/lib/rambulance/exceptions_app.rb:52:in `process'
  /path/to/gems/actionpack-5.2.3/lib/action_controller/metal.rb:191:in `dispatch'
  /path/to/gems/actionpack-5.2.3/lib/action_controller/metal.rb:236:in `block in action'
  /path/to/gems/rambulance-0.6.0/lib/rambulance/exceptions_app.rb:31:in `call'
  /path/to/gems/actionpack-5.2.3/lib/action_dispatch/middleware/show_exceptions.rb:51:in `render_exception'
  /path/to/gems/actionpack-5.2.3/lib/action_dispatch/middleware/show_exceptions.rb:36:in `rescue in call'
  /path/to/gems/actionpack-5.2.3/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
  /path/to/gems/railties-5.2.3/lib/rails/rack/logger.rb:38:in `call_app'
  /path/to/gems/railties-5.2.3/lib/rails/rack/logger.rb:26:in `block in call'
  /path/to/gems/activesupport-5.2.3/lib/active_support/tagged_logging.rb:71:in `block in tagged'
  /path/to/gems/activesupport-5.2.3/lib/active_support/tagged_logging.rb:28:in `tagged'
  /path/to/gems/activesupport-5.2.3/lib/active_support/tagged_logging.rb:71:in `tagged'
  /path/to/gems/railties-5.2.3/lib/rails/rack/logger.rb:26:in `call'
  /path/to/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
  /path/to/gems/actionpack-5.2.3/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
  /path/to/gems/actionpack-5.2.3/lib/action_dispatch/middleware/request_id.rb:27:in `call'
  /path/to/gems/rack-2.0.7/lib/rack/method_override.rb:22:in `call'
  /path/to/gems/rack-2.0.7/lib/rack/runtime.rb:22:in `call'
  /path/to/gems/activesupport-5.2.3/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
  /path/to/gems/actionpack-5.2.3/lib/action_dispatch/middleware/executor.rb:14:in `call'
  /path/to/gems/actionpack-5.2.3/lib/action_dispatch/middleware/static.rb:127:in `call'
  /path/to/gems/rack-2.0.7/lib/rack/sendfile.rb:111:in `call'
  /path/to/gems/railties-5.2.3/lib/rails/engine.rb:524:in `call'
  /path/to/gems/puma-3.12.1/lib/puma/configuration.rb:227:in `call'
  /path/to/gems/puma-3.12.1/lib/puma/server.rb:660:in `handle_request'
  /path/to/gems/puma-3.12.1/lib/puma/server.rb:474:in `process_client'
  /path/to/gems/puma-3.12.1/lib/puma/server.rb:334:in `block in run'
  /path/to/gems/puma-3.12.1/lib/puma/thread_pool.rb:135:in `block in spawn_thread'

[louim]

Hello! This is probably related to rails/rails#29742 which moved the protect_from_forgery from the ApplicationController to ActionController::Base in Rails 5.2. Because the exceptions_app inherits from ActionController::Base, the before action verify_authenticity_token will now run (and fail) when rendering errors.

rambulance/lib/rambulance/exceptions_app.rb

Line 12 in 9901c5b

class ExceptionsApp < ActionController::Base

[yuki24]

I would consider this to be an unhandled bug and will look for a solution when I have time. In the meantime, feel free to send a pull request if any of you already have a fix.

[adrianhuna]

Hi @yuki24, thanks for the fix! It looks great, however, it seems like a new bug was introduced.

If I do curl -X POST http://localhost:3000/foo on my example app with the new version of rambulance, I still get 500. This is what can be seen in stacktrace:

Error during failsafe response: uninitialized constant Rambulance::ExceptionsApp
  /home/adrian/.rvm/gems/ruby-2.6.3/gems/bootsnap-1.4.3/lib/bootsnap/load_path_cache/core_ext/active_support.rb:79:in `block in load_missing_constant'

So the ExceptionsApp is not loaded yet. In your commit you added

ActiveSupport.on_load(:action_controller) do
    ...
end

Could you explain what's the motivation? If I remove the newly added ActiveSupport.on_load method, everything works as expected and correct 404 response is rendered. Cheers.

[yuki24]

That's odd. Are you not using action controllers at all? I just tested it with Rails 6.0 and it works fine. ActiveSupport.on_load is a way to defer configuration to the time of loading ActionController. Without this, initializers have the freedom to update config values so loading constants too early would make config inconsistent across different gems, controllers, etc.

$ rails new rambulance48 && cd rambulance48
$ bundle add rambulance
$ rails g rambulance:install
$ vim config/environments/development.rb # update `config.consider_all_requests_local` to `false`
$ rails s

# in other tab:
$ curl -X POST http://localhost:3000/foo

Curl's output:

< HTTP/1.1 404 Not Found
< X-Frame-Options: SAMEORIGIN
< X-XSS-Protection: 1; mode=block
< X-Content-Type-Options: nosniff
< X-Download-Options: noopen
< X-Permitted-Cross-Domain-Policies: none
< Referrer-Policy: strict-origin-when-cross-origin
< Content-Type: text/html; charset=utf-8
< X-Request-Id: eb8e2c06-c125-4328-8582-b5aa4dc9fe80
< X-Runtime: 0.008736
< Transfer-Encoding: chunked

And Rails logs:

... (backtrace) ...

Processing by Rambulance::ExceptionsApp#not_found as */*
  Rendering errors/not_found.html.erb within layouts/error
  Rendered errors/not_found.html.erb within layouts/error (Duration: 0.0ms | Allocations: 5)
  [Webpacker] Compiling…
  [Webpacker] Compiled all packs in /Users/yuki/GitHub/tmp/rambulance-48/public/packs
Completed 404 Not Found in 5ms (Views: 4.8ms | ActiveRecord: 0.0ms | Allocations: 4090)

[adrianhuna]

Interesting, I created new app and it indeed works as expected. No idea what was wrong before. Thanks for the explanation!

[adrianhuna]

Ok, I tracked down the problem I had. In my example app, I changed config/application.rb to include only some parts of Rails framework

require "rails"
# Pick the frameworks you want:
require "active_model/railtie"
require "active_job/railtie"
# require "active_record/railtie"
# require "active_storage/engine"
require "action_controller/railtie"
# require "action_mailer/railtie"
# require "action_mailbox/engine"
# require "action_text/engine"
require "action_view/railtie"
# require "action_cable/engine"
require "sprockets/railtie"
require "rails/test_unit/railtie"

The problem is in commenting out action_text/engine. The engine accesses ApplicationController and that in turn triggers ActiveSupport.on_load(:action_controller) in rambulance.

I guess I will used fork your gem because my situation is pretty specific and simply change the rescue block to:

rescue NameError
  require "rambulance/exceptions_app" unless defined?(::Rambulance::ExceptionsApp)
  ::ExceptionsApp.call(env)
end

[yuki24]

@adrianhuna I've cut a new release 1.0.2 with a fix. Could you give it a try and tell us how it goes? Thanks for your contribution!

[adrianhuna]

It's working without any problems, thanks!