日経電子版ウェブで起きた謎のCDNエラーと Header Overflow

この記事は Nikkei Advent Calendar 2020 13日目の記事です。

日経電子版ウェブチームのエンジニアの宮本です。普段はサーバ・エッジサイドを主に担当しており、今回はその内のエッジ、CDNについてお話します。

（ところで先月下旬にFastly社のYamagoya Traverse 2020において Fastlyを用いたFeature Togglesの実装についてお話させていただいたのでよければこちらもご覧ください。）

背景と問題

ある日を境目に起きた問題

半年〜1年ほど前、社内の方方から 「ステージング環境にアクセスできない」という問い合わせがありました。 調査に乗り出したものの、自分の環境では特に問題を見受けられず、再現に苦しんでいた記憶があります。

手元の環境で再現しなかったことから、社内VPNが悪さをしている？CDNが意図せず何かで弾いている？など様々な可能性が想定されました。

また再現性の低さだけではなく、

• クライアントに返されるヘッダに情報がない
• CDNのアクセスログにも入っていない

という状況で、有効な手がかりを掴めないまま時間だけが過ぎていました。

一旦は、件数が少なく社内のステージング環境という一部で起きる謎のエラー、ということで様子見・要経過観察、として具体的な対応を中止しました。

徐々に増加する謎のエラー

ところがこの謎のエラーの遭遇頻度が徐々に増え、再び調査・対応を始めたのが最初の報告から1ヶ月ほど経った辺りです。

依然として再現条件は確定できず、でしたが結果的に何となく絞り込めた再現しやすい条件は以下の通りでした。

• ステージング環境（本番では起きない）
• Chrome Canary（stableでは起きない）
• ログイン後
• etc.

再現時のレスポンス

HTTP/1.1 503 Service Unavailabale

header overflow

問題が発生した際のレスポンスの特徴は先述の通り、

• 我々のVCLで付けたはずの resp.http.* が付いていない
• CDNのアクセスログに残っていない
• リクエストがオリジンサーバに到達していない

という点から VCLを通る前の段階で弾かれている、ということが分かりました。

原因

結論から述べると、原因は header overflow でした。（最初からレスポンスに書いてあった...）

Fastlyのドキュメント / Request and response limits にあるように、 header overflow エラーとなるケースは以下の通りです。

• Request header size: > 69KB
• Request header count: > 96
• Response header count: > 96

上の2つは いわゆる req/resp オブジェクトの .http プロパティに関するサイズ・数の制約です。例えば数の制約の場合、

set req.http.h1 = "1";
set req.http.h2 = "2";
...
set req.http.h100 = "100";

これで制約を超えてしまい header overflow となります。

実際に我々の環境でもこの 「Request header count: > 96」制限に引っかかっていた、つまりリクエストヘッダに 97 個以上のヘッダをsetしていたことになります。

ただ今回、VCLや実際のリクエストを確認した際には 問題なかった ため実際に上の条件で header overflow が起きている可能性を無意識に除外してしまっていたことで、発見の遅れにつながってしまいました。この点についての反省は今後の教訓として活かしていきたいと思っています。

なぜ確認時に問題なかったのか

具体的に req.http の定義や利用について見ていきましょう。

req.httpの特殊性

VCLの req.http は他のビルトインプロパティと比べやや特殊な使われ方をします。例えば、以下のようにサブルーチンの最後に var.* といったローカル変数をキャストして req.http に詰めることがよくあります。

sub vcl_recv {
    declare local var.isSubresourceRequest BOOLEAN;
    set var.isSubresourceRequest = /* */;

    /* some operations */

    set req.http.isSubresourceRequest =
      if(var.isSubresourceRequest, "1", "0");
}

なぜこの詰め替えが必要なのかというと、まずVCLのサブルーチンで定義した変数は他のサブルーチン内 (e.g. vcl_fetch, vcl_deliver) では参照できない点が挙げられます。 req.http が特殊なのは、どのVCLステートやサブルーチンにも必ずこのオブジェクトを参照できるという特性があるからです。

BOOLEANの変数を後で文字列にキャストして req.http に付け替えておけば、これ以降のVCLのどこからでもこの値を参照できる、ということになります。

見落とし

このようにVCL内の多くの変数が req.http に詰められていて数が徐々に増えて行った結果が header overflow です。 単刀直入な結論ですが、当初我々がこの可能性を見落としていたのはなぜでしょうか。

それはコード内に存在する set req\.http\.\w+ を列挙してユニークに絞った結果の数が制限数に達していなかったからです。

「全ての分岐を通ったとしても制限数には達しないのだからこれは関係ない」と早期に可能性を切り捨ててしまった（他の可能性に絞ってしまった）のが大きなミスでした。

なぜ確認時に問題なかったのに発生していたのか

VCLのコードだけを検証していても棄却できなかった原因について、ヒントは先ほど挙げた再現（しやすい）条件にありました。

• Chrome Canary（stableでは起きない）

当時最新のChrome Canaryでは、新たにいくつかの Sec-* 系のリクエストヘッダが付くようになっていました。例えば今のChrome Stableでは

sec-fetch-mode: navigate
sec-fetch-site: none
sec-fetch-user: ?1
sec-fetch-dest: document

このような Fetch Metadata と呼ばれるヘッダ群が付いており、Chrome 76 (2019/07) からサポートされています。また sec-fetch-dest が対応されたのは Chrome 80 (2020/02) です。

このように最新のブラウザで新しく付けられる Sec-* 系のヘッダが徐々に増えてきています。（ちなみに今のChrome Canaryでは Sec-CH-* が対応されています、楽しみですね。）

クライアントへ付けられたヘッダ群は vcl_recv の最初に req.http に初期化・展開されるため、当時我々の預かり知らぬところでリクエストヘッダの数が増えていたのです。

原因と真相

つまり

• 最新のクライアントで付けられるヘッダが多いとき
• 開発系のリクエストヘッダを付けたとき
• VCL内の条件分岐に偶然うまくハマったとき

が重なって「局所に逢着した」、というのがこの現象・エラーの真相でした。

対応

この現象に対し実際に行った対応は以下の3つで、作業の容易な順に並べています。

1. 変数として利用しているヘッダを削る
2. ブラウザから送られてくるヘッダを削る
3. オリジンに渡すヘッダを削る

req.http.* の種類

具体的な対応の話に入る前に軽く前提を共有します。

（今までの部分で既に察されている方もいるかとは思いますが）私は基本的に VCLにおけるリクエストヘッダ req.http.* を3種類に分類して考えています。

1. ブラウザから送られてくるヘッダ
   • 本来の req.http
2. オリジンへ送るヘッダ
   • 本来の bereq.http
3. VCL内の変数として使うヘッダ
   • var.* の代替

実際に、どの値がどの分類に属するのかを明確にした上で、それぞれに合わせた対応を行いました。

1. 変数として利用しているヘッダを削る

FastlyのVCL (Varnish@6.x.xでは未確認) には、「クッキーのような構造的に並んだサブプロパティを取り出す」便利な構文糖、「: 演算子」があります。

req.http.Cookie:my_id
# -> 'deadbeaf'

詳しくは Fastly の記事 Use the : operator for cookies or other header subfields を参照してください。

今回行ったのは、「散在する変数用ヘッダを削減する」こと、つまり「一つのヘッダに全ての変数を格納する」ことで解決します。

set req.http.isSubresourceRequest = "1";
set req.http.isRequestFromTokyo = "1";

# -> 

set req.http.vars = "";
set req.http.vars:isSubresourceRequest = "1";
set req.http.vars:isRequestFromTokyo = "1";

このように変換することで、 req.http.vars という変数に key=value; 形式で複数格納することができます。このヘッダはVCL内部でしか参照されない、つまりオリジンに渡す必要がないので、

sub vcl_miss {
# sub vcl_pass {
    unset bereq.http.vars;
}

という処理も忘れないようにします。オリジンのRequest Header のサイズ上限に引っかかりエラーとなりやすいためです。

このようにして、実際に我々のVCLでは約40~50ほどのヘッダを一つのヘッダにまとめることができました。

2. ブラウザから送られてくるヘッダを削る

このようなヘッダは多くのケースにおいてVCLでの処理に必要ありません。 これらのヘッダの多くは、Reverse Proxyを担う Varnish の前段でのみ必要で、オリジンにそのまま送りたいものは限定的だからです。

sub vcl_recv {
	unset req.http.upgrade-insecure-requests;
}

このように、VCLの最初の時点で不必要なヘッダを明示的に削除しておくのが良いと思います。もちろんサービス、場合によって必要・不必要なヘッダは異なりますので見極めてからです。

3. オリジンに渡すヘッダを削る

ここが最も難しいポイントで、長期間のスパンで今なお取り組み続けている問題です。「実際にオリジンに送っている」、ということは「少なくともオリジンのどこかでその値が使われている」はずであることを意味します。

unset (be)req.http.Host;
unset (be)req.http.User-Permission-A;

例えばこの値をVCL内で消してしまうと、本来受け取るはずだったオリジンで何かしらのエラーが予想されます。ほとんどのヘッダはこのようなケースなので、基本的には消すことが難しい状況です。

では必要に応じて増えていくこのヘッダ群を指を咥えて見過ごすことしかできないのでしょうか？

一つにまとめる

我々の特徴的なCDNの使い方の一つとして、「ユーザトークンをエッジで分解して 複数の権限情報をリクエストヘッダとしてオリジンに送る」、という点が挙げられます。これを行うことで、キャッシュしづらい複雑な権限体系に則った req/res を Vary を駆使してHTTP-wayに乗ってキャッシュを効かせることができます。

set req.http.User-Permission-A = "1";
set req.http.User-Permission-B = "1";
...
set req.http.User-Permission-X = "0";

このように「キャッシュヒット率のためにエッジで解決してオリジンに送る」系のヘッダは必要に応じて際限なく増えていく恐れがあります。

現実のキャッシュヒット率と向き合う

しかし、現実には User-Permission-X が 1 となりキャッシュを分けなければならないケースは大体において少なく、現実のキャッシュヒットにおいてボトルネックになるほどの負のインパクトがない 、というものもまた存在します。

つまり、それらのヘッダは一つにまとめるのも有効な手段となります。

set req.http.User-Permission-A = "1";
set req.http.User-Permission-B = "1";
...
set req.http.User-Permission-Others:X = "1";

この場合、オリジン側は User-Permission-Others:X を読んだときに（他のケースと同じように） Vary: User-Permission-Others をsetすることで、キャッシュを安全に分けることができます。

Others としてまとめられたヘッダたちは（読まれていないのにもかかわらず）キャッシュ分化の巻き添えを受けてしまいますが、現実のキャッシュヒット率に大きな影響がない、という結果になります。

どれをまとめてよいのか、という判断は非常に難しくCDNやオリジンの詳細なログを分析する必要があるため、容易に・あるいは数多く実施できる類のものではありません。しかし、「際限なく増えていくヘッダ・心理的安全性の低下に対抗する手段」としては依然として有効だと考えています。

まとめ

この現象の特殊性をまとめると、

再現性の低さ

• 当時は謎のエラーで原因が全く特定できなかった
• 再現性がかなり低く、再現条件にも謎が多かった
• 時間が経つにつれて再現確率が上がっていった

潜在的な影響範囲

• 危うく（可能性としては）本番でも容易に再現しえた
• 電子版への全てのリクエストが不通になる大事故に繋がり兼ねなかった

という点が挙げられます。

対応策として実施したのは、

1. リクエストヘッダを分類する
   1. ブラウザから送られてくるヘッダ
   2. オリジンへ送るヘッダ
   3. VCL内の変数として使うヘッダ
2. 各分類に合わせた対応を行う
   1. 不必要なものを明示的に unset する
   2. 現実のキャッシュヒット率・ログと相談して、一つにまとめる
   3. : 演算子を用いて req.http.vars の一つに格納する

でした。

おわりに

今回お話した現象は本番環境で起きる前に特定・修正ができたものの、結果としてみれば潜在的な影響範囲が非常に大きく、より早期に解決しておくべき問題だったと思っています。

個人的な反省点は所々で挙げた通りですが、日経電子版という非常にハイトラフィックなサービスを支えるエッジ・サーバだからこそ、小さな現象やきっかけを見逃さないように精進していく動機付けになりました。

本記事の内容は以上です。この記事がFastly, VCLを使うウェブエンジニアの皆さまの参考になれば幸いです。