Ruby
Rails
logger
structured-logging

構造化ログのススメとRuby向けロガーOugaiを作った理由

構造化ログ

構造化ログ とは、機械的に処理しやすいログのことであり、その機構(ロギング)である。
英語圏では、 Structured Logging と表記される。たとえば Google Cloud の Stackdriver のドキュメントには下記の説明ページがあります。(残念ながら執筆時点で、これの日本語ページがまだできてないので、Google がどう訳すか興味深い)
https://cloud.google.com/logging/docs/structured-logging

普通のログと構造化ログの比較

普通のログは、基本的に タイムスタンプレベル 、そして メッセージ の文字列だけである。ログとして残す事象(イベント)のコンテキストになる情報はメッセージに適当に埋め込む。コンソール等で人が読みやすいものである。

構造化ログは、メッセージに埋め込んでいたコンテキストになる情報をそれぞれログ構造のフィールドに独立して持たせる。そのため後から解析がしやすい。そして出力するログはテキストベースで JSON にすることが多い。

では、見比べてみましょう。通常のRubyのLoggerと自作のOugaiでのログは次のようになります。『ユーザが記事を作成した』というログです(冠詞、削ってます)。

logger.info "User created article  (user_id=#{user.id} article_id=#{article.id}"
I, [2018-05-13T17:51:08.772542 #6253]  INFO -- : User created article  (user_id=123 article_id=45)
logger.info "User created article", user_id: user.id, article_id: article.id
{"pid":6253,"level":20,"time":"2018-05-13T17:52:25.147+09:00","msg":"User created article","user_id":123,"article_id":45}"

※デフォルトフォーマットとは異なります

見てわかる通り、普通のログは埋め込んで付帯情報を文字列化しつつ書かなくてはなりません。一方、構造化ログの方が JSON にした影響で長くなるのでコンソールでは読みづらいです。しかし読みづらいことはフォーマッタの動作環境での切替やparse機構を持つログビューワを使えば問題になりません。

構造化ログの方が解析しやすいというのは、例えば普通のログでは「あるユーザのログだけ抽出したいとき」に単に grep "user_id=10" とすると user_id が 101 など他のものまで引っかけてしまいます。構造化ログでは(主に JSONPath を使って)フィルタが $.user_id = 10 のように簡単に確実に絞り込めます。

ログ管理サービスと構造化ログ

AWS CloudWatch Logs, Google Cloud の Stackdriver LoggingLoggly, Logentries といったログ管理や解析向け SaaS はどれも構造化ログをサポートしていますし、むしろそうしないとそれらのサービスの機能を活かし切れません。ただ各サービスが提供するライブラリ自体は、構造化出力に対応してなかったりするので、Fluentd で中継させて送るのが現状ベストと思います。

Ougai を作った理由

元々 フロントAPIサーバを Node.js で書いて、バックエンドの管理サービスを Ruby/Rails で作るというプロジェクトによく参加してました。Node.js には Bunyan という有名な JSON ロガーがあり、これを好んで使っていました。しかしRubyにはいくつかの構造化ログを扱うライブラリはあるものの、各々のライブラリがフレームワークになっていました。Node.js 自体に console.info のようなコンソール出力向け機能しかないのですが、Ruby にはそれ自体に Logger があるのにも関わらず。もう一つマイクロサービスにおいて複数の言語で各サービスを実装することは多いですが、できれば横断的にログを解析したいためにそのフォーマットも統一したいと思いました。

これらの背景もあり、Ruby のオリジナル Logger ベースで、前述の Bunyan 互換でログ出力するフォーマットを持つロガーを自作しました。それが Ougai です。(Bunyan がイギリスの文学者名が由来だそうなので日本の文学者から名付けました)

GitHub: tilfin/ougai: A Ruby structured logging is capable of handling a message, custom data or an exception easily and generates JSON or human readable logs.

Ruby のオリジナルの Logger クラスの拡張なのでいきなり導入しても、メッセージフィールドに出るだけでクラッシュすることはありません。徐々にコンテキストを独立したフィールドに移行することができます。フォーマットは標準で、JSON 出力用は Node.js の Bunyan と Pino 互換のもの、awesome_print を利用してターミナルでカラフルに見やすい **Readable* が入っています。JSON 用のはそれぞれ Bunyan と Pino が持つ専用ログビューワコマンドでもちろん閲覧できます。フックによって共通情報を入れやすくしたりする機能もあります。

https://github.com/tilfin/ougai/wiki
Wiki には Rails, Sidekiq, Fluentd 等と組み合わせた使うための設定例も載せてあります。

https://rubygems.org/gems/ougai
なお既にリリースしたから1年以上経っているので、知ってる範囲でも、知らないところでもそこそこ使ってもらえています。

tilfin's note よりクロスポスト


リリース当時にも記事を書いたのですが、昨年末こちらにコメントさせていただいたので、改めて構造化ログについての説明も含めて書きました。