Rubyでクラスのメソッド呼び出しを全てロギングするには

1. あるクラスの全てのメソッド呼び出しを、メソッドの処理を実行する直前にログに記録したい。しかし、すべてのメソッドの先頭に`logger.debug`を追記したくはない。どうすれば良いか。
    - 書き出す内容は、クラス名・呼び出されたメソッド名・呼び出されたメソッドに渡された引数を`inspect`したものとする
        - `SomeClass`のインスタンスメソッド`some_method`を`args`で呼び出した場合の出力例:
            - `SomeClass#some_method(#{args.inspect相当の内容})`
    - ロガーは`initialize`メソッドの引数として注入されるものとし、ロガーのインターフェースは[Rubyの標準ライブラリのlogger](https://docs.ruby-lang.org/ja/latest/library/logger.html)に準ずるものとする。日時情報も出力されるため、自前でタイムスタンプを出力する必要はない

2. 1.で作成したメソッド呼び出しデバッグの仕組みはたいそう有用だった。他のクラスにも使いたい。他のクラスで使うときに書き換える箇所を最小にできるよう、モジュール method_call_logger.rb として作成せよ。
    - 利用クラス側で書き換えるのは以下の箇所のみとする
        - A: ファイル先頭のファイルスコープの`require`文
        - B: クラススコープ
        - C: `initialize`メソッド

3. 2.までは、この機能をデバッグ用のものとしてログレベルがDEBUGの時のみ出力されるように実装してきた。しかし、一部のメソッドは非常に重要なため、ログレベルがINFOであっても出力したいという要望が挙げられた。指定した特定のメソッドのみの出力ログレベルを変更できるようにせよ。
    - 利用クラス側で出力ログレベルを変更するメソッドの指定は、B: クラススコープで行うものとする


```ruby

require "method_call_logger" # A

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

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

----

回答例

1.

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

```ruby

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

```ruby

class SomeClass

  # ...

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

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

```ruby

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`メソッドのタイミングだけは自動ロギングの対象から除外することにする。

```ruby

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
```

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

```ruby

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`を利用して取得できる。
下記は、ログメッセージを見やすいようにフォーマットしてクラス名も表示するようにしたものだ。

```ruby

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
```

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

```ruby

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})
```

2.

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

```ruby

class SomeClass
  method_call_logging

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

クラススコープへのメソッドの追加は、[ActiveSupportのソースコード](https://github.com/rails/rails/blob/master/activesupport/lib/active_support/core_ext/class/attribute.rb)を参考にした。`cattr_reader`のようなイメージだ。
`Class`クラスのインスタンスメソッドに`method_call_logging`を追加する。この中の`self`が、呼び出し元の機能を追加するクラスになるので、今までのコードがそのまま使えるわけだ。

```ruby

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`のリファレンスマニュアル](https://docs.ruby-lang.org/ja/latest/method/Kernel/m/set_trace_func.html)をよく読むと、これを複数回呼び出した場合は上書きされ、最後のProcのみが有効になるようだ。
ということで、複数のProcを管理する仕組みを作る必要がある。
`Class`クラスのスコープにインスタンス変数を作って管理することにした。

```ruby

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`が動作した。

3.

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

```ruby

class SomeClass
  method_call_logging sample_method: Logger::INFO

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

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

```ruby
  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

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