読者です 読者をやめる 読者になる 読者になる

CUBE SUGAR CONTAINER

技術系のこと書きます。

ログローテーション機能のないプログラムのログを logrotate でローテートする

ログローテーションを実現するには二つのやり方がある。 一つ目はログを出力するアプリケーション側でローテーションの機能を作りこむやり方で、もう一つは今回扱う 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 に任せる、といった実装方針を取ると楽をすることができそうだ。