ログが1か月間出力されていなかった話

はじめに

「本番環境でやらかしちゃった人 Advent Calendar 2021」の16日目の記事になります。

以前私が管理していたシステムで発生した出来事になります。

何が起こったのか

そのシステムでは毎月1回、アクセスログを集計した結果をまとめる定期作業がありました。

サーバ側でやることとしてはログを取得するだけであり、手順書もあるため、毎月の作業は他メンバーに任せておりました。

長期出張から久々に自社に帰ってきて一息つきながら溜まった残務処理をしていた時に、それは起こりました・・・

担当A：「〇〇システムのことでお話が・・・」

お願いしていた見積もりのことかな？それとも次に提案予定のシステム構成のことかな？と出張土産を頬張りながら聞いたところ・・・

担当A：「〇〇システムのAサーバのログが1か月出力されていませんでした。」

え・・・？

問題の整理

以下ヒアリングした結果。

• 1ヶ月間ログが出力されていないサーバは1台のみ
• ちょうど1ヶ月前に先月分のログ取得作業を行っていた
• 先月分の作業を行っていた際に誤って一度オリジナルのログを消してしまっていた（！）

というわけで作業ミスであることは明白・・・

お客様には取り急ぎ一次報告を行い、復旧作業の結果無事ログ出力されることを確認しました。

ちなみに対象のサーバではsyslog転送等も行っておらず、OSもRHEL5だったか6だったかのベースでjournalログもなかったためログの復旧はできませんでした・・・

ログが出力されなかった原因

結論から言うと、バックアップからログを戻した後にrsyslogのサービスを再起動しなかったことが原因でした。

各種サービス、プログラムからファイルを開く、書き込む等のファイル操作が行われる場合、ファイルディスクリプタを介して行われますが、1ヶ月前の作業でオリジナルのログを消してしまったことで、ファイルディスクリプタの管理から外れてしまったため、たとえ同じ名前のファイルを同じ場所に置いたとしても、書き込まれなかったということが原因でした。

なぜ同じファイル名のファイルを戻してもログが書き込まれなかったか。

コマンドライン等でファイル操作を行う場合、ファイル名を指定して操作を行いますが、カーネル上はinodeを見て操作を行っています。

inode番号はstatコマンドやls -iコマンドで確認することができます。

statコマンドでのinode番号の確認

# stat /var/log/messages
  File: `/var/log/messages'
  Size: 107495          Blocks: 216        IO Block: 4096   通常ファイル
Device: 805h/2053d      Inode: 9863630     Links: 1
Access: (0600/-rw-------)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2021-12-03 07:48:52.668174258 +0900
Modify: 2021-12-03 07:48:07.242268153 +0900
Change: 2021-12-03 07:48:07.242268153 +0900
 Birth: -

inode番号はmvでファイル名変更する分には変わりませんが、cpでコピーするとinode番号が変わってしまうため、見た目上、同じファイル名であってもinode番号が異なることから、まったく別のファイルということになります。

mvした場合のinode番号

# ls -i /var/log/messages
8481074 /var/log/messages
# mv /var/log/messages /var/log/messages.test
# ls -i /var/log/messages.test
8481074 /var/log/messages.test

cpした場合のinode番号

# ls -i /var/log/messages
8481074 /var/log/messages
# cp -p /var/log/messages /var/log/messages.test
# ls -i /var/log/messages.test
8481171 /var/log/messages.test

/proc/[プロセス番号]/fdを見ると、各プロセスで使用しているファイルディスクリプタを確認できますが、一度オリジナルログを削除した後、同じファイル名のバックアップファイルを戻したとしてもdeletedとなり、/var/log/messagesが削除状態であることが分かります。
※以下はCentOS7で再現させた例

ファイルを戻した後のrsyslogdのファイルディスクリプタ

# ls -l /proc/[プロセス番号]/fd
合計 0
lr-x------ 1 root root 64 12月  6 07:34 0 -> /dev/null
l-wx------ 1 root root 64 12月  6 07:34 1 -> /dev/null
l-wx------ 1 root root 64 12月  6 07:34 2 -> /dev/null
lr-x------ 1 root root 64 12月  6 07:34 3 -> anon_inode:inotify
lrwx------ 1 root root 64 12月  6 07:34 4 -> socket:[35399]
lr-x------ 1 root root 64 12月  6 07:34 5 -> /run/log/journal/7408d4861a614db99426cca5c8e364fb/system.journal
l-wx------ 1 root root 64 12月  6 07:34 6 -> /var/log/secure
l-wx------ 1 root root 64 12月  6 07:34 7 -> /var/log/messages (deleted)
l-wx------ 1 root root 64 12月  6 07:34 8 -> /var/log/cron
l-wx------ 1 root root 64 12月  6 07:34 9 -> /var/log/maillog

バックアップファイルから同じファイル名で戻したとしても、rsyslogは削除された元ファイルに紐付いたままなので再読み込みしてログファイルの紐付けを変えてやらないといけなかったという事ですね。

惨劇はなぜ起こってしまったのか

事故事例の教科書があったとしたら真っ先に紹介されるような、起こるべくして起こった問題でした。

• ログ取得するだけの作業という意識の低下
• 商用環境で一人作業を行っていた
• 手順書がメンテナンスされておらず、一部人の判断が必要となっていた
• 想定外の問題について個人の判断で進めていた

二度と惨劇を起こさないためにどうしたか

関係者全員集めて事故がなぜ起きたか、何をすれば防げたかを話し合い、今後の対策を決めました。

人的な対策としては、当たり前の話ですが以下を徹底するように再周知。

• 変更・追加・削除等の操作が行われる場合は1人作業禁止
• 誰でも手順書通りに作業できるように手順書修正
• 何か想定外の事象が発生した場合にはすぐに報告

システム的な対策としては、以下を検討・実施。

• 定期作業の自動化
• なるべく変更・追加・削除等の操作を行わなくて済むような手順検討
• そもそもサーバにログインしなくても済むようなシステムデザインの検討

但し自動化は場合によっては取り返しがつかないバグが発生して二次災害が発生する場合もあるので、その点を意識してしっかり試験を実施しましょう。

おわりに

人間どんなに注意して作業を行っても、問題が発生するときは発生してしまうものですが、何度もチェックしたり、違う観点でチェックすることで少なくすることはできると思います。

そもそもシステム化してミスを防止することも重要ですが、各メンバーの作業意識についても定期的に見直しが必要だと感じさせられた問題でした。