Qiitaを眺めていて

[Ruby] caller を利用してメソッド呼び出しをログに記録させる。という記事を見つけて，「これ面白い！でも，既存のメソッドにログとる部分を追加するみたいにできないかな？」と思って色々試行錯誤．

イメージとしては，

def test
  puts “hello world”
end
add_trace :test

みたいな感じ．

このときadd_traceをうまいこと定義したら，testメソッド内にログ用のコードを埋め込めるはず．

結果

まぁできたけど，けっこう複雑…（検証環境：ruby-2.1.0dev）
Qiitaってサイト内記事を引用する方法あるのかな？
毎度毎度，Qiitaの綴りがわからなくなる．

コード

trace.rb

# このモジュール内はほぼ参考記事通り
module Util
  class Trace
    @@enable = true
    @@log = nil

    class << self

      def enable= bool
        @@enable = bool
      end

      def log= log
        @@log = log
      end

      def trace *args
        @@log.debug "#{caller.first} (#{args.join(',')})" if @@enable && @@log
      end

      # add_trace用のメソッドだけ追加（callerではうまくいかない）
      def trace2 source, *args
        @@log.debug "#{source.join(':')} (#{args.join(',')})" if @@enable && @@log
      end

    end
  end
end

define_method :add_trace do |method_name|
  # メソッド定義位置をあらかじめ取得（evalを使うため）
  __source = method(method_name).source_location.push("`#{method_name}'")
  # 新しいメソッド名
  __new_method = "__original_#{method_name}".to_sym
  # パラメータリストを取得（eval用に文字列にしておく）
  __params = method(method_name).parameters.map{|a| a[1]}.join(',')
  # traceコードを含んだ新しいメソッドを定義
  self.instance_eval <<-EOS
    alias :#{__new_method} :#{method_name}
    def #{method_name}(#{__params})
      Util::Trace.trace2(#{__source},#{__params})
      self.send(:#{__new_method}, #{__params})
    end
  EOS
end


if $0 == __FILE__

  require 'logger'

  Util::Trace.log = Logger.new(STDERR) do |log|
    log.level = Logger::DEBUG
  end

  def sub
    puts "'sub' is called"
  end
  add_trace :sub

  def sub2( x, y )
    puts "'sub2’( #{x}, #{y} ) is called"
  end
  add_trace :sub2

  Util::Trace.enable = true
  puts "----- trace on"
  sub
  sub2 1, {a: 2, b: 3}

  Util::Trace.enable = false
  puts "----- trace off"
  sub
  sub2 1, {a: 2, b: 3}

end

長い…　結局重要なのはdefine_method :add_traceのブロック．
if $0 == __FILE__以下は検証用．

パラメータ渡す部分はけっこう悩んだけど，とりあえずevalさんの破壊力で解決．
というか，ほぼevalさん頼みであまり美しくはない．
特にこの表示だと変にハイライト効いちゃって意味不明．

そういえば，Methodオブジェクトってあまり使ったことなかったけど，今回は大いに役立ってくれました．

以下，実行結果．

$ ruby trace.rb
----- trace on
D, [2013-12-30T04:58:20.325428 #69889] DEBUG -- : trace.rb:56:`sub' ()
'sub' is called
D, [2013-12-30T04:58:20.325507 #69889] DEBUG -- : trace.rb:61:`sub2' (1,{:a=>2, :b=>3})
'sub2'( 1, {:a=>2, :b=>3} ) is called
----- trace off
'sub' is called
'sub2'( 1, {:a=>2, :b=>3} ) is called

ちゃんとメソッドの定義位置もとれてる．

おわりに

しばらくRubyつかってなかったけど，やっぱり何でもありな感じが楽しい言語でした．

メソッド呼び出しのログをとる記事が面白かったのでマクロみたいな感じにしてみた

Qiitaを眺めていて

結果

コード

おわりに