あるクラスの全てのメソッド呼び出しを、メソッドの処理を実行する直前にログに記録したい。しかし、すべてのメソッドの先頭にlogger.debugを追記したくはない。どうすれば良いか。
- 書き出す内容は、クラス名・呼び出されたメソッド名・呼び出されたメソッドに渡された引数をinspectしたものとする
  - SomeClassのインスタンスメソッドsome_methodをargsで呼び出した場合の出力例:
    - SomeClass#some_method(#{args.inspect相当の内容})
- ロガーはinitializeメソッドの引数として注入されるものとし、ロガーのインターフェースはRubyの標準ライブラリのloggerに準ずるものとする。日時情報も出力されるため、自前でタイムスタンプを出力する必要はない
1.で作成したメソッド呼び出しデバッグの仕組みはたいそう有用だった。他のクラスにも使いたい。他のクラスで使うときに書き換える箇所を最小にできるよう、モジュール method_call_logger.rb として作成せよ。
- 利用クラス側で書き換えるのは以下の箇所のみとする
  - A: ファイル先頭のファイルスコープのrequire文
  - B: クラススコープ
  - C: initializeメソッド
2.までは、この機能をデバッグ用のものとしてログレベルがDEBUGの時のみ出力されるように実装してきた。しかし、一部のメソッドは非常に重要なため、ログレベルがINFOであっても出力したいという要望が挙げられた。指定した特定のメソッドのみの出力ログレベルを変更できるようにせよ。
- 利用クラス側で出力ログレベルを変更するメソッドの指定は、B: クラススコープで行うものとする


require "method_call_logger" # A

class SomeClass
  # B
  
  def initialize(xxx, yyy, zzz, logger)
    # C
  end

  def some_method(arg)
    # ...
  end
  
  # ...
end

回答例

Kernelモジュールのset_trace_funcを使う。
set_trace_funcで登録されたProcは、式評価・メソッド呼び出し開始/終了・クラス定義突入/終了などあらゆるイベント発生時に実行される。
今回フックしたいのは、メソッド呼び出し開始のタイミングのイベントである。これはset_trace_funcに渡すProcの第一引数で判定できる。


  set_trace_func(
    proc {|event, file, line, id, binding, klass|
      if event == "call"
        # TODO
      end
    }
  )

特定のクラスのメソッドだけロギングしたい。クラスの判定には、Procの第六引数を利用する。
クラススコープでのselfはクラス自身になるので、これと比較する。
第六引数klassは第一引数eventが"call"の時、「呼び出されたメソッドが所属するクラス」を返す仕様である。したがって、派生元のクラスのインスタンスからこのクラスのメソッドを呼び出した時でもこの分岐内を通る。


class SomeClass

  # ...

  set_trace_func(
    proc {|event, file, line, id, binding, klass|
      if event == "call" && klass == self
        # TODO
      end
    }
  )
end

ロガーにアクセスするには、インスタンスにアクセスする必要がある。インスタンスは、Procの第五引数bindingにBindingが渡されるので、そのreceiverとしてアクセスできる。
ロガーをinitialize内でインスタンス変数に保持するようにしておいて、Procの中ではBindingを通じてアクセスする。
ロガーをクラスの外から隠蔽したい場合は、Proc内からロガーを参照する穏便な方法がないためinstance_variable_getでカプセル化を壊してアクセスせざるを得ない。
メソッド名は、Procの第四引数idでアクセスできる。


class SomeClass
  def initialize(logger)
    @logger = logger
  end

  # ...

  set_trace_func(
    proc {|event, file, line, id, binding, klass|
      if event == "call" && klass == self
        binding.receiver.instance_variable_get(:@logger).debug("#{id}")
      end
    }
  )
end

eventが"call"のタイミングは、initializeメソッドが呼ばれたタイミングも該当する。しかし、initializeメソッドが呼ばれたタイミングではロガーは設定されていない。したがって、initialzeメソッドのタイミングだけは自動ロギングの対象から除外することにする。


class SomeClass
  def initialize(logger)
    @logger = logger
  end

  # ...

  set_trace_func(
    proc {|event, file, line, id, binding, klass|
      if event == "call" && klass == self
        if id != :initialize
          binding.receiver.instance_variable_get(:@logger).debug("#{id}")
        end
      end
    }
  )
end

ここまでで、メソッド呼び出しが自動でロギングされるようになっているはずだ。


logger = Logger.new(STDOUT)
smp_inst = SomeClass.new(logger)
smp_inst.sample_method1
# D, [2019-09-19T01:08:00.372395 #2574] DEBUG -- : sample_method1

次に、引数に渡された値を取得してロギングする。
引数は、メソッド呼び出し直後のローカル変数に等しい。メソッド呼び出し直後はスコープが切り替わった直後なので、ローカル変数はメソッドに渡された引数以外存在しない。
ローカル変数は、Procの第五引数bindingのlocal_variables, local_variables_getを利用して取得できる。
下記は、ログメッセージを見やすいようにフォーマットしてクラス名も表示するようにしたものだ。


class SomeClass
  def initialize(logger)
    @logger = logger
  end

  # ...

  set_trace_func(
    proc {|event, file, line, id, binding, klass|
      if event == "call" && klass == self
        if id != :initialize
          msg = "#{self.to_s}##{id.to_s}"
          unless binding.local_variables.empty?
            msg += "("
            msg += binding.local_variables.map{|vname|
                      "#{vname}:#{binding.local_variable_get(vname).inspect}"
                    }.join(", ")
            msg += ")"
          end
          binding.receiver.instance_variable_get(:@logger).debug(msg)
        end
      end
    }
  )
end

引数名と渡された値がセットでロギングされるようになった。
これで完成。


class SomeClass
  def sample_method(sth1, sth2, sth3)
    # ...
  end
end

smp_inst.sample_method("a", ["b"], {c: 1})
# D, [2019-09-19T01:25:18.518278 #2600] DEBUG -- : SampleClass#sample_method(sth1:"a", sth2:["b"], sth3:{:c=>1})

クラススコープにmethod_call_loggingというメソッドを追加することにする。
つまり、以下のように記述したら今までのメソッド呼び出しロギング機能が使えるようにする。


class SomeClass
  method_call_logging

  def initialize(logger)
    @logger = logger
  def
  
  # ...
end

クラススコープへのメソッドの追加は、ActiveSupportのソースコードを参考にした。cattr_readerのようなイメージだ。
Classクラスのインスタンスメソッドにmethod_call_loggingを追加する。この中のselfが、呼び出し元の機能を追加するクラスになるので、今までのコードがそのまま使えるわけだ。


class Class
  def method_call_logging
    set_trace_func(
      proc {|event, file, line, id, binding, klass|
        # 略
      }
    end
  end
end

しかし、このままだと複数のクラスにmethod_call_loggingを追加すると、最後に宣言したクラス以外でのロギング機能が動作しなかった。
set_trace_funcのリファレンスマニュアルをよく読むと、これを複数回呼び出した場合は上書きされ、最後のProcのみが有効になるようだ。
ということで、複数のProcを管理する仕組みを作る必要がある。
Classクラスのスコープにインスタンス変数を作って管理することにした。


class Class
  def self.add_proc(proc_filter)
    unless defined?(@proc_list)
      @proc_list = []
      set_trace_func(
        proc {|*args|
          @proc_list.each{|_proc| _proc.call(*args)}
        }
      )
    end
    @proc_list.push(proc_filter)
  end

  def method_call_logging
    Class.add_proc(
      proc {|event, file, line, id, binding, klass|
        # 略
      }
    )
  end
end

これで、複数のクラスからmethod_call_loggingが動作した。

ここまでできていれば、このエンハンスは難しくない。
まず、仕様としてはmethod_call_logging呼び出しに以下のようにメソッド名シンボルとログレベルをハッシュで指定するようにする。


class SomeClass
  method_call_logging sample_method: Logger::INFO

  def initialize(logger)
    @logger = logger
  def
  
  # ...
end

method_call_loggingの定義側では、渡されたオプションに基づいて以下のようにログレベルを切り替えれば良い。

  def method_call_logging(option={})
    Class.add_proc(
      proc {|event, file, line, id, binding, klass|
        # 略
            logger = binding.receiver.instance_variable_get(:@logger)
            if option[id]
              logger.log(option[id], msg)
            else 
              logger.debug(msg)
            end
      }
    )
  end

ここまでの結果をGitHubにリポジトリとして公開した。
https://github.com/kosuke-suzuki/method_call_logger

また、https://rubygems.org にも公開してみた。
https://rubygems.org/gems/method_call_logger

クラスメソッドのロギングとか、ログレベルの細やかな制御とか、指定するときのインターフェースの改善点とか、自分と同じようなことをやりたい人がいれば、そのような要望を伺いたい。