Node.jsのbunyan互換のRuby用JSON Loggerを作った #Ruby

動機

最近、ログを全て JSON 化しようといて、Node.js のアプリケーションでは bunyan を使っている。このモジュールの良いところは整形して見るためのコマンドを持っている。そのため JSON ログを fluentd やサードパーティサービスに送りつつも、ターミナルで見たい場合は bunyan output.log なり ~ | bunyan で確認できる。

Node.js と Ruby のプログラムを作ることが多いため Ruby も JSON でログを出力したかったが、ビューコマンドまで持つものが見つからなかったので、bunyan 互換のロガーを自作してみた。

使い方

純正の Logger のサブクラスとなっており各種ログメソッドに対して、メッセージとともに例外や含めたいデータを付加できる。

require 'rubygems'
require 'ougai'

logger = Ougai::Logger.new(STDOUT)
logger.debug('Debugging', data_id: 1, data_flag: true, data: { value: 100 })

begin
  1 /0
rescue => ex
  logger.error('Caught error', ex)
end

ログ出力

{
  "name": "main",
  "hostname": "mint",
  "pid": 14607,
  "level": 20,
  "time": "2016-10-16T22:26:48.836+09:00",
  "v": 0,
  "msg": "Debugging",
  "data_id": 1,
  "data_flag": true,
  "data": {
    "value": 100
  }
}
{
  "name": "main",
  "hostname": "mint",
  "pid": 14607,
  "level": 50,
  "time": "2016-10-16T22:26:48.836+09:00",
  "v": 0,
  "msg": "Caught error",
  "err": {
    "name": "ZeroDivisionError",
    "message": "divided by 0",
    "stack": "main.rb:18:in `/'\n  main.rb:18:in `<main>'"
  },
  "reason": "zero spec"
}

※実際には各JSON毎に一行で出力されるので整形はされない。

bunyan コマンドで見たときの出力

[2016-10-16T22:26:48.836+09:00] DEBUG: main/14607 on mint: Debugging (data_id=1, data_flag=true)
    data: {
      "value": 100
    }
[2016-10-16T22:26:48.836+09:00] ERROR: main/14607 on mint: Caught error (reason="z
    main.rb:10:in `/'
      main.rb:10:in `<main>'

※実際にはターミナルでは色付けされる

名前の由来

bunyan（バニヤン）が作家の名前らしい（もしくは神話の巨人名？）ので、日本製ということで ougai にしてみた。bunyan という名前の Gem は既に MongoDB 向けで存在していたため。