こんにちは、ネクストモードのゆきなわです。
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 エラーを調査した、まなべによる下記記事もあわせてご覧ください。
調査対象は、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 セッションを確立できなかった接続の集計値Failed:UnmappedConnectionError：失敗した個々の接続のステータス / 理由。送信元は CloudFront のオリジン向け IP アドレス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 → バックエンドという通信経路を、検証用に単純化し最小構成で用意しました（下図）。
検証環境の構成
主な条件は次の通りです。
テストクライアントは 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);
試行の構成は次の通りです。
このリクエスト頻度は、単純平均では実環境（CloudFront で平均約 59 リクエスト/秒）と同程度です。ただし、クライアント数やセッション数、リクエストの時間分布まで再現した負荷試験とはしていません。
なお、テストクライアントから CloudFront までの HTTP/2 ストリームと、CloudFront から ALB への HTTP/1.1 接続は別の通信区間です。CloudFront はオリジンとの接続を独自に確立・再利用するため、ストリーム数と ALB 側の接続数は一対一には対応しない点にご注意ください。
試験中の通信の流れは次の通りです（下図）。
ストリーム中断時の通信の流れ
| 中断タイミング | 中断したストリーム | TLS エラー （CloudWatch メトリクス） |
TLS エラー （ALB 接続ログ） |
|---|---|---|---|
| 10 ms | 900 / 900 | 7 | 7 |
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 内部の接続終了処理は直接観測できないため、あくまでもログと試験結果に基づいた推定になります。
ClientCommError、ALB の ClientTLSNegotiationErrorCount、接続ログの Failed:UnmappedConnectionError が揃って現れました。ClientCommError やオリジン系エラー）も同じ時間帯で見ます。今回はこれらを突合し、TLS エラーが ClientCommError と同じ時間帯に低頻度で発生し、CloudFront、ALB、ターゲットの障害を示す 5xx を伴わないことを確認しました。ただし、該当リクエストでは、ビューワーへのレスポンスが中断されたことが ClientCommError として記録されています。ClientTLSNegotiationErrorCount について、実環境のログ調査から検証環境での再現までを紹介しました。接続が途中で終われば TLS ハンドシェイクも失敗するという意味では当たり前の結果ですが、ビューワー側の中断がオリジン側の記録にも現れるかどうかは必ずしも自明ではありませんでした。検証の結果、ALB 接続ログに失敗が記録され、ClientTLSNegotiationErrorCount にも計上される場合があること、また、記録の有無は中断のタイミングによってばらつくことを確認しました。
調査には、運用で取得していた ALB 接続ログと CloudFront 標準ログを利用しました。両者を突き合わせることで、HTTP リクエストとして記録される前に発生した接続失敗まで追うことができました。本記事がメトリクスだけでは判断がつかない事象を調査する際の参考になれば幸いです。