障害の開始時刻を四十分遅く報告してしまった

目標

Lokiのクエリ上限を自分で超えてみながら、静かに切られる場合と、400で拒否される場合を見分け、上限の範囲内で広い区間を漏れなくスキャンする方法を作ります。

なぜ重要なのか

ログクエリの結果数は、3つのつまみが決めます。リクエストのlimitは静かに切り、サーバーのmax_entries_limit_per_queryとmax_query_lengthは400で拒否します。拒否はすぐに見えますが、静かに切られた答えは「これで全部」のように見えます。さらに、directionが何が切り捨てられるかを決めるので、デフォルトのbackwardでインシデントの開始を探すと、まさに見つけたいものが切り捨てられます。広い区間をスキャンする必要があるときの答えは、上限を引き上げることではなく、区間を切って何度も尋ねて合算することです。各断片が上限より小さいことが、合計を信頼できるものにします。

ステップ

/root/lk-query-limitsでLokiを起動し、date +%sを/root/lk-query-limits/anchor.txtに書いたあと、python3 /opt/lab/d5/gen.py querylimits "$(cat anchor.txt)"でデータを入れてください。そして、{app="gateway"}を基準時刻から過去2時間の区間でログクエリして、全体の行数を/root/lk-query-limits/01-total.txtにtotal=<정수>の1行で書いてください(プレースホルダーは整数です)。limitは5000を指定し、返ってきた数がその値より小さいかを、必ず確認してください。
同じ2時間の区間をlimit=100、direction=backwardでログクエリして、返ってきた行数と、そのうち最も早い行のナノ秒タイムスタンプを、/root/lk-query-limits/02-cut.txtに2行で書いてください。returned=<정수>とoldest_ts=<나노초>です(プレースホルダーは整数と、ナノ秒のタイムスタンプです)。レスポンスのどこにも「切られた」という表示がないことを、自分で確認してください。
同じクエリをlimit=6000で投げてみてください。レスポンスのステータスコードと、本文に書かれた上限値、そしてサーバーの/configから読んだその設定の値を、/root/lk-query-limits/03-entries.txtに3行で書いてください。code=<정수>、limit_in_body=<정수>、limit_in_config=<정수>です(プレースホルダーは整数です)。
同じクエリを60日の区間で投げてみてください。ステータスコードと、サーバーの/configの区間の長さの上限を、/root/lk-query-limits/04-length.txtに3行で書きます。code=<정수>、param=<설정 이름>、value=<서버가 찍은 값 그대로>です(プレースホルダーは整数、設定名、サーバーが出力した値そのままです)。
同じクエリを2時間の区間と30分の区間でそれぞれ投げて、レスポンス統計のsplitsを測り、サーバーの断片間隔の設定も読んで、/root/lk-query-limits/05-splits.txtに3行で書いてください。splits_2h=<정수>、splits_30m=<정수>、interval=<서버가 찍은 값 그대로>です(プレースホルダーは整数、整数、サーバーが出力した値そのままです)。
limitを50・500・5000の3回指定して同じクエリを投げ、結果を/root/lk-query-limits/detect.tsvに、ヘッダーなしで3行、タブで区切った3つの欄<limit><탭><returned><탭><truncated>(プレースホルダーはタブです)で書いてください。truncatedはyesまたはnoで、判定基準は、ステップ1で求めた本当の合計です。
/root/lk-query-limits/scan.shを作成して、2時間の区間を30分ずつ4つの断片に分けて、それぞれクエリし、合計を出してください。各断片はlimit=5000で投げ、断片の結果数がlimitと同じなら、INCOMPLETEも一緒に出力する必要があります。スクリプトを実行した結果を、/root/lk-query-limits/07-scan.txtにsum=<정수>とchunks=4の2行で書きます(プレースホルダーは整数です)。合計は、ステップ1の合計と同じである必要があります。
2時間の区間でstatus=500の行のうち直近50件を取得するクエリを設計して、/root/lk-query-limits/08-latest.txtに3行で書いてください。returned=<정수>、newest_ts=<나노초>、oldest_ts=<나노초>です(プレースホルダーは整数、ナノ秒のタイムスタンプ、ナノ秒のタイムスタンプです)。50件より少なければ、ある分だけ出れば済みます。

参考

作業ディレクトリは/root/lk-query-limitsです。Lokiはステップ1で自分で起動します。
データ生成器は/opt/lab/d5/gen.pyで、querylimitsデータを書き込みます。採点ツールはこのファイルを読みません。
400レスポンスの本文を捨てないでください。どの上限をどれだけ超えたかが、数字まで書かれて出てきます。curl -w '\n%{http_code}'で本文とコードを一緒に受け取ると便利です。
行数を正確に数える必要があるときは、ログクエリの代わりにsum(count_over_time(...))のメトリクスクエリを使ってください。メトリクスクエリにはlimitが適用されません。
よくある間違い: 区間を分割するとき、境界を重ねたり、漏らしたりしてしまいます。左端を含み、右端を除く形に合わせると、合計が正確になります。
HTTP API・設定ドキュメント・リクエスト検証とレート制限・ログクエリ

2時間分を入れて、本当の合計を求める

/root/lk-query-limitsでLokiを起動し、date +%sを/root/lk-query-limits/anchor.txtに書いたあと、python3 /opt/lab/d5/gen.py querylimits "$(cat anchor.txt)"でデータを入れてください。そして、{app="gateway"}を基準時刻から過去2時間の区間でログクエリして、全体の行数を/root/lk-query-limits/01-total.txtにtotal=<정수>の1行で書いてください(プレースホルダーは整数です)。limitは5000を指定し、返ってきた数がその値より小さいかを、必ず確認してください。

返ってきた数がlimitと同じなら、切られたという意味なので、合計として使えません。小さければ、その区間をすべて受け取ったことになります。この数字が、後のステップの間ずっと、「切られたか」を判定する基準になります。メトリクスクエリ(sum(count_over_time(...[2h])))でも数えられますが、範囲集計は区間の左端を含まないため、1行ほど違って出ることがあります。

limitは、何も言わずに切る

同じ2時間の区間をlimit=100、direction=backwardでログクエリして、返ってきた行数と、そのうち最も早い行のナノ秒タイムスタンプを、/root/lk-query-limits/02-cut.txtに2行で書いてください。returned=<정수>とoldest_ts=<나노초>です(プレースホルダーは整数と、ナノ秒のタイムスタンプです)。レスポンスのどこにも「切られた」という表示がないことを、自分で確認してください。

backwardは、最近のものから埋めます。そのため、返ってきた100行の最も早い時刻は、区間の開始ではなく、ずっと後ろです。この値をインシデントの開始時刻として報告するとどうなるか、考えてみてください。

サーバーの上限は、はっきり拒否する

同じクエリをlimit=6000で投げてみてください。レスポンスのステータスコードと、本文に書かれた上限値、そしてサーバーの/configから読んだその設定の値を、/root/lk-query-limits/03-entries.txtに3行で書いてください。code=<정수>、limit_in_body=<정수>、limit_in_config=<정수>です(プレースホルダーは整数です)。

400の本文は親切です。どの上限をどれだけ超えたかが、数字まで書かれています。/configのlimits_configから同じ名前を探して、2つの値が同じかを確認してください。自動化でこの本文を捨てて、ステータスコードだけを残すと、あとで原因を探せなくなります。

区間が長すぎても拒否する

同じクエリを60日の区間で投げてみてください。ステータスコードと、サーバーの/configの区間の長さの上限を、/root/lk-query-limits/04-length.txtに3行で書きます。code=<정수>、param=<설정 이름>、value=<서버가 찍은 값 그대로>です(プレースホルダーは整数、設定名、サーバーが出力した値そのままです)。

startを60日前に指定すれば済みます。本文に、クエリの長さと上限が並んで書かれて出てきます。/configのlimits_configから同じ名前を探してください。値の表記が本文と違うことがあります。

クエリは時間の断片に分割されて動く

同じクエリを2時間の区間と30分の区間でそれぞれ投げて、レスポンス統計のsplitsを測り、サーバーの断片間隔の設定も読んで、/root/lk-query-limits/05-splits.txtに3行で書いてください。splits_2h=<정수>、splits_30m=<정수>、interval=<서버가 찍은 값 그대로>です(プレースホルダーは整数、整数、サーバーが出力した値そのままです)。

splitsはdata.stats.summaryにあります。断片の数が、区間の長さと設定値からどう出るかを計算してみてください。短い区間で0が出ることにも、意味があります。

切られたかに気づく方法

limitを50・500・5000の3回指定して同じクエリを投げ、結果を/root/lk-query-limits/detect.tsvに、ヘッダーなしで3行、タブで区切った3つの欄<limit><탭><returned><탭><truncated>(プレースホルダーはタブです)で書いてください。truncatedはyesまたはnoで、判定基準は、ステップ1で求めた本当の合計です。

返ってきた行数がlimitと同じなら、ほぼ確実に切られていて、合計より小さければ、確実に切られています。2つの基準がずれる場合があるかも考えてみてください。合計と同じ数を受け取ったなら、limitと同じでも、切られてはいません。

応用①: 区間を分割して、漏れなく数える

/root/lk-query-limits/scan.shを作成して、2時間の区間を30分ずつ4つの断片に分けて、それぞれクエリし、合計を出してください。各断片はlimit=5000で投げ、断片の結果数がlimitと同じなら、INCOMPLETEも一緒に出力する必要があります。スクリプトを実行した結果を、/root/lk-query-limits/07-scan.txtにsum=<정수>とchunks=4の2行で書きます(プレースホルダーは整数です)。合計は、ステップ1の合計と同じである必要があります。

各断片の開始と終了を、重ならないように取ることが核心です。境界の1秒を2つの断片が一緒に数えると合計が大きくなり、漏らすと小さくなります。区間の左端を含み、右端を除く形に合わせると、すっきりします。

応用②: 直近のエラー50件を正確に取得する

2時間の区間でstatus=500の行のうち直近50件を取得するクエリを設計して、/root/lk-query-limits/08-latest.txtに3行で書いてください。returned=<정수>、newest_ts=<나노초>、oldest_ts=<나노초>です(プレースホルダーは整数、ナノ秒のタイムスタンプ、ナノ秒のタイムスタンプです)。50件より少なければ、ある分だけ出れば済みます。

方向とlimitを一緒に決める必要があります。「直近」がほしいときの方向と、ステップ2でインシデントの開始を探すときに必要だった方向が、互いに逆であることが、このラボの要点です。返ってきた数がlimitと同じかも、あわせて確認してください。