はんドンクラブにおいて,以下の障害が発生していましたが,現在は復旧しています。ご迷惑をおかけしたことをお詫びいたします。
- 日時: 2019年11月27日(水) 22:46 〜23:34 (JST)
- 影響範囲: はんドンクラブの全ユーザ
- 障害内容: レスポンスが悪いため,アクセス困難な状態になる(Web・API経由いずれも)
- 原因:大容量動画投稿による処理遅延の発生
- 解決方法: 自然回復
根本原因
mastodonでは,動画が投稿された際,ffmpegによる動画ファイルの再エンコードが行われます。(おそらくffmpeg側の不具合で)ffmpegがCPUリソースをほぼ100%使い果たしてしまい,結果的に他の処理ができなくなってしまいました。なお,ffmpegはwebデーモン(bundle exec puma)から呼び出されるため,今回CPUリソースをほぼ100%使い果たしてしまったのはwebサーバのみです。
根拠ですが,実はれっきとした証拠はつかめていません。客観的に見てその可能性が高いと判断した,ということになります。
その詳細を説明します。はんドンクラブにある2台のwebサーバはDNSラウンドロビンにより負荷分散されています。今回,2台のwebサーバのCPU利用率の高騰が開始した直前に,いずれのサーバにも全く同じ動画が投稿されていました。なぜ2台のwebサーバに同じ動画の投稿がリクエストされたかは分かりませんが,3rd party製クライアントで動画アップロードを試みたものの失敗したためリトライ処理が行われ,その際にたまたまDNSのTTLが切れた可能性があります。この状況から,原因を推測しました。
今回の対処方法
自然回復しました。
今後の対処方針,改善点
再発防止策は現状分かっておらず,再発の可能性は十分にあります。
nginx設定の変更
根本対処にはなりませんが,今後大容量なファイルができるかぎりアップロードされないよう,リバースプロキシ(nginx)側でアップロードファイルサイズの上限を制限しました。この対処により,ffmpegに動画を渡す前にあまりに容量の大きな動画はrejectできますので,今回と同様の事象の発生確率は下げられるものと推察します。
- Before
client_max_body_size 80m;
- After
client_max_body_size 50m;
なお,念のため述べておきますが,コンフィグ中の「50MB」というのは,「アップロード時に受け付けるサイズの上限値」であり,「実際にはんドンクラブサーバに格納される場合のサイズの上限値」ではありません。ffmpeg等により再エンコード/リサイズされるため,実際には数MB程度にまで圧縮されています。
アラート発報閾値の見直し
はんドンクラブでは,prometheus+grafanaを使った常時監視を行っています。さらに,アラートが発生すると管理者全員にLINEで通知される仕組みとなっています。しかし今回は,実際にサービス影響が出始めてからGrafanaのアラート発報まで10分程度要してしまいました。一部の閾値を見直し,より早く気づけるように修正を行いました。
本件が発生した環境
対応時系列
特に意味はないかもしれませんが,今回の対応時系列を公開します。
2019年11月27日
- 22:46:30頃 web1サーバ CPU利用率高騰開始
- 22:46:45頃 HTTPレスポンス警戒域
- 22:48:30頃 web2サーバ CPU利用率高騰開始
- 22:48:59 dbサーバ pbouncer でのエラー多発(
.env.production
のuser名/db名設定が無効化される ) - 22:49:04 web2サーバ rack_attack.rb での API レートリミットが多発
- 22:49:15頃 web1サーバ CPU利用率警戒域(60%超)
- 22:51:50頃 web2サーバ CPU利用率警戒域(60%超)
- 22:54:01 監視サーバからのHTTPレスポンス警報が発報,管理者へLINE通知
- 22:55:16 監視サーバからのCPU利用率警報が発報,管理者へLINE通知
- 22:55:19 web2サーバ rack_attack.rb での API レートリミットが多発
- 23:30頃 管理者による対応開始
- 23:32:15頃 web1,2サーバ共にCPU利用率の低下開始
- 23:34:35頃 HTTPレスポンス 通常値に復旧
- 23:36:15頃 web1サーバ CPU利用率 定常レベルに改善
- 23:38:15頃 web2サーバ CPU利用率 定常レベルに改善
- 23:41頃 管理人により障害発生第一報の正式周知
2019年11月28日
- 00:33頃 管理者によりあらかたの原因が発覚
- 01:14頃 管理人により障害発生・復旧報(最終報)の正式周知