【AWS】低頻度で発生する ALB の ClientTLSNegotiationErrorCount を CloudFront ログから読み解く

はじめに

こんにちは、ネクストモードのゆきなわです。

CloudFront のオリジンに Application Load Balancer（ALB）を設定した環境で、ALB の CloudWatch メトリクス ClientTLSNegotiationErrorCount がごく低頻度で断続的に計上されていたため、原因を調査しました。本記事では、実環境のログを調べ、検証環境でリクエストを意図的に中断して再現した過程を紹介します。

本記事のポイント

• ビューワーから CloudFront へのリクエストを中断する試験で、その先の ALB に TLS 接続の失敗が記録されるケースを再現しました。このとき、CloudWatch メトリクスと ALB 接続ログでは、TLS エラーの件数も一致しました。
• ただし、何 ms 以内に中断すると発生する、といった明確な閾値は確認できず、同じ中断タイミングでも発生件数にばらつきがありました。
• 証明書や TLS 設定に不備がなくても、ALB の ClientTLSNegotiationErrorCount は計上されることがあります。今回は CloudFront と ALB の 5xx やオリジン系のエラーは観測されませんでした。

関連記事として、CloudFront から ALB への TLS ハンドシェイクに起因する 502 エラーを調査した、まなべによる下記記事もあわせてご覧ください。

低頻度で計上される ClientTLSNegotiationErrorCount

調査対象は、CloudFront、ALB、バックエンド（EC2）からなる企業 Web サイトです。CloudFront から ALB への通信にも HTTPS を使用しており、この区間の TLS は ALB で終端しています。平日の日中にアクセスが集中し、1 日あたり数百万件規模のリクエストを処理します。運用監視では、ALB の ClientTLSNegotiationErrorCount が全体のリクエスト数に対してごく低頻度で断続的に計上される状況が続いていました（下図）。ただし、5xx エラーは伴っておらず、メトリクスの集計値だけでは原因が判断できない状況でした。

実環境で断続的に計上された ClientTLSNegotiationErrorCount

なお、本システムでは、マネージドプレフィックスリストを用いて、ALB への接続元を CloudFront に限定しています。そのため、ALB に TLS 接続するクライアントは CloudFront であり、このメトリクスは CloudFront と ALB の間の TLS 接続の失敗回数を表しています。以降、CloudFront へ接続する側をビューワー、接続先の ALB をオリジンと呼びます。

ログ調査

同じ時間帯について、次の 3 点を確認しました。

• ClientTLSNegotiationErrorCount（CloudFront → ALB）：TLS セッションを確立できなかった接続の集計値
• ALB 接続ログの Failed:UnmappedConnectionError：失敗した個々の接続のステータス / 理由。送信元は CloudFront のオリジン向け IP アドレス
• CloudFront 標準ログの ClientCommError（ビューワー → CloudFront）：ビューワーとの通信上の問題により応答が中断されたリクエストの結果タイプ

対象とした時間帯（平日日中の 7 時間）の ALB 接続ログでは、106,232 接続のうち 32 件（約 0.03%）が Failed:UnmappedConnectionError で失敗していました。いずれも CloudFront のオリジン向け IP アドレスからの TLS 1.2・ハンドシェイク未完了の接続でした。1 秒単位で見ると 32 件は 16 秒に分布しており、その 16 秒すべてで、CloudFront ログにも ClientCommError が記録されていました。

一方、この時間帯全体では、ClientCommError が記録された秒は約 1 割でした。この時間的な重なりに加え、大半の接続は同じ条件で成功し、同じ時刻に 5xx やオリジン系のエラーも見られなかったことから、設定の不備による恒常的な失敗というより、個々のビューワーの通信中断に関連するものではないかと考えました。

仮説

公開情報では、CloudFront が応答する前にビューワーが接続を閉じた場合は sc-status = 000、CloudFront とビューワー間の通信上の問題で応答が中断した場合は ClientCommError が記録されると説明されています。また、TLS 確立前の失敗は ALB 接続ログで確認できます。ただし、ビューワー側の通信中断がオリジン TLS 接続の失敗として現れるかを両者のログで突き合わせた事例は、調べた範囲では見つかりませんでした。

そこで、次の仮説を立てました。

ビューワーがレスポンスの完了前にリクエストを中断すると、CloudFront はビューワーとの通信を ClientCommError として記録する。その時点で CloudFront から ALB への TLS 接続が確立途中だった場合、その接続も完了せず、ALB では ClientTLSNegotiationErrorCount と Failed:UnmappedConnectionError として記録される。

CloudFront 標準ログと ALB 接続ログには共通の接続 ID がなく、実環境のログだけでは個々の接続を一対一に結びつけられません。そのため、本番から切り離した検証環境を構築し、意図的にリクエストを中断して同じ組み合わせが現れるかどうかを検証しました。

検証方法

ビューワー → CloudFront → ALB → バックエンドという通信経路を、検証用に単純化し最小構成で用意しました（下図）。

検証環境の構成

主な条件は次の通りです。

• CloudFront のキャッシュを無効化し、各リクエストがオリジン経路を通るようにする
• CloudFront から ALB へは、実環境でエラーが記録された接続と同じ HTTPS（HTTP/1.1、TLS 1.2）で接続する
• バックエンドは 2 秒待ってから応答し、レスポンスが返る前にストリームを中断できる状態を保つ（CloudFront と ALB 間の TLS ハンドシェイクを遅らせる設定ではない）
• CloudFront 標準ログ、ALB アクセスログ、ALB 接続ログ、CloudWatch メトリクスを同じ試験時間帯で突合する

テストクライアントは Node.js の http2 モジュールで実装しました。1 本の HTTP/2 セッション上に複数のストリームを作成し、リクエスト開始から一定時間後に RST_STREAM(CANCEL) を送ります。この待ち時間（cancelAfterMs）を以降では中断タイミングと呼びます。

ストリームの中断に関係する部分を抜粋すると、以下の通りです。

const stream = session.request(headers, { endStream: true });

setTimeout(() => {
  if (!stream.closed && !stream.destroyed) {
    stream.close(constants.NGHTTP2_CANCEL);
  }
}, cancelAfterMs);

試行の構成は次の通りです。

• 1 試行は 3 ラウンド × 300 リクエストの計 900 ストリーム（HTTP/2 では 1 リクエストが 1 ストリームに対応）
• 同時実行数は 100、ラウンド間隔は 6 秒
• リクエスト頻度は実測で約 64 リクエスト/秒（中断タイミングを 10 ms に設定した試行）

このリクエスト頻度は、単純平均では実環境（CloudFront で平均約 59 リクエスト/秒）と同程度です。ただし、クライアント数やセッション数、リクエストの時間分布まで再現した負荷試験とはしていません。

なお、テストクライアントから CloudFront までの HTTP/2 ストリームと、CloudFront から ALB への HTTP/1.1 接続は別の通信区間です。CloudFront はオリジンとの接続を独自に確立・再利用するため、ストリーム数と ALB 側の接続数は一対一には対応しない点にご注意ください。

試験中の通信の流れは次の通りです（下図）。

ストリーム中断時の通信の流れ

結果

エラーの再現

10 ms の試行では、CloudWatch の ClientTLSNegotiationErrorCount が 7 件、同じ集計時間帯の ALB 接続ログにある Failed:UnmappedConnectionError も 7 件となり、件数が一致しました。

証明書や TLS 設定を変更せず、ビューワー側のストリームを中断した試験で、実環境と同じメトリクスと接続ログの組み合わせが現れました。7 接続はいずれも TLS 1.2・実環境と同じ暗号スイートで、tls_handshake_latency は -（ハンドシェイク未完了）でした。同じ時間帯の CloudFront ログには ClientCommError が記録され、5xx は 0 件でした。なお、TLS エラーの 7 件は ALB への接続単位の件数で、中断した 900 ストリームとはカウントする対象が異なります。

中断タイミングを変えた追加試験

その他の条件は変えず、中断タイミングだけを 10〜250 ms の範囲で段階的に変えた追加試験も行いました。ALB 接続ログでは、合計 32,874 接続のうち 1,311 件で TLS エラーを観測しました。なお、この件数は意図的に大量の中断を発生させた検証条件でのもので、実環境の発生率を示すものではない点にご留意ください。

また、発生の有無を分ける明確な閾値は見つかりませんでした。中断タイミングと発生件数は単純な比例関係にならず、同じ 10 ms でも試行によって件数が変わるなど、観測上は確率的に現れる振る舞いを示しました。実測では 10 ms の設定でも、ストリームが閉じるまでの平均時間は試行によって約 94〜116 ms でした。

上記の結果は、設定した時間そのものではなく、TLS ハンドシェイク中のオリジン接続とビューワー側の中断が重なった場合に発生する、という仮説と整合しています。ただし、CloudFront 内部の接続終了処理は直接観測できないため、あくまでもログと試験結果に基づいた推定になります。

調査と検証から分かったこと

1. ビューワー側の通信中断とオリジン側の記録：TLS ハンドシェイク中の接続が終了すれば失敗として記録されること自体は、仕組み上は自然です。個々の接続を一対一に追跡したわけではありませんが、ビューワー側のストリームを中断する試験で、CloudFront の ClientCommError、ALB の ClientTLSNegotiationErrorCount、接続ログの Failed:UnmappedConnectionError が揃って現れました。
2. 実環境での見立て：実環境では読み込み中の離脱や再読み込み、画面遷移などで、リクエストが途中で中断されることがあります。一方で、CloudFront はオリジンとの接続を再利用するため、TLS ハンドシェイクが発生するのは新規に接続を確立する一部のリクエストに限られます。中断がたまたまこのハンドシェイクと重なったときにだけ TLS エラーが記録されるとすれば、計上がごく低頻度で断続的だったことも自然に説明できそうです。
3. 証明書や TLS 設定に不備がなくても計上されるケース：今回は同じ TLS 1.2 と暗号スイートで大半の接続が成功し、失敗は断続的でした。少なくとも、証明書や TLS 設定の恒常的な不備だけでは説明しにくい結果でした。
4. メトリクスとログによる影響範囲と原因の切り分け：ALB 接続ログでは、総接続数に占める TLS 接続失敗の割合と失敗理由を確認します。あわせて、ALB とターゲットの 5xx、CloudFront の 5xx エラー率、CloudFront 標準ログの結果タイプ（ClientCommError やオリジン系エラー）も同じ時間帯で見ます。今回はこれらを突合し、TLS エラーが ClientCommError と同じ時間帯に低頻度で発生し、CloudFront、ALB、ターゲットの障害を示す 5xx を伴わないことを確認しました。ただし、該当リクエストでは、ビューワーへのレスポンスが中断されたことが ClientCommError として記録されています。

おわりに

参考ドキュメント

• Application Load Balancer の CloudWatch メトリクス - AWS
• Application Load Balancer の接続ログ - AWS
• CloudFront 標準ログのフィールド - AWS
• カスタムオリジンのリクエストとレスポンスの動作 - AWS
• CloudFront マネージドプレフィックスリスト - AWS
• ALB の ClientTLSNegotiationErrorCount メトリクスが記録されているのにアクセスログに出力されないのはなぜですか - DevelopersIO