Dev Study
← SLI を数える — 分母と分子を決める
レッスン 4 / 10·約 8 分·第28期 SLI を数える

失敗は、見た層のログにしか残らない — アプリ・nginx・外からの3か所で数える

リクエストがアプリケーションに届くまで
  1. ブラウザURL入力今ここ
  2. DNS名前→IP
  3. ルータ経路選択
  4. ロードバランサ振り分け
  5. Nginx受け口今ここ
  6. アプリ処理今ここ
  7. DB保存

SLI の値は測りますが、何を数えるかは決めます。今回決めるのは、数える場所です。

まず結論

同じ壊し方でも、行が残る場所は層ごとに違います。アプリ停止・読み取りタイムアウト・nginx 停止の3つを同じ1分間に起こすと、可用性は外からの prober で 53.8%、nginx で 66.7%、アプリで 100% と、3つの別の数になりました。

prober の応答なし(000)を分母から外すと 66.7% になり、nginx と同じ数になります。外で見えた失敗が、分母の決め方ひとつで数字から消えます。

? 読む前に予測

nginx の奥のアプリを10秒止める、アプリを5秒寝かせて nginx にタイムアウトさせる、nginx を10秒止める。この1分間の可用性(5xx 以外 ÷ 全件)を、アプリのアクセスログだけで数えるとどうなるでしょうか。

当てることが目的ではありません。外した予測ほど記憶に残るので、直感で選んでください。

抽象原理

行を書くのは、その要求を見た層だけ

要求は prober → nginx → アプリの順に進み、各層は自分が受け取った要求についてだけ行を書きます。nginx の文書は Requests are logged in the context of a location where processing ends. と書き、$request_time を time elapsed between the first bytes were read from the client and the log write after the last bytes were sent to the client と定めます。行は処理が終わったときに、その層が見た結果で書かれます。

手前で止まった要求は、奥のログの分子にも分母にも現れません。RFC 9110 は 503 の Note で Some servers might simply refuse the connection. と書きます。接続を拒まれた要求には、拒んだ側のログに行がありません。

この回で決めること: 数える場所。 同じ1分間の同じ要求でも、どの層のログを数えるかで分母が変わり、失敗の種類ごとに良い・悪い・存在しないが入れ替わります。どの層で数えるかは、SLI 仕様に書く決め事です。

層ごとに、見えた要求だけが行になる(実測 r2 の件数)
prober(外)送った全件に1行。応答なしは 000
nginx に届いた要求だけ
nginx処理が終わった時点で1行
アプリに転送できた要求だけ
アプリ応答を送る前に1行
  • ・分母は奥ほど小さい: 52 → 42 → 32
  • ・nginx 停止中の10件は nginx とアプリに無く、アプリ停止中の10件はアプリに無い
具体実物

同じ1分間を、3つのログで数える

環境は nginx 1.30.4(nginx:1.30.4-alpine)、Python 3.14.7(python:3.14-slim、http.server.ThreadingHTTPServer)、curl 8.16.0(curlimages/curl:8.16.0)、Docker Engine 28.4.0(Docker Desktop、aarch64)、2026-09-28 です。nginx は upstream にアプリ1台を置き、proxy_connect_timeout 2s と proxy_read_timeout 2s に縮めました(既定はどちらも 60s)。prober は 60 秒間、約1秒ごとに nginx へ GET を送ります。

その1分間に、10秒目からアプリのプロセスを10秒止め、30秒目からアプリを10秒間「応答前に5秒寝る」状態にし、45秒目から nginx を10秒止めました。良い = 5xx でも 000 でもない件数、として3つのログを数えた結果です。

count.py の出力(r2。原文のまま)コマンド出力
window (prober start..end, UTC): 14:12:40 .. 14:13:40 (60s)
where total good bad avail breakdown
prober(外) 52 28 24 53.8% {'000': 10, '200': 28, '502': 10, '504': 4}
nginx 42 28 14 66.7% {'200': 28, '502': 10, '504': 4}
app 32 32 0 100.0% {'200': 32}

件数はつながっています。prober 52 = nginx 42 + nginx 停止中の 000 が10。nginx 42 = アプリ 32 + アプリ停止中の 502 が10。アプリの 32 は nginx の 200(28)に、nginx が 504 と書いた4件を足した数です。同じ手順の再実行(r3)でも nginx 66.7%・アプリ 100.0% で、prober は 51 件中 28 件の 54.9% でした。

1分間の外で、1回ずつ2つの壊し方も試しました。まとめると、1つの要求に3つの判定が付きます。

壊し方ごとに各層が残したもの(r2 の生ログから整理)表
壊し方 外(curl) nginx の行 アプリの行
(a) アプリのプロセスを止める 502 502(接続拒否) なし
(a') アプリのコンテナごと止める 504 504(接続タイムアウト) なし
(b) アプリが5秒寝る 504 504(読み取りタイムアウト)200(約3秒後)
(c) nginx を止める 000(exit 7) なし なし
(d) クライアントが1秒で打ち切る 000(exit 28) 499 200(約4秒後)

(a') と (d) は1分間の外で各1回、prober とは別のクライアントコンテナから curl で送りました。「アプリを止めると 502」は止め方次第でした。接続を拒まれれば 502(error_log は connect() failed (111: Connection refused))、接続先が消えると 504 です。接続拒否で 502 になる理由も、読み取りタイムアウトで 504 になることも、nginx の文書には書かれていません(確認範囲: proxy・upstream モジュールの文書全文)。どちらもこの版での実測です。

✓ ここまでの確認

アプリを5秒寝かせ、nginx が2秒で 504 を返した要求について、アプリのアクセスログには何が残りましたか(Python 3.14.7 の http.server)。

抽象原理

2つの層が、同じ要求を逆に数える

(b) の1件を、4つのログから時刻順に並べます。

r2 の (b) 1件目(prober.log・nginx.access.log・app.log・app.stderr.log から1行ずつ。stderr はトレースバックの最終行で時刻なし)追跡ログ
2026-09-28T14:13:10Z prober 504 2.002483 0
2026-09-28T14:13:12+00:00 nginx status=504 upstream_status=504 request_time=2.001 upstream_response_time=2.001 "GET / HTTP/1.1"
2026-09-28T14:13:15.453Z app "GET / HTTP/1.1" 200 -
BrokenPipeError: [Errno 32] Broken pipe

nginx が 504 と書いた約3秒後に、アプリが同じ要求を 200 と書いています。http.server の send_response() は最初に log_request() を呼び、ソケットへ書くのはそのあとです。書き込みの失敗は stderr の BrokenPipeError に別に出ました(4回。504 の件数と同じ)。アプリが失敗を知らないのではありません。アクセスログの行が 200 のままなので、status 列で数えるかぎり良いに入るのです。 他の実装(gunicorn や Node など)が同じ行を書くかは確かめていません。

アプリは生きていて、応答を作り終えていました。504 はアプリが落ちた証拠ではありません(第12期「タイムアウトは証拠ではなく推測」)。upstream が1台の群では max_fails などは無視されるので(such a server will never be considered unavailable)、nginx がアプリを外したわけでもありません。502 も 504 も、毎回の試行の結果です。

(d) の 499 は、nginx のソースが HTTP does not define the code for the case when a client closed the connection と書いて導入した値です。RFC 9110 の §15 の一覧にも、保存した nginx の公式文書(log・proxy・upstream・core モジュールと変数索引)にも 499 はありませんでした。付録A の We only count HTTP 5XX status messages as error codes; everything else is counted as success. を字面どおり当てると、499 は成功に入ります。悪いに入れるか、分母から外すかは、決めることです。

具体実物

外の失敗は、分母の決め方で消える

(c) で nginx を止めた10秒間、prober は 000(curl の終了コード 7、Failed to connect to host.)を10件記録し、nginx とアプリのログは空でした。Workbook 第2章はロードバランサで数える例を選んだ理由を closer to the user’s experience than those from the application server’s logs と書き、付録A は同じ方式に may fail to accurately measure cases where user requests didn’t reach the load balancer と注意書きを付けています。(c) はその注意書きの実物です。

prober で数えても、000 を「応答が無いので判定できない」として分母から外すと、次のようになります。

r2 の同じ1分間を、場所と分母の決め方で数え直す(python3 で検算)表
数え方 良い / 分母 可用性
prober(000 も悪いに数える) 28 / 52 53.8%
prober(000 を分母から外す) 28 / 42 66.7%
nginx 28 / 42 66.7%
アプリ 32 / 32 100.0%

外で数えているのに、nginx と同じ数になりました。nginx 停止の失敗は、どのサーバのログにも無いうえに、外の数字からも消えています。SRE Book 第4章も not measuring behavior at the client can miss a range of problems that affect users but don’t affect server-side metrics と書いています。ただし prober も全部を見るわけではなく、第15期で読んだとおり may miss issues that affect only a subset of users です。

✓ ここまでの確認

prober の 52 件(200 が28、502 が10、504 が4、000 が10)から、000 を「無効」として分母から外すと、可用性はいくつになりますか。

⇄ 2つを見比べる
具体例 A

読み取りタイムアウトの 504

同じ要求に nginx は 504、アプリは約3秒後に 200 の行を書いた。2つの層が同じ要求を逆に数え、アプリのログで数えると失敗が良いに入る。

具体例 B

nginx 停止中の接続失敗

prober は 000 を記録し、nginx とアプリには行が無い。どのサーバのログにも失敗が無く、外で数えても 000 を分母から外せば消える。

片方は行が逆の値で残り、片方は行が無い。共通する構造は何でしょうか。

それぞれの失敗を、どの層が見ていたかを書き出してみてください。

この章のまとめ

  • 各層は自分が見た要求にだけ行を書く。同じ1分間が prober 53.8%(28/52)、nginx 66.7%(28/42)、アプリ 100%(32/32)になった。
  • (b) では nginx の 504 の約3秒後にアプリが 200 を書いた(Python 3.14.7 の http.server)。失敗は stderr に別に出る。
  • アプリを止めると、接続拒否なら 502、接続先が消えれば 504(nginx 1.30.4 の実測。文書は 504 を返すとは書いていない)。
  • 499 は HTTP に無い nginx の記録用の値。どこに数えるかは決めるもの。
  • prober の 000 を分母から外すと 28/42 = 66.7% で nginx と同じ。外の失敗が分母の決め方で消える。

自分の現場で確かめる

読んだだけでは身につきません。手元の環境で実際に見てみてください。

理解度チェック

読んだ直後は「分かった」と感じやすいものです。実際に解いて確かめてください。

問題 1 / 3正解: 0

nginx のアクセスログに出る 499 について、確認できた範囲で正しいのはどれですか。

用語集(3語)
prober
サービスの外から要求を送り、結果を記録する仕組み。本回は curl を約1秒ごとに回すコンテナ。応答が無ければ curl は 000 を表示した(実測)。
499
nginx が、応答を送る前にクライアントが接続を閉じた要求を記録するための値。HTTP には定義が無い。どの側に数えるかは SLI 仕様で決める。
proxy_read_timeout
nginx が上流からの読み取りを待つ時間。既定 60s。文書は超えると接続を閉じるとだけ書く。本回は 2s にし、504 になるのを実測した。