サーバーごとではなく、一度だけ鳴るアラート

運用上のアラートの1つである、公開中のビルダーのアプリの「クレジット残量が少ない」通知は、1日に最大1回届くことを想定しています。ところがある日の午後、それが5回届きました。原因は、APIのコピーごとに、すでに送信したアラートをそれぞれのメモリに記憶していたことです。サーバーが2台あるため2回送られ、デプロイのたびにそのメモリが消去されるため、再び送られていました。同じパターンで、バックグラウンドジョブの処理も二重に実行されていました。どちらも、現在は共有ストアを介して調整するようになっています。さらに、そのストアが利用できない場合は、安全な側に倒れる（失敗時にアラートを送る）ようにしています。

症状

Mythexは、何かに注意が必要なときにチーム向けのアラートを送ります。サービスが停止した、ジョブが止まった、公開中のアプリのクレジット残高が少なくなった、といった場合です。各アラートには重複排除の期間があり、その間は同じアラートは1回しか送られません。クレジット残量のアラートの場合、その期間は24時間です。

同じアラートが1日の午後に5回届いたということは、この期間が機能していなかったことを意味します。さらに悪いことに、約11分の間隔を空けて2回ずつ届いていました。

原因

当社のアラートパッケージは、重複排除の情報をメモリ内で保持していました。実行中のプロセスの中に「アラートのキー → 最後に送った時刻」の表があるだけです。これは、プロセスが1つだけで、再起動しない場合には機能します。しかし本番環境では、そのどちらも当てはまりません。

APIのレプリカが2台あります。 本番環境では、APIを2つのコピーで動かしています。それぞれが独自の表を持っているため、各レプリカが1回ずつ送っていました。これがペアで届く理由です。
デプロイ。 デプロイのたびに、2つのレプリカが新しいプロセスに置き換わり、表は空になります。そのため、デプロイ後にはまるで一度も送っていないかのように、アラートが再び送られていました。

ペアの2つのアラートの間の約11分は、このアラートを発生させるジョブに由来していました。このジョブは両方のレプリカで実行され、ロックを取得するため、レプリカが交互にロックを取り、それぞれが順番が来たときにアラートを発生させていたのです。

同じコードには、もう1つ目立たないバグがありました。表が際限なく大きくなるのを防ぐため、表に500件のキーが溜まると、15分より古いエントリをすべて削除していました。その際、各エントリの期間は考慮されていません。負荷が高いと、24時間の重複排除が15分程度しか持たなくなっていました。

修正

アラートごとに1つの共有レコード

APIはアラートを送信する前に、そのアラートの重複排除キーをRedisに登録するようになりました。Redisは、両方のレプリカが参照する共有のインメモリストアで、APIが再起動してもリセットされません。登録は「キーが存在しない場合にのみ設定し、期間が過ぎたら期限切れにする」という1回の操作です。先に登録したレプリカがアラートを送り、もう一方はそのキーがすでに使われていることを確認して黙ります。デプロイ後に新しく起動したプロセスも、そのキーが残っているのを確認できます。

キーと期間は、アラートパッケージが使用しているのと同じルールから生成されます。このルールを両方の層で共有しているため、「同じアラート」とは何かについて、2つの層の判断が食い違うことはありません。

失敗時は送る側に倒す

最も重要な判断は、Redisに接続できない場合の対応でした。私たちは、その場合でもアラートを送ることを選びました。Redisがダウンしている場合、あるいは1.5秒以内に応答がない場合は、アラートを送信します。重複したアラートは雑音にすぎません。しかし、送られなかったアラートは、誰かに知らせるべき情報が届かないことを意味します。

もっとも深刻なP0のアラートは、重複排除によって保留されることがそもそもありません。

エントリごとに自分の期間を持つ

アラートパッケージ独自のインメモリの重複排除では、各エントリに期間の終了時刻を保存するようになりました。そして削除時には、期間が終わったエントリだけを削除します。24時間のキーは、他のアラートがいくつ届いても24時間保持されます。

別の場所にあった同じバグ

同じパターンは、バックグラウンドの処理も二重にしていました。それは、各ワークスペースの状態を、サンドボックスプロバイダーの状態と一致させ続ける照合ジョブです。このジョブは毎回、アカウント内のすべてのサンドボックス（本番環境では数千件、約5秒かかります）と、実行中または一時停止中のすべてのプロジェクトを一覧取得します。両方のレプリカが2分ごとにこれを実行していました。

書き込みは冪等（何回実行しても結果が1回実行した場合と同じ）であるため、何かが壊れることはありませんでした。ただ、作業量が2倍になっていただけです。現在は、2分ごとの各時間枠をRedisで確保するようにしました。これは、使用量の計測がすでに同じ方法で時間枠を確保しているのと同じ仕組みです。その時間枠を確保したレプリカだけが、この処理を実行します。Redisに接続できない場合は、それでも処理を実行します。作業を2回実行しても害はありませんが、実行しないと処理されない作業が出てしまうからです。

テストの方法

テストは実際の構成を再現しています。アラートモジュールを2回読み込んで、2つの別々の「レプリカ」として扱い、両方を同じ共有ストアに接続します。そして、それぞれから同じアラートを発生させます。その後、「デプロイ後」を模して、新しく3つ目のコピーを読み込み、もう一度アラートを発生させます。送信されるアラートは1件だけになります。他のテストでは、別のビルダーのアラートは引き続き届くこと、P0は両方のレプリカから送信されること、共有ストアがダウンしていたりタイムアウトを超えて応答しなかったりした場合でもアラートは送信されることを確認しています。削除の修正には専用のテストがあります。20分後に他の600件のアラートが届いても、24時間のキーは残り続けることを確認しています。

照合ジョブについては、2つのレプリカが同時に実行され、さらに同じ時間枠で3回目の実行が行われても、一覧取得は1回だけになることを確認しています。

得られた教訓

インメモリの状態はプロセスごとのものです。 「1回だけ送信された」「1回だけ実行された」のように、サーバー間で真であるべきことは、共有される場所に保存する必要があります。
デプロイは再起動です。 次の再起動までしか残らない状態は、通常の業務の1日さえ保たれません。
どちらの方向に失敗させるかを決めておきましょう。 アラートの場合、共有ストアがダウンしたときに届くのは、アラートが減ることではなく、増えることであるべきです。
インスタンスだけでなく、パターンを探しましょう。 アラートは目立った例でしたが、二重になっていた照合ジョブは、同じバグが静かに作業のムダを生んでいた例でした。

こうした仕組みはMythexの内側からは見えません。プラットフォームを安定させる取り組みについては、デプロイで502エラーをゼロに近づけた方法と、見落とされていたスワップファイルをご覧ください。サービスを複数のコピーで動かすという考え方が初めての方は、サーバーとは何かのガイドで基本を説明しています。