フランス拠点の障害対応で使うログ時刻、現地表記のまま突き合わせる手順

パリ郊外の拠点で、注文APIの5xxが夜間に増える事象を追った。環境は Ubuntu 22.04、アプリはJava、ログは logback が現地時刻（Europe/Paris）で 2024-03-28 02:14:07,331 のようにミリ秒まで出す設定。1ノードあたり1日400MB、3ノードで約1.2GB。監視側のアラートはUTCで飛んでくるので、そのままでは「アラートの02:14」と「ログの02:14」が同じ時刻だと信じられなかった。夏時間の切り替え週だったこともあり、まず突き合わせの土台を作ることにした。

やったのは、ログを読む前に各ノードのタイムゾーン設定とオフセットを機械的に確認する手順の固定。まず対象ノードで以下を実行し、出力を障害チケットに貼る。

timedatectl | grep -E 'Time zone|Local time'
date +'%Y-%m-%dT%H:%M:%S%z'
cat /etc/timezone 2>/dev/null

そのうえで、アラート時刻を現地時刻に直してからgrepする。UTC→Europe/Parisの変換はスクリプトで行い、手で足し算しない。

TZ=Europe/Paris date -d '2024-03-28T00:14:00Z' +'%Y-%m-%d %H:%M'
# => 2024-03-28 01:14

ログ側は現地時刻なので、この変換結果の前後5分を awk で切り出す。

awk '$0 >= "2024-03-28 01:09" && $0 <= "2024-03-28 01:19"' app.log

なぜ変換をスクリプトに寄せたかというと、3月最終日曜の前後でオフセットが+01:00から+02:00に変わり、手計算だと1時間ずれるから。実際、切替当日の夜間バッチで「アラートは02:14、ログにも02:14がある」と思って読んだら、片方はCET、片方はCESTで、別のリクエストを見ていた。時刻をまたぐ障害では、どの表現がどのオフセットかを先に固定しないと、存在しない1時間を探すことになる。

この手順が効かないのは、アプリが logback.xml で %d{yyyy-MM-dd HH:mm:ss} とオフセットなしのパターンを使っていて、しかもノードごとに user.timezone が違う場合。時刻だけでは同一性を保証できないので、必ずリクエストIDやスレッド名を併記して照合する。あと、ログがgzipのまま残っているとこのawkはそのままでは通らないので、対象時間帯だけ zcat で展開してから渡している。過去にここを省いて、空の結果を「ログなし」と誤認した。

同じ拠点で、夏時間切り替えをまたぐ障害を追ったときに、時刻の同一性をどう確認しているか。リクエストIDで突き合わせる以外に、運用で決めているルールがあれば知りたい。