この記事はエイチームブライズ/エイチームコネクト/エイチーム引越し侍 Advent Calendar 2018 17日目の記事です。みんな業務外での技術チャレンジを記事にしているのが多いので、たまには実際に業務でハマった話を。
背景
2016年のQiitaアドベントカレンダーで cron から Rundeck での運用へ移行する記事を書いたように、引越し侍でのバッチ処理を Rundeck で管理するようになってからちょうど2年が経ちました。
そのちょうど2年経った頃に突然 Rundeck のジョブが全て実行に失敗するという事態に陥ったためその顛末を記録しておきます。
ちなみに、Rundeck のバージョンは 2.7.1 です。2年前に入れたまま…いつの間にか3系になってたんですね…
起きたこと
11月のある日曜日の夜、スマホの画面に Rundeck のジョブ実行が失敗した旨のChatwork通知が続々と届く…
（うちでは、Rundeckのジョブの実行が失敗した際に Webhook で AWS の API Gateway ＆ Lambda 経由で Chatwork に通知が行くようにしてあります）
なんだなんだと思って Rundeck のサーバにSSHでログインしてみると、何かをしようとすると /tmp にファイルが書けないというメッセージが出る。
/tmp にもディスクボリューム全体にも空き容量は十分にあるが…？？
一旦、OSを再起動してみる。
問題なく停止して、起動してくる。
再起動後は /tmp にファイルを書き込めるし、Rundeckのジョブも普通に動くようになった。。。
何があった？
原因
ふと思いついた。
inode かも。
$ df -i
ファイルシス Iノード I使用 I残り I使用% マウント位置
devtmpfs 503510 435 503075 1% /dev
tmpfs 506232 1 506231 1% /dev/shm
/dev/xvda1 3276800 3244430 32370 100% /
やっぱり！ビンゴ。
上記は再起動後なので、その直前には残り inode はなくなっていたのだと思われます。
inode が枯渇したことでファイルが生成できなくなってジョブの実行が失敗していた模様。
でも、どこにそんな大量のファイルが…と思って調べてみると
/var/lib/rundeck/logs/rundeck/<Project名>/job/<Job ID>/logs/ 以下に大量のログファイルが生成されていた。
ジョブが実行されるたびに上記ディレクトリに <実行ID>.rdlog と <実行ID>.state.json という 2つのファイルが生成されている。
現状うちの環境では、ジョブは 1日にざっと 3,000回以上実行されているようなので、毎日 6,000個程度のファイルが生成されて蓄積されていることになる。
上記の df の結果を見ると / の inode の最大数は 300万程度のようなので 500日でいっぱいになる計算。ジョブの定義数や実行回数は徐々に増えていったことを考えると、ちょうど2年程度でいっぱいになったのは辻褄が合う。
回避策
このログファイルは Rundeck の API 経由で消せるようだけど、ジョブの実行IDごとに一つ一つ消していくか、ジョブIDごとに全消ししかできないようなので、すんごく時間がかかるか、全部消えちゃって不便。
ログファイルをOSコマンドで直接削除して大丈夫かどうかは明確には分からなかったのですが、このあたりの議論を読む限り、ワークアラウンドとしてはアリだと判断しました。
（3系だとログの有効期限＆自動削除機能は実装されてたりするのかな…）
実際にファイルを消してみても Rundeckの稼働には特段の影響は感じられませんでした。
で、以下のようなコマンドを実行する JOB を Rundeck に登録して日次で実行しています。
半年以上（185日）前のログファイルを消しています。
find /var/lib/rundeck/logs/rundeck/<Project名>/job/*/logs/ -type f -mtime +185 -exec rm {} +
これでひとまず inode が枯渇する心配はなくなりました。めでたしめでたし！
ただ、これで半年以上前の実行ログは見られなくなると思っていたら、なぜかファイルを削除しても管理画面からはまだ見ることができる…
ファイルの他にもDBに記録しているのでしょうか…なぜそんな二重化を…
ファイル消してもログが確認できるのであれば半年と言わずもっと短期間でファイルを消しても良さそう。
これについてはこれ以上深掘りしてないです。
おまけ
登録 JOB 数が 100個を越え、毎日 3,000回以上 JOB が実行されるようになってくると、Rundeck の管理画面を開くのも非常に重い状態になっていました。
何らかのJOBが実行状態になるたびに（つまり数分ごとに） MySQL(RDS)側の CPU が 100％ になっていました。
Rundeckサーバを分割しないといけないかなあ、どっかでパフォーマンスチューニングできないかなあと思っていたところ、上記のログファイルでいろいろ調べている際にここの記事を発見。
同じように INDEX を貼ってみたところ CPU使用率が劇的に下がり（下記グラフの 11/18 22時あたり）、
mysql> ALTER TABLE workflow_workflow_step ADD INDEX workflow_commands_id(workflow_commands_id);
管理画面もキビキビ動くようになりました。めでたしめでたし！
お知らせ
エイチームグループでは一緒に活躍してくれる優秀な人材を募集中です。
興味のある方はぜひともエイチームグループ採用ページ（Webエンジニア詳細ページ）よりお問い合わせ下さい！
明日は、引越し侍のエンジニア @nao_70 の出番です。お楽しみに。