LoginSignup
8
3

More than 3 years have passed since last update.

@HMMNRST

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

Last updated at Posted at 2020-11-08

概要

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

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

環境： Rails 6.0.0 / Ruby 2.5.3 / Ubuntu 20.04

ログのサンプル

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

ルーティングあり
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)
ルーティングなし
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 の中で一連のアプリを登録していた。 ※railsの設定によって個数は変わる

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

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

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

DebugExceptions

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

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

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

対処（の試行錯誤）

案1. DebugExceptions を外す

「クラス名がdebugだし、無くても動くだろう」と思って試した。railsの設定時に、登録したミドルウェアを抜くことができる。

config/environments/<env>.rb などに追加
config.middleware.delete ::ActionDispatch::DebugExceptions

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

クライアント側
$ 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の設定項目に存在する。

config/environments/<env>.rb などに追加
config.action_dispatch.show_exceptions = false

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

illegal-500.png

ログ
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ログの出力箇所はひとつのメソッドに纏められているので、それを何もしないように上書きしてしまえばいい。

config/environments/<env>.rb などに追加
class ::ActionDispatch::DebugExceptions
  def log_error(*); end
end

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

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

案4. DebugExceptions の代替品を自作

案3よりは正攻法であり、柔軟性があり、その分だけ面倒でもある。

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の設定で可能。

config/environments/<env>.rb などに追加
# app 以外の引数はここで指定できる
config.middleware.swap ActionDispatch::DebugExceptions,
                       MyDebugExceptions, "arg1", "arg2"

結局…

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

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

付録

実験に使用したrailsアプリ

実験ではほとんどの設定を削ぎ落とすため、過去に作成した20行程度のものをベースにした。以下にコード全文を載せる。

クリックして展開
Gemfile
source "https://rubygems.org"
gem "railties", "6.0.0"
bin/rails
APP_PATH = File.expand_path('../config/application', __dir__)
require 'rails/commands'
config.ru
require_relative 'config/environment'
run Rails.application
config/environment.rb
require_relative 'application'
Rails.application.initialize!
config/application.rb
require 'action_controller/railtie'

class MiniApp < Rails::Application
  config.logger = ::Logger.new(STDOUT)  # ログをターミナル上で見れるように
end
config/routes.rb
Rails.application.routes.draw do
  root to: 'mini#index'
end
app/controllers/mini_controller.rb
class MiniController < ActionController::Base
  def index
    render plain: "Hello, world!\n"
  end
end

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

（コードはここまで）

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

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

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

$ RAILS_ENV=production SECRET_KEY_BASE=_ bundle exec rails server

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

8
3
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
8
3