エラーが出た。それでも集計は成立した ── 読めなかったことが、数字に現れない
今回の登場人物
Ron(ロン)
AI パートナー / Web Site Support プロデューサー
サイトの運用と解析の担当。「測る」ことを仕事の中心に置いていて、自分の測定が壊れたときに、その壊れ方を型にして残す人。
この記事は、私(本ブログの編集担当)が自分で踏んだ話です。登場するもう一人 ── AI パートナーの Ron(ロン) は、私を 2 回 正した側です。
ログの集計コマンドを叩いたら、こう返ってきました。
gzip: ssl_access.log-20260905.gz: No such file or directory
18033
エラーが出ています。そして、その下に数字が出ています。
この 18033 という数字を、私はそのまま報告に使うところでした。存在するファイルだけが処理され、集計は成立してしまったからです。
そもそもの発端 ── 「0 件」には 3 つの顔がある
前日の夜、AI パートナーの Ron(ロン) から、こういう整理が届いていました。
「0 件」には 3 つの顔があります。
① 本当に来ていない / ② 針が壊れている / ③ 探す場所が違う③ がいちばん見つかりません。
①② は同じファイルの中で直せば出ます。③ は、そのファイルを何度 測り直しても永久に 0 のまま。
そして彼は、自分がなぜ ③ を疑えなかったかも、続けて書いていました。
そして俺の場合、②を直した成功体験が「もう大丈夫」を作っていました。
ここでいう「針」は、検索や集計に使うパターンのことです。grep の正規表現でも、SQL の WHERE でも同じです。
- ① 本当に 0 件 ── 正常
- ② 針が壊れている ── パターンが間違っている。これは対照を置けば見つかります(在ると分かっているもので試して、鳴るかを確かめる)
- ③ 探す場所が違う ── 針は正しい。見に行ったファイルが違う。対照も同じ場所で試すので、両方 0 件になって気づけない
私たちのサイトでも、これは実害になっていました。HTTPS のサイトで access.log(HTTP 側)を見ると、実トラフィックの 1 割も入っていません。正しくは ssl_access.log を見る必要があります。
③ を守って測りました。それでも落としました
翌朝、私は ssl_access.log の側で測り直しました。見に行く場所は、正しかったはずです。
直近 7 日分を集計するため、圧縮されたログをまとめて展開しました。
zcat ssl_access.log-20260830.gz ... ssl_access.log-20260905.gz | wc -l
ここで冒頭のエラーが出ました。ssl_access.log-20260905.gz が存在しなかったからです。
調べたら、実体はこうなっていました。
ssl_access.log-20260905 241,626 B ← 拡張子 .gz が付いていない
ssl_access.log-20260904.gz ← ここから下は圧縮済み
原因は logrotate の delaycompress というオプションです。ログを切り替えた直後の 1 世代だけ、圧縮を遅らせます。(切り替えた瞬間はまだ書き込み中のプロセスがいる可能性があるため、安全側に倒す設定です)
つまり、*.gz で走査すると いちばん新しい 1 日だけが、静かに分母から消えます。
どれくらい消えたか ── 2 つのサーバーで測りました
私がこれを報告したところ、Ron が 自分の担当サーバーでも同じことを測って、10 分で返してきました。彼のサーバーの非圧縮ファイルは 1,027,179 B(私の側の 4 倍以上)でした。
| どこを測ったか | *.gz のみ | 生ファイルも足す | 落ちていた分 |
|---|---|---|---|
| 私のサーバー(HTTPS 側) | 18,033 行 | 19,201 行 | 6.5% |
| 私のサーバー(HTTP 側) | 1,228 行 | 1,743 行 | 42% |
| Ron のサーバー(HTTPS 側) | 22,049 行 | 27,603 行 | 20.1% |
割合が、まったく違います。アクセス量の日ごとの偏りと、1 日ぶんが全体に占める比率で決まるからです。
だから 「◯% 落ちます」とは書けません。「落ちます」としか書けない ── これが、この件でいちばん実務的な結論でした。
「③ の内側」ではなく、別の層でした
私はこれを、Ron の言う ③「探す場所が違う」の一段 内側だと考えて、そう伝えました。場所は合っていて、その中の選び方(*.gz)が外していた、と。
10 分で、訂正が返ってきました。
これは俺の ③ の内側ではなく、【別の層】だと思います。
言われて、確かにそうでした。
- ③ の対処は「探す場所を増やす」
- 今回の対処は「読めなかった件数を、出させる」
対処が違うなら、別の層です。私は「落ちた」という結果が同じだったので、同じ層だと読んでいました。結果が同じでも、落ちた理由が違えば、対処も違う。
そして、これが【4 つ目の顔】になりました
Ron はその日のうちに、自分の整理に 1 つ 足しました。ここがこの記事でいちばん重い部分です。
① 使っていないから 0
② 針が壊れているから 0
③ 探す場所が違うから 0
④ 集める範囲から漏れているから【少ない】── 0 にならない。だから疑えない
④ がいちばん質が悪いと思います。
①②③ は「0 件」という異常な形で出る。④ は【もっともらしい数字】で出ます。
ここが、この件の本体です。
①②③ は、いずれも 「0 件」という、目立つ形で出ます。0 は異常です。だから人は立ち止まります。
④ は違います。18,033 という数字が返ってきます。それらしい数字です。桁も、オーダーも、前日との比較も、何もおかしくありません。
Ron はこう書いています。
そしてあなたの実測がそれを証明しています ── 18,033 行と 19,201 行。どちらも「それらしい」。
正しい数字(19,201)を知っている今でさえ、18,033 を単独で見せられたら、私は疑えません。
だから、この記事の教訓は 「0 件のときに疑え」ではありません。むしろ逆です。
もっともらしい数字が返ってきたときこそ、何本を対象にして、何本 読めたのかを確かめる。
おまけ ── 「52」と「53」が、両方 正しかった話
同じやりとりの中で、ログの世代数が食い違いました。私は 52、Ron は 53。
私は「1 本 違います。理由は分かりません」で止めていました。Ron が内訳で解きました。
私の測り方 ssl_access.log-* → 52 本
正しい内訳 .gz 51 + 生 1 + 現行 1 = 53 世代
差の 1 本 現行ファイル(ハイフンが付かないので、ワイルドカードに入らない)
「52」も「53」も正しかった。数えた対象が違っただけでした。
そして私は、その食い違いを報告した同じ文書の中で、「どのファイルを測ったか」を書くという自分の約束を守っていませんでした。件数だけ書いて、何を数えたかを書いていなかった。
ただし、この「53」には数え方以上の意味があります。ログの保持世代数だからです。
53 世代ということは、54 日前のログは、もう存在しません。毎日 1 つずつ、いちばん古いものが消えていきます。Ron は前日、こう書いていました。
「あとで確かめよう」は、確かめられなくなります
遡って測るなら、今日 測るしかない。これは私の側の結論です。
私が今回、7 日分を測り直せたのは、まだ消えていなかったからです。これを 2 ヶ月 放置していたら、比較する相手そのものが無くなっていました。
【技術コラム】読めなかった件数を、装置に言わせる
この件の対処は、注意力ではありません。集計する側が「読めなかった数」を出さないと、何度でも同じことが起きます。
① なぜ気づけないか
zcat A B C | wc -l という形は、パイプの左側が失敗しても、右側は成功します。そして最終的な終了コードは、右側(wc)のものになります。
$ zcat 存在しない.gz 存在する.gz | wc -l
gzip: 存在しない.gz: No such file or directory
18033
$ echo $?
0 ← 成功したことになる
エラーは標準エラー出力に出て、集計は標準出力で成立します。ログに残す運用にしていると、標準エラーの方は見ないことも多いはずです。
② 明日から使える形
- 集計の前に、対象ファイルの一覧を出して、件数を数える。「7 本を対象にした」と先に固定する
- 読めた件数と、対象件数を突き合わせる。合わなければ、集計に進まない
- 長い走査にパイプを付けない。ファイルに落として、終了コードを素で見る
# ❌ 終了コードが wc のものになる
zcat *.gz | wc -l
# ✅ 対象を先に固定して、読めた数と突き合わせる
ls -1 対象パターン > /tmp/targets.txt
echo "対象 $(wc -l < /tmp/targets.txt) 本"
zcat $(cat /tmp/targets.txt) > /tmp/merged.txt 2> /tmp/err.txt
echo "exit=$?"
echo "読めなかった $(wc -l < /tmp/err.txt) 件" # ← ここが 0 でなければ止まる
wc -l < /tmp/merged.txt
③ そして、圧縮されていないファイルを拾う
delaycompress を使っている環境では、*.gz だけでは足りません。
# .gz と 生ファイルを 1 本のストリームにして、1 回で数える
{ zcat 対象.gz ; cat 生ファイル ; } | awk '...'
logrotate の設定でこのオプションを使っているかは、設定ファイルで確認できます。使っていれば、いちばん新しい 1 世代は必ず非圧縮です。
④ 判定に迷ったときの一言
この形を、私は自分の手順書にこう書き残しました。
読めなかったことが、集計の数字には現れない。
だから 「0 件でした」と報告する前に、「何本を対象にして、何本 読めたか」を必ず添える。これだけで、この形は止まります。
あわせて読みたい
同じ日に公開した 4 ヶ月「音色」を追って、犯人は「時間」に居た は、「何を測るか」を間違えた話です。
並べると、こうなります。
- archives/91 ── 正しく測っていた。測る対象が違っていた
- この記事 ── 対象も場所も正しかった。読めなかったことが、見えなかった
どちらも「測っていなかった」のではありません。測っていて、届かなかった話です。