Addressed (wanted) RoutingError appearing in the log at FATAL level in Rails

Overview

The problem is that RoutingError is logged at ** FATAL level **. FATAL has decided that "immediate action is required" during operation so that an alert will sound even at night, but RoutingError can be easily raised if the client makes an illegal request, so it is logged in the first place. You don't have to. (404 can be found in the access log of the web server)

I was wondering if I made a mistake in the settings, but the same thing happened with rails app just created according to the Rails guide, so what is rails? I decided to check the source code variously to see if I was doing it. In the end, I couldn't find a suitable option and ended up modifying Rails' MiddlewareStack. (It was the harvest that I could read the mechanism around here.)

Environment: Rails 6.0.0 / Ruby 2.5.3 / Ubuntu 20.04

Log sample

The rails log when the request is received is shown below.

With routing

I, [2020-11-07T23:01:42.988933 #12481]  INFO -- : Started GET "/" for 127.0.0.1 at 2020-11-07 23:01:42 +0900
I, [2020-11-07T23:01:42.992722 #12481]  INFO -- : Processing by MiniController#index as HTML
I, [2020-11-07T23:01:43.002614 #12481]  INFO -- :   Rendering text template
I, [2020-11-07T23:01:43.005314 #12481]  INFO -- :   Rendered text template (Duration: 0.0ms | Allocations: 4)
I, [2020-11-07T23:01:43.005728 #12481]  INFO -- : Completed 200 OK in 9ms (Views: 8.9ms | Allocations: 1395)

No routing

I, [2020-11-07T23:03:08.801059 #12481]  INFO -- : Started GET "/illegal" for 127.0.0.1 at 2020-11-07 23:03:08 +0900
F, [2020-11-07T23:03:08.801822 #12481] FATAL -- :   
ActionController::RoutingError (No route matches [GET] "/illegal"):
  
actionpack (6.0.0) lib/action_dispatch/middleware/debug_exceptions.rb:36:in `call'
actionpack (6.0.0) lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
(abridgement)
/opt/rbenv/versions/2.5.3/lib/ruby/2.5.0/webrick/server.rb:307:in `block in start_thread'

By the way, in rails5, the FATAL log was divided into four (blank line, exception, blank line, back trace). With rails6, it's all together like this, so it's easier for the monitor to ignore the logs.

Mechanism until the log comes out

I wondered how the RoutingError occurred in the first place and where it was logged.

Nesting middleware

When I grep the gem by relying on the stack trace of the log, [Rails :: Application :: DefaultMiddlewareStack](https://github.com/rails/rails/blob/v6.0.0/railties/lib/rails /application/default_middleware_stack.rb) I registered a series of apps. * The number varies depending on the rails settings.

Middleware

::ActionDispatch::HostAuthorization
::ActionDispatch::SSL
::Rack::Sendfile
::ActionDispatch::Static
::Rack::Cache
::Rack::Lock
::ActionDispatch::Executor
::Rack::Runtime
::Rack::MethodOverride
::ActionDispatch::RequestId
::ActionDispatch::RemoteIp
::Rails::Rack::Logger
::ActionDispatch::ShowExceptions
::ActionDispatch::DebugExceptions
::ActionDispatch::ActionableExceptions
::ActionDispatch::Reloader
::ActionDispatch::Callbacks
::ActionDispatch::Cookies
config.session_store
::ActionDispatch::Flash
::ActionDispatch::ContentSecurityPolicy::Middleware
::Rack::Head
::Rack::ConditionalGet
::Rack::ETag
::Rack::TempfileReaper

• https://github.com/rails/rails/tree/v6.0.0/actionpack/lib/action_dispatch/middleware
• https://github.com/rack/rack/tree/master/lib/rack

These classes have a #call method, and the upper class has a ** nested structure ** that passes the request to the lower class and receives the response. Of course, not only calling #call, but also editing request / response before and after, throwing and catching exceptions, etc. as needed, each of which plays its own role.

• The nesting order is managed by MiddlewareStack, so each class does not need to know who to call.

DebugExceptions I read the contents of what this essential app is doing.

https://github.com/rails/rails/blob/v6.0.0/actionpack/lib/action_dispatch/middleware/debug_exceptions.rb#L30

ActionDispatch::DebugExceptions#call

    def call(env)
      request = ActionDispatch::Request.new env
      _, headers, body = response = @app.call(env)

      if headers["X-Cascade"] == "pass"
        body.close if body.respond_to?(:close)
        raise ActionController::RoutingError, "No route matches [#{env['REQUEST_METHOD']}] #{env['PATH_INFO'].inspect}"
      end

      response
    rescue Exception => exception
      invoke_interceptors(request, exception)
      raise exception unless request.show_exceptions?
      render_exception(request, exception)
    end

0. Immediately pass the request to the next app and receive the response
1. Send RoutingError if X-Cascade: pass is set in the response header
2. If an exception occurs during processing, catch it and process it as necessary.

• Execute if interceptor is registered (added in rails6)
• ** Log exceptions **
• Create a response about the details of the exception * The one that often appears in the development environment
• If you do not create a response, re-throw the exception (leave it to the previous application)

It would be good if there was a conditional branch that could avoid this "logging exceptions" process and would not adversely affect other processes. (Note that the log output is hardcoded with fatal and the level cannot be lowered)

Coping (trial and error)

Proposal 1. Remove DebugExceptions

I thought, "The class name is debug, and it will work without it." You can remove the registered middleware when setting rails.

config/environments/<env>.rb Add to etc.

config.middleware.delete ::ActionDispatch::DebugExceptions

Then, although the FATAL log disappeared, the response body was only Not Found, and ** 404 page was not displayed **.

Client side

$ curl -i http://localhost:3000/illegal
HTTP/1.1 404 Not Found 
X-Cascade: pass
Cache-Control: no-cache
X-Request-Id: fefa1568-57dd-45be-bc31-f91f17a5c916
X-Runtime: 0.005418
Server: WEBrick/1.4.2 (Ruby/2.5.3/2018-10-18)
Date: Sat, 07 Nov 2020 14:32:30 GMT
Content-Length: 9
Connection: Keep-Alive

Not Found

Removing DebugExceptions means that RoutingError will not appear, and ** the apps in the previous stage will not handle the same exceptions as the original **. ~~ Contrary to the name ~~ Very important middleware?

That's why it was rejected.

Proposal 2. show_exceptions option

Make sure that request.show_exceptions? In the code is false by saying "I wish I could throw an exception in DebugExceptions without logging it. " This is in the rails settings.

config/environments/<env>.rb Add to etc.

config.action_dispatch.show_exceptions = false

When I tried it, I got a ** 500 error **. Rails is fine for logs, but the web server (webrick, puma, etc.) is throwing an error.

log

I, [2020-11-07T23:34:09.728873 #13864]  INFO -- : Started GET "/illegal" for 127.0.0.1 at 2020-11-07 23:34:09 +0900
[2020-11-07 23:34:09] ERROR ActionController::RoutingError: No route matches [GET] "/illegal"
	/.../actionpack-6.0.0/lib/action_dispatch/middleware/debug_exceptions.rb:36:in `call'
	/.../actionpack-6.0.0/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
(abridgement)
	/opt/rbenv/versions/2.5.3/lib/ruby/2.5.0/webrick/server.rb:307:in `block in start_thread'

Because, as the name implies, this invalidates the previous ShowExceptions, and no error response such as /public/404.html is prepared. Furthermore, although the RoutingError was originally captured here, it will be ** retransmitted **, and the processing of the application group in the previous stage will change.

• ActionDispatch::ShowExceptions rescues any exception returned by the application and renders nice exception pages if the request is local or if config.consider_all_requests_local is set to true. If config.action_dispatch.show_exceptions is set to false, exceptions will be raised regardless.

Quoted from https://guides.rubyonrails.org/configuring.html#configuring-middleware, partially emphasized

That's why it was rejected.

Proposal 3. Monkey patch for DebugExceptions

Try to make sure you succeed. The output part of the FATAL log in question is combined into one method, so you can ** overwrite it so as not to do anything **.

config/environments/<env>.rb Add to etc.

class ::ActionDispatch::DebugExceptions
  def log_error(*); end
end

Successful examples are omitted. The problem is

• Exceptions other than RoutingError will not be logged
• Vulnerable to library code changes (and private methods)
• Bad manners because it is a monkey patch

Proposal 4. Make your own alternative to DebugExceptions

It's more straightforward than Plan 3, it's more flexible, and it's more troublesome.

my_debug_exceptions.rb

#I copied only the part that sent the RoutingError
class MyDebugExceptions
  #The first argument app is required, additional arguments are free (ignored this time)
  def initialize(app, *)
    @app = app
  end

  #The argument is env
  def call(env)
    request = ActionDispatch::Request.new env
    _, headers, body = response = @app.call(env)

    if headers["X-Cascade"] == "pass"
      body.close if body.respond_to?(:close)
      raise ActionController::RoutingError, "No route matches [#{env['REQUEST_METHOD']}] #{env['PATH_INFO'].inspect}"
    end

    response
  rescue ActionController::RoutingError => routing_error
    #Processing dedicated to RoutingError, this time there is no processing
    raise routing_error
  rescue Exception => exception
    #Processing other than RoutingError, this time there is no processing
    raise exception
  end
end

Replace the created app with the original one. This is possible with the rails settings.

config/environments/<env>.rb Add to etc.

#Arguments other than app can be specified here
config.middleware.swap ActionDispatch::DebugExceptions,
                       MyDebugExceptions, "arg1", "arg2"

After all ...

I felt like, "Is there really only such a method?" Hesitate to incorporate it into what you release. I will continue to investigate a little more.

As mentioned earlier, rails 6 has put together the FATAL logs in question, so I think it's easier to understand if rails has standard operation and is ignored by the monitoring side.

appendix

Rails app used for the experiment

In the experiment, most of the settings were stripped off, so I used [about 20 lines created in the past](/ HMMNRST / items / 5595a4eeebaecf47da26) as a base. Below is the full code.

source "https://rubygems.org"
gem "railties", "6.0.0"

APP_PATH = File.expand_path('../config/application', __dir__)
require 'rails/commands'

require_relative 'config/environment'
run Rails.application

require_relative 'application'
Rails.application.initialize!

require 'action_controller/railtie'

class MiniApp < Rails::Application
  config.logger = ::Logger.new(STDOUT)  #Logs can be viewed on the terminal
end

Rails.application.routes.draw do
  root to: 'mini#index'
end

class MiniController < ActionController::Base
  def index
    render plain: "Hello, world!\n"
  end
end

Settings may be added in the development environment, so execute it in the production environment. You need to specify SECRET_KEY_BASE, but it's fine.

Execution method

$ bundle install --path vendor/bundle  #Easy to search and modify code

$ bundle exec rails routes  #Routing confirmation

$ RAILS_ENV=production SECRET_KEY_BASE=_ bundle exec rails server

You can try it by accessing http: // localhost: 3000 / with curl or your browser.