パーサーが黙って何も取り出せないとき

一言でいうと

Lokiは本文をインデックス化しないので、本文の中の値で絞り込むには、クエリのたびにパーサーで取り出す必要があります。パーサーは失敗すると__error__ラベルを付けますが、何も取り出せなくてもエラーを出さないパーサーがあります。

なぜ必要なのか

あるチームが、決済サービスのエラー率をLokiで測っていました。クエリは{app="pay"} | logfmt | status="500"で、ダッシュボードは数か月間、平穏でした。ところが、障害対応の会議で、同じ時間帯の実際の5xxの件数を数えてみたところ、ダッシュボードの数字の3倍でした。

原因は単純でした。そのサービスの一部の経路が、JSONでログを出力していたのです。logfmtパーサーは、JSONの行に出会ってもエラーを出しません。ただ何のラベルも取り出せないまま通り過ぎます。ラベルがなければstatus="500"は偽になり、その行は静かに抜け落ちます。ダッシュボードには「データなし」も「パースエラー」も表示されません。ただ数字が小さくなるだけです。

どう動くのか

LogQLのパーサーは4つです。すべてセレクターと行フィルターの後ろに付き、クエリのたびにその行を読み直してラベルを作ります。

パーサー	読む形式	失敗したとき
logfmt	키=값(プレースホルダーはキーと値です)が空白でつながった行	エラーなしで何も取り出しません
json	JSONオブジェクト1行	__error__="JSONParserErr"を付けます
pattern	<이름>(プレースホルダーは名前です)で取り出す位置を示した固定の形	形が違うと取り出しません
regexp	名前付きキャプチャグループを持つRE2	合わないと取り出しません

そのため、調査は常に2方向で行う必要があります。まず| json | __error__!=""で、壊れた行がどれだけあるかを数え、次に| logfmt | status=""で、エラーはないのに値が出なかった行がどれだけあるかを数えます。2つの数字がどちらも0であって初めて、そのストリームのパーサーを信頼できます。

パースエラーが出た行を消したければ| __error__=""を付けます。しかし、習慣的に付けてはいけません。その行こそが「形式の異なるログが混ざっている」というサインだからです。まず数え、原因を知り、そのあとで消します。

抽出されたラベルは、そのクエリの中でだけ生きます。保存もされず、インデックス化もされません。そのため、パーサーを変えると、過去のデータも一緒に解釈し直されます。メトリクスとは正反対です。メトリクスは計装を間違えると、過去が永遠に失われますが、ログは本文さえ残っていれば、あとから別の見方で読み直せます。これが「インデックス化しない」という選択がもたらす最大の利点です。

値は常に文字列です。| dur_ms > 500のように比較しようとすると、LogQLが数値に変換してくれますが、単位が混ざっていると(ミリ秒と秒が1つのフィールドに)、静かに間違った答えが出ます。数値を入れるフィールドは、名前に単位を入れておくほうが安全です。

現場での姿

最もよくある事故は「1つのストリームに2つの形式」です。アプリケーションはJSONで出力しているのに、その前のプロキシやランタイムが、平文の警告を同じstdoutに混ぜて入れてきます。ストリームラベルは同じなので1つのストリームであり、クエリは1つのパーサーしか使えません。

解決策はクエリではなく配置にあります。形式の異なるログは、ラベルを変えて別のストリームに送ります。コレクターで一度分けておけば、クエリは単純になり、パーサーエラーも消えます。それができないレガシーなら、少なくともパーサーごとに別々に数えて合算するクエリを作っておき、その事実をダッシュボードの横に書いておきます。

もう1つ。patternパーサーはregexpより速くて読みやすいので、アクセスログのように位置が固定された行には、ほとんど常にこちらのほうが優れています。正規表現は、位置が揺れる行にだけ使います。

次のラボですること

3つの形式が混ざったストリーム1つと、形式がきれいなストリーム1つを、Pod内の本物のLokiに入れ、4つのパーサーを順に付けてみます。jsonがエラーを出す行数と、logfmtが静かに通り過ぎた行数をそれぞれ数え、patternとregexpでレガシーの行から値を取り出したあと、最後に、形式ごとに別々に数えて合算して初めて出てくる、本当の5xx件数を求めます。