今更ですが、障害対応のご紹介
はじめに
こんにちは。MKです。
今更な気もしますが、普段障害対応を行っている中で、
原因調査をしている際に、「自分はどういうフローで切り分けをして対応しているかなー？」と考え、
これは、意外と初学者の方や一般ユーザの方の参考にもなるのでは？と思い、
簡単にフローにして纏めてみることにしました。
インフラに携わっている方やそうでない方にも、何かの参考になれば幸いです。
① 障害を検知
まず、弊社の監視システムから保守を行っているお客様のサーバにおいて、
どういった障害が発生しているかの通知が飛んできます。
その通知を確認してから、対応スタートとなります。
② 実際に状況を確認する
弊社監視システムの場合ですと、飛んできた通知に
「どういった状態になっているか」という内容の記載があります。
そこから確認し、例えば「ロードアベレージが閾値を超えて上昇している」や
「HTTPSの通信ができなくなった」といった具合です。
その為、「ロードアベレージが閾値を超えて上昇している」という通知の場合は
実際にサーバにログインしてみて負荷状況の確認。
「HTTPSの通信ができなくなった」という場合は、
対象のページへアクセスをしてみて、正常にページが表示されるか？という状況の確認を行います。
③ 調査対象のあたりをつける
正直なところ、障害が発生してしまう要因というのは
「アクセスが多すぎて、サーバ側が耐えられないよー」とか
「コンテンツファイルを変更したら、ページが表示できなくなっちゃったよー」等
非常に色々なパターンがあります。
その為、やみくもに調べようとするといくら時間があっても
足りなくなってしまうので、はじめの段階である程度のあたりをつけることが
重要になってきます。
Apacheであったり、MySQL等の特定のミドルウェアに通信ができない状態であれば、
「サービスはちゃんと起動しているか？」や「何かエラーが発生していないか？」を確認したり
CPUやメモリの使用率、ロードアベレージ等が高い場合は、
「Webページへのアクセスが集中していないか？」や「怪しい接続元からアタックを受けていないか？」
といった感じです。
ここから、状況の切り分けを行い調査を行っていきます。
④-1 原因調査（特定のミドルウェアに接続ができない場合）
この場合はまず、対象のミドルウェアの起動状態を確認します。
停止してしまっている場合は、起動を試みる、
起動はできている場合は、ログにエラーの出力がないか確認をする。
[root@netassist ~]$ grep -i "max" /var/log/httpd/error_log
[Mon Feb 12 XX:XX:XX.XXXX 2024] [mpm_prefork:error] [pid XXXX] AH00161: server reached MaxRequestWorkers setting, consider raising the MaxRequestWorkers setting
こんな感じでエラーが発生しまっている場合は、内容を確認のうえ
対応していきます。
④-2 原因調査（サーバの負荷が上昇している場合）
この場合には、おなじみの「w」コマンドや「top」コマンド、「free」コマンド等にて
負荷状況の確認を行います。
[root@netassist ~]# top
top - XX:XX:XX up 106 days, 9:29, 1 user, load average: 53.82, 56.66, 48.03
Tasks: 287 total, 39 running, 247 sleeping, 0 stopped, 1 zombie
%Cpu0 : 94.3 us, 4.9 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.8 hi, 0.0 si, 0.0 st
%Cpu1 : 90.3 us, 8.1 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.8 hi, 0.8 si, 0.0 st
%Cpu2 : 92.8 us, 5.6 sy, 0.0 ni, 0.0 id, 0.0 wa, 1.6 hi, 0.0 si, 0.0 st
%Cpu3 : 95.2 us, 3.2 sy, 0.0 ni, 0.0 id, 0.0 wa, 1.6 hi, 0.0 si, 0.0 st
MiB Mem : 15531.4 total, 748.0 free, 10322.2 used, 4461.1 buff/cache
MiB Swap: 4096.0 total, 2671.2 free, 1424.8 used. 4489.9 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3110321 apache 20 0 889840 198808 120132 R 49.6 1.3 1:05.63 httpd
3108774 apache 20 0 878936 149736 79808 R 23.2 0.9 1:39.15 httpd
1139 mysql 20 0 9653752 1.7g 15528 S 21.6 11.4 11220:31 mysqld
3110086 apache 20 0 784804 156704 107072 R 18.4 1.0 1:03.96 httpd
3111015 apache 20 0 876952 179876 110332 S 16.0 1.1 0:46.59 httpd
3112139 apache 20 0 862964 163328 107500 R 14.4 1.0 0:17.16 httpd
3107965 apache 20 0 861356 173224 118572 R 11.2 1.1 1:40.55 httpd
3109057 apache 20 0 879164 192024 120216 R 11.2 1.2 1:30.95 httpd
[root@netassist ~]# free
total used free shared buff/cache available
Mem: 15531000 10279000 790000 386000 4460000 4532000
Swap: 4095000 1424000 2671000
上記のような状態の場合、メモリの使用率はそこまででもありませんが、
CPUとロードアベレージの使用率が高くなっており、
CPUを使用しているプロセスにも「httpd」が多く見受けられますので、
「Webページへのアクセスが多くなっていそうかな？」といった見立てをします。
⑤ 対応
④-2 の結果からアクセス数が多くなっていそうという見立てをしましたので、
例えば、下記の様なコマンドの組み合わせを使い
アクセスログから特定の時間帯にアクセスが多くなっているIPアドレスを抽出してみます。
[root@netassist ~]# grep "12/Feb/2024:10" /var/log/httpd/access.log | awk '{print $1}' | cut -d ":" -f 2 | sort | uniq -c | sort -rn | head -3
9189 45.XX.XX.84
22 192.XXX.XXX.251
11 153.X.XX.67
上記のコマンドで「2024年 2月 12日の10時台」にアクセス数の多かったIPアドレスを
抽出して、数えてみると「45.XX.XX.84」というIPアドレスから「9189」回もアクセスがあったことが分かりました。
これは怪しいですね。さらに調査してみましょう。
[root@netassist ~]# grep "45.XX.XX.84" /var/log/httpd/access.log | tail -3
45.XX.XX.84 - - [12/Feb/2024:10:28:09 +0900] "POST //xmlrpc.php HTTP/1.0" 200 885 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/XXX.XX (KHTML, like Gecko) Chrome/XX.X.XXXX.XXX Safari/XXX.XX"
45.XX.XX.84 - - [12/Feb/2024:10:28:10 +0900] "POST //xmlrpc.php HTTP/1.0" 200 885 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/XXX.XX (KHTML, like Gecko) Chrome/XX.X.XXXX.XXX Safari/XXX.XX"
45.XX.XX.84 - - [12/Feb/2024:10:28:11 +0900] "POST //xmlrpc.php HTTP/1.0" 200 885 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/XXX.XX (KHTML, like Gecko) Chrome/XX.X.XXXX.XXX Safari/XXX.XX"
このようにIPアドレス「45.XX.XX.84」から短時間で「xmlrpc.php」というファイルへ
POSTアクセスによるアタックを受けていることが分かりました。
この影響により、サーバの負荷が上がってしまったようですね。
このままではサービスにも影響がでてしまいますので、アタックをしている
IPアドレスをブロックしましょう。
[root@netassist ~]# top
top - XX:XX:XX up 106 days, 9:29, 1 user, load average: 13.22, 25.27, 33.14
Tasks: 287 total, 39 running, 247 sleeping, 0 stopped, 1 zombie
%Cpu0 : 94.3 us, 4.9 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.8 hi, 0.0 si, 0.0 st
%Cpu1 : 90.3 us, 8.1 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.8 hi, 0.8 si, 0.0 st
%Cpu2 : 92.8 us, 5.6 sy, 0.0 ni, 0.0 id, 0.0 wa, 1.6 hi, 0.0 si, 0.0 st
%Cpu3 : 95.2 us, 3.2 sy, 0.0 ni, 0.0 id, 0.0 wa, 1.6 hi, 0.0 si, 0.0 st
MiB Mem : 15531.4 total, 748.0 free, 10322.2 used, 4461.1 buff/cache
MiB Swap: 4096.0 total, 2671.2 free, 1424.8 used. 4489.9 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1139 mysql 20 0 9653752 1.7g 15528 S 7.6 0.4 11220:31 mysqld
3110321 apache 20 0 889840 198808 120132 R 16.6 1.1 1:05.63 httpd
3108774 apache 20 0 878936 149736 79808 R 11.2 0.6 1:39.15 httpd
3108452 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 rcu_gp
2787615 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 rcu_par_gp
1092536 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 slub_flushwq
2000218 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/0:0H-events_highpri
3211642 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 mm_percpu_wq
先程のアタックを行っていたIPアドレスをブロックした結果、
サーバ側の負荷が下がり、無事復旧いたしました！
いかがでしたでしょうか。
実際にはもっと踏み込んだ調査を行ったり、色々な設定周りの確認も行っておりますが、
ざっくりとしたイメージが伝われば幸いです。
インフラ関係の仕事に興味のある方や
フロントは分かるけど、インフラ方面はあんまり。。。といった方々の
少しでも参考になれば嬉しいです。
それでは、またどこかでお会いしましょう。
ありがとうございました！
