0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

ALB 502 の3層切り分けを実機で裏付けた

0
Posted at

TL;DR

  • 姉妹記事 ALB 502 エラーの原因を特定する「3層切り分け」定石パターン で整理した 「ALB アクセスログ → Target Group ヘルス → Pod ログ・イベント」の3層切り分け を、EKS on EC2 上で実機検証して数字で裏付けたメモです。
  • シナリオ① アプリ例外 で 502 を再現。target_status_code = '-' が決定打、Target Group は healthy のまま という、3層の典型ケースを実機で確認しました。
  • シナリオ② Pod のキャパシティ不足 で 5xx を再現しようとしたら、出てきたのは 502 ではなく 503 でした (この検証構成では 95%が 503)。ALB ログ・TG メトリクス・Pod events の3層を素直に追えば、502 と 503 の使い分けも自然に見えてきます (本文後半の副次節を参照)。
  • 「3層切り分けは本当に使えるのか」を実機で確認したかった人向け。理論編は C-1、本記事は実機裏付け編、という対です。

前提: 3層切り分けとは

ALB が 502 を返したとき、原因を切り分ける最短経路として整理した3層の見方です。詳しくは C-1 記事 を参照ください。本記事はこの図のスコープに沿って実機データで裏付けていきます。

figure1_3layer_scope.png

図1: ALB 502 の3層切り分けスコープ(C-1 記事より再掲)

見るもの 主な確認手段
第1層 ALB アクセスログ Athena / S3 Select で elb_status_code / target_status_code / target_processing_time を確認
第2層 Target Group ヘルスチェック履歴 CloudWatch メトリクス (UnHealthyHostCount / HealthyHostCount / TargetResponseTime)
第3層 Pod ログ・イベント kubectl logs --previous / kubectl get events / kubectl describe pod

「ALB の elb_status_code だけを見ない」「Pod ログだけにも飛びつかない」というのが要点で、第1層で当たりをつけてから第2層・第3層に降りていくと、責任分界が早く決まります。

3層の役割分担を一言で言うと、**「第1層 = HTTP コード追跡 (elb_status_code / target_status_code)」「第3層 = 障害理由追跡 (例外スタックトレース / OOMKilled / Liveness probe failed 等)」**です。HTTP コードを知りたいなら ALB アクセスログを見て、なぜそのコードになったかを知りたいなら Pod ログ・events を見る、という分担になります。Pod ログに HTTP コードが出るかどうかはアプリの実装次第で、出ていなくても3層切り分けは機能します。

なお、この3層切り分けは 502 専用ではありません。本記事で見ていくとおり、503 / 504 の初手にもそのまま使えます。

検証環境

項目 内容
クラウド AWS
ロードバランサ Application Load Balancer (ALB)
アプリ実行基盤 EKS on EC2(マネージドノードグループ、Kubernetes 1.32、Node.js サンプルアプリ)
ルーティング ALB → Target Group(ターゲットタイプ=IP)→ Pod(AWS Load Balancer Controller / Ingress)
分析 Athena(ALB アクセスログ)+ CloudWatch メトリクス + kubectl
負荷生成 hey

サンプルアプリは Node.js の素の HTTP サーバで、/healthy(200 OK のヘルスチェック用)と、シナリオ用のエンドポイント(例外を吐く /exception、CPU を回す /heavy)を持つだけの最小構成です。

シナリオ①: アプリ例外で 502 を再現する

3層切り分けが教科書通りに機能するケースです。

仕掛け

リクエスト処理中にソケットを破棄し、続けて例外を投げます。クライアントから見ると HTTP レスポンスが正常に返らず、ALB は「ターゲットが不正に切断した」と判定して 502 を返します。

// /exception ハンドラの中身
if (req.url === '/exception') {
  console.error('Intentional exception thrown');
  res.socket.destroy();
  throw new Error('Intentional exception for ALB 502 verification');
}

Pod は 2 レプリカ、HPA なし。Liveness / Readiness Probe は /healthy を叩く構成なので、/exception を叩いてもヘルスチェック自体は通り続けます。

負荷をかける

ALB_URL=$(kubectl get ingress sample-app -o jsonpath='{.status.loadBalancer.ingress[0].hostname}')
hey -c 20 -n 500 -t 30 "http://${ALB_URL}/exception"

結果

Status code distribution:
  [502]	500 responses

500 件すべて 502。期待通り 100% 再現できました。ここから3層に降りていきます。

第1層: ALB アクセスログ

Athena で elb_status_code = 502 を抽出し、target_status_code の分布を取ります。

SELECT target_status_code, COUNT(*) AS cnt
FROM alb_access_logs
WHERE elb_status_code = 502
GROUP BY target_status_code;
target_status_code cnt
- 501

target_status_code がすべて - = ターゲットからは「有効な HTTP レスポンス」が返ってきていない。res.socket.destroy() で切断したので、ALB は応答を受け取れないまま 502 を返しています。C-1 記事で挙げた「ターゲットからの応答なし」のパターンそのものです。

target_ip 別の 502 件数も見ます。

SELECT target_ip,
       SUM(CASE WHEN elb_status_code = 502 THEN 1 ELSE 0 END) AS errors_502,
       COUNT(*) AS total
FROM alb_access_logs
GROUP BY target_ip
ORDER BY errors_502 DESC;
target_ip errors_502 total
10.x.x.114:8080 251 304
10.x.x.101:8080 250 402

両 Pod でほぼ均等に 502 = 特定 Pod の障害ではなく、全 Pod 共通のアプリ挙動が原因だと一目で分かります。

第2層: Target Group ヘルスチェック

Target Group 側にはエラーらしいエラーは出ませんUnHealthyHostCount は増加せず、Pod は両方とも healthy のままです。ヘルスチェック (/healthy) は 200 を返し続けているため、ALB は両 Pod を健全と認識し続けています。

$ aws elbv2 describe-target-health --target-group-arn ${TG_ARN} \
    --query 'TargetHealthDescriptions[*].[Target.Id,TargetHealth.State]'
[
  ["10.x.x.114", "healthy"],
  ["10.x.x.101", "healthy"]
]

TG は healthy のまま、なのに 502 が出ている」が、シナリオ① の決定的シグナルです。ALB レイヤや Target Group 設定の問題ではなく、ターゲット側でリクエスト処理中に異常が起きている という当たりが、この時点で付きます。

第3層: Pod ログ・イベント

$ kubectl logs -l app=sample-app --tail=50
Intentional exception thrown
node:internal/errors:496
...
Error: Intentional exception for ALB 502 verification

例外スタックトレースが確認できれば、責任分界は完全にアプリ側です。インフラ側の設定変更は不要。

シナリオ① のまとめ

観測 意味
第1層 (ALB ログ) elb_status_code=502 / target_status_code='-' / 両 Pod 均等 アプリ仕様起因の不正応答
第2層 (TG ヘルス) healthy のまま 少なくともヘルスチェックは通っている (TG 設定や接続性の問題ではない)
第3層 (Pod) 例外スタックトレース アプリの実装バグ

3層を順に降りるだけで、責任分界が完全にアプリ側だと確定 できました。C-1 記事で示した手順がそのまま機能しています。

シナリオ②: Pod のキャパシティ不足では 502 ではなく 503 が出た

当初はシナリオ② でも 502 を再現するつもりでした。ところが実機では 502 ではなく 503 がほとんど (95%) になりました。3層切り分けの定石どおり、第1層→第2層→第3層の順に降りていくと、なぜ 503 になったのかが綺麗に繋がります。

仕掛け

CPU を 300ms ブロックするエンドポイント(/heavy)を、replicas=1、CPU limit=200m、Liveness Probe(timeout=2sfailureThreshold=2)の構成で動かします。CPU 制限がきついため、集中して負荷をかけるとプロセスがスロットルされ、ヘルスチェック (/healthy) も応答できなくなります。

// /heavy ハンドラの中身
if (req.url === '/heavy') {
  const start = Date.now();
  let x = 0;
  while (Date.now() - start < 300) {
    x += Math.sqrt(Math.random() * 1000000);
  }
  res.writeHead(200, { 'Content-Type': 'text/plain' });
  res.end(`processed in ${Date.now() - start}ms\n`);
}

負荷をかける

hey -c 50 -n 2000 -t 30 "http://${ALB_URL}/heavy"

結果

Status code distribution:
  [200]	96 responses
  [503]	1904 responses

502 ではなく 503 が 95%。検証前は「キャパシティ不足 = 502 が出るはず」と思い込んでいましたが、実機では大半が 503 でした。ここから3層に降りて、なぜ 503 になったのかを順に追います。

第1層: ALB アクセスログ — ターゲットに届いていない

target_processing_time の分布を取ると、最初の決定打が出ます。

SELECT
  CASE
    WHEN target_processing_time < 0   THEN '0_no_response'   -- -1
    WHEN target_processing_time < 0.5 THEN '1_under_500ms'
    WHEN target_processing_time < 1.0 THEN '2_500_1000ms'
    WHEN target_processing_time < 5.0 THEN '3_1_5s'
    WHEN target_processing_time < 30  THEN '4_5_30s'
    ELSE                                  '5_over_30s'
  END AS bucket,
  COUNT(*) AS cnt
FROM alb_access_logs
WHERE request_url LIKE '%/heavy%'
GROUP BY 1 ORDER BY 1;
bucket cnt
0_no_response (= -1) 1904
1_under_500ms 2
2_500_1000ms 5
3_1_5s 45
4_5_30s 45

ALB アクセスログでの target_processing_time = -1 は、AWS 公式の定義によれば 「ALB がターゲットへリクエストをディスパッチできなかった、あるいは ターゲットが idle timeout までに応答開始しなかった」 ことを示すシグナルです。今回の検証では:

  • -1 が 1904 件: 503 と同件数。ALB はそもそもターゲットへリクエストを送れていない(=届く先がなかった)。
  • 正常応答した 200 系も 1〜30 秒の長尾: 応答できたリクエストも CPU スロットルで大きく遅延していたことが分かります。

第1層の時点で「ALB → ターゲットの経路の手前で何かが起きている」という当たりが付きます。シナリオ① では数値 (接続後の切断) が混在しましたが、今回は -1 一色なので、接続切断ではなく「そもそも届かなかった」方がほとんどだった ことが読み取れます。

第2層: Target Group メトリクス — 応答時間は急騰、しかし HealthyHostCount は健全に見える

第1層で「届いていない」と分かったら、次は Target Group のメトリクスを見ます。

TargetResponseTime
  通常時:     avg 0.001s / max 0.003s
  負荷投入時: avg 11.067s / max 28.869s

CPU スロットルで応答が10秒オーダーまで遅延しています。これは ALB が Pod を ready と判定しているリクエスト (1〜30秒の長尾、100件弱)があった時間帯です。一方、

HealthyHostCount
  Minimum: 1 (負荷投入時間帯も含めて 1 のまま)

HealthyHostCountMinimum を見ても 1 のまま見え、0 に落ちた瞬間が出てきませんUnHealthyHostCount も同様で、CloudWatch メトリクス上はターゲットが消えていないように見えてしまいます。

これは ALB のメトリクスの集計方式が原因です。ALB は内部で複数のロードバランサノードが動いており、CloudWatch メトリクスは 各ノードが一定間隔で集計した値を集めて作られる ため、Pod 再起動のような 数秒〜十数秒の瞬間的な変化は集計の網目をすり抜けやすい、という性質があります。今回のように Pod 再起動の数秒〜十数秒だけ healthy が 0 になるケースは典型例で、HealthyHostCount だけ見ていると「健全だった」と誤判定してしまいます。

実機で確実に裏取りするには、

  • 連続値メトリクスである TargetResponseTime の急騰 (上記)
  • 同時間帯の HTTPCode_ELB_503_Count 急増 (今回は 1900 超え)
  • 第3層 (Pod) の RESTARTS カウント増加 タイミング一致

の組み合わせが安全です。「HealthyHostCount=0 が見えていないから問題なし」と判断しないことが、この検証で得た教訓です。

第3層: Pod ログ・events — Liveness 失敗で再起動していた

第1層・第2層で「ターゲットには届いていないが、CloudWatch では健全に見える」という一見矛盾した状況が見えました。第3層で謎解きをします。

Warning  Unhealthy  Liveness probe failed: Get "http://10.x.x.101:8080/healthy": context deadline exceeded
Normal   Killing    Container app failed liveness probe, will be restarted
Warning  Unhealthy  Readiness probe failed: Get "http://10.x.x.101:8080/healthy": context deadline exceeded
$ kubectl get pods -l app=sample-app
NAME                          READY   STATUS    RESTARTS      AGE
sample-app-795c84f8b9-vjkpf   1/1     Running   1 (92s ago)   11m

Liveness probe failedKilling のイベントと RESTARTS=1 が直接の証拠です。CPU スロットルで Liveness Probe がタイムアウトし、kubelet がコンテナを kill → 再起動の間、唯一のレプリカが Ready ではなくなった ということです。

これで第1層・第2層が繋がります。AWS 公式のトラブルシューティングでは、ALB が 503 を返す条件として「登録ターゲットがない / 全ターゲットが unused / ready なターゲットがない」が挙げられています。今回は Pod 再起動の数秒〜十数秒、ready なターゲットがゼロになる 状態が断続的に発生していたため、その間に到達したリクエストが 503 を受けました。第1層の target_processing_time = -1 一色も、「ALB がそもそもターゲットへ送れなかった」状態と整合します。第2層の HealthyHostCount が表面上 1 のままだったのは、再起動の窓が短すぎて集計に乗らなかっただけ、というのが種明かしです。

シナリオ② のまとめ

観測 意味
第1層 (ALB ログ) elb_status_code=503 / target_processing_time=-1 がほぼ全件 ALB がターゲットへ送れていない
第2層 (TG ヘルス) TargetResponseTime 急騰、ただし HealthyHostCount は表面上 1 のまま (集計の窓から瞬時の 0 が漏れる) 連続値メトリクスや 503 カウントと組み合わせて裏取り
第3層 (Pod) Liveness probe failed → KillingRESTARTS CPU スロットル → ヘルスチェック失敗 → 再起動の間 ready ターゲットがゼロに

シナリオ① と同じく、第1層 → 第2層 → 第3層 の順に降りるだけで原因まで辿り着けました。コードが 502 でも 503 でも、見るべき場所も降りる順も変わりません。

おまけ: 502 と 503 の使い分け

検証中に副次的に得られた発見として、502 と 503 の見分け方を整理しておきます。今回のように「キャパシティ不足 = 502 が出るはず」と思い込んでいると、現場で迷子になります。AWS 公式のトラブルシューティングと照らし合わせると、各コードの原因と対応はこう整理できます。

コード 典型シグナル 主な原因 (AWS 公式準拠) 一次対応
502 target_status_code='-' / TG は healthy のまま アプリ側の不正レスポンス・接続切断・HTTP ヘッダ不正・TLS ハンドシェイク失敗 など アプリ修正 (例外ハンドリング・接続管理など)
503 target_processing_time=-1 がほぼ全件 / TargetResponseTime 急騰 / HealthyHostCount は瞬時の 0 を取りこぼしうる 登録ターゲットがない / 全ターゲットが unused / ready なターゲットがない (今回のような Pod 再起動・レプリカ不足・HPA 未設定・リソース不足はこの状態を作る一因) レプリカ増、HPA、リソースチューニング、Liveness Probe しきい値の見直し
504 target_processing_time が大きい / ALB idle timeout 超過 アプリ処理遅延、接続 timeout、NACL、Content-Length 不整合、Lambda、TLS ハンドシェイク timeout など アプリのパフォーマンス改善、idle timeout 調整、NW 経路確認

「502 と 503 のどちらが多いか」を最初に見るだけで、調査の方向性が変わる ということです。3層切り分けの第1層(ALB アクセスログ)の集計で elb_status_code 別の件数を出す癖をつけておくと、この見分けは無料で付いてきます。

まとめ

  • C-1 記事で整理した 「ALB アクセスログ → Target Group ヘルス → Pod ログ・イベント」の 3層切り分けは、実機でもそのまま機能 しました。
  • シナリオ① 502 の決定打は target_status_code = '-' + TG healthy 維持、原因はアプリ層。
  • シナリオ② は 502 ではなく 503 がほとんどでしたが、3層切り分けの手順自体は変わらず、第1層 (target_processing_time = -1 が大半) → 第2層 (TargetResponseTime 急騰、HealthyHostCount は集計の窓を漏れる) → 第3層 (Liveness probe failedRESTARTS 増) の順で原因まで辿れました。
  • 副次的に 「Pod のキャパシティ不足では 502 ではなく 503」 という気付きも得られました。3層を素直に追えば、コードに依らず原因仮説に直結します。

実務での初動の合言葉として、まずは elb_status_code の件数を集計する」 をお勧めします。502 が多いのか、503 が多いのか、それだけ分かれば、本記事の3層切り分けでどちらに振っていくべきかが決まります。

理論編はこちら: ALB 502 エラーの原因を特定する「3層切り分け」定石パターン(AWS アクセスログ × Target Group × EKS Pod)

出典・参考

0
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?