A Post Mortem on August 2022 incidents — JP

Published in

oVice

19 min readSep 17, 2022

まずは8月に起きた障害において、皆様に多大な迷惑をおかけしたこと、この場をお借りしてお詫びいたします。本当に申し訳ありませんでした。このブログでは、7月の終わりと8月に起きた各障害において、1. 何が起きたのか、とその 2.対策についてユーザーの皆様に共有したいと思います。

より正確に情報を伝えるため、内容はテクニカル寄りになりますがご了承ください。

2022年7月29日の障害について

11:49 AM JST、APIがダウンしたというアラートが届き、5分ほどサービスが落ちたという通知が届きました。

DatadogのPod availability monitor — ダウンした時のアラート

内容を見てみると、k8sのPod（サーバーの一部だと思っていただければ大丈夫です。以降は「Pod」とのみ記載します。）が再起動する頻度が急に増え、そしてそれはいずれすべてのAPIにアクセスできなくなるほどでした。

oViceの一日においてのtrafficの分布傾向 — 赤の部分は障害発生した時の時間帯

また、APIの遅延を確認すると、いくつか非常に遅いものが目につきました。

上記のスクリーンショットは数週間前にリリースされたカレンダー連携機能と関連しているのですが、リリース後、徐々に遅延の数値が上がっているので、障害との関連性は高いと推測しました。

調査

問題のAPIは二つの処理を行っており、

OAuth認証成功後に渡されたcodeをaccess tokenに交換する処理
認証したユーザーのカレンダーへ連携を試みる処理（会議が始まる、などのイベントをoVice側が探知できるようにするためのもの）

基本的に、#1の処理は早く終わるものなのですが、#2の処理はかなり遅くなることがあります。例えばMicrosoft TeamsのGraph APIはレスポンスが帰ってくるまで10秒もかかることがあり、それによってtimeoutされ、処理がキャンセルされることもしばしば起こります。

Google calendarはそこまでひどくはないものの、それでも数秒ほどの遅延は発生します。そのうえ、両者（特にMSの方）の連携処理が不明瞭な理由で失敗することも頻繁に起きるため、我々からretryをしなければならず、さらに処理時間が伸びることもあります。

対応

まず、緊急対応として

APIを一つ前のバージョンに戻す
APIの利用できるリソースを増やす
連携処理をAPIではなくて、Background processorに移す

の最初の2つの対応を行い、連携処理がAPIのレスポンス遅延に影響を与えないようにし、あくまでOAuthのcodeとaccess tokenのみの交換だけを行うように変更しました。

対応としては簡単だったため、比較的軽い問題だと思っていたのですが、APIの状態をその後も続けて観察していると、頻度自体は減ったものの、問題そのものは解消されていませんでした。どうやら連携処理自体は本来の問題をただ悪化させていただけで、根本原因ではなかったようです。

引き続き調査を行ったところ、原因はAPIが使っているSwooshというメールクライアントであることが特定できました。詳細は別のブログ記事に掲載していますので、興味がある方はぜひそちらをご覧ください。

根本原因の特定とその対策をリリースしたため、現在問題は収束しています。今後の対策としても、APIの開発や修正に当たってresponse timeには厳重な速度規定を設定しています（Apdex 100ms）。もし、レスポンスタイムがこの規定時間を超えるようなことがあれば、background processorで実行されるように書き換えることになります。

2022年8月3日の障害について

8:51 AM JST、APIが落ちたと監視システムのDatadogから通知が来ました。5分後にはユーザーからもサービスが落ちたという報告が入り始め、スペースに入場できない事態になりました。

試み

過去の障害の学びから、まずは直近でリリースされた変更をロールバックしました。その変更は主にパフォーマンス改善関連のものだったので、あまり関連があるようには思えなかったものの、まず動作が確認できている状態へ戻すことが先決だったため、ロールバックを決行しました。

しかし、残念なことに、APIのロールバックでは問題は解消されず、さらにパフォーマンスの改善も見られなかったため、全体的に状態が悪化してしまいました。そのときどんな状態だったかというと、CPUの利用率が常に高く、メモリーの利用量も3G（普段は1Gほどの利用量なので、2 ~ 3倍の利用量）まで跳ね上がってしまっており、さらにAPIの遅延も非常に多くなっていました。

APIの遅延の問題は、Podの再起動に起因するものでした。具体的にご説明すると、Kubernetesで設定しているhealth checkがあるのですが、予め設定された時間内（我々の場合は10秒）に反応がないと、Podが落ちたと判断し自動で再起動を行い状態を改善しようとします。

本来、問題の改善を自動化するための設定が、今回に限っては裏目に出て状態を悪化させていました。現象としては以下になります。

Podのhealth checkの反応の遅延が長くなる
Kubernetesは時間内で反応がないので、Podが落ちたと判断されていたが、実際はまだ稼働している
Podが再起動され、立ち上がる際に大量のtrafficが流れ込み、処理しきれなくなって #1 に戻る

Sentry

問題をより正確に把握するために、複数人でさまざまなものをチェックしていた際、Sentry（システムのエラーレポートに使うツール）から一つの興味深い通知が届きました。

8月はもうエラーレポートの予算がなくなった。。？まだ2週間しか経っていないのに？

どう見てもおかしいので、落ちているPodのログを見てみると、以下のエラーが発生していました。しかもかなり頻繁に。

00:04:31.923 [info] JOINED user_call:3694632 in 10msParameters: %{}00:04:31.923 request_id=a48af8b8029476faa05538f691f299d4 trace_id=708587351750908735 span_id=874386591673519646 [info] Sent 200 in 3086ms00:04:31.924 [error] an exception was raised:** (FunctionClauseError) no function clause matching in OviceWeb.UserChannel.join/3(ovice 0.1.0) lib/ovice_web/channels/user_channel.ex:10: OviceWeb.UserChannel.join(“user:xxxxxx”, %{}, %Phoenix.Socket{assigns: %{user_id: xxxxxx}, channel: OviceWeb.UserChannel, channel_pid: #PID<0.1117.1>, endpoint: OviceWeb.Endpoint, handler: OviceWeb.UserSocket, id: “user_socket:xxxxxxx”, join_ref: “xxxx”, joined: false, private: %{log_handle_in: :debug, log_join: :info}, pubsub_server: Ovice.PubSub, ref: nil, serializer: Phoenix.Socket.V2.JSONSerializer, topic: “user:xxxxxx”, transport: :websocket, transport_pid: #PID<0.4437.0>})(phoenix 1.6.6) lib/phoenix/channel/server.ex:376: Phoenix.Channel.Server.channel_join/4(phoenix 1.6.6) lib/phoenix/channel/server.ex:298: Phoenix.Channel.Server.handle_info/2(stdlib 3.17) gen_server.erl:695: :gen_server.try_dispatch/4(stdlib 3.17) gen_server.erl:771: :gen_server.handle_msg/6(stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/300:04:31.926 [info] JOINED user_call:3583827 in 8msParameters: %{}00:04:31.930 [info] JOINED user_call:3563518 in 8msParameters: %{}

他の落ちていたPodも見てみると、案の定同様のエラーが短時間で大量に発生していたことが確認できました。

これによって、問題の原因が何なのかを以下のように絞り込むことができました。

直近リリースされたUIの変更で、特定の条件を満たさない限りAPIへアクセスしなくていいようにするチェックを誤って外してしまっていたこと
受け取るAPI側で、パターンに合わないリクエストが来たときの処理が実装されていなかったこと

問題を把握した段階で、まず #1 の対応に取り掛かり、急いで外されてしまったチェックを戻しました。この時点でサイトはすぐにアクセス可能な状態に戻りましたが、少しだけ事象をまとめると、

99%以上のスペースはまだこの機能を使っていません
チェックを外してしまったことでUIが全スペースへのアクセスを試みるようになり
エラーを大量に発生させる状態を引き起こし
そのエラーが少しずつAPIへの負荷としてのしかかり
最終的にはKubernetesがトドメをさしたことになります

#2の問題もすぐさま修正し、期待されたリクエストが来てもエラーを起こさずに対応できるように変更しました。

学び

Elixirがいかにスケールできるかということは、今回の障害で再確認できました。何を言ってるんだ？と思われる方もいるかと思いますが、たしかに最終的に落ちはしたものの、500万以上のエラーを30分以内に起こしながらも、かなり長い時間耐えられていたということが正直驚きです。少なくとも、技術選定における自信が今回の事象で確かなものになりました。

2022年8月8日の障害について

1:07 PM JST、またしてもAPIが落ちたというアラートが飛びます。しかし、今回は今までのものとは少し違い、どうやらデータベースにアクセスできなくなっているようでした。

データベースのCPU利用率が徐々に上がり、80%を超えたタイミングでアラートが飛ぶ様子

CPU稼働率100%、これが意味することはそんなに多くありません。

誰かがDDoSをしている
非常に効率の悪いSQLクエリが実行されていて、DBのリソースを使い切ってしまっている

の2つくらいです（もちろん他にもあるけど、簡略化するために今回は割愛）。

原因

DBの問題を解消するプロセスはそんなに難しくありません。

DBへログインする
犯人と思われる実行中のSQLクエリを見つけて、キャンセルする

これで、おおよその問題は解決します。

ただ、そんな簡単なプロセスも、今回のようにCPUの稼働率が100%だと簡単ではなくなっていきます。なぜなら、処理するキャパがほとんどないのでアクセスするだけでも一苦労です。

何度も試した末、やっとの思いでDBへログインし、実行中のクエリ一覧を吐き出させました。

| 98293642 | ovice_admin | 10.xx.x.xxx:60756 | ovice | Execute | 439 | removing tmp table | <QUERY> || 98293835 | ovice_admin | 10.xx.xx.xxx:51358 | ovice | Execute | 438 | Sending data | <QUERY> |

Removing tmp table…? これが意味することは、スキャンを行う際に、取り出そうとしてるデータ量が多すぎるために、メモリー内に収まらず、ディスク上に一時的に書き込まなければならない状態です。

もう一つあるクエリはどうやら何千回も呼ばれているようで、ほとんどが実行待ち状態になっていました。

もう少し掘り下げると、どうやら関連のクエリは個人のawayメモの履歴を引き出そうとしているものでした。

解決

緊急対応として、まず該当するクエリを実行するAPIを無効にしました。無効といっても、実行自体をスキップしてデータを返さないだけで、API自体はまだ残っている状態です。

その変更を加えたところ、すぐさまCPUの稼働率が落ちていくのが目に見えて分かりました。

実は、今回の障害を引き起こしたDBのテーブルは、すでにエンジニアリングチームで問題児だと認識していました。そこで当然最初に疑問に思われるのは、なぜ事前に対応しなかったのか？だと思います。

問題児と言っても、定期的に内部でのデータの読み込みの際にデータ量が多すぎて処理しきれなくなるくらいで、実際のところ、本番ではほとんど問題はありませんでした。また、スタートアップである以上、リソースの配分はどうしてもシビアにならざるをえません。そのため、問題になりそうなタイミングで対処しようと考え、問題を先送りにしていました。

これは、技術負債の放置によって引き起こされる典型的な問題です。とは言え、問題を引き起こしてしまったため、これ以上放置するわけにはいかないので、下記のような対策をすでに実行済み、あるいは現在進行形で対処しています。

問題のクエリ自体は必要なものですが、DBの設計自体はもっと効率よく書き直せるものです。また、MySQL => PostgreSQLへの移行も行っているところなので、より効率のいいDBで実行させるように書き直しました。この書き直しはすでにリリースされていて、しばらくの間、面倒見なくてもいいようになると思います。
実は、問題のテーブルと比較的近い構造のテーブルは、他にも2つあります。ただ用途的にはRelational DBに保存するものではないので、近い将来、的確なDBへ移行することになります。

2022年8月23日の障害について

9:00 AM JST、スペースへアクセスできない非常通知が鳴り響きます。すぐさまPodのメモリーを使い切ってしまっている状態が確認できました。

直近でいくつかの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というサービスがいつでも正常に稼働していないと多くの方にご迷惑をおかけすることも認識しています。エンジニアチーム一同として、社内のプロセスや自動化の発展に精進し、また、たとえどんな原因のものであろうと、問題や障害を可能な限り最小限に抑えられるよう引き続き努力してまいります。