同じ5xx、違う犯人 — 時計をそろえてタイムラインを組み立てる

目標

タイムゾーンと時計が互いに異なる記録(サーバーログ2つ、ロードバランサーのサンプル、gitのデプロイ記録、フラグ記録、アラート・メトリクス)を1つの基準時計にそろえてタイムラインを組み立て、最初のエラー・疑わしい変更・検知遅延・緩和時刻をデータで決めます。最後に、同じ症状の3つのサービスを原因ごとに切り分け、ロールバックすべきものだけをロールバックします。

なぜ重要か

ポストモーテムのタイムラインが間違っていれば、その上に積み上げた原因と対策もすべて間違ったものになります。そしてタイムラインを誤らせるのは、たいてい大きなミスではなく、タイムゾーン表記1つ、数分ずれた時計1つです。インシデントの最中には、同じ錯覚が「全部ロールバックしよう」という判断につながります — 正常な変更をロールバックすることは新しい変更をもう1つ加えることであり、本当の原因はそのまま残ります。

ステップ

python3 /opt/fixtures/ic/ickit.py open timeline で素材を展開し、/root/ic/timeline/README.txt を読んでください。web-1.log と web-2.log でステータスコードが5xxの行数を合計し、/root/ic/timeline/answers/errors.txt に数字1つで書いてください。
deploys.log(git log)のデプロイと flags.log のフラグ変更をすべてUTCに変換し、古いものから順に /root/ic/timeline/answers/changes.tsv に <utc-time>\t<change-id> の形で1行ずつ書いてください。時刻は 2026-11-04T05:12:03Z の形式、変更idはデプロイならコミットshaの先頭7文字、フラグなら flag:<name> です。
lb-sample.log(基準時計)と2つのサーバーログで同じreq idで記録されたリクエストをペアにし、サーバーごとに server_time − reference_time を整数秒で測って、/root/ic/timeline/answers/skew.txt に web-1=<seconds>、web-2=<seconds> の2行で書いてください(進んでいる時計は+、遅れている時計は−)。
前のステップのずれを差し引いて2つのサーバーの5xxを基準時計にそろえ、最も早いものの時刻(UTC、秒まで)とサーバーを /root/ic/timeline/answers/first-error.txt に first_error_utc=<time>、host=<server> の2行で書いてください。
基準時計での最初のエラーの前30分(最初のエラーの時刻を含む)以内に入った変更のidを、/root/ic/timeline/answers/suspects.txt に1行に1つずつ書いてください。
基準時計での最初のエラーからこのインシデントのアラート(alerts.csv の api-5xx-rate fired)までにかかった秒数と、READMEで定義された緩和時刻(分の開始、UTC)を、/root/ic/timeline/answers/phases.txt に detect_delay_sec=<seconds>、mitigated_utc=<time> の2行で書いてください。
incident ic-error-spike を実行するとインシデントが発生します。cart・search・payの3つのサービスが今日順番にデプロイされ、3つともその頃から5xxが続いています(記録は /srv/spike/、まずREADMEを読んでください)。サービスごとにエラーを始めさせたものを見つけ、ロールバックすべきものだけを /srv/spike/rollback.conf に <service> app=<previous-version> または <service> config=<previous-revision> の形で書いてください(ロールバックの必要がないサービスは書きません)。/root/incident/ic-error-spike/report.txt に cart: <code>、search: <code>、pay: <code> の3行と、サービスごとにその原因を示す素材の1行を evidence-cart: <line>、evidence-search: <line>、evidence-pay: <line> の形で書いてください(原因となった変更の行、または依存先サービスのメトリクス・タイムアウトの行)。さらに、サービスごとに基準時計(ロードバランサー)に合わせた最初の5xxの時刻を start-cart: <utc-time>、start-search: <utc-time>、start-pay: <utc-time> の形で書いてください(2台のサーバーのうち早いほう、±10秒まで受け付けます)。原因はサービスごとに個別に決まっているため、同じ原因が複数あることもあります。コードはサービスごとに次のいずれかです: bad-deploy(新しいアプリバージョンの欠陥)、clock-skew(時刻のずれが生んだ錯覚)、config-push(設定デプロイ)、traffic-surge(リクエスト急増)、upstream-timeout(依存先サービスの遅延)。

参考

素材ツール: python3 /opt/fixtures/ic/ickit.py open <name> が素材を /root/ic/<name>/ に展開します。素材は人ごとに異なるランダムシードで作られ、採点ツールは同じシードで正解を再計算します — 他人の数字は合いません。再展開しても同じ素材で、--fresh を付けると新しい素材で最初からやり直しになります。
答えは /root/ic/<name>/answers/ の下に書きます。セッションが終わると消えるので、必要なら別に保管してください。
インシデントツール: incident list で発生させられるインシデントと一行の症状を、incident show <name> でチケットを再確認できます。同じインシデントを再度発生させると、新しいランダムな素材で最初の故障状態になります(先に書いた答えは合わなくなります)。
レポートは /root/incident/<name>/report.txt です。対象ごとに <target>: <cause-code> を1行ずつ書き、最後に evidence: <line> をそのまま付けます。証拠は素材や観察記録にそのまま存在する1行(20文字以上)でなければなりません。採点ツールは修正後の実際の状態をまず確認し、レポートは判断を確かめるために使います。
ログの1行: <time> <server> req=<id> GET <path> <status> <latency>ms。5番目の列がパス、6番目の列がステータスです。
git logのDate形式はpythonの datetime.strptime(s, "%a %b %d %H:%M:%S %Y %z") で読みます。ISO形式は datetime.fromisoformat で読めます (末尾のZは +00:00 に置き換えてください)。
よくあるミス2つ — タイムゾーン(+09:00)を時刻のずれとして読むこと、そしてgit logの日付文字列(Nov 3)を瞬間のように並べ替えること。

素材を展開する — 5xxは何行か

python3 /opt/fixtures/ic/ickit.py open timeline で素材を展開し、/root/ic/timeline/README.txt を読んでください。web-1.log と web-2.log でステータスコードが5xxの行数を合計し、/root/ic/timeline/answers/errors.txt に数字1つで書いてください。

ステータスコードは行の6番目の列です。4xxはサーバー側の問題ではないので数えません。

変更をUTCで1列に並べる

deploys.log(git log)のデプロイと flags.log のフラグ変更をすべてUTCに変換し、古いものから順に /root/ic/timeline/answers/changes.tsv に <utc-time>\t<change-id> の形で1行ずつ書いてください。時刻は 2026-11-04T05:12:03Z の形式、変更idはデプロイならコミットshaの先頭7文字、フラグなら flag:<name> です。

gitのDateはコミットした人のタイムゾーン(+0900・-0800)で記録され、最新のものが上です。その形式はGNU dateでは読めないので、pythonのstrptime("%a %b %d %H:%M:%S %Y %z")を使ってください。日付の文字列ではなく瞬間で並べ替える必要があります。

サーバーの時計は何秒ずれているか

lb-sample.log(基準時計)と2つのサーバーログで同じreq idで記録されたリクエストをペアにし、サーバーごとに server_time − reference_time を整数秒で測って、/root/ic/timeline/answers/skew.txt に web-1=<seconds>、web-2=<seconds> の2行で書いてください(進んでいる時計は+、遅れている時計は−)。

タイムゾーン表記(+09:00、Z)をまず読んで同じ瞬間(エポック秒)に変換してから引きます。リクエストはロードバランサーを通過してから1秒以内にサーバーに届くので、複数組の中央値(median)を四捨五入すれば十分です。

基準時計での最初のエラー

前のステップのずれを差し引いて2つのサーバーの5xxを基準時計にそろえ、最も早いものの時刻(UTC、秒まで)とサーバーを /root/ic/timeline/answers/first-error.txt に first_error_utc=<time>、host=<server> の2行で書いてください。

そろえた時刻 = サーバーが記録した時刻 − そのサーバーのずれ。時計が遅れているサーバーの行をそのまま読むと、デプロイより先にエラーが起きたように見えます。

疑わしい変更を絞り込む

基準時計での最初のエラーの前30分(最初のエラーの時刻を含む)以内に入った変更のidを、/root/ic/timeline/answers/suspects.txt に1行に1つずつ書いてください。

前の2つの成果物(changes.tsv、first-error.txt)を突き合わせれば十分です。そろえていない時計の最初のエラーでウィンドウを取ると、引き金となった変更がウィンドウの外へ押し出されます。

検知遅延と緩和時刻

基準時計での最初のエラーからこのインシデントのアラート(alerts.csv の api-5xx-rate fired)までにかかった秒数と、READMEで定義された緩和時刻(分の開始、UTC)を、/root/ic/timeline/answers/phases.txt に detect_delay_sec=<seconds>、mitigated_utc=<time> の2行で書いてください。

緩和時刻はmetrics.csvの1分あたりのエラー率から定義どおりに見つけます — 初めて5%以上になった分より後で、1%未満が5分連続する最初の分です。インシデント前の静かな分を選ばないよう注意してください。

インシデント — 3つのサービスすべてでデプロイ直後にエラー、何をロールバックするか

incident ic-error-spike を実行するとインシデントが発生します。cart・search・payの3つのサービスが今日順番にデプロイされ、3つともその頃から5xxが続いています(記録は /srv/spike/、まずREADMEを読んでください)。サービスごとにエラーを始めさせたものを見つけ、ロールバックすべきものだけを /srv/spike/rollback.conf に <service> app=<previous-version> または <service> config=<previous-revision> の形で書いてください(ロールバックの必要がないサービスは書きません)。/root/incident/ic-error-spike/report.txt に cart: <code>、search: <code>、pay: <code> の3行と、サービスごとにその原因を示す素材の1行を evidence-cart: <line>、evidence-search: <line>、evidence-pay: <line> の形で書いてください(原因となった変更の行、または依存先サービスのメトリクス・タイムアウトの行)。さらに、サービスごとに基準時計(ロードバランサー)に合わせた最初の5xxの時刻を start-cart: <utc-time>、start-search: <utc-time>、start-pay: <utc-time> の形で書いてください(2台のサーバーのうち早いほう、±10秒まで受け付けます)。原因はサービスごとに個別に決まっているため、同じ原因が複数あることもあります。コードはサービスごとに次のいずれかです: bad-deploy(新しいアプリバージョンの欠陥)、clock-skew(時刻のずれが生んだ錯覚)、config-push(設定デプロイ)、traffic-surge(リクエスト急増)、upstream-timeout(依存先サービスの遅延)。

方向: 同じ症状でも開始パターンが異なります — 新バージョンが入ったサーバーから順にか、すべてのサーバーが同時にか、依存先サービスの遅延が先に跳ね上がったか。時計をそろえる前は順序を信じないでください。ツール: lb-sample.logでサーバーごとのずれを測る、git logのDateをstrptimeで読む、metricsのdep_p99_ms、エラー行のステータスコードと応答時間。具体: サービスごとに2つのサーバーの最初の5xxを基準時計にそろえ、その時刻をそのサービスのアプリデプロイ・設定デプロイの時刻と並べてください。ロールバックするなら、エラーを始めさせた変更の直前のバージョン(リビジョン)です。