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