TT Lab
はじめる
学ぶ 学習パス コース

nginx障害対応

504なのに掛かったタイムアウトが違う

TT Labで続きを見る

一言でいうと

502と504は症状の名前であり、犯人の名前はすでにerror.logの1行に書かれています。その行を読まずに推測を始めた瞬間から、時間が漏れ始めます。

なぜ必要なのか

障害対応で最も高くつくミスは、原因を見つけられないことではなく、間違った原因を確信することです。

典型的な1日は、次のように流れます。モニタリングに502が出ます。「バックエンドが死んだのだろう」と、WASを再起動します。直りません。「それなら遅いのか」と、proxy_read_timeoutを30秒に上げます。直りません。「サーバーが足りないのか」と、インスタンスを増やします。直りません。3時間が過ぎましたが、その間error.logは最初の1分から答えを持っていました。

そこでこのコースは、ログを読むことから始めません。障害を自分で作ってみます。死んだポート、接続を受け付けないポート、遅い応答、バッファーより大きいヘッダーを手で作り、そのときnginxが何と書くかを目で確かめます。一度見た文言は、次に実戦で見たとき0.5秒で見分けられます。

4つの署名

下の4行は、ラボのイメージ(nginx 1.24.0)で実際に再現して書き写したものです。行の中のどの部分が犯人を指しているかも示してあります。

① アップストリームがそもそも起動していない → 502

[error] connect() failed (111: Connection refused) while connecting to upstream,
  request: "GET /dead/ HTTP/1.1", upstream: "http://127.0.0.1:9999/"

connect() failedは、TCP接続そのものが拒否されたという意味です。ここでどんなタイムアウトを上げても、何も起こりません。502でタイムアウトを上げるのが無駄な理由は、この1行にあります。待つ時間さえなかったのです。カーネルがすぐにRSTを返しました。

② アップストリームは起動しているが遅い → 504

[error] upstream timed out (110: Connection timed out) while reading response
  header from upstream, request: "GET /app/slow?d=10 HTTP/1.1"

③ アップストリームが接続すら受け付けない → 504

[error] upstream timed out (110: Connection timed out) while connecting to
  upstream, request: "GET /hang/ HTTP/1.1"

②と③を並べて見てください。ステータスコードも同じ504で、括弧内のエラー番号も同じ110です。違うのは、後ろのフレーズ1つだけです。

フレーズ 実際に引っかかった設定
while connecting to upstream proxy_connect_timeout
while reading response header from upstream proxy_read_timeout
while sending request to upstream proxy_send_timeout

このフレーズを読まないとどうなるかが、このコースの核心の場面です。ラボのステップ5で、その場所にproxy_read_timeout 30sを入れます。30秒待つと宣言したのです。ところが、リクエストは相変わらず2秒で504になって落ちます。引っかかったのはproxy_connect_timeout 2sだったからです。上げたタイムアウトは、発動したタイムアウトではありませんでした。

これが「タイムアウトを上げたのに直らないんですが」の正体です。上げる値を選ぶ前に、ログのフレーズを読む必要がある理由です。

④ レスポンスヘッダーがプロキシバッファーより大きい → 502

[error] upstream sent too big header while reading response header from upstream,
  request: "GET /app/bighdr?n=8000 HTTP/1.1"

これが4つの中で最も厄介です。サーバーは問題なく生きており、ヘルスチェックはずっと緑で、curlで叩いてみると200が返ります。特定のユーザーだけが502を受け取ります。その特定のユーザーは、たいていSSOでログインしてセッションクッキーが大きい人か、権限リストが長くてレスポンスヘッダーが膨らんだ人です。

proxy_buffer_sizeのデフォルトは4kで、レスポンスヘッダー全体がこのバッファー1つに収まる必要があります。超えると、nginxはレスポンスを受け取ったのに処理できず、502を返します。仕様が言う502は「上流が死んだ」ではなく、「ゲートウェイが上流から無効なレスポンスを受け取った」であり、このケースがまさにその定義に当たります。

ここに、もう1つ罠があります。proxy_buffer_sizeだけを16kに上げると、nginxはそもそも起動しません。

[emerg] "proxy_busy_buffers_size" must be less than the size of all
  "proxy_buffers" minus one buffer

proxy_buffersも一緒に大きくする必要があります。明け方にこのメッセージを初めて見ると、手が固まります。一度見てしまえば、何でもありません。

access.logの2つの欄で切り分ける

error.logが犯人を指すなら、access.logはどちらの方向を見るかを決めてくれます。ログフォーマットにこの3つの変数を入れておくことが、このコースで最も安上がりな投資です。

log_format ev '$time_local $status ut=$upstream_response_time '
              'rt=$request_time us=$upstream_status "$request"';

実測した3行を見てみましょう。

504 ut=3.004 rt=3.004 us=504 "GET /app/slow?d=10 HTTP/1.1"
200 ut=0.049 rt=4.173 us=200 "GET /app/big?n=8000000 HTTP/1.1"
413 ut=-     rt=0.002 us=-   "POST /app/upload HTTP/1.1"

us=-を読めるようになれば、「うちのアプリのログにはそんなリクエストはありませんが」という返答が、根拠のあるものになります。読めなければ、その返答はただの責任転嫁に聞こえます。

現場での姿

診断のはしごの最後の段を、先に踏みます。プロキシを飛ばして、アップストリームに直接、元のHostヘッダーを維持したまま1回叩いてみます。

curl -sSI -H 'Host: api.example.com' http://127.0.0.1:8080/health

ここで正常なら、問題はプロキシとアップストリームの間(設定・ヘッダー・バッファー・タイムアウト)にあり、ここでも失敗するならプロキシは無実です。この1回で、探索空間が半分になります。-H 'Host: ...'を外すと、バーチャルホストのルーティングがかかっている場合はまったく別のアプリに行くため、比較が無意味になります。

症状だけが書かれたチケットを受け取ったら、まずコードとフレーズを尋ねます。「502が出ます」は、ほとんど情報がありません。「502で、ログにconnect() failed (111: Connection refused)が出力されています」は、事実上の原因報告です。この習慣1つが、チームの平均復旧時間を変えます。

次のラボですること

Pythonで障害発生器を作り、死んだポート・応答しないポート・遅い応答・大きなヘッダーを自分で作ります。そして4つのケースそれぞれで、ステータスコードとerror.logのフレーズ、実際に引っかかったタイムアウトを、証拠ファイルとして残します。最後に、4行の判定表と障害報告書を書きます。