Railsで RoutingError がFATALレベルでログに出てくることへ対処（したかった）

## 概要
`RoutingError` が**FATALレベル**でログ出力される点が困っている。FATALは運用時に「即時対処が必要なもの」と決めていて夜間でもアラートが鳴るようにしているのだが、 `RoutingError` はクライアントが不正なリクエストをすれば簡単に起こせるので、そもそもログに出されなくていい。（404はwebサーバーのアクセスログでもわかる）

何か設定を間違えているだけかと思っていたが、[Railsガイド通りに新規作成したばかりのrailsアプリ](https://railsguides.jp/getting_started.html)でも同じことが起きたため、railsが何をしているのかソースコードを色々と調べることになった。結局適切なオプションは見つけられず、railsの MiddlewareStack に手を加えるという形になってしまった。（この辺の仕組みに目を通せたのは収穫。）

環境： Rails 6.0.0 / Ruby 2.5.3 / Ubuntu 20.04

## ログのサンプル
リクエストを受けた際のrailsのログを以下に示す。

```text:ルーティングあり
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)
```

```text:ルーティングなし
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'
（省略）
/opt/rbenv/versions/2.5.3/lib/ruby/2.5.0/webrick/server.rb:307:in `block in start_thread'
```

ちなみにrails5ではFATALログが4つに分割されていた（空行・例外・空行・バックトレース）。rails6ではこの通りひとまとめになったので、監視側でログを無視するのは楽になった。

## ログが出るまでの仕組み
そもそも `RoutingError` はどう発生し、どこでログに記録しているのだろうと疑問に思った。

### ミドルウェアの入れ子
ログのスタックトレースを頼りにgemをgrepしていたところ、 [`Rails::Application::DefaultMiddlewareStack`](https://github.com/rails/rails/blob/v6.0.0/railties/lib/rails/application/default_middleware_stack.rb) の中で一連のアプリを登録していた。 ※railsの設定によって個数は変わる

```ruby:ミドルウェア
::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

これらのクラスには `#call` メソッドがあり、上側のクラスはひとつ下のクラスにリクエストを渡してレスポンスを受け取るという**入れ子構造**になっている。もちろんただ `#call` を呼ぶだけでなく、前後にリクエスト・レスポンスを編集したり、例外の送出や捕捉なども必要に応じてしていて、それぞれが自分の役割を果たしている。

※入れ子の順序は MiddlewareStack が管理するので、各クラスは自分が誰を呼び出すか知っている必要は無い。

### `DebugExceptions`
肝心のこのアプリが何をしているのか、中身を読んだ。

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

```ruby:ActionDispatch&#x3A;&#x3A;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. すぐ次のアプリにリクエストを渡してレスポンスを受け取る
0. レスポンスヘッダーに `X-Cascade: pass` が設定されていたら `RoutingError` を送出する
0. 処理中に例外が起きていれば捕捉し、必要に応じて処理をする
	* interceptorが登録されていれば実行する（rails6で追加）
	* **例外をログに記録する**
	* 例外の詳細についてのレスポンスを作成する ※development環境でよく出てくるやつ
	* レスポンスを作成しないなら例外を再送出する（前段のアプリに任せる）

この「例外をログに記録する」処理を回避でき、他の処理にも悪影響が出ない条件分岐があればいい。（なお、ログ出力は `fatal` でハードコードされていて、レベルを下げることはできない）

## 対処（の試行錯誤）
### 案1. `DebugExceptions` を外す
「クラス名がdebugだし、無くても動くだろう」と思って試した。railsの設定時に、登録したミドルウェアを抜くことができる。

```ruby:config/environments/&lt;env&gt;.rb&#x20;などに追加
config.middleware.delete ::ActionDispatch::DebugExceptions
```

するとFATALログは消えたものの、レスポンスボディが `Not Found` だけになってしまい、**404ページが表示されなくなった**。

```shell-session:クライアント側
$ 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
```

`DebugExceptions` を外すということは `RoutingError` が出なくなるということであり、**前段のアプリ群が元と同じ例外処理をしなくなってしまう**。~~名前に反して~~かなり重要なミドルウェア？

というわけで却下。

### 案2. `show_exceptions` オプション
「 `DebugExceptions` の中でログ出力せずに例外を投げてくれればいいだろう」ということで、コード中の `request.show_exceptions?` が偽になるようにする。これはrailsの設定項目に存在する。

```ruby:config/environments/&lt;env&gt;.rb&#x20;などに追加
config.action_dispatch.show_exceptions = false
```

やってみたら**500エラー**になってしまった。ログもrailsは問題ないが、webサーバー（webrick, pumaなど）のほうでエラーを吐き出している。

![illegal-500.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/127130/456d8c4b-b7f3-ad8c-1b91-761f32d8e86f.png)

```text:ログ
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'
（省略）
	/opt/rbenv/versions/2.5.3/lib/ruby/2.5.0/webrick/server.rb:307:in `block in start_thread'
```

というのも、これは名前通り前段の `ShowExceptions` を無効化するもので、 `/public/404.html` などエラーレスポンスが用意されなくなる。さらに、元々はここで `RoutingError` を捕捉していたのに**再送出してしまう**ようになり、前段のアプリ群の処理が変わってしまう。

> * `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**.
>
> https://guides.rubyonrails.org/configuring.html#configuring-middleware より引用、一部強調

というわけで却下。

### 案3. `DebugExceptions` にモンキーパッチ
確実に成功する方法を試しておく。問題のFATALログの出力箇所はひとつのメソッドに纏められているので、それを**何もしないように上書き**してしまえばいい。

```ruby:config/environments/&lt;env&gt;.rb&#x20;などに追加
class ::ActionDispatch::DebugExceptions
  def log_error(*); end
end
```

成功例は省略する。問題としては、

* `RoutingError` 以外の例外もログ出力されなくなってしまう
* ライブラリのコード変更に弱い（しかも対象がprivateメソッド）
* モンキーパッチということで行儀が悪い

### 案4. `DebugExceptions` の代替品を自作
案3よりは正攻法であり、柔軟性があり、その分だけ面倒でもある。

```ruby:my_debug_exceptions.rb
# RoutingError の送出部分だけをコピーした
class MyDebugExceptions
  # 第1引数 app は必須、追加の引数は自由（今回は無視）
  def initialize(app, *)
    @app = app
  end

  # 引数は 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
    # RoutingError 専用の処理、今回はひとまず無し
    raise routing_error
  rescue Exception => exception
    # RoutingError 以外の処理、今回はひとまず無し
    raise exception
  end
end
```

作成したアプリを元のものと差し替える。これはrailsの設定で可能。

```ruby:config/environments/&lt;env&gt;.rb&#x20;などに追加
# app 以外の引数はここで指定できる
config.middleware.swap ActionDispatch::DebugExceptions,
                       MyDebugExceptions, "arg1", "arg2"
```

### 結局…
「本当にこんな方法しか無いの？」という気持ちになった。リリースするものに組み込むのは躊躇する。一応もう少し調べ続けてみようと思う。

先に述べた通り、rails6では問題のFATALログがひとまとめになったので、railsには標準的な動作をさせておいて監視側で無視したほうがわかりやすい気もする。

## 付録
### 実験に使用したrailsアプリ
実験ではほとんどの設定を削ぎ落とすため、[過去に作成した20行程度のもの](/HMMNRST/items/5595a4eeebaecf47da26)をベースにした。以下にコード全文を載せる。

<details><summary>クリックして展開</summary><div>

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

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

```ruby:config.ru
require_relative 'config/environment'
run Rails.application
```

```ruby:config/environment.rb 
require_relative 'application'
Rails.application.initialize!
```

```ruby:config/application.rb 
require 'action_controller/railtie'

class MiniApp < Rails::Application
  config.logger = ::Logger.new(STDOUT)  # ログをターミナル上で見れるように
end
```

```ruby:config/routes.rb
Rails.application.routes.draw do
  root to: 'mini#index'
end
```

```ruby:app/controllers/mini_controller.rb 
class MiniController < ActionController::Base
  def index
    render plain: "Hello, world!\n"
  end
end
```

エラーページの静的ファイル `public/404.html` はお好みで。

（コードはここまで）

</div></details>

---

development環境だと設定が追加されることがあるので、production環境で実行する。 `SECRET_KEY_BASE` を指定する必要があるが、適当でいい。

```shell-session:実行方法
$ bundle install --path vendor/bundle  # 検索やコード改変しやすいように

$ bundle exec rails routes  # ルーティング確認

$ RAILS_ENV=production SECRET_KEY_BASE=_ bundle exec rails server
```

あとは `curl` やブラウザで `http://localhost:3000/` にアクセスすれば試せる。