ログ形式を設計し、エラーだけを分ける

目標

アクセスログの内容・形・シンク・フィルターの4つを順に設計し、それぞれが実際のログファイルにどう現れるかを確認します。

なぜ重要なのか

アクセスログは、オブザーバビリティの設定の中で唯一、取り返しがつかない部分です。事故が起きた後で「アップストリームのアドレスも残しておけばよかった」と気づいても、その事故のログにはありません。そのため、形式を選ぶ基準は好みではなく問いです。午前3時に、この1行だけを見て原因を絞り込めるか。これに加えて、ファイルシンクがバッファーにためてから空にするという事実、値がない位置に何が出力されるか、フィルターをどの階層に書くべきかは、文書を読むだけではなかなか身につかず、一度経験して初めて身につきます。

ステップ

アップストリームを2つ起動してください。8091はok、8092はfailです。/root/envd-log/log-text.yamlに、/ping(pongを返すdirect_response)、/bad(クラスターbad)、/(クラスターgood)の3つのルートと、ファイルのアクセスログのシンクを置いてください。パスは/root/envd-log/access.log、形式は%RESPONSE_CODE%|%REQ(:PATH)%|%UPSTREAM_HOST%です。--file-flush-interval-msec 200を付けて起動し、/helloを1回リクエストしてから、ログが残るまで待って確認してください。
/root/envd-log/log-wide.yamlを作ってください。ログのパスは/root/envd-log/wide.log、形式は8フィールドです: %RESPONSE_CODE%|%REQ(:METHOD)%|%REQ(:PATH)%|%PROTOCOL%|%DURATION%|%UPSTREAM_HOST%|%RESPONSE_FLAGS%|%BYTES_SENT%。その設定で起動してから、/hello・/ping・/bad/xを1回ずつリクエストし、3行が残ることを確認してください。
/root/envd-log/log-miss.yamlを作ってください。パスは/root/envd-log/miss.log、形式は%RESPONSE_CODE%|%REQ(:PATH)%|%UPSTREAM_HOST%|%REQ(X-TENANT)%です(最後のフィールドはリクエストヘッダーx-tenant)。起動してから、/pingと/helloをヘッダーなしで1回ずつリクエストし、/root/envd-log/03-missing.txtにping_upstream=(/pingの行の3つ目のフィールド)、ping_tenant=(4つ目のフィールド)、hello_tenant=の3行を書いてください。
/root/envd-log/log-json.yamlを作ってください。パスは/root/envd-log/access.json、形式はjson_formatで、キーはcode・path・upstream・flags・duration_msの5つです。起動してから、/helloと/bad/xを1回ずつリクエストし、jqで読めることを確認してください。
/root/envd-log/log-err.yamlを作ってください。シンクは1つだけで、filter.status_code_filterで500以上だけを残し(比較演算子GE、値500)、パスは/root/envd-log/errors.json、キーはcode・path・upstream・flagsです。起動してから、/helloを2回と/bad/xを1回リクエストし、/root/envd-log/05-filter.txtにlines=(errors.jsonの行数)とcodes=(その行のcodeの値を空白区切りで)の2行を書いてください。
/root/envd-log/log-two.yamlを作ってください。シンクが2つあります。1つはテキストですべてのリクエストを/root/envd-log/all.logに(形式%RESPONSE_CODE%|%REQ(:PATH)%|%UPSTREAM_HOST%)、もう1つはJSONで500以上だけを/root/envd-log/only5xx.jsonに残します。起動してから、/helloを3回と/bad/xを2回リクエストし、/root/envd-log/06-two.txtにall=・err=・ratio_ok=(allとerrの差)の3行を書いてください。
/root/envd-log/log-reqid.yamlを作ってください。パスは/root/envd-log/reqid.log、形式は%RESPONSE_CODE%|%REQ(:PATH)%|%REQ(X-REQUEST-ID)%です。起動してから、/givenにはヘッダーx-request-id: envd-777を付けて、/noneにはヘッダーなしでリクエストしてください。/root/envd-log/07-reqid.txtにgiven=(最初のリクエストの行の3つ目のフィールド)、none_len=(2つ目のリクエストの行の3つ目のフィールドの文字数)、none_is_given=(その値がenvd-777と同じならyes、違えばno)の3行を書いてください。
/root/envd-log/08-report.mdに、fields=(ステップ2の形式のフィールド数)、missing_marker=(ステップ3で値がないときに出力された文字)、all_lines=・error_lines=(ステップ6の2つの値)の4行を書き、その下に学んだことを4行以上書いてください。

参考

Envoyを起動するときは、--file-flush-interval-msec 200を付けてください。デフォルトは10秒なので、リクエストの直後はログが空のように見えます。
それでも、固定のsleepは使わないでください。줄 수가 N 이상이 될 때까지(韓国語の文は「行数がN以上になるまで」という意味です)回るループで待ちます。
起動し直す前にはpkill -x envoyで片付け、起動は/readyがLIVEを返すまで回るループで待ってください。
フィールドを数えたり取り出したりするにはawk -F'|'を、JSONを確認するにはjq -c .を使ってください。
Envoyはログファイルに追記します。形式を変えて起動し直す前に、そのファイルを削除してください。そうしないと、古い形式の行と新しい形式の行が1つのファイルに混ざります。
よくある間違い: シンクのfilterをtyped_configの内側に書いてしまうことです。そこにはないフィールドなので、設定がまるごと拒否されます。nameと同じ階層に書きます。

ログをファイルに残し、出力が遅れる理由を知る

アップストリームを2つ起動してください。8091はok、8092はfailです。/root/envd-log/log-text.yamlに、/ping(pongを返すdirect_response)、/bad(クラスターbad)、/(クラスターgood)の3つのルートと、ファイルのアクセスログのシンクを置いてください。パスは/root/envd-log/access.log、形式は%RESPONSE_CODE%|%REQ(:PATH)%|%UPSTREAM_HOST%です。--file-flush-interval-msec 200を付けて起動し、/helloを1回リクエストしてから、ログが残るまで待って確認してください。

ファイルシンクは、リクエストごとにディスクへ書き込みません。バッファーにためて、定期的に空にします。その間隔のデフォルトは10秒なので、リクエストの直後にcatすると、何もないように見えます。「ログが残らない」という報告の相当な割合が、これです。ラボでは--file-flush-interval-msec 200で間隔を縮め、待ち時間をなくします。それでも、固定のsleepではなく、行ができるまで回るループを使ってください。

事故の後に必要な値を事前に決める

形式文字列の%...%はコマンド演算子です。リクエストヘッダーは%REQ(이름)%、レスポンスヘッダーは%RESP(이름)%(プレースホルダーはヘッダー名です)、:METHODや:PATHのようにコロンで始まるものは、HTTP/2の疑似ヘッダーです。ここに入れる値を選ぶ基準は1つです。午前3時に、この行だけを見て原因を絞り込めるか。ステータスコードだけでは絞り込めず、どのアップストリームが受け、何ミリ秒かかり、どんなフラグが付いたかがあって、初めて絞り込めます。

値がないときに何が出力されるかを知っておく

/root/envd-log/log-miss.yamlを作ってください。パスは/root/envd-log/miss.log、形式は%RESPONSE_CODE%|%REQ(:PATH)%|%UPSTREAM_HOST%|%REQ(X-TENANT)%です(最後のフィールドはリクエストヘッダーx-tenant)。起動してから、/pingと/helloをヘッダーなしで1回ずつリクエストし、/root/envd-log/03-missing.txtにping_upstream=(/pingの行の3つ目のフィールド)、ping_tenant=(4つ目のフィールド)、hello_tenant=の3行を書いてください。

/pingはdirect_responseなので、アップストリームへ行きません。そうすると、%UPSTREAM_HOST%に入れる値がありません。送らなかったヘッダーも同じです。Envoyはこのような位置を空にせず、1文字の表示で埋めます。その表示が何かを知っておかないと、ログを機械で読むときに、その値を本物の値だと思って、そのまま保存してしまいます。フィールドを数えるには、awk -F'|'が便利です。

機械が読める形式に変える

/root/envd-log/log-json.yamlを作ってください。パスは/root/envd-log/access.json、形式はjson_formatで、キーはcode・path・upstream・flags・duration_msの5つです。起動してから、/helloと/bad/xを1回ずつリクエストし、jqで読めることを確認してください。

区切り文字で切ったテキスト形式は人間には読みやすいですが、値の中に区切り文字が入った瞬間(パスにクエスチョンマークと値が付く場合)、フィールドがずれます。ログをコレクターに送ってクエリする予定なら、最初からjson_formatにしておくほうが優れています。キーの名前は自由に決められ、値の位置には同じコマンド演算子を使います。確認はjq -c . 파일(プレースホルダーはファイル名です)で行います。1行でも壊れていれば、jqがその場で失敗します。

エラーだけを別に集める

/root/envd-log/log-err.yamlを作ってください。シンクは1つだけで、filter.status_code_filterで500以上だけを残し(比較演算子GE、値500)、パスは/root/envd-log/errors.json、キーはcode・path・upstream・flagsです。起動してから、/helloを2回と/bad/xを1回リクエストし、/root/envd-log/05-filter.txtにlines=(errors.jsonの行数)とcodes=(その行のcodeの値を空白区切りで)の2行を書いてください。

シンクごとにfilterを付けられます。filterはtyped_configの内側ではなく、nameと同じ階層に書きます。内側に書くと、「そのようなフィールドはない」と設定が拒否されます。フィルターには、ステータスコードのほかにも、所要時間(duration_filter)、レスポンスフラグ、ヘッダーの条件があります。エラーだけを別に集めれば、保存期間を長くしても容量を賄えます。

シンクを2つ併用する

/root/envd-log/log-two.yamlを作ってください。シンクが2つあります。1つはテキストですべてのリクエストを/root/envd-log/all.logに(形式%RESPONSE_CODE%|%REQ(:PATH)%|%UPSTREAM_HOST%)、もう1つはJSONで500以上だけを/root/envd-log/only5xx.jsonに残します。起動してから、/helloを3回と/bad/xを2回リクエストし、/root/envd-log/06-two.txtにall=・err=・ratio_ok=(allとerrの差)の3行を書いてください。

シンクはリストなので複数置け、それぞれ別の形式と別のフィルターを持てます。実務でよくある構成が、まさにこれです。全体のログは短い形式で短く保存し、エラーのログは詳しい形式で長く保存します。2つを1つのファイルに混ぜると、保存期間を別々に決められません。

リクエストIDは誰が作るのか

/root/envd-log/log-reqid.yamlを作ってください。パスは/root/envd-log/reqid.log、形式は%RESPONSE_CODE%|%REQ(:PATH)%|%REQ(X-REQUEST-ID)%です。起動してから、/givenにはヘッダーx-request-id: envd-777を付けて、/noneにはヘッダーなしでリクエストしてください。/root/envd-log/07-reqid.txtにgiven=(最初のリクエストの行の3つ目のフィールド)、none_len=(2つ目のリクエストの行の3つ目のフィールドの文字数)、none_is_given=(その値がenvd-777と同じならyes、違えばno)の3行を書いてください。

リクエストIDは、複数のサービスを通る1つのリクエストをつなぎ合わせる糸で、そのため一番前のプロキシが、なければ作り、あればそのまま引き継ぎます。クライアントが渡した値をそのまま使うのがデフォルトの動作なので、外から任意の値を入れて送れるという点も一緒に覚えておく必要があります(信頼境界の外から来た値を消す設定が別にあります)。文字数はawk '{print length($0)}'やwc -cで数えます。

ログ設計のメモを残す

/root/envd-log/08-report.mdに、fields=(ステップ2の形式のフィールド数)、missing_marker=(ステップ3で値がないときに出力された文字)、all_lines=・error_lines=(ステップ6の2つの値)の4行を書き、その下に学んだことを4行以上書いてください。

このメモは、次のサービスのログ形式を決めるときに自分が読む文章です。「何を入れた」よりも「なぜそれを入れることにしたのか」を書いてください。値は、前のステップで作ったファイルから取ります。