デバッグログを入れた日に、調査に必要な行が消えた

目標

固定されたログファイル1つでレベルごとのコスト表を作り、リクエスト単位のサンプリング・エラーの保持・繰り返しの折りたたみ・1秒あたりの上限を自分で実装して、コストと調査可能性のトレードオフを数字にしたうえで、ポリシーファイルとして固定します。

なぜ重要なのか

ログのコストを減らせという要求は、必ず来ます。そのとき最も簡単な答えが「レベルを上げる」と「サンプルを選ぶ」ですが、どちらも誤ると、コストだけが減って調査能力は0になります。人が調査するときに読む単位は行ではなく、1つのリクエストが残した行のまとまりだからです。行単位で10%を残すと、どのリクエストも最後まで読めませんが、リクエスト単位で10%を残せば、その10%は完全です。ここに「エラーで終わったリクエストは除外しない」というルールを1つ加えると、コストはほぼそのままで、失敗したリクエストの保持率が0%から100%に上がります。このラボで作る表は、次回のコスト会議でそのまま使える根拠です。

ステップ

用意されたログは/opt/lab/logsample/app.logです。行の形式は<시각> <수준> req=<id> handler=<경로> msg="<메시지>"で、レベルはDEBUG・INFO・WARN・ERRORの4つです(プレースホルダーは時刻、レベル、id、パス、メッセージです)。/root/obs-log-sampling/cost.tsvに、ヘッダーなしで4行、各行はタブで区切った3列<수준> <줄 수> <바이트>を書いてください(プレースホルダーはレベル、行数、バイト数です)。バイトは、そのレベルの行が占めるバイト数で、改行文字1つを含みます。
DEBUGの行をすべて捨てたときの結果を、/root/obs-log-sampling/drop-debug.txtに6行で書いてください。kept_lines=<남은 줄 수>、kept_bytes=<남은 바이트>、saved_pct=<바이트 기준 절감률, 소수 두 자리>、req=<오류로 끝난 요청 중 request_id 가 사전순으로 가장 앞선 것>、req_lines_before=<그 요청의 원래 줄 수>、req_lines_after=<DEBUG 를 뺀 뒤 그 요청에 남은 줄 수>です(プレースホルダーは、残りの行数、残りのバイト数、バイト基準の削減率で小数第2位まで、エラーで終わったリクエストのうちrequest_idが辞書順で最も前のもの、そのリクエストの元の行数、DEBUGを除いたあとにそのリクエストに残った行数です)。「エラーで終わったリクエスト」は、レベルがERRORの行を1つ以上持つリクエストです。
/root/obs-log-sampling/sample.pyを作成してください。python3 sample.py --rate N < 입력 > 출력で呼び出すと(プレースホルダーは入力と出力です)、標準入力の行を読んで、残す行だけをそのまま標準出力に書きます(入力の順序は維持)。残す基準はリクエスト単位です。行のreq=の値をrとしたとき、int(hashlib.md5(r.encode()).hexdigest()[:8], 16) % N == 0ならその行を残します。--rate 1はすべて残します。そのあとpython3 sample.py --rate 10 < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10.logで、結果ファイルを作成してください。
/root/obs-log-sampling/sample.pyに、--keep-errorsオプションを加えてください。このオプションがあると、レベルがERRORの行を1つでも持つリクエストは、サンプリング率に関係なくすべての行を残します(入力の順序は維持)。オプションがないときの動作は、ステップ3と同じでなければなりません。そのあとpython3 sample.py --rate 10 --keep-errors < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10-err.logで、結果を作成してください。
サンプリング率Nを1・4・10・50に変えながら、/root/obs-log-sampling/tradeoff.tsvを作成してください。ヘッダーなしで4行、各行はタブで区切った5列<N> <표본만 썼을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수> <오류 보존까지 켰을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수>です(プレースホルダーは、サンプルだけを使ったときに残った行数、そのとき完全に残ったエラーリクエスト数、エラーの保持まで有効にしたときに残った行数、そのとき完全に残ったエラーリクエスト数です)。「完全に残ったエラーリクエスト」は、エラーで終わったリクエストのうち、結果ファイルに行が1つでも残っているリクエストを数えます。
/root/obs-log-sampling/squeeze.pyを作成してください。python3 squeeze.py [--max-debug-per-sec K] < 입력 > 출력(Kのデフォルトは20)で呼び出すと(プレースホルダーは入力と出力です)、2つのルールを順に適用します。①直前の行と(レベル、handler、msg)がすべて同じなら1つのまとまりと見て最初の行だけを残し、まとまりの行数kが2以上なら、その行の末尾に repeated=<k>を付けます。②折りたたんだあと、DEBUG行だけを、同じ秒(時刻文字列の先頭19文字)の中で先頭からK個まで残し、残りは捨てます。そのあとpython3 squeeze.py < /opt/lab/logsample/app.log > /root/obs-log-sampling/squeezed.logを作成し、/root/obs-log-sampling/squeeze.txtに4行in_lines=、after_collapse=、after_cap=、bytes_saved_pct=<소수 두 자리>を書いてください(プレースホルダーは小数第2位です)。
sample.py --rate 10 --keep-errorsの出力を、squeeze.py(デフォルトの上限)にそのまま流して、/root/obs-log-sampling/final.logを作成してください。そして/root/obs-log-sampling/final.txtに8行を書いてください。in_lines=、out_lines=、in_bytes=、out_bytes=、reduction_pct=<바이트 기준, 소수 두 자리>、error_requests_kept=<final.log 에 줄이 남아 있는 오류 요청 수>、trace_req=<2단계에서 고른 그 요청 id>、trace_lines=<final.log 에 남은 그 요청의 줄 수>です(プレースホルダーは、バイト基準で小数第2位まで、final.logに行が残っているエラーリクエスト数、ステップ2で選んだそのリクエストのid、final.logに残ったそのリクエストの行数です)。
/root/obs-log-sampling/policy.ymlをYAMLで書いてください。levelsの下に、DEBUG・INFO・WARN・ERRORの4つのレベルごとに、retain_days(整数)とsample_rate(整数)を置きます。ERRORのsample_rateは1である必要があり、retain_daysはDEBUGより大きくなければなりません。DEBUGのsample_rateは2以上でなければなりません。rulesの下には、keep_errors_whole_request: true、collapse_repeats: true、max_debug_per_sec(ステップ6で使ったデフォルト値)を置きます。estimateの下には、raw_bytes・kept_bytes・reduction_pctを、ステップ7の結果と同じ値で書き、最後にnoteとして、このポリシーのトレードオフを40文字以上の1文で書いてください。

参考

作業ディレクトリは/root/obs-log-samplingです。なければ先に作成してください。
用意されたログは/opt/lab/logsample/app.logです(約8,280行・795KiB)。固定されたファイルなので、何度実行しても同じ答えが出ます。作り方は、同じディレクトリのgen_log.pyにあります。
行の形式は<시각> <수준> req=<id> handler=<경로> msg="<메시지>"で、空白で区切った2番目の列がレベルです(プレースホルダーは時刻、レベル、id、パス、メッセージです)。
フィルターは、標準入力を読んで標準出力に書くプログラムとして作ってください。そうすればパイプでつなげます。
Lokiは起動しないでください。このラボが扱うのは、ストレージに入れる前に、アプリケーションが出力する行そのものを選ぶことです。
よくある間違い: サンプルを行番号で選んでしまうこと。1つのリクエストが半分に割れて、何も再構成できなくなります。
よくある間違い: 1秒あたりの上限を、レベルの区別なしにかけてしまうこと。急増するその瞬間にERRORが切り落とされます。
Logs (OpenTelemetry)・Logs Data Model (OTel仕様)・hashlib (Python標準ライブラリ)・Effective Troubleshooting (SRE Book第12章)・Monitoring (SRE Workbook第4章)

レベルごとにいくら使っているかから数える

用意されたログは/opt/lab/logsample/app.logです。行の形式は<시각> <수준> req=<id> handler=<경로> msg="<메시지>"で、レベルはDEBUG・INFO・WARN・ERRORの4つです(プレースホルダーは時刻、レベル、id、パス、メッセージです)。/root/obs-log-sampling/cost.tsvに、ヘッダーなしで4行、各行はタブで区切った3列<수준> <줄 수> <바이트>を書いてください(プレースホルダーはレベル、行数、バイト数です)。バイトは、そのレベルの行が占めるバイト数で、改行文字1つを含みます。

レベルは、空白で区切った2番目の列です。awk '{print $2}'で取り出せます。バイトは、awk '{n[$2]++; b[$2]+=length($0)+1}'のように、行の長さに1を足して集計すればよいのです。4つの数字の比率が、このラボの出発点です。どのレベルが量の大部分を占めているかを見てください。

DEBUGを切ると、何が残り、何が消えるか

DEBUGの行をすべて捨てたときの結果を、/root/obs-log-sampling/drop-debug.txtに6行で書いてください。kept_lines=<남은 줄 수>、kept_bytes=<남은 바이트>、saved_pct=<바이트 기준 절감률, 소수 두 자리>、req=<오류로 끝난 요청 중 request_id 가 사전순으로 가장 앞선 것>、req_lines_before=<그 요청의 원래 줄 수>、req_lines_after=<DEBUG 를 뺀 뒤 그 요청에 남은 줄 수>です(プレースホルダーは、残りの行数、残りのバイト数、バイト基準の削減率で小数第2位まで、エラーで終わったリクエストのうちrequest_idが辞書順で最も前のもの、そのリクエストの元の行数、DEBUGを除いたあとにそのリクエストに残った行数です)。「エラーで終わったリクエスト」は、レベルがERRORの行を1つ以上持つリクエストです。

辞書順で最も前のIDは、grep ' ERROR ' | grep -o 'req=[0-9a-f]*' | sort -u | head -1で見つけられます。そのリクエストの行だけを見るには、grep 'req=<id>'とすればよいのです(プレースホルダーはidです)。残った行数ではなく、そのリクエストの流れを読めるかが、このステップの問いです。

行ではなくリクエストをサンプルとして選ぶ

/root/obs-log-sampling/sample.pyを作成してください。python3 sample.py --rate N < 입력 > 출력で呼び出すと(プレースホルダーは入力と出力です)、標準入力の行を読んで、残す行だけをそのまま標準出力に書きます(入力の順序は維持)。残す基準はリクエスト単位です。行のreq=の値をrとしたとき、int(hashlib.md5(r.encode()).hexdigest()[:8], 16) % N == 0ならその行を残します。--rate 1はすべて残します。そのあとpython3 sample.py --rate 10 < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10.logで、結果ファイルを作成してください。

判定を行ではなくリクエストにかけるので、1つのリクエストの行がまるごと残るか、まるごと消えます。それがこのフィルターのすべてです。結果ファイルから任意のrequest_idを選んでgrepしてみると、元のファイルと行数が同じです。ハッシュの方式は、課題に書かれたとおりに使う必要があります。採点ツールが同じルールで再計算して、行単位で突き合わせます。

エラーで終わったリクエストは、サンプルから外さない

/root/obs-log-sampling/sample.pyに、--keep-errorsオプションを加えてください。このオプションがあると、レベルがERRORの行を1つでも持つリクエストは、サンプリング率に関係なくすべての行を残します(入力の順序は維持)。オプションがないときの動作は、ステップ3と同じでなければなりません。そのあとpython3 sample.py --rate 10 --keep-errors < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10-err.logで、結果を作成してください。

どのリクエストがエラーで終わったかは、ファイルを最後まで読まないとわからないので、2回走査する必要があります。最初にERROR行のrequest_idを集め、そのあと行を走査し直して判定します。このルールを入れると、行数がどれだけ増えるかを、ステップ3の結果と比べてみてください。思ったより少ししか増えません。

サンプリング率と調査可能性のトレードオフを表にする

サンプリング率Nを1・4・10・50に変えながら、/root/obs-log-sampling/tradeoff.tsvを作成してください。ヘッダーなしで4行、各行はタブで区切った5列<N> <표본만 썼을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수> <오류 보존까지 켰을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수>です(プレースホルダーは、サンプルだけを使ったときに残った行数、そのとき完全に残ったエラーリクエスト数、エラーの保持まで有効にしたときに残った行数、そのとき完全に残ったエラーリクエスト数です)。「完全に残ったエラーリクエスト」は、エラーで終わったリクエストのうち、結果ファイルに行が1つでも残っているリクエストを数えます。

sample.pyをオプションだけ変えて8回実行すればよいのです。エラーリクエスト数は、grep ' ERROR ' <결과> | grep -o 'req=[0-9a-f]*' | sort -u | wc -lで数えられます(プレースホルダーは結果ファイルです)。3列目がどこで0になるか、そしてそのとき4列目が2列目よりどれだけ増えるかを見てください。

繰り返しを折りたたみ、1秒あたりの上限をかける

/root/obs-log-sampling/squeeze.pyを作成してください。python3 squeeze.py [--max-debug-per-sec K] < 입력 > 출력(Kのデフォルトは20)で呼び出すと(プレースホルダーは入力と出力です)、2つのルールを順に適用します。①直前の行と(レベル、handler、msg)がすべて同じなら1つのまとまりと見て最初の行だけを残し、まとまりの行数kが2以上なら、その行の末尾に repeated=<k>を付けます。②折りたたんだあと、DEBUG行だけを、同じ秒(時刻文字列の先頭19文字)の中で先頭からK個まで残し、残りは捨てます。そのあとpython3 squeeze.py < /opt/lab/logsample/app.log > /root/obs-log-sampling/squeezed.logを作成し、/root/obs-log-sampling/squeeze.txtに4行in_lines=、after_collapse=、after_cap=、bytes_saved_pct=<소수 두 자리>を書いてください(プレースホルダーは小数第2位です)。

折りたたみは、「連続」しているときだけ行います。間に別のリクエストの行が挟まれば、別のまとまりです。after_collapseは、上限をとても大きくして、もう1回実行して数えると簡単です。上限をDEBUGだけにかける理由が、このステップの核心です。レベルを区別せずにかけると、急増するその瞬間にERRORが切り落とされ、最も必要な時刻のログだけが消えます。

応用①: 2つのフィルターをつないで、調査できるかを確認する

sample.py --rate 10 --keep-errorsの出力を、squeeze.py(デフォルトの上限)にそのまま流して、/root/obs-log-sampling/final.logを作成してください。そして/root/obs-log-sampling/final.txtに8行を書いてください。in_lines=、out_lines=、in_bytes=、out_bytes=、reduction_pct=<바이트 기준, 소수 두 자리>、error_requests_kept=<final.log 에 줄이 남아 있는 오류 요청 수>、trace_req=<2단계에서 고른 그 요청 id>、trace_lines=<final.log 에 남은 그 요청의 줄 수>です(プレースホルダーは、バイト基準で小数第2位まで、final.logに行が残っているエラーリクエスト数、ステップ2で選んだそのリクエストのid、final.logに残ったそのリクエストの行数です)。

2つのフィルターはどちらも標準入出力を使うので、パイプでつなげばよいのです。trace_linesを、ステップ2のreq_lines_beforeと比べてみてください。DEBUGを切ったときと何が違うかが、このラボの結論です。繰り返しが折りたたまれたリクエストなら、行数が元より減ることもあります。

応用②: レベル・サンプリング率・保持期間・コストをポリシーファイルとして固定する

/root/obs-log-sampling/policy.ymlをYAMLで書いてください。levelsの下に、DEBUG・INFO・WARN・ERRORの4つのレベルごとに、retain_days(整数)とsample_rate(整数)を置きます。ERRORのsample_rateは1である必要があり、retain_daysはDEBUGより大きくなければなりません。DEBUGのsample_rateは2以上でなければなりません。rulesの下には、keep_errors_whole_request: true、collapse_repeats: true、max_debug_per_sec(ステップ6で使ったデフォルト値)を置きます。estimateの下には、raw_bytes・kept_bytes・reduction_pctを、ステップ7の結果と同じ値で書き、最後にnoteとして、このポリシーのトレードオフを40文字以上の1文で書いてください。

python3 -c "import yaml,sys;yaml.safe_load(open('policy.yml'))"で、先に文法を確認してください。数字は手で写さず、final.txtから読み取って埋めればミスがありません。保持期間を決めるときは、「このレベルを何日後に探すことがあるか」を自問してみてください。四半期の振り返りで探すのはERRORであって、DEBUGではありません。