ログは全部あったのに、何を尋ねればよいか分からなかった

目標

Pod内の本物のLokiにLogQLを自分で投げて、ストリームセレクターと行フィルターで目的の行だけを取り出し、返ってきたJSONの形まで読めるようになります。

なぜ重要なのか

Lokiに問いを投げる作業は、2つの層に分かれます。まずセレクターがどのストリームのチャンクを読むかを決め、次に行フィルターが、読んできた行を1つずつ照合します。この順序を知らないと、「なぜこのクエリは速く、あのクエリは遅いのか」を、いつまでも説明できません。本文はインデックス化されていないため、行フィルターはセレクターが選んだ分をすべて読みます。そのため、インシデント調査で最初に行うのは、セレクターと時間区間を絞ることです。limitとdirectionも、インシデント調査の結果を変えます。方向を知らずにlimitをかけると、最も重要な最初のエラーではなく、最後のエラーだけを見ることになります。

ステップ

/root/lk-logqlでLokiを起動し、date +%sの値を/root/lk-logql/anchor.txtに1行で書いたあと、python3 /opt/lab/d5/gen.py logql "$(cat anchor.txt)"でデータを入れてください。そして、現在Lokiにストリームがいくつあるかを数えて、/root/lk-logql/01-boot.txtにstreams=<정수>の1行で書いてください(プレースホルダーは整数です)。
基準時刻から過去1時間の間に、appがwebでlevelがerrorの行が何行あるかを求めてください。書いたクエリを/root/lk-logql/02-selector.logqlに、行数を/root/lk-logql/02-selector.txtにlines=<정수>の1行で書きます(プレースホルダーは整数です)。
同じ1時間の間に、3つのサービス(web・api・worker)全体で、本文にtimeoutが入っている行が何行あるかを求めてください。クエリは/root/lk-logql/03-line.logql、答えは/root/lk-logql/03-line.txtにlines=<정수>で書きます(プレースホルダーは整数です)。
3つのサービス全体で、本文にrefusedが入っていて、rpcは入っていない行を数えてください。クエリは/root/lk-logql/04-chain.logql、答えは/root/lk-logql/04-chain.txtにlines=<정수>で書きます(プレースホルダーは整数です)。
3つのサービス全体で、本文に500または503という3桁の数字が入っている行を、正規表現の行フィルター1つで数えてください。クエリは/root/lk-logql/05-regex.logql、答えは/root/lk-logql/05-regex.txtにlines=<정수>で書きます(プレースホルダーは整数です)。クエリには、正規表現の行フィルター演算子が必ず入っている必要があります。
{app="web",level="error"}を同じ1時間の区間に、limit=5で2回クエリしてください。1回はdirection=forward、もう1回はdirection=backwardです。結果を/root/lk-logql/06-order.txtに3行で書きます。forward_first=<나노초 타임스탬프>、backward_first=<나노초 타임스탬프>、total=<구간 전체 줄 수>です(プレースホルダーは順に、ナノ秒のタイムスタンプ、ナノ秒のタイムスタンプ、区間全体の行数です)。
どのログクエリでもよいので1回投げて、元のJSONを見て、/root/lk-logql/07-shape.txtに3行を書いてください。result_type=の後ろにはdata.resultTypeの値、ts_unit=の後ろにはvaluesの最初の欄がどの時間単位か(ns・us・ms・sのいずれか)、entry_len=の後ろにはvaluesの要素1つが何個分の配列かを整数で書きます。
webとapiの2つのサービスで、本文にtimeoutまたはrefusedが入っている行だけを選び、そのうち最も早い行のナノ秒タイムスタンプと、全体の行数を求めてください。クエリは/root/lk-logql/08-triage.logql、答えは/root/lk-logql/08-triage.txtにlines=<정수>とfirst_ts=<나노초>の2行で書きます(プレースホルダーは整数と、ナノ秒のタイムスタンプです)。クエリには正規表現の行フィルターが入っている必要があり、workerは入ってはいけません。

参考

作業ディレクトリは/root/lk-logqlです。LokiはPodが起動しても自動では起動しません。ステップ1で自分で起動します。
データ生成器は/opt/lab/d5/gen.pyです。logqlデータを、基準時刻の引数とともに実行します。採点ツールは読まないので、内容を直す必要はありません。
クエリはlogcliでも投げられます: LOKI_ADDR=http://localhost:3100 logcli query --limit=5 '{app="web"}'。ただし、このラボの答えは絶対区間で測る必要があるため、query_range APIを直接呼ぶほうが正確です。
よくある間違い: since=1hで測ってしまいます。時間が経つと答えが変わり、再採点で落ちます。anchor.txtの基準時刻でstart・endを指定してください。
よくある間違い: 行フィルターの文字列を二重引用符で囲んでしまいます。LogQLではバッククォートが安全です。バックスラッシュがエスケープとして解釈されません。
LogQL概要・ログクエリ・HTTP API・ラベル

Lokiを起動して、1日分ではなく1時間分を入れる

/root/lk-logqlでLokiを起動し、date +%sの値を/root/lk-logql/anchor.txtに1行で書いたあと、python3 /opt/lab/d5/gen.py logql "$(cat anchor.txt)"でデータを入れてください。そして、現在Lokiにストリームがいくつあるかを数えて、/root/lk-logql/01-boot.txtにstreams=<정수>の1行で書いてください(プレースホルダーは整数です)。

設定は/opt/lab/loki/loki.yamlをコピーして使います。/readyがreadyを返すまで20秒ほどかかるので、固定のsleepの代わりに、条件を見るループを使ってください。ストリーム数は/opt/lab/loki/streams.shが数えてくれます。ストリームは、異なるラベルの組み合わせの個数です。

セレクターだけで見る場所を決める

基準時刻から過去1時間の間に、appがwebでlevelがerrorの行が何行あるかを求めてください。書いたクエリを/root/lk-logql/02-selector.logqlに、行数を/root/lk-logql/02-selector.txtにlines=<정수>の1行で書きます(プレースホルダーは整数です)。

ストリームセレクターは、波括弧の中のラベルマッチャーです。条件をカンマでつなぐと、両方を満たすストリームだけを選びます。区間はstart・endをナノ秒で指定してください。anchor.txtの値に1000000000を掛けるとナノ秒になります。

行フィルターで本文を探す

同じ1時間の間に、3つのサービス(web・api・worker)全体で、本文にtimeoutが入っている行が何行あるかを求めてください。クエリは/root/lk-logql/03-line.logql、答えは/root/lk-logql/03-line.txtにlines=<정수>で書きます(プレースホルダーは整数です)。

行フィルターはセレクターの後ろに来ます。文字列をそのまま探す演算子と、正規表現で探す演算子は別です。本文はインデックス化されていないので、行フィルターは、セレクターが選んだストリームの行をすべて読みながら照合します。

フィルターをつなげてふるい分ける

3つのサービス全体で、本文にrefusedが入っていて、rpcは入っていない行を数えてください。クエリは/root/lk-logql/04-chain.logql、答えは/root/lk-logql/04-chain.txtにlines=<정수>で書きます(プレースホルダーは整数です)。

行フィルターは複数をつなげて書け、左から順に適用されます。「入っていない」を意味する演算子が別にあります。2つの条件を1つの正規表現にまとめようとしないでください。否定は、つなげて書くほうが読みやすいです。

正規表現の行フィルター

3つのサービス全体で、本文に500または503という3桁の数字が入っている行を、正規表現の行フィルター1つで数えてください。クエリは/root/lk-logql/05-regex.logql、答えは/root/lk-logql/05-regex.txtにlines=<정수>で書きます(プレースホルダーは整数です)。クエリには、正規表現の行フィルター演算子が必ず入っている必要があります。

正規表現の行フィルターは、RE2の文法です。文字1つが複数の値のうちのどれかでありうる、ということを、角括弧で書きます。2つの|=をつなげて書くと「両方が入っている行」になり、答えが変わります。

limitとdirection: 何が切り捨てられるか

{app="web",level="error"}を同じ1時間の区間に、limit=5で2回クエリしてください。1回はdirection=forward、もう1回はdirection=backwardです。結果を/root/lk-logql/06-order.txtに3行で書きます。forward_first=<나노초 타임스탬프>、backward_first=<나노초 타임스탬프>、total=<구간 전체 줄 수>です(プレースホルダーは順に、ナノ秒のタイムスタンプ、ナノ秒のタイムスタンプ、区間全体の行数です)。

limitは「前から何行」ではなく、「ソート方向を基準に何行」です。方向を変えると、同じlimitが正反対の行を返します。インシデント調査でこれを知らないと、最も重要な最初のエラーを見逃し、最後のエラーだけを見ることになります。全体の行数は、limitを十分に大きく指定して数えます。

返ってきたJSONを読む

どのログクエリでもよいので1回投げて、元のJSONを見て、/root/lk-logql/07-shape.txtに3行を書いてください。result_type=の後ろにはdata.resultTypeの値、ts_unit=の後ろにはvaluesの最初の欄がどの時間単位か(ns・us・ms・sのいずれか)、entry_len=の後ろにはvaluesの要素1つが何個分の配列かを整数で書きます。

curl ... | jq .でそのまま見ます。ログクエリとメトリクスクエリでは、resultTypeが異なります。タイムスタンプの桁数を数えると、単位がわかります。epochの秒は10桁です。この形を知っていて初めて、自動化スクリプトを書けます。

応用: 1つのクエリでインシデントの区間を絞る

webとapiの2つのサービスで、本文にtimeoutまたはrefusedが入っている行だけを選び、そのうち最も早い行のナノ秒タイムスタンプと、全体の行数を求めてください。クエリは/root/lk-logql/08-triage.logql、答えは/root/lk-logql/08-triage.txtにlines=<정수>とfirst_ts=<나노초>の2行で書きます(プレースホルダーは整数と、ナノ秒のタイムスタンプです)。クエリには正規表現の行フィルターが入っている必要があり、workerは入ってはいけません。

セレクターで2つのサービスだけを選ぶマッチャーと、どちらか一方を探す正規表現を、一緒に使います。最も早い行を見つけるには、ソート方向を前方にするか、受け取った結果を自分でソートします。これがインシデント調査の最初の動作です。範囲を絞り、開始時刻を固定する作業です。