2018年最初の投稿になります。
早速ですが、年始からSCDB JAPANにちょっとした事件（障害）がありました。 正月休みを返上して（というのはだいぶ大袈裟ですが）原因調査と対応に当たりましたのでその一部始終を記載します。
Bing襲来！？（Welcome！！）
上はBingウェブマスターツール上から確認できるBingクローラーのアクセス状況です。
従来は1日当たりのクロール数は概ね数千から2万ページ程度だったのですが、 12月28日あたりからアクセス数が急増し始め、1月2日～本日まで10万ページ/日を記録し続けています。
1月1日までは「いよいよXデーが近いか」と期待して見守っていたのですが、1月2日の夕方に事件が起きました。
Redisサーバと正常な通信ができない事態が発生
上記の過去記事で、冗長化の話を書いたとき、 SCDB JAPANは100倍のアクセスが来ても耐えられると調子に乗って宣言していたのですが、 恥ずかしながら、たかが10倍程度のアクセスでまさかのサービス停止に追い込まれる障害を発生させてしまいました。
Webサーバの負荷
SCDB JAPANはフロントにLVSサーバを配置し、WebサーバはH2Oサーバ2台構成でロードバランシングを行っています。 Bingからのアクセスが急増し始めた後の1月1日の時点でも、CPU使用率はまだ一桁台、メモリ使用率もまだ50%を切る状況で十分に余裕がありましたので、この程度のアクセスが翌日のサービスダウンに繋がるとは初夢にも思いませんでした。
500エラーの急増とOOMの多発
Webサーバの負荷が十分低いにも関わらず、1月2日の18時頃から500エラーが急増し始めました。 実際にブラウザでアクセスしてもWebページが表示されず、一人緊急対策会議を始めました。
unicornのログ
まず調べたのはアプリケーションサーバであるunicornのログです。 恐れていた通り”FATAL”という致命的なエラーが発生してしまっています。
F, [2018-01-02T18:10:50.417908 #82334] FATAL -- : [6849ed35-e5bf-472e-8bf1-3da7413842a2] ActionView::Template::Error (OOM command not allowed when used memory > 'maxmemory'.):
このエラーメッセージをヒントにググってみると、先人の経験から、どうやらこのエラーはRedisに関して発生している可能性が高いことが分かりました。
SCDB JAPANではキャッシュサーバとアクセス数集計サーバにRedisを使っており、 リソースはまだ最低限しか割り当てていませんので、十分に可能性が考えられました。
キャッシュサーバ用のRedisとアクセス数集計サーバのRedisは別サーバで運営しているのですが、 普段、アクセス数集計サービスの方が数倍の負荷がかかっていることを見ていたこともあって、先入観からアクセス数集計サービスの方が原因と思い込んでしまい、対応に時間を要する羽目になりました。
先人の経験を参考に同様の対策を施してサービスを再起動しても減少は解消せず、一旦手探り状態となりました。
Redis以外の原因を疑う
Webサーバ越しにアクセスすると500エラーが頻発する状況の中、本番環境上のRails consoleを使ってRedisへの疎通を確認すると、キャッシュサーバ、アクセス数集計サーバともに、全くエラーなく接続できる状況だったため、Redis以外に原因がある可能性も否定できませんでした。
LVSサーバのログを調べたり、ロードバランサ越しのアクセスではなく、直接Webサーバに接続するなどして挙動を見ていましたが、LVSやWebサーバ自体のログには問題となりそうな異常は見つけられませんでした。
TCP接続エラーを疑う
解決のヒントを探して色々なブログ記事などを見ている中で、一つ気になる情報を見つけました。
この記事はmemcachedに関する記事なのですが、SCDBのredisもキャッシュサーバを担っていることから、もしかしてと思い調べてみることにしました。
キャッシュサーバのsomaxconn（TCPソケットが受け付けた接続要求を格納するキューの最大長）の設定値を調べてみます。
$ sysctl net.core.somaxconn net.core.somaxconn = 128
、、、自らの知識不足に情けなさを感じると同時に、一筋の光が差した思いがしました。
念のため、netstatも見てみます。
Tcp:
232712 active connections openings
2956 passive connection openings
13370619 failed connection attempts
90 connection resets received
5 connections established
59221754 segments received
39087217 segments send out
10131 segments retransmited
0 bad segments received.
659 resets sent
上から3つ目に13370619 failed connection attemptsとあり、一千万を超えるTcp接続要求が失敗していることが判明しました。
この時点で疑惑は確信に変わりました。
somaxconnの設定値を変更する
早速sysctlの定義ファイルを作成し、somaxconnの設定値を変更します。 今回は128→4096に増やしてしばらく様子を見ることにします。
１．定義ファイルの作成
vi /etc/sysctl.d/custom.conf
net.core.somaxconn=4096
２．定義ファイルの反映
$sudo sysctl --system (略) * Applying /etc/sysctl.d/custom.conf ... net.core.somaxconn = 4096 * Applying /etc/sysctl.conf ...
設定変更が反映されました。
３．Redisの再起動
$ systemctl restart redis.service
藁にも縋る思いでWebサーバ越しのアクセスを確認すると、待望の「http status 200」の文字が並び始めました！！
その後の経過
1月3日に対策を行って以降、この記事を書いている1月5日時点までにはその後問題は起きていません。 障害によってクロールペースがダウンすることが懸念されましたが、BingにもGoogleにも今のところ大きな変化は起きていないようです。
ただ今回設定した値の妥当性についてはまだ手探りですので、もしかしたらまたいつか同じ事象が起きる可能性があります。
実アクセスが原因でこの手の障害が起きてしまうと色々と損失が大きいので、正月という閑散期にクローラーが原因で起きたことは寧ろ非常にラッキーだったと言えると思います。
今回のようにクローラーではなく実アクセスを伴うようになって来ればサーバを増強する予算もついてくると思いますので、 財布と相談しながら早め早めに手を打てるように、今年も頑張りたいと思います。