2021年12月1日に起きたoViceの障害について
2021年12月1日の日本時間16:38から21:41までの間、oViceの一部の機能が使えなくなる障害がありました。復旧までに当初の想定よりも長い5時間もの時間がかかってしまった理由と、その間に私達が講じていた対策について、時系列で書いてみたいと思います。
簡単な障害レポートについては、障害発生直後にステータスページの https://status.ovice.io/incident/60976 にて報告しております。
発生した障害について
リアルタイム処理の機能を担っているEchoサーバ(後述)が高頻度のリクエストに耐えられず停止し、oViceのスペース内で以下の機能が利用不可能となっていました。
- 会議室への入退出
- アバターアイコンの右上の絵文字の変更
- スペースのレイアウト変更
インフラ全体のアーキテクチャは現在下図の様になっており、oVice内の上記の機能以外を担うAPIサーバとミーティングの機能を担うCoreサーバは正常に稼働していたため、ログインや通話は可能な状況でした。
なお後述しますが、障害復旧中にAPIサーバも一時高負荷状態になり、繋がりにくくなっていた時間帯がありました。
レスポンスタイムの異常を検知
まず最初に異常に気がついたのは、16:34にAPIサーバのレスポンスタイムが異常に遅くなっていることのアラートが飛んできたためです。通常p50で150ms程度でレスポンスを返しているAPIサーバがp50で5~6secとなっていました。
ユーザがoViceにログインするとEchoサーバに20ほどリクエストが飛び、そこからEchoサーバがAPIサーバに対してさらに問い合わせをするのですが、この時EchoサーバからAPIサーバへのリクエスト数が異常に多く、APIサーバに高い負荷がかかっている状況となっていました。3分ほど経った16:37頃にAPIサーバのレスポンスタイムは正常に近い値まで戻ったので一安心したのですが、この時実際にはEchoサーバのプロセスが落ちAPIサーバに対してリクエストを送らない状態となり、負荷が下がっていただけでした。
一台のEchoサーバが落ちてしまうと、クライアント側から再接続のリクエストが(最長)30秒毎に行われるため、他のEchoサーバの負荷が高まります。その結果すべてのEchoサーバが高負荷状態となり全Echoサーバにおいてプロセスが落ち、LoadBalancerから切り離されリクエストを受け付けることができない状況でした。(再発防止策1)
Echoサーバの死活監視に失敗した通知を受け取ったのが16:44です。
復旧に向けた対応
ここから作業ログにタイムスタンプの記録がないため(要改善)、実行手順のみ記載していきます。
Echoサーバを再起動させたいのですが、前述の通りクライアントからは再接続のリクエストが30秒毎に来続けるためサーバ起動直後に再度高負荷状態になることが想像されます。そのため、サーバの性能を上げてから起動することにしました。ここで水平スケーリングではなく、垂直スケーリングを選択しているのは、コンテナ化やAMI等によりすぐに同等の環境が作れる状況になっていないためです。(再発防止策2)
しかし予想に反して、再度プロセスが殺されてしまい先程と同じ現象が起きてしまいました。これは Node.js のプロセスが --max-old-space-size のオプションを指定せずに起動されており、サーバの性能に関わらずメモリ使用量の上限がデフォルトの1456MBになっていたためだと推測しています。メモリの使用過多ではないので /var/log/message にはOOMのエラーメッセージも出ておらず、これは推測の域を出ておりません。
その後 --max-old-space-size のオプションを有効にして起動しようと試みたのですが、Echoサーバの起動スクリプトではShebangを使って
#! /usr/bin/env nodeのように書かれていたため、容易にオプションを渡せる状況ではありませんでした。少し調べると
#!/bin/sh
":" //# ; exec /usr/bin/env node --<option> "$0" "$@"に書き換えることでオプションを渡すことが可能であるという記事をいくつか見つけることができ、障害対応中もこの解法には気づいていたのですが、きれいな解決策ではなかったので採用を見送ってしまいました。今考えると復旧を最優先に考えて取り急ぎこの方法で対応すべきでした。
つまりこの時Echoサーバは垂直にも水平にもスケーリングが難しい状況という判断をしていることになります。
障害発生によりアクティブユーザ数が減少しリクエストを捌ける可能性があること、また時間帯を考えてもユーザが減っている可能性があることから、特に改善は施されていませんが、再度全Echoサーバを再起動することにしました。(19:10頃)
するとEchoサーバは耐えることができましたが、APIサーバへの問い合わせ数が急増してしまい、APIサーバのp50レスポンスタイムが20秒前後となってしまいました。その結果クライアントからの30秒毎の再接続リクエストに対して、30秒以内に返すことができず永遠と再接続のリクエストが送られて来てしまう結果となりました。
以下のグラフが障害開始時から終了時までのAPIサーバのメトリクスです。19:10頃に急激に負荷が高まっていることが分かります。
APIサーバのレスポンスタイムが遅くなると、oViceへのログインやチャット機能などほとんど全ての機能に関して動作が重くなってしまうため、この状況は早急に解消する必要がありました。
解決策としては、以下の2つの方法を考えていました。
- APIサーバの垂直スケーリング
- クライアントからの再接続のリトライ間隔を伸ばすパッチをリリース
APIサーバは現在PHPで動いており、先程のNode.jsの垂直スケーリングを妨げるような問題はなかったため、選択肢1を取ることにしました。
19:30頃からAPIサーバの強化を順次行い、20時に全台に対して強化が完了しました。この過程で19:41にEchoサーバが再度全台死んでしまったため、APIサーバの垂直スケーリング完了を持って20時にEchoサーバを再起動しました。
その結果、上のメトリクスからもわかるように再度APIサーバへのリクエストは急増しましたが、なんとか捌き切ることができ、クライアントからの30秒毎の再接続ループからは抜け出せているように見えました。
この時実際にサービスにアクセスしてみると、Echoサーバから30秒以内にレスポンスが返ってきており全ての機能を問題なく使えているユーザとそうでないユーザが混在している状況でした。上のグラフでAPIサーバへのリクエスト数とレイテンシの関係を見ても20:30 ~ 21:30の間はAPIサーバは低レイテンシでレスポンスを返しているにも関わらず、APIへのリクエスト数は減っておらず、Echoサーバからリクエストが来続けていることが分かります。(つまり特定クライアント群にはEchoサーバから30秒以内にレスポンスを返すことができておらず、再接続ループが続いていたということです。)
この状況はEchoサーバのCPU使用率からも見て取ることができました。LoadBalancerでIPアドレスベースのSticky Sessionを有効にしているため、クライアント毎に決まったEchoサーバに対してリクエストが飛びます。下のメトリクスがEchoサーバのCPU使用率ですが、一定のCPU使用率を長時間保ち続けていることが分かります。また、サーバ毎のネットワークコネクション数を見てもかなり偏りがある状態でした。
特定のクライアント群に対してのみ問題が発生していた原因は結局突き止めることができず、時間が経過しても状況が改善しないためEchoサーバを再起動することにしました。(21:35頃)
その結果、全ユーザに対して正常にレスポンスを返せるようになり、21:41に正常な状態に回復したと判断しました。
再発防止策
きっかけは短期間の急激なログイン数増加により起きたEchoサーバのダウンでしたが、今回の障害から様々な課題とその改善点を見つけることができました。
1. プロセスが自動再起動するように修正
Echoサーバに関しては、systemdなどのシステム管理デーモンによる自動再起動の設定がされていませんでした。プロセスが死んでしまっても、自動で再起動するような設定に変更します。
また同時に起動スクリプトも--max-old-space-size のオプションを渡せるように修正し、少なくとも垂直スケーリングが出来る構成に変更します。
2. 水平スケール可能なアーキテクチャへの変更
現在のサーバ構成はデプロイ時にVMで動いているコードに対して更新をかける形になっており、水平スケーリングが容易にできない形になっています。これについては、コンテナ化をしKubernetes上でサービスを動かすように現在作業を進めている最中です。
3. APIサーバへの問い合わせロジックの改善
クライアントからの再接続時にEchoサーバからAPIサーバへ問い合わせが発生する箇所に関して、ロジックを改善することで問い合わせの回数を約1/20に減らせることが分かりました。この修正によりEchoサーバに負荷がかかっている際にも、APIサーバに与える影響を少なくすることができます。
4. 再接続間隔の改善
今回の障害の原因となった問題は、Thundering herd problem としてよく知られています。その解決策の1つとして、リトライ間隔にランダム性を加えることと指数関数的にリトライ間隔を伸ばすものがあります。これは私達が使用しているSocket.IOではデフォルトで実装されていますが、リトライの最大間隔を30秒と短い時間に設定していたことにより今回の復旧がより難しいものとなってしまいました。最大リトライ間隔を更に長い時間にすることで、サーバーへの負荷を下げる対策をします。
まとめ
インフラのアーキテクチャに関しては伸びしろばかりで、公開するのは憚られるような状態でしたが、透明性を担保しユーザの方々に現状を知ってもらうことを優先して今回障害レポートを書く運びとなりました。
物理的なオフィスでは突然会話ができなくなることはありません。当然バーチャルオフィスでも同じことが実現されるべきです。安心して毎日お使い頂き、oViceを空気のように当たり前な存在として使っていただけるように、信頼性を高めていきたいと思っています。
改めて、今回の障害で影響を受けた全てのユーザにお詫び申し上げます。
