Hatena::Grouprubyist

うんたらかんたらRuby RSSフィード

2010-03-10Logger!!! (ログにタイムスタンプを追加する方法)

Logger!!!(ログにタイムスタンプを追加する方法)

| Logger!!!(ログにタイムスタンプを追加する方法) - うんたらかんたらRuby を含むブックマーク はてなブックマーク - Logger!!!(ログにタイムスタンプを追加する方法) - うんたらかんたらRuby

Railscasts - The Logger

Logger!!! - うんたらかんたらRuby - Rubyist


ログに日時を追加(簡易版)

/opt/local/lib/ruby/gems/1.8/gems/activesupport-2.3.5/lib/active_support/core_ext/logger.rb

コメントに日付フォーマットのみ変更してタイムスタンプを表示する方法が書いてた。

 20 # Extensions to the built in Ruby logger.
 21 #
 22 # If you want to use the default log formatter as defined in the Ruby core, then you
 23 # will need to set the formatter for the logger as in:
 24 #
 25 #   logger.formatter = Formatter.new
 26 #
 27 # You can then specify the datetime format, for example:
 28 #
 29 #   logger.datetime_format = "%Y-%m-%d"
 30 #
 31 # Note: This logger is deprecated in favor of ActiveSupport::BufferedLogger
 32 class Logger

とりあえずミリ秒まで不要であれば、これだけでいけました。

(Loggerのoverride不要)

# environment.rb
  config.logger = Logger.new(config.log_path) 
  config.logger.formatter = Logger::Formatter.new
  config.logger.datetime_format = "%Y-%m-%d %H:%M:%S"
D, [2010-03-08 03:07:33#5394] DEBUG -- :   Memo Load (1.2ms)   SELECT * FROM "memos" LIMIT 10 OFFSET 0
I, [2010-03-08 03:07:33#5394]  INFO -- : Rendering template within layouts/application
I, [2010-03-08 03:07:33#5394]  INFO -- : Rendering memos/index
D, [2010-03-08 03:07:33#5394] DEBUG -- : Rendered memos/_sidebar (0.7ms)
I, [2010-03-08 03:07:33#5394]  INFO -- : Completed in 147ms (View: 140, DB: 1) | 200 OK [http://localhost/memos]


以下、試行錯誤及び、もっとカスタマイズしたい場合の書き方。


Logger::Formatterを追加

apiを見てみると、Formatterというクラスがあるらしい。

早速追加。

# environment.rb
  config.logger = Logger.new(config.log_path) 
  config.logger.formatter = Logger::Formatter.new

Processing MemosController#index (for 127.0.0.1 at 2010-03-08 01:00:46) [GET]
D, [2010-03-08T01:00:46.375185 #74468] DEBUG -- :   Memo Load (0.6ms)   SELECT * FROM "memos" LIMIT 10 OFFSET 0
I, [2010-03-08T01:00:46.376684 #74468]  INFO -- : Rendering template within layouts/application
I, [2010-03-08T01:00:46.376992 #74468]  INFO -- : Rendering memos/index
D, [2010-03-08T01:00:46.393688 #74468] DEBUG -- : Rendered memos/_sidebar (0.1ms)
I, [2010-03-08T01:00:46.394937 #74468]  INFO -- : Completed in 25ms (View: 19, DB: 1) | 200 OK [http://localhost/memos]

おお、それっぽい。


Loggerのソースを見てみる

apiにはcallメソッドがあると記載されていたので、ソースを見てみた。

/opt/local/lib/ruby/gems/1.8/gems/activesupport-2.3.5/lib/active_support/core_ext/logger.rb

/opt/local/lib/ruby/1.8/logger.rb

class Logger
  class Formatter
    Format = "%s, [%s#%d] %5s -- %s: %s\n"


    def call(severity, time, progname, msg)
      Format % [severity[0..0], format_datetime(time), $$, severity, progname,
        msg2str(msg)]
    end

あった、これっぽい。


Railscastsのようにしてみる

# environment.rb
class Logger
  class Formatter
    def call(severity, time, progname, msg)
      "#{time.to_s(:db)} #{severity} -- #{msg}\n"
    end
  end
end
Processing MemosController#index (for 127.0.0.1 at 2010-03-08 01:07:17) [GET]
2010-03-08 01:07:17 DEBUG --   Memo Load (1.1ms)   SELECT * FROM "memos" LIMIT 10 OFFSET 0
2010-03-08 01:07:18 INFO -- Rendering template within layouts/application
2010-03-08 01:07:18 INFO -- Rendering memos/index
2010-03-08 01:07:18 DEBUG -- Rendered memos/_sidebar (0.7ms)
2010-03-08 01:07:18 INFO -- Completed in 135ms (View: 128, DB: 1) | 200 OK [http://localhost/memos]

おおお、おしい。


ようやく完成

やっぱミリ秒出したり、プロセスIDも出力したいので

デフォルトの内容に若干手を入れることにした。

# environment.rb
class Logger
  class Formatter
    def call(severity, time, progname, msg)
      format = "[%s #%d] %5s -- %s: %s\n"
      format % ["#{time.strftime('%Y-%m-%d %H:%M:%S')}.#{'%06d' % time.usec.to_s}",
                  $$, severity, progname, msg2str(msg)]
    end
  end
end

Formatは使用しているので、format変数を別途定義。


Processing MemosController#index (for 127.0.0.1 at 2010-03-08 02:27:12) [GET]
[2010-03-08 02:27:12.854925 #95499] DEBUG -- :   Memo Load (1.1ms)   SELECT * FROM "memos" LIMIT 10 OFFSET 0
[2010-03-08 02:27:12.938415 #95499]  INFO -- : Rendering template within layouts/application
[2010-03-08 02:27:12.938720 #95499]  INFO -- : Rendering memos/index
[2010-03-08 02:27:12.973117 #95499] DEBUG -- : Rendered memos/_sidebar (0.8ms)
[2010-03-08 02:27:12.976412 #95499]  INFO -- : Completed in 128ms (View: 120, DB: 1) | 200 OK [http://localhost/memos]

あと

log4rも試してみたいところ。

トラックバック - http://rubyist.g.hatena.ne.jp/rochefort/20100310