Zenn
📝

SadServers解説#1 "Saint John": what is writing to this log file?

2024/01/15に公開
Linux
#
free
SadServers
tech

https://ja.wikipedia.org/wiki/セントジョン_(ニューブランズウィック州)

問題概要

シナリオ

このログファイルに書き込んでいるのは何者ですか？

問題詳細

ある開発者が作成したテストプログラムが、ログファイル/var/log/bad.logに書き込み続け、ディスク容量を圧迫しています。例えば、コマンドtail -f /var/log/bad.logを実行することで確認できます。

~$ tail -f /var/log/bad.log
2024-01-16 13:00:19.007207 token: 590469299
2024-01-16 13:00:19.307685 token: 711233412
2024-01-16 13:00:19.608161 token: 850657266
※終了するには Ctrl+C

このプログラムはもう必要ないため、プログラム見つけて終了させてください。

解決判定

（ログファイルのサイズ計測の間隔よりも長い時間）ログファイルのサイズが変化しないこと。
※例えば、ログファイルのサイズが1秒ごとに観測される場合、1秒以上ファイルサイズが変化しなければ解決と判定されます。

Check My Solutionボタンをクリックすると、合格を判定するスクリプト/home/admin/agent/check.shが実行されます。
 

問題解決の方針

【表示する】

とあるプロセスがログファイルに書き込みを続けており、ログファイルへの書き込みを止める必要があります。
そのため、ログファイルに書き込んでいるプロセスを特定し、停止させる必要があります。

解決の手順を表示する
  1. /var/log/bad.logに書き込んでいるプロセスのプロセスIDを調べる
  2. 得られたプロセスIDを使用して、当該プロセスを停止する

 

ヒント

一部、SadServers公式のヒントを改変しています。

ヒント1

psコマンドを実行することで、すべてのプロセスを表示し、今回の問題に関連するものがあるかどうか確認できます。
たとえば、ps auxfコマンドを実行します。

実行コマンド
~$ ps auxf 
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
...
admin 585 0.1 1.7 12508 8280 ? S 14:38 0:00 /usr/bin/python3 /home/admin/badlog.py
...

↑怪しいプロセス発見

 
しかし、上記の方法では、プロセスが開いているファイルを必ずしも確認できるとは限りません。
さらに最適な方法として、lsofコマンドを実行することで、開かれているファイルを一覧表示することができます。

ヒント2

lsofコマンドを実行し、bad.logを含む行にフィルタをかけることで、/var/log/bad.logに関連しているプロセスのプロセス名(一列目)とプロセスID(2列目の"PID")を見つけます。[]で囲まれたプロセスはシステムプロセスのため、今回は無視します。

実行コマンド
~$ lsof | head -1
  COMMAND PID TID TASKCMD  USER FD TYPE DEVICE SIZE/OFF   NODE NAME
~$ lsof | grep bad.log
badlog.py             585 admin 3w  REG  259,1    45842 265802 /var/log/bad.log

/var/log/bad.logを開いているプロセスのプロセスID(PID)が585であることが分かりました。
※PIDは上記と一致するとは限りません。

ヒント3

/var/log/bad.logに書き込んでいるプロセスのプロセスIDを使い、killコマンドを実行してプロセスを終了します。

実行コマンド
~$ kill -9 585

上記コマンドを実行後、Check My Solutionボタンをクリックしてください。

別解

fuser /var/log/bad.logを実行することでも、問題のプロセスを迅速に見つけることができます。

~$ fuser /var/log/bad.log
/var/log/bad.log: 585

 
今回は必要ではありませんが、プロセスIDがあれば、pwdx PID(もっと詳細に知りたい場合は、lsof -p PID)を実行することで、プログラムが存在するディレクトリを見つけることができます。
これにより、プログラムの所有者を確認したり、プログラムが(バイナリではなく)スクリプトであれば問題のあるコードを調査できたりします。
(補足:バイナリファイルとは、コンピュータが直接実行するエンコード済みファイルのことです。バイナリファイルを人間が中身を読んで理解するのは無茶です)

~$ pwdx 585
585: /home/admin
~$ lsof -p 585
COMMAND   PID  USER   FD   TYPE DEVICE SIZE/OFF   NODE NAME
badlog.py 585 admin  cwd    DIR  259,1     4096 272476 /home/admin
badlog.py 585 admin  rtd    DIR  259,1     4096      2 /
badlog.py 585 admin  txt    REG  259,1  5479736   5453 /usr/bin/python3.9
…

 

余談

問題のプログラムを見てみる

cat /home/admin/badlog.pyを実行して、問題のプロセスの中身を見てみます。

badlog.py
#! /usr/bin/python3
# test logging

import random
import time
from datetime import datetime

with open('/var/log/bad.log', 'w') as f:
    while True:
        r = random.randrange(2147483647)
        print(str(datetime.now()) + ' token: ' + str(r), file=f)
        f.flush()
        time.sleep(0.3)

無限ループのプログラムで、0.3秒ごとにランダムな数字を書き込んでいるようです。
 

問題一覧はこちら

https://zenn.dev/comf_nakamura/articles/sadservers_sitemap

Discussion