オンコールの夜を軽くする — 深夜2時の自分を助ける4つの仕込み

2時14分、9回目の開き直し。

同じ50GBのログを、今夜だけでもう9回開いています。なぜ調査は、同じファイルを何度も開き直す作業になるのでしょうか。

答えは、あなたの手際とは関係のないところにあります。

深夜2時の自分は、昼の自分より確実に判断が鈍っています。それは避けられません。避けられるのは、その鈍った頭に「今その場で組み立てる仕事」をさせることのほうです。夜に効く工夫は、たいてい昼のうちに仕込めます。

以下、オンコールの夜に効く4つの場面を並べます。開き直しの積み重ね・眠い頭での条件再構築・散発する5xx・パニック直前の30秒。4つとも、詰まっているのは同じ1点です。

先に結論: UwView Pro なら、一度開いた47.73GBのログは2回目以降0.02〜0.07秒で行番号付きのまま開き直せ、保存した検索条件をそのまま当て直せます（特定環境での実測。環境により異なります。詳細は記事末尾）

1. 同じログを1日に10回開き直していないか

状況

障害対応の最中です。50GBのアプリケーションログを開き、時刻の当たりを付け、リクエストIDを拾い、そのIDでもう一度探すために——開き直します。

1回あたり2分。今夜9回で18分。それだけなら耐えられます。耐えられないのは、その2分のあいだに別のタブへ移り、戻ってきたときに「何を確かめようとしていたか」を思い出すところからやり直すことです。

なぜ起きるか

調査が本質的に反復で、道具が「1回開いて終わり」を前提にしているからです。

調査は仮説→確認→次の仮説の繰り返しです。1回で終わることはまずありません。ところが多くのビューアやエディタは、開くたびに行の境界を数え直し、索引をメモリ上に作り、プロセスを閉じた瞬間にそれを捨てます。 次に開くとき、そのファイルが前回と同じものであっても、道具は何も覚えていません。

積算の仕方も直感に反します。2分の待ちは2分では終わりません。作業の中断から元の思考へ戻るまでには、待ち時間そのものより長い時間がかかります。昼なら吸収できるその差が、深夜2時には吸収できません。

汎用ツールでの対処と限界

開き直しを減らす方向で工夫するのが定石です。

less +40000000g app.log                        # 行番号で飛ぶ（先頭から数え直す）
tail -c +53687091200 app.log | head -n 200     # バイト位置で飛ぶ（行番号は失われる）
split -b 2G app.log part_                      # 小さく割って開きやすくする

2本目は速いです。バイト位置で飛べば行を数える必要がありません。

限界は3つ。ひとつめ、バイト位置で飛ぶと行番号が消えることです。同僚に「何行目？」と聞かれて答えられない。報告書にも書けない。速さと座標のどちらかを諦める構図になります。

ふたつめ、分割すると原本との対応が崩れることです。part_ac の12,043行目は原本の何行目か。足し算で出せますが、深夜2時にやりたい計算ではありません。

みっつめ、開きっぱなしにする戦略が長時間もたないことです。メモリを抱えたまま数時間、途中で別のファイルも開きたくなり、間違えてウィンドウを閉じる。そして閉じた瞬間、また2分が始まります。

2. 眠い頭で、検索条件を組み直さない

状況

3週間前にも同じ症状を見ました。あのとき絞り込んだ条件が効いたはずです。

Ctrl-R でシェル履歴を遡ります。grep を含む行が30件出てきます。似たものが並んでいて、どれが当たりだったのか分かりません。結局、その場で書き直します。

なぜ起きるか

検索条件が「その場のもの」として扱われ、成果物として保存されないからです。

ポストモーテムには結論が残ります。「upstream のコネクションプール枯渇が原因だった」。しかしその結論へ至るまでに当てた検索条件は、どこにも残りません。 残っているのは各自のシェル履歴だけで、それは共有もされず、検索もしづらい形をしています。

そしてこれが夜に効いてきます。条件を組み立てる作業は、対象の構造を頭に入れたうえで正規表現を書く仕事です。判断力が落ちているときに、いちばんやりたくない種類の仕事です。

汎用ツールでの対処と限界

条件に名前を付けて持ち歩くのが基本です。

# runbook.sh に置いておく
check_pool_exhaustion() { grep -nE 'pool (exhausted|timeout)' "$1"; }
check_slow_upstream()   { awk '$NF > 3.0 {print NR": "$0}' "$1"; }

これはよく効きます。名前が付いた瞬間、条件は「思い出すもの」から「呼ぶもの」になります。

限界は3つ。ひとつめ、条件は保存できても結果は保存できないことです。呼ぶたびに50GBの全走査が走ります。第8回で書いた「3回目のzgrepも8分」と同じ構図です。定点観測とは同じ条件を繰り返し当てることなのに、繰り返すたびに満額を払います。

ふたつめ、微調整のたびに関数の外へ出ることです。pool timeout だけを見たい、期間を絞りたい、前後を広げたい。そのつど関数を書き換えるか、手で書き直すかになります。夜に増えるのは後者です。

みっつめ、「絞り込んだ状態」を渡せないことです。朝の引き継ぎで渡せるのはコマンド文字列だけで、受け取った側はまた全走査から始めます。条件ではなく絞り込んだ結果そのものを渡せれば、この往復は要りません。

3. 5xxが「たまに」出る — 散発エラーを文脈つきで抜く

状況

1日3,000万リクエスト。5xxは1日80件。率にして0.0003%です。

監視は率の閾値で見ているので、アラートは鳴りません。手がかりはユーザーからの申告だけ。「ときどき失敗する」という報告と、80件の行が手元にあります。

なぜ起きるか

監視は集約値を見ていて、ログは個別事象を持っているからです。

率で丸めた瞬間、80件は0.0003%になります。0.0003%は運用上ほぼゼロで、閾値には引っかかりません。それでも80人のユーザーは実際に失敗を見ています。集約は正しく、そして役に立ちません。

もうひとつは文脈です。5xxの行そのものには、たいてい原因が書かれていません。手前にある upstream のタイムアウト、直後のリトライ、同じ秒に走った別のリクエスト——第2回で扱ったとおり、原因はヒットした行の外にあります。 散発エラーの場合、その「外」を80回ぶん見る必要があります。

汎用ツールでの対処と限界

文脈つきで抜くのが定石です。

awk '$9 ~ /^5/ {print NR": "$0}' access.log | head -100   # 5xxの行番号を出す
grep -B3 -A3 ' 502 ' access.log > 502_context.txt         # 前後3行つきで抜く
awk '{print $9}' access.log | sort | uniq -c              # ステータスの分布を見る

2本目で目的の形にはなります。前後の文脈が付いた抜粋が手に入ります。

限界は3つ。ひとつめ、-B/-A の値を先に決めなければならないことです。3行では足りないと分かるのは、3行ぶんを見たあとです。5行にして走らせ直すと、もう一度アクセスログ全体を読みます。

ふたつめ、期間を広げるコストが跳ね上がることです。「たまに」を確かめるには1日では足りません。30日ぶんを見たい。しかし30日ぶんは圧縮された30本のファイルで、まとめて当てるとそれだけで数分から十数分になります。

みっつめ、抜き出した瞬間に原本から切り離されることです。502_context.txt の中で気になる行を見つけても、その周辺をもう10行広げるには原本に戻る必要があります。既存記事のアクセスログ5xxを1本の線でつなぐでは色分けとブックマークで線をつなぎましたが、そこで前提になっているのは原本を開いたまま作業していることでした。

4. カーネルパニック直前の30秒を、安全に読む

状況

サーバが落ちて、再起動しました。見たいのは /var/log/syslog の末尾です。

正確には、パニックの瞬間ではありません。その30秒前です。何かが直前に始まっていたはずで、それを知りたい。ところが末尾を開くと、最後の数十行が途中で切れていて、そのあとにNULバイトらしき塊が続いています。

なぜ起きるか

書き込み途中のログが、フラッシュされないまま失われるからです。

通常のログ出力はページキャッシュを経由してディスクへ書かれます。パニックで停止すると、キャッシュ上にあったぶんが消えます。結果、末尾数KBが欠けるか、ファイルシステムの都合でゼロ埋めされます。いちばん知りたい時間帯が、いちばん壊れやすい場所にあります。

もうひとつ、末尾は「行数」で数えたい場所ではありません。知りたいのは「パニック時刻の30秒前から」であって「末尾から500行」ではない。ログの流量が一定でない以上、この2つは一致しません。

汎用ツールでの対処と限界

末尾側から寄せていくのが基本形です。

tail -n 500 /var/log/syslog
tail -c 2000000 /var/log/syslog | strings | less        # 壊れた末尾をテキストとして拾う
journalctl -k -b -1 --since "02:13:30" --until "02:14:10"
zcat /var/log/syslog.1.gz | tail -n 200                  # 前世代とつなぐ

3本目が使えるなら、それがいちばん素直です。時刻で範囲を切れます。

限界は3つ。ひとつめ、壊れた末尾では行の境界が信用できないことです。tail -n は改行を数えて遡ります。NUL埋めやバイナリ片が混ざると、500行のつもりが数バイトになったり、逆に巨大な1行になったりします。

ふたつめ、journalctl はジャーナルが壊れていると読めないことです。バイナリ形式なので、壊れ方によっては範囲指定そのものが通りません。テキストの syslog へ戻ることになりますが、そちらは1本のファイルとして扱うしかありません。

みっつめ、原本に触りたくないことです。原因調査の対象であり、場合によっては報告の根拠になるファイルです。編集機能を持つツールで開くこと自体を避けたい。しかし前世代とつなぐには zcat で展開するしかなく、数GBの一時ファイルが増えます（第4回で扱った、まさに置き場所の問題です）。

4つに共通していたもの

3列目を縦に読むと、正体が見えます。どれも「状態を次まで持ち越すこと」です。 夜の作業が重いのは、あなたの手際が悪いからではなく、道具が毎回ゼロから始まるからです。索引はプロセスと一緒に消え、検索条件は履歴に沈み、抜粋は原本から切り離される。1回ぶんのコストは小さくても、反復する作業では回数ぶん積みます。

持ち越したいものは3つです。

• 索引を、次に開くときまで — 同じファイルなら、2回目は1回目の成果を使えるはずです。開き直しが1秒未満で済むなら、9回開くことは問題ではなくなります。問題は9回ぶんの待ちであって、9回という回数ではありません。
• 検索条件と結果を、名前をつけて — 条件だけを渡すと、受け取った側は全走査からやり直します。絞り込んだ状態ごと渡せれば、朝の引き継ぎは「これを見て」で済みます。
• 原本の位置と文脈を、無改変のまま — 抜粋を作った時点で原本との対応は切れます。原本を開いたまま前後を広げられるなら、そもそも抜粋は最後の1回だけで足ります。

3つとも、夜の頑張りでは埋められません。昼のうちに道具の側へ持たせておく類のものです。

冒頭の「2時14分、9回目の開き直し」に戻ります。9回目が一瞬で開くなら、それは9回目の開き直しではなく、9回目の仮説検証です。同じ回数でも、夜の重さがまるで違います。

使っている道具

私が開発している UwView（無料）は、巨大なテキストを開いた瞬間から全体を表示・スクロール・検索できるビューアです。索引はバックグラウンドで作られ、完成すると行番号が付きます（他のビューアの多くは索引が終わるまで先頭しか見えません）。分割せず、原本を1本のまま・無改変のまま扱えます。編集機能を持たないので、調査対象のログを開くこと自体が安全な操作です。

• 開き直しを軽くする: UwView Pro は索引と圧縮を保存するので、2回目以降は行番号付きのまま開き直せます（47.73GBのテキストで実測0.02〜0.07秒。環境により異なります）。第1章の「開くたびの2分」が積まなくなります。
• 条件と結果を持ち越す: 検索結果は独立したポップアップに分離され、そこから原本の行へ飛べます。条件と結果に名前を付けて残す使い方はフィルタPopupの記事に、翌朝そのまま開き直す運用はアーカイブ×セッション復元の記事に書きました。
• 文脈幅を後から変える: 前後の行数を決め打ちしてから走らせるのではなく、結果を見ながら広げられます。第3章の「3行では足りないと分かってからの再走査」が起きません（無料版は±1行、可変の±Nは Pro）。
• 末尾側から安全に見る: 開いた瞬間から末尾へ動けるので、壊れた末尾を tail で試行錯誤せずに済みます。前世代のログを展開して並べる場合も、原本を書き換えずに扱えます。

正直に書いておくと、UwView は監視ツールではありません。閾値もアラートも持たず、5xxの率も計算しません。散発エラーに気づく仕組みは別に必要で、この道具の役割は気づいたあとの調査です。また、壊れた末尾のバイナリ片を読みやすく整形することはしません。NUL埋めはNUL埋めのまま見えます。ここは strings のほうが向いています。加えて、無料版で使えるのは1段検索・±1文脈・結果の保存までで、多段階検索・シーケンシャル検索・可変の±N・索引と圧縮の保存は Pro の機能です。

そして、ストレージを専有している巨大ログを圧縮して保管し、さらに高速に検索したいなら UwView Pro をどうぞ。永続索引・圧縮キャッシュ検索・約1/9保管で、開き直しも検索も一段速くなります（全OS対応・買い切り／月額プランあり）。オンコールのように同じファイルへ何度も戻る使い方では、持ち越せる状態が多いほど夜が軽くなります。

リンク

• 第1回: 巨大ファイルに沈む4つの定番ツールと、その先: https://uvp.y42u.net/blog/uwview-ps01-huge-file-tool-limits/
• 第2回: ログの因果を遡る4つの技法: https://uvp.y42u.net/blog/uwview-ps02-log-causality-tracing/
• 第3回: 文字コード4つの罠と切り分け手順: https://uvp.y42u.net/blog/uwview-ps03-japanese-encoding-traps/
• 第4回: 消す・残す・圧縮するの判断基準: https://uvp.y42u.net/blog/uwview-ps04-log-retention-decision/
• 第5回: 開発ログとの正しい付き合い方4選: https://uvp.y42u.net/blog/uwview-ps05-debug-log-practices/
• 第6回: 認証ログ数千万行から痕跡を拾う4手順: https://uvp.y42u.net/blog/uwview-ps06-intrusion-triage-auth-logs/
• 第7回: タイムスタンプを武器にする4つの読み方: https://uvp.y42u.net/blog/uwview-ps07-timestamp-driven-triage/
• 第8回: 圧縮保管と検索の両立: https://uvp.y42u.net/blog/uwview-ps08-compressed-archive-search/
• 第9回: 構造化データを生のまま読む4場面: https://uvp.y42u.net/blog/uwview-ps09-read-raw-structured-data/
• アクセスログの5xxを1本の線でつなぐ: https://uvp.y42u.net/blog/uwview-access-log-5xx-workflow/
• 検索結果を独立ウィンドウに分離した理由（フィルタPopup）: https://uvp.y42u.net/blog/uwview-filter-popup-jump-save-context/
• 調査済みログを棚にしまい、次の朝そのまま開き直す: https://uvp.y42u.net/blog/uwview-archive-session-restore-workflow/
• ソースコード（GitHub）: https://github.com/amru195704/UwView

開発者より: アプリ・Kindle本・オープンソースの一覧は GitHub: amru195704 にまとめています。

お願い
本記事の情報は参考目的で掲載しており、正確性・完全性を保証するものではありません。tail・journalctl・grep の挙動、パニック時のログ欠損の仕方、ログローテーションの設定は、OS・ディストリビューション・バージョン・構成により異なります。記載した実測値は特定の1環境での測定例であり、同じ結果を保証するものではありません。コマンド例は環境（GNU/BSD、シェル、awk・sed の実装とバージョン等）により調整が必要です。誤記・不正確な情報がございましたら、コメント欄よりご指摘いただければ、確認のうえ修正いたします。