ActionController::UnknownHttpMethod does not get automatically rescued as documented

[lorennorman]

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

[eileencodes]

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!

[lorennorman]

@eileencodes Challenge Accepted! Took a sec to figure out how to actually send a bad HTTP verb, but I feel pretty confident this proves the issue:

# frozen_string_literal: true

require "bundler/inline"

gemfile(true) do
  source "https://rubygems.org"

  git_source(:github) { |repo| "https://github.com/#{repo}.git" }

  # Activate the gem you are reporting the issue against.
  gem "rails", "6.0.2.2"
end

require "rack/test"
require "action_controller/railtie"

class TestApp < Rails::Application
  config.root = __dir__
  config.hosts << "example.org"
  config.session_store :cookie_store, key: "cookie_store_key"
  secrets.secret_key_base = "secret_key_base"

  config.logger = Logger.new($stdout)
  Rails.logger  = config.logger

  routes.draw do
    get "/" => "test#index"
  end
end

class TestController < ActionController::Base
  include Rails.application.routes.url_helpers

  def index
    render plain: "Home"
  end
end

require "minitest/autorun"

class BugTest < Minitest::Test
  include Rack::Test::Methods

  def test_unknown_http_method_returns_405
    # This raises ActionController::UnknownHttpMethod instead of rescuing it
    # and responding with a 405 as the docs state it should
    request "/", { "REQUEST_METHOD" => "NOT_AN_HTTP_METHOD" }
    # Doesn't get here at all because the raise is not properly rescued due
    # to the ActionDispatch::ShowExceptions middleware coming later in the stack
    # than this raise happens (which is at Rails::Rack::Logger)
    assert_equal 405, last_response.status
  end

  private
    def app
      Rails.application
    end
end

Thank you so much for pointing me at these templates, they are sort of amazing.

I think the essence of the problem might be the use of request.request_method for printing in the logger. If request.request_method raises an exception when the http request method is not allowed, then it is not the proper function to evoke there. When logging, you only want to find out what was written in the client request, you don't want to raise an ActionController::UnknownHttpMethod just yet. Maybe a raw version of request.request_method should be used instead.

Here is a simple (but not the clearest) solution:

-            request.request_method,
+            request.method(:request_method).super_method.call()

In the rack/logger.rb, line 50. This is somewhat uggly because the ActionDispatch::Request class overwrites the Rack default .request_method method with the following:

    def request_method
      @request_method ||= check_method(super)
    end

so that the direct reference to the original rack .request_method (without the checking) is lost. Not quite lost, though, because you can access it with the "super_method" trick. So one possibility is using this trick, and the other would be writing a new method in ActionDispatch::Request, something like "unchecked_request_method" to keep the reference to the original. For me something like that would be the correct thing to do; to change the order of the middlewares for examples does not seem to be the best way to attack this minor issue.

Edit: ActionDispatch::Request also provides a ".method" method with the following comment:

# Returns the original value of the environment's REQUEST_METHOD, # even if it was overridden by middleware. See #request_method for # more information.

So that might be used in the logger instead.

[lorennorman]

@davidmoseler excellent information, thank you for sharing.

I agree with your thoughts about changing the order of the middleware vs fixing the logger.

What about adding begin/rescue to the logger?

Edit: Your note about the .method method looks like it won't work because it is defined as this:

def method
  @method ||= check_method(get_header("rack.methodoverride.original_method") || get_header("REQUEST_METHOD"))
end

...more check_method() action 😦

Edit Edit: It seems the Logger could just call:

request.get_header('REQUEST_METHOD')

...because the Rack::Request::Helpers module (which ActionDispatch::Request includes) defines .request_method like this:

def request_method;  get_header(REQUEST_METHOD)                     end

...but that's still weird, feels like details are leaking out around the interface.

I'm not hitting on an obviously correct thing here...

I've created a proposed solution, but, even if everyone agrees that it is the right path to go, there is a lot of work to be done there.

I thought about what you said about an obviously correct thing, and I also don't see it, but I do think an obviously wrong thing is to do checking and raise an exception in an unexpected moment such as when reading "request_method" for the first time.

It seems to me that either the checking should be done in the constructor, or it should be explicitly done latter on. I tried doing it in the constructor and passing an extra option for not doing the checking (as when using the class as a wrapper for logging), but checking the request in the constructor blew up so many dozens of tests that it seems like a very difficult solution.

To do explicit checking only breaks the tests which expect that particular exception to be raised (so the explicit checking should be added to those tests). But it still remains to determine the places where the explicit checking should be done in the entire codebase.

This is my first time contributing (or trying to), so the pull request was just something I ended up doing after following the contributing guidelines for getting used to it, so don't take my solution too seriously and please point me to a better approach if I'm violating some norm.

[rails-bot]

This issue has been automatically marked as stale because it has not been commented on for at least three months.
The resources of the Rails team are limited, and so we are asking for your help.
If you can still reproduce this error on the 6-0-stable branch or on master, please reply with all of the information you have about it in order to keep the issue open.
Thank you for all your contributions.

[lorennorman]

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!

[eugeneius]

I commented on #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 🖖

[eugeneius]

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

[lorennorman]

@eugeneius I'm interested!

However, some core team feedback would still help, here's the fixes I suggested:

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

In the absence of guidance I'll just start trying things and see what breaks the least. 😄