2019年7月11日頃より，3rd Party製のiOS向けMastodonクライアントである「Tootle」において，そのプッシュ通知用サーバの輻輳が発生していました。その結果，はんドンクラブにおいて処理遅延が発生し，TLの配送遅延など複数の問題が発生していました。この記事では，その詳細な原因と影響範囲に加え，せっかくなのでプルリクを送るまでの流れを整理しておこうと思います。
本ブログにおけるご報告が遅くなったことをお詫びいたします。
サマリ
問題1：TLの配送遅延
- 日時： 2019年7月11日 21:28〜21:52頃
- 影響範囲： HTLやLTLの表示速度低下（配送遅延は最大1分程度）
- 原因： Tootleプッシュ通知サーバのレスポンスの大幅な低下による，重要キューの処理遅延
- 実施した対処：Tootleプッシュ通知サーバへのアクセスを遮断
/etc/hostsでTootleプッシュ通知サーバを 0.0.0.0 と解決させることで対応
問題2： Tootleプッシュ通知サーバへのアクセス不可
- 日時： 2019年7月11日 21:52〜7月14日 23:14頃
- 影響範囲： Tootleユーザにはんドンクラブからのプッシュ通知を送らない
- 原因： 上記問題への暫定対処
- 実施した対処： ソースコードの修正によりプッシュ通知のリトライ回数を削減
- リトライ回数を26回から5回に削減
今回の障害の原因について
Tootleのプッシュ通知サーバが原因ではんドンクラブ全体が重くなった理由を説明します。
〇原因1： プッシュ通知用サーバの輻輳
そもそもiOSクライアントのPush通知機能は，Tootleも含め，以下の様な通信フローとなっている場合が大半です。
+----------+ +--------+ +--------+ +----------+ | Mastodon | ---> | Client | ---> | Apple | ---> | iOS | | Server | Push | Server | Push | Server | Push | Terminal | +----------+ +--------+ +--------+ +----------+
図中の「Client Server」が，Tootleが独自に立てているプッシュ通知専用のサーバとなります。今回はこのサーバのレスポンスが極端に悪くなっていました。
〇原因2： MastodonのWebPushの処理方法
とはいえ，本来であれば，関係のないサーバの処理が遅くなったからといって，Mastodonサーバの処理が遅延するのはおかしいはずです。にもかかわらず今回配送遅延が発生した理由は，以下2つの要因が重なっていました。
- 【要因1】Tootleサーバが即座にエラーを返さなかった（例えば30秒以上かかっていた）
- 【要因2】エラーが返るまでの間，Mastodonサーバ側が他の処理をできなくなり，結果としてTL配送処理に遅延が発生した
特に【要因2】についてですが，本来Mastodonサーバ側で実装されている並列処理により，他処理に影響はないはずでした。実際はんドンクラブでは，今回のWebPush通知が処理されるDefaultキューは，15個の処理が並列処理できるよう設定されています。しかしながら，このエラーがあまりに多量に発生してしまい，15個の処理が全てTootleサーバ宛の処理で埋まってしまう事象が発生してしまいました。Defaultキューでは，LTL/HTLのへのトゥート配信を担う処理も行われるため，結果としてTL配送遅延になっていました。なお，もちろんTootleサーバが完全に断となっており，即座にエラーを返してくれればこうはならなかったのですが，【要因1】でも記載したとおり即座にエラーが返らなかったため，タイムアウト処理を待つ形となり，こういった事象となりました。
参考までに，mstdn.jpなどの他サーバへのPush（ActivityPub）については，Defaultキュートは別キューになっています。はんドンクラブでは8個の処理が（Defaultキューとは別のスレッドで）並列処理されるようになっています。そのため，はんドンに限っては，大規模サーバがダウンしたからといって，今回に類似する事象は発生しないはずです（初期設定のまま運用しているサーバでは，DefaultキューとPushキューが同じsidekiqプロセスで処理されてることが多いため，発生する可能性が高いです）。
次に，上図に，リトライ待ちの処理数と遅延時間の時間変化を示します。緑の線で示されているのがリトライ待ちの処理数（左軸）で，青の棒で示されているのがDefaultキューの処理の平均遅延時間（右軸）を表しています。Mastodonでは，様々な処理が失敗したとき，何度か決められた回数分だけリトライを行うことになっています。そのリトライ待ちの処理数が，数時間で一気に増えていることが分かるかと思います（通常運用時は100程度ですが，このときは3000超となっています）。それに伴って，青軸で示される遅延時間が増えており，最大60秒弱の遅延が発生していることが分かります（通常運用時は0.1〜1秒程度です）。先ほどの説明のとおり，このキューにはWebPush通知だけでなく，LTL/HTLへのトゥート配送処理も含まれていますので，WebPush通知もトゥート配送も青の棒で示される同じ時間だけ遅延していることとなります。このようにして配送遅延が発生しました。
今回の対処内容
〇暫定対処
実際には以下の様なエラーが大量に出力されていました（セキュリティ上の理由から，ログは一部をマスクしています）。
WARN: {"context":"Job raised exception","job":{"class":"Web::PushNotificationWorker","args":[XXXXX,XXXXX],"queue":"default","backtrace":true,"jid":"XXXXXXXXXX","created_at":XXXXXXXXX.XXX,"enqueued_at":XXXXXXXXX.XXX,"error_message":"Net::ReadTimeout with #<TCPSocket:(closed)>","error_class":"Net::ReadTimeout","failed_at":XXXXXXXXX.XXX,"retry_count":3,"error_backtrace
WARN: Net::ReadTimeout: Net::ReadTimeout with #<TCPSocket:(closed)>
原因を特定するため，argsにあるWebPushIDを調査したところ，すべてがTootleサーバ宛の通信であることが分かりました。そのため，かなりの強引な処理ですが，以下を /etc/hosts に追加することで対処しました。
0.0.0.0 tootleformastodon.appspot.com
〇本格対処
対処案は以下3つがありました。
- 【案1】WebPush通知のタイムアウトを短くする
- 【案2】WebPush通知が処理されるキューをDefaultキューから変更する
- 【案3】WebPush通知のリトライ回数を減らす
最終的にMastodonの本家ソースコードへ反映させたいと言うことで，既存コードとの整合性も考慮した結果，【案3】を選びました。本当は【案1】が最も良いと思ったのですが，これはおそらくRubyライブラリのデフォルト値で，WebPush通知だけ変更することは難しいのではないかと思いました（注意： 筆者の推測であり，確認はしていません）。更に【案2】については，有効な案ではあったと思うのですが，Mastodonのソースコードを大きく変える方式であり，本家Githubへのプルリクを行ってもどうせMergeしてくれないだろうなと判断しました。
【案3】の詳細な内容についてです。WebPush処理のリトライ実装は，リトライ回数を明示的に指定されていませんでした。そのため，sidekiqのデフォルト値である26回になっていたと思われます。今回はそこを5回に変更しました。また，【案3】で本当に効果が得られるかを確認するため，検証環境での試験を行い，確かに効果があることを確認しました。そのうえで，Githubにプルリクを送りました。
早速マージされたので，結果的に初めてのMastodonへのコントリビュートとなりました😝 たいしたことのないコードですが，大きなプロジェクトにコントリビュートするのは初めてなので，ちょっぴり嬉しいですね。
今回の障害の検知について
違う話題です。
今回の障害は私の想定より検知が遅れました。今回の障害は，私自身がサーバを使っていて，TL表示が遅いと気づいたために調査を行ったために発覚しました。本来であれば，Defaultキューの遅延が長時間閾値を超えた場合，私のLINEにアラートが飛ぶ仕組みになっていましたが，このアラートが発報されず，結果として検知が数分〜数十分遅れてしまいました。もし私が障害発生時刻にTLを見ていなければ，もっと遅くなったのではないかと思います･･･。
原因は詳しくは説明しませんが，本件は再発防止済となりますのでご安心頂ければと思います。簡単に説明すると，他のMetricsが数時間前に警戒域になった際に正常にアラートが発報されておりましたが，ただちに影響はないと判断し無視していたところ，このアラートの発報が継続されていたため，Defaultキュー遅延が発生しても新たなアラートが発報されないようになっていました。
おわりに
まず，念のため申し上げておきますが，Tootleはとても素晴らしいクライアントだと思っています。私も愛用させて頂いています。今回の問題は，Tootleのサーバ実装が悪い訳ではなく，Mastodonサーバの実装が悪いものだと理解しています。とはいえ，パラメータ設定というのはとても難しいものです。今回は実運用の中で，StatsD経由で取得しているMetricsとにらめっこしながらパラメータチューニングを行うことができました。ある程度の規模のサーバでないとできないチューニング方法だと思いますので，はんドンクラブの皆様には感謝しかありませんね。
なお，今回の障害については，はんドンクラブでは既に解消しているものと考えています。引き続き安定運用に努めたいと思います。
