ストリーミング障害発生のお詫びとご報告 - はんドンクラブ運営ブログ

みなさんこんにちは。はんドンクラブ管理人のはんです。

本日は先日発生したストリーミング障害に関するお詫びと、発生原因や再発防止策のご報告をさせていただきます。

概要

日時: 2023年8月29日 23:04 - 9月4日 23:59、および 2023年9月5日 6:16 - 14:14
対象: すべてのユーザー
内容: ユーザーストリーミングが不安定（定期的にタイムラインが更新されなくなる）

長期間にわたりストリーミングサービスが停止し、ご不便をおかけして申し訳ございませんでした。

経緯

日時(JST)	時系列
8/29 22:43	サーバー移転作業が終了し動作確認を開始
8/29 23:04	サーバー移転の動作確認が完了（このタイミングから障害が発生）
8/29 23:05	ユーザー申告により問題が発生していることを認知
8/29 23:30	Redisサーバーの設定変更を行いDebugログが取得できる状態になった
8/29 23:36	RedisサーバーとStreamingコンテナ間のTCPコネクションに異常がある可能性を発見 ※結果的にこれが根本原因の一つでした
8/30 00:13	解析の結果、影響範囲軽減に有効だと判断し、【暫定対処(1) 5分おきにStreamingコンテナを再起動】を開始（このタイミングから障害が緩和）
8/31 23:32	TCPコネクションの異常がStreamingの更新されない事象と本障害が直接関連していると断定し、対処策を本格的に検討開始
9/1 00:25	【対処案(1) ARPキャッシュTTL/TCP KeepAlive時間の調整】を実行、同時に暫定対処(1) を一時中断
9/1 00:30	対処案(1) 実行後に事象が再発したため、不十分と判断し、暫定対処(1) を再開
9/4 23:01	解析の結果、根本原因（後述する原因A・B・Cとその因果関係）を断定
9/4 23:22	【対処案(2) クラウドサービスのVPC設定変更等】を実施、監視を継続
9/4 23:59	対処案(2)の効果が見られたと判断し、暫定対処(1) を中断
9/5 06:16	対処案(2) 実行後に最初に事象が再発（一時的に障害が悪化）
9/5 09:02	暫定対処(1) を再開（障害が再度緩和）
9/5 14:14	【対処案(3) コンテナのネットワーク設定変更】を実行、暫定対処(1) を中断（障害が完全に回復）
9/5 22:37	対処案(3) により事象が完全に回復したと判断、ユーザ周知

結果的にサービス影響は以下のとおりとなります。

全く使えない状態（サービス停止状態）
- 合計3時間55分
- 8/29 23:04〜8/30 0:13の1時間9分、9/5 06:16〜9/5 09:02の2時間46分
定期的にサービスが使えなくなるものの、数分以内に自動的に再接続が行われる状態（サービスデグレ状態）
- 合計148時間58分
- 8/30 0:13〜9/4 23:59の5日23時間46分、9/5 09:02〜9/5 14:14の5時間12分

原因

データセンター内のサーバー間の通信（TCPコネクション）が不安定となり再接続が行われた場合、MastodonがRedisのSubscribe要求を再送しますが、Redisの上限値である1024*1024を超過して送出する場合があり、かつMastodonがRedisサーバーのエラーを正しくハンドリングできていないためにタイムラインの情報がStreamingで更新できない状態となりました。

発生メカニズムの詳細

まずは構成を説明します。

要因となった動作を説明するには、メインホスト （＝Streamingコンテナが動いているホスト）と Redisホスト が登場します。他にMastodonを構成するために必須なPostgresホストなどもありますが、今回の障害要因に関係ないため、この記事では記載を省略します。

メインホスト である host名 prd-host1 および prd-host2 は、Dockerでいくつかのコンテナが動いています。その中の一つがstreamingコンテナです。コンテナはbridgeでVPCに繋がっており、このbridgeではNATが行われます。

Redisホスト であるhost名 prd-redis は Redisが直接ホストで動いており、メインホストと同様にVPCに繋がっています。

さて、事象が発生するメカニズムは以下のとおりです（ただし、後の解析で、①②は③を誘発する要因の1つでしかなく、必要条件ではないことが分かっています）。

① ARPキャッシュTTL切れを契機にメインホスト → Redisホストに ARPリクエストを送出
② Redisホスト → メインホストにARPリプライを応答、メインホストは正常に受け取る
③ 根本原因は不明だが、メインホストがRedisホストに対して全てのTCPコネクションをリセットする要求を送出する場合がある･･･【原因A】
④ 直後にメインホストがRedisホストに対してTCPの再接続要求を送出し、3-way handshake完了後にRedis上でSubscribeリクエストを送出。このとき、元々のSubscribe量によって、Redisのmulti bulk 引数制限（1024*1024）を超過したメッセージを送出する場合がある･･･【原因B】
⑤ multi bulk 引数制限を超過している場合のみ、Redisサーバーはsubscribeリクエストに対してエラー応答
⑥ StreamingコンテナはSubscribe要求を再送せず、要求が認められたとして以後の処理を継続する･･･【原因C】

①②の後に100%で③が発生しています。しかし前述のとおり、③は①②のARPキャッシュTTL切れ有無によらず、発生する場合がありました。そのため、③が発生する契機は完全には解明できていません。

④はSubscribe量によるため、アクティブユーザー数によって発生する場合と発生しない場合がありました。私の感覚では10分の1〜5分の1程度です。④が発生した後、継続して⑤⑥が発生する確率は100%です。

各要因の深掘り（原因A）

特に負荷が高い状況でなくとも、当初は60秒に1度全てのTCPコネクションをリセットする送出していました。このTCPリセット送出の要因は、ホストの可能性とStreamingコンテナの可能性があります。実際にはキャプチャをVPCに接続しているNICでしか取得できなかった（＝bridge側インターフェースで取得できなかった）ため断定はしておりませんが、他のコンテナで同様の問題が発生していないことから、Streamingコンテナが送出元と想定しています。

○パケットキャプチャの例

○Redisサーバー側

12249:M 05 Sep 2023 13:24:54.971 - Reading from client: Connection reset by peer
12249:M 05 Sep 2023 13:24:55.034 - Reading from client: Connection reset by peer
12249:M 05 Sep 2023 13:24:55.083 - Reading from client: Connection reset by peer
12249:M 05 Sep 2023 13:24:55.083 - Reading from client: Connection reset by peer
12249:M 05 Sep 2023 13:24:55.274 - Reading from client: Connection reset by peer
12249:M 05 Sep 2023 13:24:55.285 - Reading from client: Connection reset by peer
12249:M 05 Sep 2023 13:24:55.679 - Reading from client: Connection reset by peer
12249:M 05 Sep 2023 13:24:55.888 - Reading from client: Connection reset by peer
12249:M 05 Sep 2023 13:24:55.988 - Reading from client: Connection reset by peer
12249:M 05 Sep 2023 13:24:56.190 - Reading from client: Connection reset by peer
12249:M 05 Sep 2023 13:24:56.218 - Reading from client: Connection reset by peer

送出している原因は断定できていません。しかし、当初はARPを契機にTCP RSTを送出していたため、ARPが一つの要因であることに間違いはありません。メインホストはRedisサーバーからAPRリプライを受け取った直後100ms以内でTCP RSTを送出していました。これは再現率100%です。しかし、MACアドレスの変動などは見受けられなかったため、この原因は不明です。

一方、ARPキャッシュ時間を長くしても、この問題は完全には解消されませんでした。そのため、TCPの何らかのタイムアウト値の設定が悪く、例えばKeep Aliveの不具合が発生しているものだと考えました。DockerをBridgeで接続していたことで間にNATが居たわけですが、このNATが原因で、タイムアウトの瞬間がほぼ同時に発生しTCPクライアント・サーバー間で状態の認識に齟齬が発生した可能性が高いと考えています。

各要因の深掘り（原因B）

MastodonのStreamingプロセスの実装上、一度TCPコネクションが切断されても再度TCPコネクションを張り直し、Redisに対してSubscribeしていた内容を再度Subscribeしようとします。この実装自体に問題はありません。

しかしながら、このSubscribeを1リクエスト（1パケット）にまとめて送る仕様のようで、稀にRedisサーバーが受け取れる上限を超えて送ってしまうようです。具体的には、Redisサーバーはmulti bulkリクエストを送る場合に1024*1024までというサイズ制限があるのに、MastodonのStreamingプロセスはこれを無視して全ての要求を一度に送ってしまうことが原因です。

○Redisサーバー側

29 Aug 2023 23:51:51.721 - Protocol error (unauth mbulk count) from client: id=502 addr=192.168.1.9:60128 fd=58 name= age=0 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=1122 qbuf-free=31646 argv-mem=0 obl=55 oll=0 omem=0 tot-mem=61440 events=r cmd=NULL user=default. Query buffer during protocol error: '*39..$9..SUBSCRIBE..$28..timeline:access_token:XXXXXX..$17..time' (... more 994 bytes ...) ':XXXXX..$14..timeline:XXXXX..$28..timeline:XXXXX:notifications..'

※ユーザIDを含む部分はログ上でマスクしています。

○Streamingプロセス側

ERR! Redis Client Error! Error: read ECONNRESET
ERR! Redis Client Error!     at TCP.onStreamRead (node:internal/stream_base_commons:217:20)
ERR! Redis Client Error!  Error: read ECONNRESET
ERR! Redis Client Error!     at TCP.onStreamRead (node:internal/stream_base_commons:217:20) {
ERR! Redis Client Error!   errno: -104,
ERR! Redis Client Error!   code: 'ECONNRESET',
ERR! Redis Client Error!   syscall: 'read'
ERR! Redis Client Error! }

各要因の深掘り（原因C）

MastodonのStreamingプロセスは大変イケてなくて、一度RedisサーバーにSubscribe要求を断られても、それを再送するということをしません。プロセス内部的には、Subscribeされた状態だと認識しているのです。これを再度Subscribeさせるためには、TCPコネクションを完全に切断するか、プロセス毎を起動するしかありません（もっとも、TCPコネクションを完全に切断してしまうと、原因Bをもう一度引き起こすので解決しないのですが）。

対処方法

StreamingコンテナのみTCPポート4000番（Streamingプロセスが利用するポート）をホストに直接接続する構成変更を行い、本件の解決を行いました。

対処方針の検討プロセス

当然ですが、発生を根絶するためには、ワークフロー後段の原因から対処を検討すべきです。

そこでまず、原因Cの対処を考えましたが、断念しました。この修正のためにはMastodonの実装の確認・修正が必要ですが、Streamingのコードを読んだことすらなかったので、時間的／スキル的制約から取りえない手段でした。

次に原因Bの対処を考えます。Redisサーバーの1024*1024制限はソースコードにハードコードされており、confファイルでは変更できないことが分かりました。ということは、原因Bと同様に、この修正のためにはMastodonの実装の確認・修正が必要です。

以上から、障害認知後の初期段階から、原因Aを修正する方法のみを中心に検討を進めていました。

原因Aの対処案(1)とその評価

発生直後から、1分単位でTCPコネクションが頻繁に切れていることはわかっており、かつUbuntuで1分のタイマ値として思いつくものがARPキャッシュ・TCP Keep Aliveしかありませんでした。そして、取得したパケットキャプチャから、ARPのタイミングとTCP RSTのタイミングが100ms以内であることを特定していましたので、まずはARPキャッシュを1日に延長することにしました。

echo xxxx >/proc/sys/net/ipv4/neigh/default/gc_stale_time

若干の影響軽減は認められたものの、根本解決はしませんでした。これは、前述のとおり、①②のARPシーケンスは原因Aの発生原因の1つでしかなかったからです。

なお、そのほか、Kernel上でTCP Keepaliveの調整をいくつか試しましたが、こちらは効果はありませんでした。

sudo sysctl -w net.ipv4.tcp_keepalive_time=xxxx
sudo sysctl -w net.ipv4.tcp_keepalive_intvl=xxxx

原因Aの対処案(2)とその評価

他に同じ事象で困っている鯖缶がいないということは、クラウド事業者側の問題ではないかと疑いました。そこで、VPCの異常を疑いました。

他社のVPSサービスで費用を払い忘れるとネットワーク帯域を絞られた経験があったので、その可能性を考え、費用を先行してデポジットしようとしました。すると、そもそもクレジットカードの支払いに失敗しており、先月分の支払いができてない状態になっていました･･･。

当初、この支払いにより障害の回復が行われたように見えていました。しかしこれも原因Aの発生確立を高める事象の1つでしかなかったようで、すぐに頻発しました。結果的に、対処案(1)ほどの効果はなかったと評価しています。

余談：当初VultrのVPC2.0をつかっていたのですが、これだとProxy ARPをしている人がいるように見えて気持ち悪かったので、VPC1.0に戻しました。しかし、この処置により改善は見られませんでした。

原因Aの対処案(3)とその評価

主に切り分けを目的として、ネットワーク経路の被疑箇所を減らすべきだと考えました。よって、NATを除去すべきだと考えました。具体的には、StreamingコンテナのみTCPポート4000番（Streamingプロセスが利用するポート）をホストに直接接続することで、切り分けを行おうとしました。実際には、docker-compose.yml に network_mode の設定を加え、docker compose down && docker compose up -d しました。

  streaming:
    network_mode: "host"

この変更は効果があり、結果的に一度も問題が再発せず、障害が解決しました。

対処プロセスの評価

早い段階でメカニズムを解明し、かつ原因Aの対処案策定に絞れたことは評価できると考えています。しかしながら、以下の理由により、具体的な対処案策定には時間を要してしまいましたので、改善が必要だと考えています。

管理人の寝不足
- 前日までの手順確認作業により寝不足であり、発生当日の切り分け時間が十分確保できませんでした。
管理人の風邪
- 子供から風邪をもらってしまい、寝込んでしまいました。

対処案策定から実行までの時間に問題はありませんでした。

加えて、例えばVPC等に障害が起こった場合に、原因A以外の原因で原因Bが発生し、結果的に同一障害が発生してしまうリスクは残っています。すなわち、原因B・原因Cの本格対処が不要となったわけではありませんので、原因Bの発生を検知したらStreamingコンテナを自動再起動するようなスクリプトの開発が必要 だと考えています。