読者です 読者をやめる 読者になる 読者になる

inFablic

Fablic開発者ブログ

Railsログを美しく Beautiful::Log

この記事はFablic　Advent Calendar 15日目の記事です。 http://qiita.com/advent-calendar/2016/fablic

はじめまして、Fablicでサーバーサイドエンジニアをやっている岸と申します。

今年の6月、Fablicにジョインして初めてRuby／Railsに触りました。

それまでJavaがメインだった*1僕にとってはRailsは気がきいて柔軟性がハンパないので、超楽しく開発しています。その一方で、Atom/Vimとターミナルでの開発は、立派な無償IDEであるeclipseと比べるといささか心もとない気がしました。*2

一番に気になったのはログ周りでした。Logger/Appenderのことにも触れていきたいのですが、一番身近なのは開発中や不具合調査中のコンソールログ。

これをキレイにするgem、beautiful-logを作ってみたのでご紹介します。

https://github.com/nogahighland/beautiful-log

イケてないRailsのログフォーマット

みなさん、こんなログよく見ませんか。

スクリーンショット 2016-12-14 1.17.09.png

エラーのrescue時に error.message の内容だけ表示して終わりのやつ。

もしくは、きちんとActiveSupport::Loggerをセットすると…

config.logger = Logger.new(log_path)

↓

スクリーンショット 2016-12-12 22.40.53.png

トレースフルパスで全部出せばええんやろ みたいなこの投げやりなログ。

いずれにせよコードのどこがミスっているのか、探すのが大変です。「帯に短し襷に長し」とはよく言ったものです。

異常箇所を特定して修正する、という開発の大部分を占める時間は、ログをキレイにすることでもっと短くできると思います！

こんなに綺麗になる

ログレベル別の色表示

2016-09-28 1 24 05

fazibear/colorizeというgemを使って、ログレベルごとの色付けをしてみました。だんだん事のヤバさが増していくのが直感的にわかると思います。これなら超速でログが流れても見逃しません。ログレベルに応じて好きな色を指定してカスタマイズすることもできます。

細かいですが、メッセージの出だしが縦に揃っていることで素早くメッセージを読み始めることができます。

問題箇所のハイライト

メッセージが例外の場合は、トレースを縦横にギュッと絞って大事な部分だけ表示します。

画像を見ると、どこで何が起きてエラーになったのか、一目瞭然ですね。

ちなみにiTermだとパスを⌘+クリックで開けるので、AtomとかSublime使ってる人はその箇所までひとっ飛びですよ（Winの人ゴメンナサイ）*3

_2016-12-10_2_54_42

だいたい問題はgemなんかより自分たちのコードにあります。つまり、大事なのは プロジェクトルート（Rails.root）以下のどこで起きているか素早く特定することです。プロジェクトルート以下のソースであればそれより上位の絶対パスは必要ないです。もっと割り切ればプロジェクト外にあるソースのパスなんて無視しても良いかもしれません。

（デフォルトでは省くようにしていますが、設定で表示することもできます。）

ステータスコード別の表示

アプリケーションがレスポンスを返したとき、意図せず異常値を返していることがあります。

ひどいときは例外を握りつぶして（ロギングもせずに）500エラーを返していて、一見ログを眺めていてもエラーだと気づかないことさえあります。

スクリーンショット 2016-12-14 1.22.19.png

スクリーンショット 2016-12-14 1.21.37.png

このように、ステータスコード別で色を分けてあげると、正常/異常応答を何も考えずに理解することができます。もちろん好きな色を指定してカスタマイズすることができます。

オブジェクトの表示

ログメッセージがプリミティブではないHashやArrayなどの複雑なオブジェクトの場合はawesome-print/awesome_printを使って、 キレイに出力します。縦揃いだったり中身が型で色分けされてとてもわかり易いですね。

  • Hash

hash

  • ActiveRecord

ar

ログレベル表示の終わり（ ...WARN -- :　のところ）にインデントを合わせておくというのも小さな工夫ではあります。

無駄のない有益なログであれば多く出しておくことで問題発見がしやすくなります。

アプリケーションで必要なことはたったこれだけです。

Rails.logger.(debug|info|warn|error|fatal) message

インストール

RailsプロジェクトのGemfileに、下記のように追記しましょう（現段階ではproduction利用はまだオススメしません）

gem 'beautiful-log'
# または
gem 'beautiful-log', git: 'git@github.com:nogahighland/beautiful-log.git'

Bundlerでインストール。

$ bundle install

または自分でGemをインストール。

$ gem install beautiful-log

次に、美しいフォーマットを使うよう設定していきます。

このあたりは一例なので、詳しくはRailsでのログ/ロガーまとめとかをご参照ください。

  • config/application.rb
config.logger = Logger.new(config.paths["log"].first)
config.logger.formatter = Beautiful::Log::Formatter.new
  • config/environments/development.rb
config.log_level = :debug # 環境に合わせたログレベルを設定します。
  • Rakefile

Rakeタスクのロギングも行えます。

Rails.logger = Logger.new(STDOUT)
Rails.logger.formatter = Beautiful::Log::Formatter.new
Rails.logger.level = Logger::DEBUG # set the level you need
  • もしくは、 Beautiful::Log をincludeすることで上記すべての設定が行なえます。
module YourApplication
  class Application < Rails::Application
    # This is equivalent to code below:
    #   Rails.logger = Logger.new(config.paths['log'].first)
    #   Rails.logger.formatter = Beautiful::Log::Formatter.new
    include Beautiful::Log
    :
  end
end

ちょっと試してみたところ、どうやら Rails.logger を先に定義しておくと、 environments/development.rb でconfig.logger を上書きしてしまうようです。

LoggerやFormatterを環境ごとに分けたい場合はenvironments以下で設定したほうが良さそうです。

出力のカスタマイズ

色や出力量は細かく設定することができます。詳しくは、README（英語）をご参照ください。 https://github.com/nogahighland/beautiful-log

さいごに

すごく地味なエントリではありますが、地味に便利なんじゃないかと個人的に思っております。 それでは良いRailsライフを！

参考†

*1:GroovyというRubyを参考にしたJVM言語と、Railsを参考にしたGrailsというフレームワークも一応使っていたんですよ

*2:RubyMineとかもっと良いのかもしれませんが、有償IDEにまだ抵抗あり使ったことない…

*3:僕はダブルクリックで iTerm2 上の Vim を開くという記事を参考にiTermの別タブでVimを開くようにしています。

nogahighland