こんにちは、SREチームの千代田です。
サイトを構築するにあたって様々なミドルウェアを扱うことがあると思いますが、
今回はキャッシュサーバであるVarnishについてのお話です。
遭遇
私が入社して一ヶ月ほどたったとき、運用中のシステムで発生している既存のエラーについて学ぶ機会がありました。
話を聞きつつどのようなエラーが存在するのかを確認すると、以下のVarnishエラーを複数見つけました。
<!DOCTYPE html>
<html>
<head>
<title>503 Backend fetch failed</title>
</head>
<body>
<h1>Error 503 Backend fetch failed</h1>
<p>Backend fetch failed</p>
<h3>Guru Meditation:</h3>
<p>XID: 532316890</p>
<hr>
<p>Varnish cache server</p>
</body>
</html>
このエラーの原因について既存のメンバーに確認すると、
複数ある特定のURLで起こる、POST/PUTのリクエストのbodyが短いと起きるなど諸説あり、発生原因はまだ特定できていないとのことでした。
調査
私はこの時Varnishに対して全く無知でした。
そのため、公式のドキュメントを頼りにトレースログを行うことにしました。
Varnishは高速で動作させるために、ログの出力をVSLと呼ばれる共有メモリセグメントに行なっています。
このログデータは一つのリクエストに対して大量の行数が出力されるため、日常的なログの出力を行っていませんでした。
膨大なログからデータを見つけるのはとても大変な作業のため、
このログをファイルに出力させつつ既存のログ側でエラーを検知した際に、
該当のVarnishログを見るといった方針で行なうことにしました。
そして、Varnishのログを取得することに成功しました。
VarnishのStateMachineについては、
公式を見ると分かりやすいと思います。
* << BeReq >> 576325623 - Begin bereq 576325622 pass - Timestamp Start: 1504590151.903285 0.000000 0.000000 - BereqMethod PUT - BereqURL /v1/microservice/ - BereqProtocol HTTP/1.0 - BereqHeader host: xxx.yyy - BereqHeader Content-Length: 4623 - BereqHeader accept: application/json - BereqHeader content-type: application/json - BereqHeader X-Varnish: 576325623 - VCL_call BACKEND_FETCH - VCL_return fetch - BackendOpen 46 reload_YYYY-MM-ddWHH:mm:ss.backend_name x.x.x.x 80 x.x.x.x 56894 - BackendStart x.x.x.x 80 - Timestamp Bereq: 1504590151.903331 0.000046 0.000046 - FetchError http first read error: EOF - BackendClose 46 reload_YYYY-MM-ddWHH:mm:ss.backend_name - Timestamp Beresp: 1504590151.907966 0.004681 0.004635 - Timestamp Error: 1504590151.907977 0.004692 0.000011 - BerespProtocol HTTP/1.1 - BerespStatus 503 - BerespReason Service Unavailable - BerespReason Backend fetch failed - BerespHeader Server: Varnish - VCL_call BACKEND_ERROR - VCL_return retry - Timestamp Retry: 1504590151.907986 0.004701 0.000009 - Link bereq 577078686 retry
http first read error: EOFといったエラーが出ていることが確認できます。
このエラーについて検索するとstackoverflowやvarnishのmailing listなど、様々な媒体の情報が見つかりました。
しかしながら、どれを読んでも今回のエラーに対して思い当たる節がありませんでした。
また、Varnishからのリクエストを受けるDjangoのエラーログには以下のログが出力されていました。
django.http.request.UnreadablePostError: error during read(4623) on wsgi.input
こちらのエラーを確認すると、
先ほどVarnishから送ったリクエストに対してのContent-Length分のbody readに失敗したエラーに見えます。
この時点で私の中では、
バージョンの古いVarnishを利用していることによってバグでリクエストが破損しているのではないかといった結論に至りました。
そのため、後日Varnishのバージョンアップを行なうことにしました。
バージョンアップ後の調査
バージョンを上げたにも関わらず相変わらず503エラーが続いていました。
しかし残念ながら、別の仕事もある都合上いつまでも調査を行うわけにもいかず一度保留することにしました。
さらに数ヶ月後、手が空いた際に再度この問題に着手することができました。
前回の調査結果を念頭に置きつつ、今回は別のリクエストをパケットレベルで追うことにしました。
今回のリクエストは、以下の流れです。
BFF -> Varnish -> Microservice
まず始めにBFF -> Varnish間のパケットをtcpdumpで確認します。
余分なヘッダ/データを削っているため、lengthは若干異なります。
HH:mm:ss IP ip-xxx-xxx-xxx-xxx.40596 > ip-yyy-yyy-yyy-yyy: Flags [P.], seq 1:328, ack 1, win 211, options [nop,nop,TS val 1858274581 ecr 947885993], length 327
POST /v1/microservice2/ HTTP/1.0
Connection: close
Content-Length: 100
accept: application/json
content-type: application/json
{"xxxxxxxx":"XXX","xxxxxxxxxxxx":"XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"}
この間は問題なく、データがきているように見えます。
次にVarnish -> Microservice間のパケットです。
HH:mm:ss IP ip-yyy-yyy-yyy-yyy.40324 > ip-zzz-zzz-zzz-zzz: Flags [P.], seq 1:260, ack 1, win 211, options [nop,nop,TS val 947885994 ecr 947921750], length 259 POST /v1/microservice2/ HTTP/1.0 Content-Length: 100 accept: application/json content-type: application/json X-Varnish: 888442338
リクエストは送られてきましたが、Content-Length分のbodyがありません。
しかしながら、Varnishのリクエストが503だった場合にretry処理を呼ぶようにしてあります。
今度はそちらのリクエストを確認しました。
HH:mm:ss IP ip-yyy-yyy-yyy-yyy.46642 > ip-zzz-zzz-zzz-zzz: Flags [P.], seq 247:606, ack 38176, win 843, options [nop,nop,TS val 947885994 ecr 947945014], length 359
POST /v1/microservice2/ HTTP/1.0
Content-Length: 100
accept: application/json
content-type: application/json
X-Varnish: 888672061
{"xxxxxxxx":"XXX","xxxxxxxxxxxx":"XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"}
再送されたリクエストにはbodyがありました。
lengthも259 -> 359へとContent-Length分増えていることが分かります。
この時点で、VarnishによってPOSTのbodyが存在したりしなかったりすることが分かりました。
しかし残念ながら、なぜbodyが消えてしまうのかまでは今回の調査では分かりませんでした。
おわりに
Backendとの相性が悪いのかを確認するために、uWSGIを辞めてGunicornに変えるなど試しましたが、
相変わらず503エラーが起こったため、少なくともバックエンド起因ではないと考えています。
また、次のブログを参照し、
varnishでbackendのapacheにPOSTしているときにたまに(1/1000ぐらい)503 Service Unavailable になる現象はpassをpipeに変えたら出なくなった
実際に、Varnishのpassをpipeに変えれば、POST/PUTによる503が出なくなることの確認が取れました。
そのため、根本的な解決とはいかず不完全燃焼ですが、今回の調査をもって一旦解決とすることにしました。
最後までお読みいただき、ありがとうございました。
今回の問題に対して他のアプローチを思いつく方や、
システムへの調査/改善/開発など多岐に渡る業務を行いたいと思っている方がいらっしゃれば、
ぜひ一度オフィスでお会いしましょう。
次回は、エンジニアののりすけさんの予定です。
