Slack-Ruby-Bot のログをファイル出力できるように修正を入れた

初OSSコミット╭( ・ㅂ・)و ̑̑ ｸﾞｯ !

以前まではSlack-Ruby-Botが吐くログはすべて STDOUT に出力されていましたが、この修正によりログの出力先を任意に設定することができるようになりました。

設定例

SlackRubyBot.configure do |config|
  config.logger = Logger.new("slack-ruby-bot.log", "daily")
end

この設定は v0.10.4 より利用できます。

修正を入れようと思った経緯

Slack-Ruby-Bot では SlackRubyBot::Loggable というモジュールを用意しており、ログを吐き出す際はこのモジュールをそれぞれのクラスやモジュールでインクルードして利用しています。
SlackRubyBot::Loggable.logger の出力先は STDOUT で固定されていたため、 Slack-Ruby-Bot 側でエラーが発生した場合は bot を起動したプロセスの標準出力にログが吐き出さます。そのため、ログをファイルに残すにはプロセス起動時に出力先をリダイレクトする必要がありました。
自分の利用する範囲では Slack-Ruby-Bot 側のログを残す必要はなかったためリダイレクトしていなかったのですが、別のある問題が度々発生していました。

長時間プロセスを起動しっぱなしにしていると、botが落ちるのです。
長いときは1週間程度、短いときは数日で落ちてしまいます。
あまりに頻繁に落ちるので、毎朝毎朝 bot の生存状況を確認しては落ちていたら起動するという介護生活が始まりました・・・・。

業務効率化のために作ったbotなのに、botの介護作業を毎日しなければいけない状態では本末転倒です。

OOM Killerに殺されたのか？

ファイルディスクリプタが足りなくなったせいで落ちたのか？

いくつか可能性の有りそうな事象を挙げてみましたが、サーバのログを見ても上記の事象が発生していた形跡はありません。

そこで、原因特定のために bot の ruby プロセスが死ぬタイミングでログを吐くようにしました。

#<Errno::EIO: Input/output error @ io_write - <STDERR>>

backtrace: [
"/home/xxx/.rbenv/versions/2.2.2/lib/ruby/2.2.0/logger.rb:610:in `write'", 
"/home/xxx/.rbenv/versions/2.2.2/lib/ruby/2.2.0/logger.rb:610:in `warn'", 
"/home/xxx/.rbenv/versions/2.2.2/lib/ruby/2.2.0/logger.rb:610:in `rescue in write'", 
"/home/xxx/.rbenv/versions/2.2.2/lib/ruby/2.2.0/logger.rb:594:in `write'", 
"/home/xxx/.rbenv/versions/2.2.2/lib/ruby/2.2.0/logger.rb:378:in `add'", 
"/home/xxx/.rbenv/versions/2.2.2/lib/ruby/2.2.0/logger.rb:452:in `error'", 
"/home/xxx/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/slack-ruby-bot-0.9.0/lib/slack-ruby-bot/server.rb:82:in `rescue in handle_exceptions'", 
"/home/xxx/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/slack-ruby-bot-0.9.0/lib/slack-ruby-bot/server.rb:86:in `handle_exceptions'", 
"/home/xxx/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/slack-ruby-bot-0.9.0/lib/slack-ruby-bot/server.rb:27:in `block in run'", 
"/home/xxx/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/slack-ruby-bot-0.9.0/lib/slack-ruby-bot/server.rb:26:in `loop'", 
"/home/xxx/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/slack-ruby-bot-0.9.0/lib/slack-ruby-bot/server.rb:26:in `run'", 
"/home/xxx/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/slack-ruby-bot-0.9.0/lib/slack-ruby-bot/bot.rb:6:in `run'",
"hogehoge-bot.rb:22:in `run'",
"hogehoge-bot.rb:58:in `<main>'"
]

これがbotの遺言です。 SlackRubyBot::Server#handle_exceptionsでエラーログを吐く際に落ちていました。

（予想ですが）長時間プロセスを起動していると標準出力が閉じられてしまうため、エラーログを吐こうとするところでEIOエラーが発生しているようです。

そのため、冒頭に書いたように Slack-Ruby-Bot にてログの吐き出し先を任意に変えられるように修正を入れ、 bot に反映したところ

＿人人人人人人＿
＞　突然の死　＜
￣Y^Y^Y^Y^YY^Y^Y^Y￣

が発生しなくなりました！

ということで一件落着、介護生活から開放されました。