20分くらいハマった。

やったこと

それぞれのfilterにかかった時間を図るために、print_start_timeとprint_end_timeを複数回呼び出す設定にしようとした。

my_controller.rb

class MyController < ApplicationController
  before_action :print_start_time
  before_action :action1
  before_action :print_end_time

  before_action :print_start_time
  before_action :action2
  before_action :print_end_time

  def print_start_time
    puts('### start time ###')
    puts(Time.now)
  end
  
  def print_end_time
    puts('### end time ###')
    puts(Time.now)
  end

  def action1
    ...
  end

  def action2
    ...
  end
end

どうなった？

挟み込まれたfilterは以下のようになった
(binding.pryで止めて_process_action_callbacksでfilterを順々に見れる)

> _process_action_callbacks.send(:chain).map{|c|puts "#{c.kind} - #{c.filter}"} 

before - action1
before - print_start_time
before - action2
before - print_end_time

つまり？

同じfilterを複数回呼ぶと、callbackが後の場所に再定義され、元々定義されたものは消えてしまうようだ。

参考

https://github.com/rails/rails/issues/20687

looking at implementation of AbstractController::Callbacks, it can be seen they are created using define_method so it's expected that next call will redefine the callback. so I guess it's expected behaviour

https://guides.rubyonrails.org/action_controller_overview.html#filters

Calling the same filter multiple times with different options will not work, since the last filter definition will overwrite the previous ones.