これまで数多くのシステム障害を復旧してきました。
障害は無いに越したことは無いですし、起こらないように最善を尽くすのが我々エンジニアの使命です。
しかし、どれだけ最善を尽くしても起こる時には起こります。
今回は、これまで数多くの障害を復旧させてきたエンジニアが、復旧作業時に何を考えているのかを改めて言語化してみたいと思います。
こういう情報ってそれぞれのエンジニアの頭の中にあってあまり共有されないので、意外に参考になるかなと思います。
障害復旧対応の醍醐味
表現が適切かは分かりませんが、僕はシステム障害を復旧させるのが大好きです。目の前に起こっている事象からヒントを集め、地道に原因を切り分けてクリティカルヒットを見つけたときは名探偵になった爽快感があります。
加えて、動いているものを常に動かし続ける日頃の保守運用とは異なり、動いてないマイナスの状況を0まで戻すということで、復旧成功した際にはめちゃくちゃ感謝されます。
後者に関してはおまけみたいなものですが、エンジニアとしての守備力を試される機会なのでいつも以上に気合を入れて対応する時間です。
先日起こったシステム障害
僕が参画しているとある会社にてシステム障害が発生しました。
詳細は割愛しますが、ざっくり https://company-domain.com/hoge_hoge にアクセスすると500エラーになったという内容。(ドメインは適当です)
これが解決されないと社内の重要な制作作業がストップしてしまい、長引くと売り上げにダイレクトに響いてくるというものでした。
トリリオンゲームの学のように腕まくりをして、復旧作業を始めます。
ヒントを集める
普段接しない見慣れぬドメインだったので、どのサーバで起こっていることかすらもわかりません。
今持っている情報は
- https://company-domain.com/hoge_hoge が500エラーを返している
- 指定のサーバは生きた化石でメンテされておらず直近1年以上ソースコードのデプロイは行われていない
- webサーバとしてnginxが使われている
これだけです。
ここから、あらゆる手段を尽くして障害の原因を突き止めて、復旧させていきます。
通信経路を読み解く
復旧対応で僕が真っ先にやっていることは、通信経路を明らかにすることです。どこまでリクエストは通っていて、どこからおかしな動作をしているのかを既存のAWSの設定やログから明らかにしていきます。
ドメインの解決
今回のドメインは company-domain.com 。
ドメインは Route53 で管理しているのでそちらを見に行きます。
Aレコードを見ると、ドメインはCloudFrontで解決していることがわかりました。
company-domain.com → CloudFrontのドメイン
CloudFrontのビヘイビア
次はCloudFrontのディストリビューションを見に行きます。
CloudFrontでは、パスによってさまざまなオリジンにリクエストをプロキシさせることができます。
ビヘイビアの設定を見てみます。
パスパターンにはマッチしないのでデフォルトに振り分けられていることがわかりました。
デフォルトオリジンはELBのようです。
ELBのリスナールール
お次はELBの設定を見に行きます。
ELBではリスナーとルールという設定でL7(アプリケーション層)のリバースプロキシができます。
(例えば、リクエストパスやリクエストヘッダーのホストを見てEC2やECSに振り分ける、など)
今回はデフォルトのターゲットグループに飛ばされていることがわかりました。
ターゲットグループの設定をみにいくと、EC2のインスタンスに行っているようです。
ようやく、サーバを突き止めることができました。
まとめると以下の経路でEC2まで到達していることがわかります。
Route53 → CloudFront → ELB → EC2
サーバの中に入って情報を集める
EC2のインスタンスまで突き止めたので、お次はサーバに入って具体的な情報を集めて行きます。
EC2に入るための認証情報すら知らない状況でしたが、どうやらSessionManagerで入れるようになっている様子でした。
サーバエラーとなる主な要因
ここから何をみていくかという話ですが、これまでの経験上デプロイをしていないのにサーバエラーとなる原因としては以下が多いです。
- メモリ不足 OOM Killed
- web, applicationサーバのプロセスが落ちている
- ディスク容量不足
ここから1つ１つ原因を切り分けていきます。
Webサーバが動いているか
まずは、Webサーバのnginxが動いているか確認します。
$ ps aux | grep [n]ginx
>
root 2407 0.0 0.0 60300 1428 ? Ss Jan31 0:00 nginx: master process /usr/sbin/nginx -c /etc/nginx/nginx.conf
ec2-user 2408 0.0 0.1 60304 5028 ? S Jan31 0:00 nginx: worker process
ec2-user 2409 0.0 0.1 60304 5060 ? S Jan31 0:00 nginx: worker process
ちゃんと動いているようでした。
※ ちなみにgrepコマンドで [n] としているのは、grepコマンド自体のプロセスを表示しないようにするハックです。
applicationサーバが動いているか
nginxのプロセスは生きていたので、次はapplicationサーバのプロセスが動いているか確認します。
いつも親しんでいるサービスであれば、どこにapplicationサーバの設定が置かれているのかわかるのですが、今回は社内の誰も詳細を知らない化石サービスなので、そこから突き止める必要があります。
nginxの設定を頼りに突き止めます。
nginxのカスタマイズ設定はだいたい以下に置くことが多いです。
/etc/nginx/conf.d/*
今回のサービスの設定がありました。
中身を見てみます。
server {
listen 80 default_server;
listen [::]:80 default_server;
server_name company-domain.com;
location /hogehoge {
fastcgi_pass unix:/var/run/php-fpm/php-fpm.sock;
}
なるほど、どうやらUNIXドメインソケットで、php-fpm.sock というapplicationサーバと疎通しているようです。
ようやくapplicationサーバのプロセス名も突き止めたので、死活チェックをします。
# ps aux | grep [p]hp-fpm
>
root 2387 0.0 0.2 434180 8396 ? Ss Jan31 0:00 php-fpm: master process (/etc/php-fpm.conf)
ec2-user 2388 0.0 0.3 434180 15452 ? S Jan31 0:00 php-fpm: pool www
・・・
ec2-user 25508 0.0 0.3 434180 14664 ? S Jan31 0:00 php-fpm: pool www
ちゃんと動いているようでした。
- メモリ不足 OOM Killed
- web, applicationサーバのプロセスが落ちている
- ディスク容量不足
のうち、2つ目のケースでは無いことがわかりました。
ログからさらなるヒントを集める
プロセスは最低限生きていることがわかったので、次はログからヒントを集めにいきます。
では、nginxのログを見に行きます。
先ほどのnginxの設定を見ると、ログはデフォルトの設定で、以下に出されているようです。
/var/log/nginx/access.log
試しに見てみましょう。
$ tail -n 100 access.log
>
表示なし
何も表示されませんでした。おかしいですね。。
ディレクトリを移動して、一覧をみてみます。
$ cd /var/log/nginx
$ ls -la
>
-rw-rw-r-- 1 ec2-user root 41960 Jan 20 03:08 access.log-20240120.gz
-rw-rw-r-- 1 ec2-user root 38000 Jan 21 03:40 access.log-20240121.gz
-rw-rw-r-- 1 ec2-user root 31477 Jan 22 03:07 access.log-20240122.gz
-rw-rw-r-- 1 ec2-user root 11828 Jan 23 03:38 access.log-20240123.gz
-rw-rw-r-- 1 ec2-user root 0 Feb 1 04:46 error.log
-rw-rw-r-- 1 ec2-user root 6352 Jan 21 03:40 error.log-20240121.gz
-rw-rw-r-- 1 ec2-user root 3037 Jan 22 03:07 error.log-20240122.gz
-rw-rw-r-- 1 ec2-user root 1797 Jan 23 03:38 error.log-20240123.gz
accessログが20240123以降出ていないことが判明しました。
最後に出ていたログを見てみましたが、特にこれといったヒントはありません。
ディスク容量が怪しいのでは？
ログがある時を境に出なくなったということは、nginxが急にファイルの書き込み権限を失ったか、そもそもディスク容量を使い切って書き込めなくなったかのどちらかです。
前者については僕は遭遇したことがありません。
そうなると、
- メモリ不足 OOM Killed
- web, applicationサーバのプロセスが落ちている
- ディスク容量不足
のうち、3つ目が怪しそうです。
ディスク容量を確認してみます。
$ df -h
>
Filesystem Size Used Avail Use% Mounted on
devtmpfs 1.9G 68K 1.9G 1% /dev
tmpfs 1.9G 0 1.9G 0% /dev/shm
/dev/xxxxxxxx 50G 50G 50G 100% /
4行目を見ると、Usedが100%になっており、ディスクを使い果たしていることが判明しました。
やりました、どうみてもこれが原因です！
原因がわかったので後は復旧作業
原因さえ突き止めればあとは粛々と復旧させるだけです。
EC2はEBSでボリュームの管理をしていたので、一時対応としてボリュームの容量を増やし、
サーバ内でいくつかのおまじないコマンドを叩いて、/dev/xxxxxxxx に割り当てて完了。
無事にnginxのログが吐き出されるようになりました。
$ tail -f /var/log/nginx/access.log
172.31.19.85 - - [01/Feb/2024:05:01:30 +0900] "GET / HTTP/1.1" 200 179 "-" "ELB-HealthChecker/2.0"
172.31.42.61 - - [01/Feb/2024:05:01:33 +0900] "GET / HTTP/1.1" 200 179 "-" "ELB
その後、社内の方に動作確認を依頼し、無事に復旧したことを確認できました。
今後の対応
今回はあくまで一時対応として、ボリュームの容量をあげて切り抜けましたが、以下のIssueを作って復旧作業はおしまいにしました。
- ログローテの仕組みを入れる
- 不要なファイルを削除する
- 監視を入れて容量が逼迫してきたらslackに通知が飛ぶようにする
まとめ
以上、インシデント報告を受けてから復旧成功するまでに考えていたことを全て言語化して見ました。
今回は1時間ぐらいで復旧させることができたので、かなりスムーズなケースかもしれませんが、どんな障害であってもやることはほとんど同じです。
- 通信経路を明らかにする
- ログからヒントを集める
- よくある障害パターンを覚えておき、１つずつ原因を切り分けしていく
これらを徹底していけば様々なケースのシステム障害に対応できるのはないかなと思います。
ただ、障害復旧対応力はどれだけノウハウを詰め込んでも一夜では身に付かず、海千山千越えて意図せずについてくる筋力なので、へ〜そんなこと考えてるんだと話半分程度に受け取っていただけると幸いです笑
冒頭にも述べましたが、システム障害を起こさないことが我々エンジニアの使命ですので、まずはそこに全力を注ぎ、平和な世界を作り上げていきましょう！