失敗したテストのログだけを出力するぞ

表題の通りのことができるgem、CiLoggerが便利ですよという話です。

私達は大量のテストをCI上で実行しています。テスト結果を見れば失敗理由が自明なものもありますが、E2Eテストなどでよく起きる「たまに失敗するテスト」の調査はログやスクリーンショットなど、可能な限りの情報を集めないと根本原因がつかめないことが多いです。

そんなときに、特に考えずRailsデフォルトの設定(config.log_level #=> :debug)のままにしておくと、膨大なログの中から該当するテストに関連する行を探し当てる作業が必要になります。これは事前の準備なしではほぼ不可能です。

事前の準備として簡単に思いつく方法は、テスト前後で「どのテストが開始/終了したか」をログに出力することです。

config.around do |example|
  Rails.logger.debug("start example at #{example.location}")
  example.run
  Rails.logger.debug("finish example at #{example.location}")
end

これで頑張れば失敗したテストに関連するログを探せるようになりました。が、やってみるとわかるのですが大量のログから該当行を探し当てるのは面倒です。それでも他の方法がなかったので長い間これで運用を続けていました。

そんな折ふと「そもそもCIでほしいのは失敗したテストのログだけであり、他は不要では？」と思いついたのでCiLoggerを作ってみました。このgemの内部ではloggerへの書き込みをいったんメモリ上に保持しておき、テストが失敗したらファイルに書き出す、という処理を行っています。これでしばらく運用してみて、仮説(失敗したログだけあれば良い)が正しそうであることを実感しています。

また、GitHub ActionsやCircleCIなどはArtifactの容量によって課金されるので、CiLoggerを使うとそれらの料金を抑えられるのもメリットです。よければ使ってみてください。

注意点

現時点(v0.3.0)ではRSpecのみに対応しています。minitestで使いたい人はPRお願いします :pray:

余談

開発当初は、CiLoggerを使うとログファイルへの書き込み量が減るので速度改善効果もあるだろうと想定していたのですが、少なくとも僕が測定した限りでは優位な速度差が出ませんでした。CiLoggerを使わずにlog_levelを:errorにしても速度差が出なかったので、計測方法が悪いのかなにか見落としがあるのか…。知見ある人いたら教えて下さい＞＜