2015年5月20日

grepでログ解析をするなんてひどい話だ

Unix/Linux

著者プロフィール非公開

本記事は、原著者の許諾のもとに翻訳・掲載しております。

今でも、 systemdのjournal におけるバイナリのストレージフォーマットに関して、不満を漏らす人が多くいることに私は驚きを隠せません。私は長年、システム管理者として働いてきており、1年以上も syslog-ng のオープンソースエディションのメンテナとして活動してきました。だからこそ、テキストではないストレージフォーマットに対して、なぜ多くの人が批判的なのか、私は理解に苦しんでいます。更に、反論を唱える人までいることが信じられません。もしかしたら、私は別世界の人間なのかもしれません。ですが、より良い選択肢があるのに、テキストのストレージを使う理由はほとんどありません。ロギングをする必要性、そしてなぜ、テキストのログストレージに対してそこまで用心深いのかについて、私は何度も尋ねられました。ここに、私が導き出した答えを紹介したいと思います。

これは、journalについて弁明するものではないということをご承知おきください。私は、journalが導入される、かなり前からバイナリのログストレージをデプロイしてきましたし、私がここで推奨する解決策もjournalではありません。（正直なところ、journalのアイデアそのものは好きです。私が所有するいくつかのPCに搭載されているjournalの機能も楽しんでいます。しかし、それは私が必要とする解決策ではありませんし、将来的に必要とすることもないでしょう。）

（なお、頂いたいくつかの反響にお答えして、フォローアップの記事を投稿しました。）

要件

まず初めに、システムと必要条件について説明します。異なるニーズに合わせた2つのセットアップがあります。私自身、以前はそれぞれ別の解決策を取っていましたが、後に1つに絞っています。

小規模な構成

まず1つ目は簡単なもの、つまりサーバ、コンピュータ、ガジェットを用いた個人的なセットアップです。このシステムは、VPS用マシンが2台、自宅にあるPCが1台、ノートPCが2台（どれもDebianが搭載されています）、Raspberry Pi Bが1台（ログの収集はしているかどうかもわからないOpenELEC、または、上記のインフラストラクチャに連結したRaspbianを搭載）で構成されています。以前はカスタムファームウェアを搭載したルータを所持していましたが、手放してしまいました。

入力メッセージの数は、平均して毎秒数百件です。

必要とする条件はシンプルです。

ログを保存するセントラルサーバが1台必要
私はコンピュータ毎のログを気にしたり、保存したりはしません。全てセントラルサーバに送り、サーバにアクセスできない時のみ、個々のコンピュータにログを保留しておきます。どこかでいくつかのメッセージが失われたとしても、それは問題ありません。
簡単に変更できるセントラルサーバでなくてはならない
外出先で、場合によってはインターネットにアクセスできない状況で、ノートPCが勝手にセントラルサーバにメッセージを送ってほしくありません。ローカルでダミーのノードを引き出したいのです。

仮のローカルにあるコレクタノードとセントラルサーバにあるものが統合できなくても構いません。統合する必要がある場合は、ローカルからログをエクスポートして、それをセントラルサーバにインポートすることができます。ですが、滅多にこの作業をすることはありません。
効率的に全てのログを保存したい
実験用、そして遊び用として履歴データが欲しいのです。
データの後処理が行われ、構造化され処理されたバージョンのみを保存する
syslogやjournal、または他のソースから全てのログを取り、後処理を行い、キーフィールドや相互に関連のあるメッセージなどを抽出します。興味があるのは、これらのデータだけで、オリジナルのメッセージは捨ててしまいます。
プログラムやマシンにまたがってクエリを実行したい
私が、頻繁に行うことの1つとして、送信したメールがどうなったかを監視するというのがあります。私のPCから同じマシンのmsmtpやraspberry pi上またはリモートサーバ上のpostfix経由をして送信されたメッセージから成るGnusのログです。これらは、3つのホストそして4つのプログラムにまたがります。

システムへの問い合わせはこんな感じです。「ｍessage-id Xを含むメールのログを表示」または「今日送信したメールで、1時間以上経ってから送信されたもののログを表示」など、他にも似たような問い合わせをします。
適度に速く、効率的なアドホッククエリを行いたい
ログの後処理を行っている間、すぐにクエリを行いたいと考えています。過去のログを再度処理することなく履歴データの作業を行ったりする場合です。もちろん、抽出したフィールドに対してのみ行わなければなりません。もし、新しいフィールドを入れたいのであれば、古いデータを再度処理するか、新しいログにだけ処理を行うかのどちらかです。

大規模な構成

より複雑なセットアップでは、システムも少し大きくなります。その主要部分は、処理能力の高いマシンの5つのノードからなるクラスタであり、稼働しているメインのアプリケーショングループから、毎日、各ノード100ギガバイトの生ログを収集します。

こちらの要件も小規模な構成の場合とほぼ同様です。

ログを保存するセントラルサーバが1台必要
コンピュータ毎のログを気にしたり、保存したりはしません。全てセントラルサーバに送り、サーバにアクセスできない時のみ、個々のコンピュータにログを保留しておきます。セントラルストレージは冗長で、ローカルマシンは半日分に相当するログを簡単にバッファすることができます。バッファに保存されたログは、セントラルストレージに転送される目的だけにそこにあり、入力データとして処理されることは決してありません。
効率的に全てのログを保存したい
ポリシーや必要条件があるので、全てのデータは保存されなければなりません。生データは必要ないのですが、後処理されたログは保存されなければならず、長期に渡って保管されます。
データの後処理が行われ、構造化そして処理されたバージョンのみを保存する
syslogやjournal、または他のソースから全てのログを取り、後処理を行い、キーフィールドや相互に関連のあるメッセージなどを抽出します。興味があるのは、このデータだけで、オリジナルのメッセージは捨ててしまいます。
プログラムやマシンにまたがってクエリを行いたい
稼働するサービスは、マシン全体にまたがって分配されるので、同じイベントの異なる部分は、異なるノードによって処理されることがあります。ですから、複数のマシンやプログラムにまたがって、セッション全体に属するログに対してクエリを行う必要があります。
適度に速く、効率的なアドホッククエリを行いたい
システムからは様々なアラートが発せられ、更に過去に想定したり経験したりした問題であれば通知してくれますが、事前に設定されていないクエリもできなければなりません。数カ月前にさかのぼる必要があるかもしれず、それもすぐに答えが返ってくることが必要です。

なぜテキストではないのか？

小規模なシステム

小規模なシステムでは、テキストでログを保存する場合に2つの問題が挙げられます。

テキストは、構造化され、型付けされたストレージには効率が悪い
ログが構造化され型付けされると、それをテキストで保存するためには、シリアル化しなければなりません。そして、更に処理を行うために元に戻します。これは、リソースの無駄であり、テキストログの利点の大部分であるヒューマンリーダビリティを損なうことにもなります。
テキストでのアドホッククエリは難しい
バイナリのログストレージを批判する多くの人は、ログの検索方法としてgrepや正規表現に言及してきます。クエリがシンプルである、またはログを事前にフィルタすることができるのであれば、それで問題ありません。いくつかのルールを設定する場合は、grepで十分です。しかし、その場で思いついたようなクエリを行いたい時は、ほとんどの場合、正規表現に限定されてしまうでしょう。

ただし、正規表現で問題となるのは、それがほとんどヒューマンリーダブルではないということと、それを構築するのが困難であるということです。私には、クエリを正規表現に変換しないと機能しないシステムよりも、変換しなくても機能するシステムの方がより安心です。

もちろん、ログをインデックスし、検索するためにプログラムを使用することもできるでしょう。しかし、クエリを行うには特別なプログラムを使わなくてはいけなくなります。また、そうした全てのテキストログをかき集めておいた方が良いでしょう。いずれにしても生ログを見ないということには変わりないからです。

大規模なシステム

大規模なシステムでは、テキストでログを保存する場合、上で挙げたことに加えて更なる問題があります。

テキストは冗長である
好き嫌いはさておき、テキストは冗長です。ほとんどの場合、ログローテーションを行う際にはテキストを圧縮できる（そしてそれが大量の処理には最も効果的な方法である）とはいえ、これは、相当な量のリソースを食います。バイナリログでは、初めから多くのデータがもっと効率的に保存されます（UUIDやタイムスタンプなどの数を考えてみてください）。なぜなら、ヒューマンリーダビリティを気にする必要がないからです。

常にインデックスのためにメモリを使用するのであれば、こちらの方がよりデータを簡単に圧縮できます。テキストでは、ほぼ不可能です。
ギガバイト単位のgrepはスケールしない
私たちのセッションは、長期間、複数のマシンまたプロセスにまたがるでしょう。grepするほど小さいにも関わらず、必要な全てのデータを含むようなデータ保存することなんてできません。

もし、全ての処理が単一のファイルにログされているのであれば、サイズまたは時間ごとにファイルを分配する必要があるでしょう。この場合、あるセッションの全てのログを見つけるには、何ギガバイトもあるファイルを無駄に、何度もgrepしなくてはいけなくなります（なぜなら、例えばですが、セッションは1時間アイドルである場合もあるからです）。言うまでもなく、最初にすべきことは、セッションがいつ始まったかを確認することです。どこかにこの情報を保存していない限り、試行錯誤してこの情報を見つけなくてはなりません。

アプリケーションで分けた場合、手動でメッセージを紐付けしなければなりません。またいずれにしても、この場合も時間やサイズによる分割が必要です。

セッションごとに分ける場合は、あるユーザの全てのログを見つけるために多数のファイルを確認しなければいけません。そして、この場合も時間やサイズによる分割が必要です。セッションは多量のログを発生させるため、1つのファイル内に保存するのは非効率的です。

ログを複製し、異なる種類のクエリに対応するように違った方法で保存すると、あっという間にディスクの容量がなくなってしまいます。これは、やはり非効率的です。もっといい方法があるはずです。

使用例

大規模システムの詳細はお話しできませんが、私が個人的に実践しているログの、使い方をいくつかご紹介しましょう。

メールを追跡する

メールをGnusに組み込むようにしてからというもの（そしてこの時、そのために「message-id」が生成されました）、メールがシステムから離れるまでの過程を追うことが可能になりました。各ステージでかかった時間や、ヘッダに適用された変更、問題の有無などが確認できます。また、メールが送れず返ってくる場合も、同じクエリを使って確認することができます。

これは、少なくとも2つのマシンと3つのプログラムをまたいだ操作になります。
サイトYからサイトXに移動してきた訪問者が、サイトXで閲覧した全てのページを確認する

私が運営するサイトの中に、相互リンクを持つサイトがいくつかあります。そして、サイトYを経てサイトXに来た訪問者が、サイトXで何ページ閲覧するのかを知りたくなることがあります。

システムを使って、この対象となるページを探すことができます。システムはリファラがサイトYであるセッションの開始部分を探すことで、対象ページを見つけ、そのセッションのページをリストにしてくれます。
前日のユーザセッションで発生したログを確認する

前日のログを利用して何かをしたいとします。まずは、全てのログを見つけたいと思うのですが、私のログインセッションで開始したプログラムで生成されたログに限定することにします。また、私のユーザIDが使われていても、cronで開始されたセッションのログは返すべきではありません。Bansheeで生成されたログはフィルタをかけて除外します。これは多数のプログラムをまたぐことになります。
前月に母が訪問したサイトを調べる

前月は、どんなサイトを訪問したか調べて欲しいと、母に頼まれることがよくあります。母の要望に応えるため、私はロギングシステムを起動させます。これで、プロキシサーバのログをクエリし、母が自分のデバイスでログインしている間に訪問したサイトを調べることができます。

やり方は簡単で、以下のような記述になります。

program="proxy" and client="mom's device" date="2015-04-01 to 2015-05-01"

あまり難しいクエリではありませんが、これが次のクエリの基本になります。

直近の6週間で、母が1時間以上ブラウジングしたサイトを調べる

この場合、検索エンジンを使って、いくつかの訪問を集計しなければいけません。これには、少なくとも2カ月に渡り、膨大な数のセッションをまたぐものになります。

バイナリログに対する批判への反論

バイナリログは壊れやすい

まず、この説は正しくありません。もし、バイナリログが破損しても、append-only(追記のみ)であれば有効な部分を取り出すことができます。確かに、このためのツールが必要になりますが、大きな問題ではないでしょう。

バイナリログの優れているところは、損傷するとすぐに分かる点です。また、検証や暗号による署名なども容易です。

テキストログにも損傷する可能性はあります。私は何度も経験してきました。バイナリログの有効な部分を復旧するのは、ちっとも難しくありません。

バイナリログにはツールが必要だ

その通りです。しかし、その何が問題なのでしょう。テキストログにもツールは必要です。grepやlessなど、皆さんが使いたいものを使ってください。また、grepを使うためにログのフォーマットについて確認する必要があります。

バイナリログでは、検索しやすい方法で構造化データを保存するのがより簡単になります。特定のメールに関するログが必要な場合は、message-idフィールドを探すことが可能で、これによって取得できます。テキストログでは、message-idフィールドの記述にのみ一致する正規表現を構築しなければなりません。できないことはありませんが、少し手間ですね。

バイナリログは切り替えが困難だ

切り替え困難な解決策を利用しているなら、その通りです。切り替える必要はありません。

テキストはUnixで使用されている

そうですね。それはwtmpやutmpのようにでしょうか？　または、全てのデータベースのようにでしょうか？

テキストが有効なのは、マシンが1つで、多数の独立したアプリケーションがあり、それを異なるログファイルに分けることができる場合です。しかし、システム全体が対象で、相互依存するアプリケーションがある場合は、アドホッククエリを得るために、ログをインデックス化しなければいけません。

バイナリインデックスとテキストログの両方を使うことができる

その通りです。しかし、だからどうだというのでしょう。ログをクエリするのに特別なツールが必要なことに変わりはありません。バイナリストレージの利点を享受してみるのもいいでしょう。

バイナリログは新しく、一過性の流行にすぎない

この説には賛同できません。ログをSQLに保存するのが主流になってから10年以上が経ち、これが衰退することはないように思えます。非リレーショナルデータベースと検索エンジンの登場で、SQLでログを扱うようになったばかりの時代より、ログの保存や検索のツールは改善されています。

バイナリログは不明瞭だ

テキストログと大差はありません。テキストログはヒューマンリーダブルな形式になっていますが、読み方が分からなければ役に立ちません。アプリケーションの正確なロギングフォーマットを知っていればログを理解できますが、読み方が分からなければ、それは単語と記号の羅列でしかありません。

例えば以下のログで、どのフィールドがリファラか分かりますか？

127.0.0.1 - - [04/May/2015:16:02:53 +0200] "GET / HTTP/1.1" 304 0 "-" "Mozilla/5.0"

皆さんがどうかは分かりませんが、私はHTTP/1.1″ \d+ \d+ “-“よりもreferrer=”-“使う方が好きです。もちろん、ログを事前に処理してJSONなどに保存し、jq ‘.referer=”-“‘を使用することもできます。しかし、この方法だと大規模なログファイルを扱う場合に、処理速度がとても遅くなってしまいます。また、JSONもヒューマンリーダブルな形式ではないので、JSON内を検索する場合も特別なツールが必要になります。

テキストログの使い方を間違えている！

最も頻繁に耳にするのは、以下のようなことです。

“もしも1日に100ギガバイトのログがあるなら、何か間違ったことをしていますし、ログを多く取り過ぎています” 。失礼ですが、私たちがどのくらい、何をログすると決めるかは、あなたには関係のないことです。自分で決定しますし、私たちはそれだけの量を扱わなくてはいけないのです。

“grepしやすいように、ログを小さなファイルに分ければいいのです” 。はい、違いますね。ファイルサイズは問題ではありません。問題は、データの量です。grepするデータの量に制限をかける必要があるでしょう。何百ギガバイトという単位では大きすぎるからです。特に、反復して、検索を絞り込む（単に狭めるのではなく、おそらく拡張もして）場合にはそうです。先に挙げた大規模な構成の要件を見てください。ファイルを分割する合理的な方法がないので、私たちにはインデックスが必要です。

“正規表現を正確に学びなさい” 。おやまあ、どこから手をつけたらいいのでしょう？正規表現はテキストのマッチングには最適なのですが、私のデータはテキストではなく構造化された値のセットです。ですから私は、基本的には正規表現の記述も解析しなくてはならなくなります。あるいはgrepのように使え、かつより便利な、なにか特殊なツールが必要でしょう。どちらにしても反論がありそうです。率直に言わせてもらえば、2行の正規表現は、ヒューマンリーダブルではありません。そして2行というのは、私たちが行う（私たちが実際に試した）いくつかの検索のために必要になるであろう正規表現の標準的な長さです。検索を複数の段階に分割することで正規表現を簡単にすることができますが、それを行うと応答時間やリソースの使用に深刻な影響がありますから、そうはしないでしょう。

組み込みシステムには、リソースがありません

いくつかのシステムは関連づけられていないので、それぞれで検索エンジンを動作させたりログにインデックスをつけたりすることは莫大な時間を無駄にすることになります。その通りです。そしてテキスト形式のログストレージでもまったく問題ありません。それがあなたのものであれば。

私なら、それでもバイナリログストレージを使います。なぜならバイナリログは書いたり解析したりするのにより効果的だということが分かったからです。しかしこの場合、インデックスすることは役に立ちません。バイナリログを書くことができるsyslogは、できないものに比べても大きさは変わらず、更なるリソースを必要とすることもありません。より多くを必要とするのはログにアクセスするためのツールですが、このような小さいデータならlogcatプログラムが必要になるだけです。それはおそらく、lessでなければ15～20kBくらいでしょう。自身のログを保存するほとんどのデバイスでは、これはさほど大きくはありません。もしも大きいなら、そのデバイスにログを保存するべきではないでしょう。

テキストなら、ブラウズがより簡単になります

いえ、簡単にはなりません。lessを使ってログのブラウジングをするのは信じられないほど退屈ですし、非常に困難なプロセスです。非常に多くのログがある場合は特にそうでしょう。それに、バイナリログのブラウジングはちっとも大変ではありません。lessの代わりにlogcatや、それに似たものを使うでしょう。tail -fを使っているかのように追加されたキューを監視できますし、何だってできます。もしかしたら、また違った名前のツールを使う必要があるかもしれませんね。まぁ、なんと大きな問題でしょうか！

最後に言っておきたいこと

私がテキストベースのログストレージを使うのをやめてからのここ数年、生のテキストログの必要性を感じたことは、正確に数えると…一度もありません。私が利用している検索とブラウズのツールは、grepやlessの10倍は便利です。私は自分のログの構造を覚えておく必要がありませんし、その知識を全ての正規表現に応用する必要がありません。私のツールははるかに賢いのです。アラートに加えるべきイベントを探すのも簡単になりましたし、傾向を見るのも、持っているデータを理解するのも簡単になりました。

なぜでしょうか？　それは、私のためにコンピュータに仕事をさせ、それをより効率的にし、コンピュータが対処できるフォーマットでログを保存するからです。ともかく、私には必要がないので、生データは見ません。

私は怠け者なので、コンピュータが仕事をしてくれるなら、その恩恵を享受したいのです。やらなくて済むなら、正規表現を書くために指さえ持ち上げたくありません。その代わりに、より理解しやすいクエリ言語を求めます。

私と、テキストベースのログストレージの信奉者の主な違いを挙げますと、私は結果がヒューマンリーダブルであるクエリを求め、それがどのように作られるのかを気にしません。一方、信奉者たちはヒューマンリーダブルな生データを求め、データをテキスト形式で保存するために利便性を犠牲にするのです。

申し訳ありませんが、私は信条よりも利便性と効率を重視します。