rails: ActionController::UnknownHttpMethod does not get automatically rescued as documented

TL;DR: Rails::Rack::Logger will raise ActionController::UnknownHttpMethod and appears earlier in the middleware stack than ActionDispatch:ShowExceptions or DebugExceptions, meaning we get 500s and our exception notifiers fire, instead of getting the quiet, documented 405s.

Steps to reproduce

Here’s an integration test snippet that demonstrates the issue (make sure to call a route that exists):

class UnknownHttpMethodTest < ActionDispatch::IntegrationTest
  test 'invalid http method should 405' do
    process "NOT_A_METHOD", '/'
    assert_response :method_not_allowed
  end
end

Expected behavior

According to the Rails Guides, ActionController::UnknownHttpMethod should be automatically rescued and respond with :method_not_allowed, or HTTP 405.

From the Guides:

config.action_dispatch.rescue_responses = {
  'ActionController::RoutingError' => :not_found,
  'AbstractController::ActionNotFound' => :not_found,
  'ActionController::MethodNotAllowed' => :method_not_allowed,
  'ActionController::UnknownHttpMethod' => :method_not_allowed,
  'ActionController::NotImplemented' => :not_implemented,
  'ActionController::UnknownFormat' => :not_acceptable,
  'ActionController::InvalidAuthenticityToken' => :unprocessable_entity,
  'ActionController::InvalidCrossOriginRequest' => :unprocessable_entity,
  'ActionDispatch::Http::Parameters::ParseError' => :bad_request,
  'ActionController::BadRequest' => :bad_request,
  'ActionController::ParameterMissing' => :bad_request,
  'Rack::QueryParser::ParameterTypeError' => :bad_request,
  'Rack::QueryParser::InvalidParameterError' => :bad_request,
  'ActiveRecord::RecordNotFound' => :not_found,
  'ActiveRecord::StaleObjectError' => :conflict,
  'ActiveRecord::RecordInvalid' => :unprocessable_entity,
  'ActiveRecord::RecordNotSaved' => :unprocessable_entity
}

Actual behavior

The exception is not rescued by Rails and we end up getting a 500 and notifying our team unnecessarily. (Case in point, this StackOverflow post talking about their exception notifiers blowing up when bots come through, and getting no quality answers.)

Rails::Rack::Logger creates an ActionDispatch::Request object to wrap the request, then uses it to produce pretty logs, as seen here: https://github.com/rails/rails/blob/master/railties/lib/rails/rack/logger.rb#L48-L54

        def started_request_message(request) # :doc:
          'Started %s "%s" for %s at %s' % [
            request.request_method,
            request.filtered_path,
            request.remote_ip,
            Time.now.to_default_s ]
        end

Unfortunately, request.request_method raises the error in question.

Why isn’t it rescued? Here’s the default middleware stack:

use Rack::Sendfile
use ActionDispatch::Static
use ActionDispatch::Executor
use ActiveSupport::Cache::Strategy::LocalCache::Middleware
use Rack::Runtime
use Rack::MethodOverride
use ActionDispatch::RequestId
use ActionDispatch::RemoteIp
use Sprockets::Rails::QuietAssets
use Rails::Rack::Logger
use ActionDispatch::ShowExceptions
use WebConsole::Middleware
use ActionDispatch::DebugExceptions
use ActionDispatch::Reloader
use ActionDispatch::Callbacks
use ActiveRecord::Migration::CheckPending
use ActionDispatch::Cookies
use ActionDispatch::Session::CookieStore
use ActionDispatch::Flash
use ActionDispatch::ContentSecurityPolicy::Middleware
use Rack::Head
use Rack::ConditionalGet
use Rack::ETag
use Rack::TempfileReaper
run MyApp::Application.routes

Rails::Rack::Logger appears before any of the automatic exception handling middleware (ActionDispatch::ShowExceptions or ActionDispatch::DebugExceptions)

Possible fixes

  • Rails::Rack::Logger could rescue specific exceptions from ActionDispatch::Request in order to still log reasonably and let later middleware deal with the problem.
  • the middleware stack could be re-ordered to catch this appropriately

I would be happy to work on this and submit a PR with a nudge in the right direction.

System configuration

Rails version: 6.0.2.2

Ruby version: 2.6.3p62

About this issue

  • Original URL
  • State: closed
  • Created 4 years ago
  • Reactions: 2
  • Comments: 19 (14 by maintainers)

Commits related to this issue

Most upvoted comments

I think we’ve waited long enough that you can pick this up @lorennorman, if you’re still interested.

I commented on https://github.com/rails/rails/pull/39041 with a suggested fix, and I’d like to give @davidmoseler a chance to implement it if they’re still interested, since they went boldly forward already 🖖

Done and done, can’t thank you enough for the guidance on every step of this!

Other than the test, a changelog entry would be good.

What do you think of my suggestion in https://github.com/rails/rails/pull/39041#issuecomment-664110607:

How about aliasing Rack’s version of the method before we override it?

It seems like the fix least likely to cause unintended side effects.

Hello, Rails team!

This bug continues to exist, and this issue still explains it well and reproduces it with a failing test.

I’ve not attached a PR because I wanted some feedback from a core team member about the right approach, it touches some deeper middleware/logging/organization topics that I’m less versed in. I can always “go boldly forward” with something if that’s preferred!

Hi @lorennorman thanks for the report. There’s not enough information here to determine whether your application is raising something other than ActionController::UnknownHttpMethod and that’s why you’re seeing the 500 or if Rails isn’t working correctly.

To help us debug can you provide a script using one of our templates here https://github.com/rails/rails/tree/master/guides/bug_report_templates to reproduce or create a new application that demonstrates the issue?

Thanks!