こんにちはクラウド経費開発チーム・クラウド債務支払開発チームの江口です。普段 Ruby on Rails （以降Railsといいます）を使って開発しています。今回は before_action のデバッグを助ける action-tracer という gem を紹介します。

はじめに

Rails のコントローラではよく before_action を使ってコードを再利用します。しかし before_action が大量になり、コントローラの継承関係も深くなってくると、実行順序を追跡するのが難しくなります。コード理解が浅いプログラマーはもちろん、ベテランのプログラマーでも手を焼かされた経験は多いのではないでしょうか。action-tracer はこのデバッグの苦しみを和らげてくれます。

before_action, after_action がどの順序で実行されたか
before_action, after_action がスキップされたかどうか
before_action, after_action の定義はどのファイルにあるのか

と言った情報をログに書き出してくれます。この記事では実例を踏まえて action-tracer の使い方を紹介したいと思います。なお、わかりやすさを重視するため、一部の用語は gem の README と異なるものを利用します。

インストール

Gemfile に追加するだけで利用を始められます。細かな設定は不要です。

gem 'action_tracer', group :development, :test

インストール後、適当なページにアクセスすると action-tracer のログが書き出されるようになります。デフォルトでは log/action_tracer.log に出力します。

ログの仕様

action_tracer はコントローラでイベントに遭遇した時に、1行ずつ出力します。ここで言うイベントとは下記のものを指します。

before_action
action
after_action

AwesomeController の index アクションを実行した場合の例は下記の通りです。

I, [2020-09-27T03:25:43.018298 #1]  INFO -- : ["ACTION", :index, "/myapp/app/controllers/awesome_controller.rb", 7]

より一般的には下記の形式でログを出力します。

I, [TIMESTAMP] INFO -- : [<LABEL>, <METHOD_NAME>, <FILE_PATH>, <LINE_NUMBER>]

これらは下記の意味を持ちます。

要素	意味
`<LABEL>`	イベントの種類・実行したかどうか
`<METHOD_NAME>`	メソッド名
`<FILE_PATH>`	定義ファイルパス
`<LINE_NUMBER>`	定義行数

<LABEL> の種類は下記のものがあります。

ラベル	意味
`"ACTION"`	コントローラの action の呼び出し（実行したかどうかは不明）
`"APPLIED"`	before_action または after_action を実行した
`"NO_APPLIED"`	before_action または after_action を実行しなかった
`"UNRECOGNIZED"`	before_action または after_action を実行したかどうか不明

基本的な例

README に掲載されているサンプルの前半を見てみましょう。

I, [2020-09-27T03:25:43.018298 #1]  INFO -- : ["APPLIED", :set_turbolinks_location_header_from_session, "/usr/local/bundle/gems/turbolinks-5.2.1/lib/turbolinks/redirection.rb", 43]
I, [2020-09-27T03:25:43.019410 #1]  INFO -- : ["APPLIED", :verify_authenticity_token, "/usr/local/bundle/gems/actionpack-5.1.7/lib/action_controller/metal/request_forgery_protection.rb", 211]
I, [2020-09-27T03:25:43.021131 #1]  INFO -- : ["APPLIED", :require_login, "/myapp/app/controllers/awesome_controller.rb", 17]
I, [2020-09-27T03:25:43.022063 #1]  INFO -- : ["NO_APPLIED", :set_awesome, "/myapp/app/controllers/awesome_controller.rb", 25]
I, [2020-09-27T03:25:43.023716 #1]  INFO -- : ["APPLIED", :with_readonly, "/myapp/app/controllers/awesome_controller.rb", 21]

タイムスタンプは無視して <LABEL> と <METHOD_NAME> にあたる部分に注目しましょう。下記の表は、主要な情報をまとめたものです。

イベント	メソッド名	実行
before_action	set_turbolinks_location_header_from_session	o
before_action	verify_authenticity_token	o
before_action	require_login	o
before_action	set_awesome
before_action	with_readonly	o

ここで、4番目のイベントが NO_APPLIED であることに注意してください。実行されなかった理由は下記のいずれかです。

それ以前の before_action が失敗して before_action のチェーンが中止され実行されていない。
if/unless 条件を満たさなかったのでスキップした。

続けて後半を見てみます。

I, [2020-09-27T03:25:43.025547 #1]  INFO -- : ["ACTION", :index, "/myapp/app/controllers/awesome_controller.rb", 7]
I, [2020-09-27T03:25:43.026297 #1]  INFO -- : ["APPLIED", :with_readonly, "/myapp/app/controllers/awesome_controller.rb", 21]
I, [2020-09-27T03:25:43.027203 #1]  INFO -- : ["APPLIED", :store_location, "/myapp/app/controllers/awesome_controller.rb", 27]
I, [2020-09-27T03:25:43.030074 #1]  INFO -- : ["APPLIED", :verify_same_origin_request, "/usr/local/bundle/gems/actionpack-5.1.7/lib/action_controller/metal/request_forgery_protection.rb", 240]

これも書き下してみましょう。 action-tracer のログだけでアクションを実行したと判断することはできない点に注意が必要です。

イベント	メソッド名	実行
action	AwesomeController の index	?
after_action	with_readonly	o
after_action	store_location	o
after_action	verify_same_origin_request	o

以上のように、すべての before_action/after_action をリストアップし、実行順を知ることができます。

実践的な例

より複雑なサンプルをみてみましょう。下記は実際に私が開発しているアプリケーションのログを一部書き換え、抜粋したものです。

I, [2023-04-24T18:13:21.129276 #25129]  INFO -- : ["APPLIED", :activate_draper, "/ruby/lib/ruby/gems/3.1.0/gems/draper-4.0.2/lib/draper/view_context.rb", 14]
I, [2023-04-24T18:13:21.129304 #25129]  INFO -- : ["APPLIED", :set_paper_trail_enabled_for_controller, "/ruby/lib/ruby/gems/3.1.0/gems/paper_trail-13.0.0/lib/paper_trail/frameworks/rails/controller.rb", 79]
I, [2023-04-24T18:13:21.129331 #25129]  INFO -- : ["APPLIED", :set_paper_trail_controller_info, "/ruby/lib/ruby/gems/3.1.0/gems/paper_trail-13.0.0/lib/paper_trail/frameworks/rails/controller.rb", 96]
I, [2023-04-24T18:13:21.129354 #25129]  INFO -- : ["NO_APPLIED", :verify_authenticity_token, "/ruby/lib/ruby/gems/3.1.0/gems/actionpack-6.1.7.3/lib/action_controller/metal/request_forgery_protection.rb", 227]
I, [2023-04-24T18:13:21.129378 #25129]  INFO -- : ["NO_APPLIED", :sanitize_referer!, "/dummy/app/controllers/application_controller.rb", 113]
I, [2023-04-24T18:13:21.129399 #25129]  INFO -- : ["NO_APPLIED", :authenticate_user!, "/dummy/app/controllers/application_controller.rb", 87]
I, [2023-04-24T18:13:21.129949 #25129]  INFO -- : ["APPLIED", :Proc, "/ruby/lib/ruby/gems/3.1.0/gems/active_decorator-1.4.0/lib/active_decorator/view_context.rb", 35]
I, [2023-04-24T18:13:21.129965 #25129]  INFO -- : ["NO_APPLIED", :Proc, "/ruby/lib/ruby/gems/3.1.0/gems/actiontext-6.1.7.3/lib/action_text/engine.rb", 58]
I, [2023-04-24T18:13:21.129651 #25129]  INFO -- : ["UNRECOGNIZED", RequireActivationFilter]
I, [2023-04-24T18:13:21.130000 #25129]  INFO -- : ["ACTION", "show", "/dummy/app/controllers/simple_controller.rb", 10]
I, [2023-04-24T18:13:21.130039 #25129]  INFO -- : ["NO_APPLIED", :Proc, "/ruby/lib/ruby/gems/3.1.0/gems/actiontext-6.1.7.3/lib/action_text/engine.rb", 58]
I, [2023-04-24T18:13:21.130055 #25129]  INFO -- : ["APPLIED", :Proc, "/ruby/lib/ruby/gems/3.1.0/gems/active_decorator-1.4.0/lib/active_decorator/view_context.rb", 35]
I, [2023-04-24T18:13:21.130070 #25129]  INFO -- : ["NO_APPLIED", :verify_same_origin_request, "/ruby/lib/ruby/gems/3.1.0/gems/actionpack-6.1.7.3/lib/action_controller/metal/request_forgery_protection.rb", 257]

整理して表にしてみます。

イベント	メソッド名	実行
before_action	activate_draper	o
before_action	set_paper_trail_enabled_for_controller	o
before_action	set_paper_trail_controller_info	o
before_action	verify_authenticity_token
before_action	sanitize_referer!
before_action	authenticate_user!
before_action	ViewContect 由来の Proc	o
before_action	ActionText 由来の Proc
before_action	RequireActivationFilter	?
action	SimpleController の show	?
after_action	ActionText 由来の Proc
after_action	ViewContect 由来の Proc	o
after_action	verify_same_origin_request