ログローテーションを実現するには二つのやり方がある。 一つ目はログを出力するアプリケーション側でローテーションの機能を作りこむやり方で、もう一つは今回扱う logrotate のように別のプログラムを使うやり方だ。
今回は Python で書かれたログローテーションの機能を持たないプログラムを題材にしてみる。 そのプログラムが出力するログファイルを logrotate を使ってローテーションする、という寸法だ。 あらかじめ断っておくと Python には logging モジュールにログローテーションの機能があるため、実際には logrotate に頼らずともローテートは可能だ。
尚、今回の検証には CentOS7 を使っている。
$ cat /etc/redhat-release CentOS Linux release 7.1.1503 (Core) $ uname -r 3.10.0-229.el7.x86_64
ログローテーション機能の無いプログラムを用意する
以下のサンプルプログラムは三つの機能を持っている。 一つ目は一定間隔で現在の時刻を特定のファイルに書き込む機能、二つ目は自身のプロセス ID を pid ファイルとして書き残す機能、そして三つ目が SIGHUP シグナルを受信した際に最初の機能のファイル書き込みを一旦終了して始めからやり直す機能だ。 一つ目の機能は今回の本題であるログローテーションの動作を確認するためのもので、二つ目と三つ目は logrotate がログファイルのローテートを完了させた場合にログの書き込みを行っていたプログラムにそれを通知するのに使う。 何故ローテートが完了した場合に通知を送る必要があるかというと、logrotate がログファイルの名前をローテートのためにリネームしたとしても、ファイルディスクリプタはリネームされたファイルをずっと指し続けるため、通知がない限り書き込みを行っているプログラムはそれを使い続けてしまうためだ。 この通知を行うための機能は必ずしもシグナルを使って実装されている必要はなく、あくまで手段の一つとして使っているに過ぎない。
#!/usr/bin/env python # -*- coding: utf-8 -*- from __future__ import print_function import os import sys import time from datetime import datetime import signal RELOAD = False def _create_pid_file(directory): ''' プロセス ID の書き込まれたファイルを作成する関数 ''' prog_name = os.path.basename(sys.argv[0]).split('.')[0] filename = '{name}.pid'.format(name=prog_name) filepath = os.path.join(directory, filename) with open(filepath, 'w') as fp: pid = os.getpid() pid_str = '{pid}'.format(pid=pid) fp.write(pid_str) def _remove_pid_file(directory): ''' プロセス ID の書き込まれたファイルを削除する関数 ''' prog_name = os.path.basename(sys.argv[0]).split('.')[0] filename = '{name}.pid'.format(name=prog_name) filepath = os.path.join(directory, filename) os.unlink(filepath) def _logging_date(directory, interval=1): ''' 一定時間毎に時刻をファイルに書き残す関数 ''' prog_name = os.path.basename(sys.argv[0]).split('.')[0] filename = '{name}.log'.format(name=prog_name) filepath = os.path.join(directory, filename) with open(filepath, 'a+') as fp: while True: # 現在時刻をファイルに書き込む now = datetime.now() now_str = now.strftime('%Y-%m-%d %H:%M:%S\n') fp.write(now_str) fp.flush() # ついでに標準出力にも書いておく print(now_str, end='') global RELOAD if RELOAD: # シグナル SIGHUP を受信した時はファイルを書き込んでいたループを抜ける # 同じ関数がもう一度最初から実行されるが、その際に組み込み関数 open() も # 再度実行されるため参照先のファイルディスクリプタが新しくなる print('Reload!') RELOAD = False break # 一定時間毎に書き込むためにスレッドを sleep する time.sleep(interval) def _sighup_handler(signum, frame): ''' シグナル SIGHUP を受信したときに発火するハンドラ ''' global RELOAD RELOAD = True def main(): signal.signal(signal.SIGHUP, _sighup_handler) try: _create_pid_file('/var/run') while True: _logging_date('/var/log') finally: _remove_pid_file('/var/run') if __name__ == '__main__': main()
まずは上記のサンプルプログラムが動くことを確認しておこう。 ここでは sampled.py という名前をつけた。 実行すると標準出力に対して現在時刻を出力するのが見える。
$ sudo python sampled.py 2015-08-17 20:47:51 2015-08-17 20:47:52 2015-08-17 20:47:53 2015-08-17 20:47:54 2015-08-17 20:47:55 2015-08-17 20:47:56 2015-08-17 20:47:57 ^CTraceback (most recent call last): File "sampled.py", line 90, in <module> main() File "sampled.py", line 84, in main _logging_date('/var/log') File "sampled.py", line 68, in _logging_date time.sleep(interval) KeyboardInterrupt
実行中は /var/run に PID ファイルができていることがわかる。
$ ls /var/run/ | grep sampled sampled.pid $ cat /var/run/sampled.pid 16904
また、/var/log 以下に標準出力と同様の内容が書き込まれる。 これが今回ローテーションの動作確認に使うログだ。
$ cat /var/log/sampled.log 2015-08-17 20:47:51 2015-08-17 20:47:52 2015-08-17 20:47:53 2015-08-17 20:47:54 2015-08-17 20:47:55 2015-08-17 20:47:56 2015-08-17 20:47:57
logrotate を使ってログをローテートする
さて、ここからやっと本題で上記のログを logrotate を使ってローテートさせる。
まずは logrotate をインストールする。 おそらく大抵の場合は OS のインストール時点で既に入っているはず。
$ sudo yum -y install logrotate
logrotate の設定は /etc/logrotate.d 以下に作る。 それぞれの設定では、対象とするファイルに対してどのようにローテーションするかを指定していく。 以下では 1 時間毎に名前に時間を付ける形で 3 世代までログを残す設定になっている。 postrotate の部分で、ローテートが終わった際には kill コマンドを使って sampled のプロセスに対して SIGHUP シグナルを送ってそれを通知する。 ここはプログラムが元のファイルディスクリプタを手放しさえすれば良いため、サービスを再起動するなり別のやり方を取っても問題はない。
$ cat << EOF | sudo tee /etc/logrotate.d/sampled > /dev/null /var/log/sampled.log { dateext hourly missingok rotate 3 notifempty compress sharedscripts delaycompress postrotate /bin/kill -HUP \`cat /var/run/sampled.pid 2> /dev/null\` 2> /dev/null || true endscript } EOF
設定が終わったら、まずは sampled を実行する。
$ sudo python sampled.py 2015-08-17 20:49:18 2015-08-17 20:49:19 2015-08-17 20:49:20 ...
このまま 1 時間待つのも良いけど、そこまで悠長ではないので logrotate コマンドを使って強制的にローテートさせる。 -f オプションで強制実行、-v オプションで詳細を出力する。 最後に指定するのはローテートを実行したい logrotate の設定ファイルだ。
$ sudo logrotate -fv /etc/logrotate.d/sampled reading config file /etc/logrotate.d/sampled Handling 1 logs rotating pattern: /var/log/sampled.log forced from command line (3 rotations) empty log files are not rotated, old logs are removed considering log /var/log/sampled.log log needs rotating rotating log /var/log/sampled.log, log->rotateCount is 3 dateext suffix '-2015081720' glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]' glob finding logs to compress failed glob finding old rotated logs failed renaming /var/log/sampled.log to /var/log/sampled.log-2015081720 running postrotate script
なんか圧縮 (compress) に失敗しているけど何だろう。 とりあえず今は先に進むことにする。
上記を実行するとプロセスに SIGHUP シグナルが送られて、標準出力に "Reload!" の表示が出る。 プロセスを一旦止めて状況を確認しよう。
$ sudo python sampled.py 2015-08-17 20:49:18 2015-08-17 20:49:19 2015-08-17 20:49:20 2015-08-17 20:49:21 2015-08-17 20:49:22 2015-08-17 20:49:23 2015-08-17 20:49:24 2015-08-17 20:49:25 Reload! 2015-08-17 20:49:25 2015-08-17 20:49:26 2015-08-17 20:49:27 2015-08-17 20:49:28 2015-08-17 20:49:29 2015-08-17 20:49:30 ^CTraceback (most recent call last): File "sampled.py", line 90, in <module> main() File "sampled.py", line 84, in main _logging_date('/var/log') File "sampled.py", line 68, in _logging_date time.sleep(interval) KeyboardInterrupt
ログのあるディレクトリを調べるとローテートされたファイルができている。
$ ls /var/log | grep sampled sampled.log sampled.log-2015081720
中身を確認するとちゃんと途中までのログが残っていてローテーションが適切に実行されていることがわかる。
$ cat /var/log/sampled.log-2015081720 2015-08-17 20:47:51 2015-08-17 20:47:52 2015-08-17 20:47:53 2015-08-17 20:47:54 2015-08-17 20:47:55 2015-08-17 20:47:56 2015-08-17 20:47:57 2015-08-17 20:49:18 2015-08-17 20:49:19 2015-08-17 20:49:20 2015-08-17 20:49:21 2015-08-17 20:49:22 2015-08-17 20:49:23 2015-08-17 20:49:24 2015-08-17 20:49:25 $ cat /var/log/sampled.log 2015-08-17 20:49:25 2015-08-17 20:49:26 2015-08-17 20:49:27 2015-08-17 20:49:28 2015-08-17 20:49:29 2015-08-17 20:49:30
まとめ
今回はログローテーション機能のないプログラムが出力するログを、logrotate を使ってローテーションするやり方について扱った。 Python のようにプログラム言語自体にログローテーションの機能が組み込まれているものはさておき、例えば C 言語などでログローテーションの機能をアプリケーション側で作りこむのは手間がかかる割に見返りが少ないはずだ。 そうした場合には、今回のようにアプリケーション側ではシグナルなどを使ってファイルディスクリプタを手放す手段だけを作っておき、ローテーションの部分については logrotate に任せる、といった実装方針を取ると楽をすることができそうだ。
