2022--Shareまずは8月に起きた障害において、皆様に多大な迷惑をおかけしたこと、この場をお借りしてお詫びいたします。本当に申し訳ありませんでした。ついてユーザーの皆様に共有したいと思います。正確に情報を伝えるため、内容はテクニカル寄りになりますがご了承ください。JST、APIがダウンしたというアラートが届き、5分ほどサービスが落ちたという通知が届きました。ダウンした時のアラート内容を見てみると、k8sのPod(サーバーの一部だと思っていただければ大丈夫です。以降は「Pod」とのみ記載します。)が再起動する頻度が急に増え、そしてそれはいずれすべてのAPIにアクセスできなくなるほどでした。赤の部分は障害発生した時の時間帯また、APIの遅延を確認すると、いくつか非常に遅いものが目につきました。上記のスクリーンショットは数週間前にリリースされたカレンダー連携機能と関連しているのですが、リリース後、徐々に遅延の数値が上がっているので、障害との関連性は高いと推測しました。認証したユーザーのカレンダーへ連携を試みる処理(会議が始まる、などのイベントをoVice側が探知できるようにするためのもの)基本的に、#1の処理は早く終わるものなのですが、#2の処理はかなり遅くなることがあります。APIはレスポンスが帰ってくるまで10秒もかかることがあり、それによってtimeoutされ、処理がキャンセルされることもしばしば起こります。calendarはそこまでひどくはないものの、それでも数秒ほどの遅延は発生します。そのうえ、両者(特にMSの方)の連携処理が不明瞭な理由で失敗することも頻繁に起きるため、我々からretryをしなければならず、さらに処理時間が伸びることもあります。tokenのみの交換だけを行うように変更しました。対応としては簡単だったため、比較的軽い問題だと思っていたのですが、APIの状態をその後も続けて観察していると、頻度自体は減ったものの、問題そのものは解消されていませんでした。連携処理自体は本来の問題をただ悪化させていただけで、根本原因ではなかったようです。引き続き調査を行ったところ、原因はAPIが使っているSwooshというメールクライアントであることが特定できました。詳細は別のブログ記事に掲載していますので、興味がある方はぜひそちらをご覧ください。根本原因の特定とその対策をリリースしたため、現在問題は収束しています。processorで実行されるように書き換えることになります。JST、APIが落ちたと監視システムのDatadogから通知が来ました。5分後にはユーザーからもサービスが落ちたという報告が入り始め、スペースに入場できない事態になりました。試み過去の障害の学びから、まずは直近でリリースされた変更をロールバックしました。その変更は主にパフォーマンス改善関連のものだったので、あまり関連があるようには思えなかったものの、まず動作が確認できている状態へ戻すことが先決だったため、ロールバックを決行しました。残念なことに、APIのロールバックでは問題は解消されず、さらにパフォーマンスの改善も見られなかったため、全体的に状態が悪化してしまいました。3倍の利用量)まで跳ね上がってしまっており、さらにAPIの遅延も非常に多くなっていました。APIの遅延の問題は、Podの再起動に起因するものでした。checkがあるのですが、予め設定された時間内(我々の場合は10秒)に反応がないと、Podが落ちたと判断し自動で再起動を行い状態を改善しようとします。本来、問題の改善を自動化するための設定が、今回に限っては裏目に出て状態を悪化させていました。現象としては以下になります。戻るSentry問題をより正確に把握するために、複数人でさまざまなものをチェックしていた際、Sentry(システムのエラーレポートに使うツール)から一つの興味深い通知が届きました。月の上限を使い切った時の通知メール8月はもうエラーレポートの予算がなくなった。?まだ2週間しか経っていないのに?どう見てもおかしいので、落ちているPodのログを見てみると、以下のエラーが発生していました。%{}他の落ちていたPodも見てみると、案の定同様のエラーが短時間で大量に発生していたことが確認できました。これによって、問題の原因が何なのかを以下のように絞り込むことができました。対応に取り掛かり、急いで外されてしまったチェックを戻しました。この時点でサイトはすぐにアクセス可能な状態に戻りましたが、少しだけ事象をまとめると、99%以上のスペースはまだこの機能を使っていませんチェックを外してしまったことでUIが全スペースへのアクセスを試みるようになりエラーを大量に発生させる状態を引き起こしそのエラーが少しずつAPIへの負荷としてのしかかり最終的にはKubernetesがトドメをさしたことになります#2の問題もすぐさま修正し、期待されたリクエストが来てもエラーを起こさずに対応できるように変更しました。学びElixirがいかにスケールできるかということは、今回の障害で再確認できました。何を言ってるんだ?と思われる方もいるかと思いますが、たしかに最終的に落ちはしたものの、500万以上のエラーを30分以内に起こしながらも、かなり長い時間耐えられていたということが正直驚きです。少なくとも、技術選定における自信が今回の事象で確かなものになりました。JST、またしてもAPIが落ちたというアラートが飛びます。今回は今までのものとは少し違い、どうやらデータベースにアクセスできなくなっているようでした。データベースのCPU利用率が徐々に上がり、80%を超えたタイミングでアラートが飛ぶ様子CPU稼働率100%、これが意味することはそんなに多くありません。誰かがDDoSをしている非常に効率の悪いSQLクエリが実行されていて、DBのリソースを使い切ってしまっているの2つくらいです(もちろん他にもあるけど、簡略化するために今回は割愛)。原因DBの問題を解消するプロセスはそんなに難しくありません。DBへログインする犯人と思われる実行中のSQLクエリを見つけて、キャンセルするこれで、おおよその問題は解決します。そんな簡単なプロセスも、今回のようにCPUの稼働率が100%だと簡単ではなくなっていきます。処理するキャパがほとんどないのでアクセスするだけでも一苦労です。何度も試した末、やっとの思いでDBへログインし、実行中のクエリ一覧を吐き出させました。これが意味することは、スキャンを行う際に、取り出そうとしてるデータ量が多すぎるために、メモリー内に収まらず、ディスク上に一時的に書き込まなければならない状態です。一つあるクエリはどうやら何千回も呼ばれているようで、ほとんどが実行待ち状態になっていました。掘り下げると、どうやら関連のクエリは個人のawayメモの履歴を引き出そうとしているものでした。緊急対応として、まず該当するクエリを実行するAPIを無効にしました。無効といっても、実行自体をスキップしてデータを返さないだけで、API自体はまだ残っている状態です。その変更を加えたところ、すぐさまCPUの稼働率が落ちていくのが目に見えて分かりました。データベースのCPUの他に連動してる他のmetrics実は、今回の障害を引き起こしたDBのテーブルは、すでにエンジニアリングチームで問題児だと認識していました。そこで当然最初に疑問に思われるのは、なぜ事前に対応しなかったのか?だと思います。問題児と言っても、定期的に内部でのデータの読み込みの際にデータ量が多すぎて処理しきれなくなるくらいで、実際のところ、本番ではほとんど問題はありませんでした。スタートアップである以上、リソースの配分はどうしてもシビアにならざるをえません。そのため、問題になりそうなタイミングで対処しようと考え、問題を先送りにしていました。これは、技術負債の放置によって引き起こされる典型的な問題です。言え、問題を引き起こしてしまったため、これ以上放置するわけにはいかないので、下記のような対策をすでに実行済み、あるいは現在進行形で対処しています。問題のクエリ自体は必要なものですが、DBの設計自体はもっと効率よく書き直せるものです。PostgreSQLへの移行も行っているところなので、より効率のいいDBで実行させるように書き直しました。この書き直しはすでにリリースされていて、しばらくの間、面倒見なくてもいいようになると思います。実は、問題のテーブルと比較的近い構造のテーブルは、他にも2つあります。DBに保存するものではないので、近い将来、的確なDBへ移行することになります。JST、スペースへアクセスできない非常通知が鳴り響きます。Podのメモリーを使い切ってしまっている状態が確認できました。OOM発生時によく見られる直近でいくつかのAPIの変更を行っていたので、すぐに変更をロールバックしました。一瞬問題が解決されたように見えましたが、まもなく同じ問題が浮上しました。この時点で、直近の変更によるものではないということが、はっきりとしましたが、不可解なことに問題は少し経つと自然と収束していきました。原因この現象がどうしても不可解だったため、チーム一丸となり調査していると、一つのことに気付きました。それは、本来内部利用のために作られたAPIが、障害中かなり頻繁に呼ばれていたため、これが社内の人間が実行していたものではないということがはっきりしました。実行回数的に人間のできる速度ではないからです。問題となったこの内部用のAPIは何をしているかというと、スペース内の特定のステータスのユーザーを抽出するというものです。内部のために作られていたもののため、多少のパフォーマンスの悪さには目をつむってきました。実行頻度自体が少なく、問題になりえないからです。した状態ではなくなっていました。一般利用でも使われるようになったからです。最近のUI変更で、オフラインのユーザー一覧というものが増えたことをご存じでしょうか?これは、その内部用のAPIを再利用することで実装されているものです。いうのも、リソースが圧迫されながらも、変更を出し続けなければならないという状態において、エンジニアとしては再利用できるものがあるならしようと考えます。この考え方自体は全く問題ではなく、私個人としてもそうしていたと思います。API自体も多少パフォーマンスに問題があるのは承知していたうえで、それでもサービスが落ちるほどの問題になりえないと思い再利用する意思決定をしました。何が起きたのでしょうか?調査してわかったことは、どうやら、ある一つのスペースで、400,000人以上のユーザーが紐付いていたことです。そのスペースにアクセスする時に、自動で400,000人分ものデータを引き出そうとします。これは誰かがスペースにアクセスする度に起こります。その結果、APIは何度も400,000人のデータを読み込もうとし、Podのメモリーが足りなくなったことで、最終的に許可しているリソース以上を使おうとしていたため、KubernetesがPodを自動で落としていました。これが何回か連続、かつ高速で起こると全Podはアクセスできなくなり、結果としてこの障害が起きてしまったのです。自然と収束したこともこれで簡単に説明できます。そのスペースへのアクセスが一時的に増え、そのアクセスが減ると共に、膨大なデータ量にアクセスしようとする試みも一緒に収束していきます。最初の対応策として、引き出せるユーザーの量を強制的に絞るようにしました。その引き出せるリミットはoViceで2番目に大きいスペースに合わせていますが、それでも問題となったスペースの1/100ほどで、APIが十分対応できるレベルです。フォローアップとして、リミット以上のデータを取得しようとする場合は、Paginationを行うようAPIを少し変更します。学びバグではないこと最初の2つの原因は不注意により引き起こしてしまったことですが、これらすべての障害で共通していることは、どれもバグではないということです。エンジニアたちは実装後に自分たちで検証環境でのテストを行っており、QAも共に通っているため、個別に見ると挙動はあっています。スケールした時のみに起きる問題oViceの現在の環境は、機能やバグなどのチェック(自動化も含めて)を行うことは可能ですが、大規模なスケールで起きる問題は検知することができません。この問題は、今回の一連の障害ではっきりとわかったため、今後の対策としてはカナリア環境というものを追加し、一部のユーザーで、ある程度の規模以上での挙動を確認してから全体にリリースするように変更します。将来似たような問題が起きたとしても、インパクトの規模を制限できるような対策も講じています。進歩とは、つまり変化することで、変化すれば必ず問題は一緒に付いてきます。故に「すべての問題を防ぐ」ことは考えていませんし、現実的に不可能です。本来の予想と違った挙動をするただ一つのAPIが全体を落とすような事態になってはならないので、問題が発生した際の規模を絞れるようにします。技術負債ご覧の通り、いくつかの問題の原因は対応を後回しにしていた技術負債から一気にしっぺ返しを食らったことで起こったものでした。運が悪いかと言えば、そう言えるかもしれません。運が悪かったで終わらせるつもりは当然ありません。今後も、今回の問題のようにショートカットを選択することはありえます。これに関しては避けようのないことです。問題を把握していれば規模を制約することも可能なので、これからはまず、完全ではなくとも、把握している問題の対策を行ってからリリースするようチーム全体でしていきます。最後に日頃からoViceをご利用いただいてる皆様、本当にありがとうございます。反省することは多くあるのですが、少し見方を変えてみると、これらは本当に多くの方々がoViceをたくさん使っていただいたことでしか起きない問題でもあるため、個人的には非常に良い悩みの機会をいただいたと思っています。oViceというサービスがいつでも正常に稼働していないと多くの方にご迷惑をおかけすることも認識しています。エンジニアチーム一同として、社内のプロセスや自動化の発展に精進し、また、たとえどんな原因のものであろうと、問題や障害を可能な限り最小限に抑えられるよう引き続き努力してまいります。