🗒️

Python でログファイルを圧縮する方法

2022/11/08に公開

Python

log

gzip

tech

はじめに

Python でログ出力を行う場合、標準ライブラリの logging を使用することが多いと思います。
logging モジュールに用意されている既定のハンドラの中の RotatingFlieHander を使用するとファイルのログローテーションが簡単に行えて便利なのですが、ローテーションした古いログファイルを圧縮したい場合はひと手間加える必要があります。

コード例

RotatingFlieHander を利用して圧縮を行う場合、下記を対応する必要があります。

ローテーションしたファイルの名称を決定する関数を用意して、ハンドラのインスタンス変数 namer に代入しておく。
ローテーションしたファイルを圧縮するための関数を用意して、ハンドラのインスタンス変数 rotator に代入しておく。

次のサンプルコードでは create_logger 関数でロガーオブジェクトを生成しています。
この関数内で、ローテーションしたログファイルを gzip 形式で圧縮するための関数 gzip_namer と gzip_rotator を用意して、前述の二つのインスタンス変数への代入を行っています。

import os
import shutil
import gzip
import datetime
import logging
import logging.handlers


def main():
    # ロガー生成
    logger = create_logger(__name__)
    # ログ出力してローテーションの動作確認
    logger.debug('foobar')
    logger.info('foobar')
    logger.warning('foobar')
    logger.error('foobar')
    logger.critical('foobar')


def create_logger(name):
    """ロガー生成"""
    logger = logging.getLogger(name)
    formatter = logging.Formatter(
        '%(asctime)s [%(levelname)s] %(filename)s - '
        '%(funcName)s: %(message)s', '%Y-%m-%d %H:%M:%S'
    )
    handler = logging.handlers.RotatingFileHandler(
        filename='log.txt',
        backupCount=5,
        maxBytes=100,  # MEMO: ローテーションさせるためにあえて小さい値にしています
    )

    handler.setLevel(logging.DEBUG)
    handler.setFormatter(formatter)
    logger.setLevel(logging.DEBUG)
    logger.addHandler(handler)

    def gzip_namer(name):
        """ローテーションファイル名生成 (gzip)"""
        # 拡張子を付与 (log.txt.# -> log.txt.#.gz)
        return name + '.gz'

    def gzip_rotator(src, dst):
        """ログローテーション処理 (gzip)"""
        # 入力ファイルを一時的な名称にリネーム (log.txt -> log.txt.tmp2022...)
        # 出力ファイル生成には元の入力ファイル名 (log.txt) を利用
        src_tmp = src + '.tmp' + datetime.datetime.now().strftime('%Y%m%d%H%M%S%f')
        os.rename(src, src_tmp)
        dst_tmp = src
        # 入力ファイルを gzip ファイルへ圧縮
        with open(src_tmp, 'rb') as sf:
            with gzip.open(dst_tmp, 'wb') as df:
                shutil.copyfileobj(sf, df)
        # 実際の出力ファイル名にリネーム (log.txt -> log.txt.1.gz)
        os.rename(dst_tmp, dst)
        # 入力ファイルを削除
        os.remove(src_tmp)

    # 関数をハンドラに登録
    handler.namer = gzip_namer
    handler.rotator = gzip_rotator

    return logger


if __name__ == '__main__':
    main()

補足説明

前述のコードを実行すればログローテーション＋ファイル圧縮を行うことができますのでこれで目標達成ですが、ここではもう少しコードの詳細を見てみます。

`gzip_rotator` が必要以上に複雑に見えるのは何故か

gzip_rotator は、src を dst に変更する（ローテーションする）ための処理を記述する関数ですが、一時ファイルへのリネームなど必要以上に複雑なことをしているように見えます。
ファイルを圧縮するだけであれば、下記のような単純なコードで良いはずです。

def gzip_rotator(src, dst):
    """ログローテーション処理 (gzip)"""
    # 入力ファイルを gzip ファイルへ圧縮
    with open(src, 'rb') as sf:
        with gzip.open(dst, 'wb') as df:
            shutil.copyfileobj(sf, df)
    # 入力ファイルを削除
    os.remove(src)

しかし、実際に上記のコードで実行すると、困ったことが発生します。ログローテーション処理によって作られる log.txt.1.gz ～ log.txt.5.gz の内部ファイル名がすべて log.txt.1 になってしまうのです（最初に掲載したコードでは log.txt になります）。

もちろん、ログファイルは正常に解凍して中を読むことができるので実害はないのですが、少し気持ち悪いですね。なぜこのようなことになるのかを知るためには、namer と rotator がどのように呼び出されているのかを知る必要があります。

まず、logging モジュール内でどのように関数が呼び出されているのかを追ってみましょう。

`namer` と `rotator` はどのように呼び出されているのか

まず、今回のサンプルコードの例における関数のコールフローを下記に示します。
ポイントとなる箇所に番号を付けてありますので、それぞれの処理について順番に見ていくことにします。

ログ出力時の `logging` モジュール内のコールフロー

Logger.debug (または info, warning, error, critical) ... (1)
- Logger._log
  - Logger.handle
    - Logger.callHandlers
      - Handler.handle
        
        BaseRotatingHandler.emit
        
        RotatingFileHandler.shouldRollover ... (2)
        
        RotatingFileHandler.doRollover ... (3)
        
        BaseRotatingHandler.rotation_filename ... (3-1)
        
        (handler).namer
        
        (リネーム処理)
        
        BaseRotatingHandler.rotate ... (3-2)
        
        (handler).rotator
        
        FileHandler.emit ... (4)
        
        StreamHandler.emit
        
        FileIO.write

(1) 各種ログ出力関数～ `BaseRotatingHandler.emit`

スクリプト側から、 debug や info などのログ出力関数を呼び出すところからスタートします。

ここからはしばらく Logger, Handler 系クラスの内部呼び出しが続きます。
emit 関数がログ出力処理のコア部分です。

(2) `RotatingFileHandler.shouldRollover`

実際にファイルへログを出力する前に、ログを書き込むことでカレントのログファイルが最大サイズを超えてしまわないかをチェックします。

もし超えてしまうようであれば、先にログローテーション処理を実行します。→ (3) へ進みます。
超えないのであれば、ログローテーションは不要なので (4) へ飛びます。

(3) `RotatingFileHandler.doRollover` とリネーム処理の繰り返し

ここがログローテーション処理です。

まず、ローテーション結果のファイル名を得るために (3-1) rotation_filename が呼び出されます。この関数は内部でハンドラの namer を呼び出しますので、こちらで用意した関数 gzip_namer(name) が呼び出されることになります。
引数 name には既定のローテーション後ログファイル名が渡されます。gzip_namer はそれに .gz の拡張子を付けて返す単純な関数です。

namer は複数回呼び出され、返された名前を利用して古いログファイルの削除やリネームが行われます。仮に最大数までバックアップファイルが作られているとすると、以下のような処理が行われることになります。

log.txt.5.gz を削除する。
log.txt.4.gz を log.txt.5.gz にリネームする。
log.txt.3.gz を log.txt.4.gz にリネームする。
log.txt.2.gz を log.txt.3.gz にリネームする。
log.txt.1.gz を log.txt.2.gz にリネームする。

この時点で、ログファイルの状態は下記のとおりです。

log.txt : カレントのログファイル
log.txt.2.gz ～ log.txt.5.gz : バックアップファイル

最後に、(3-2) BaseRotatingHandler.rotate が呼び出されます。この関数は内部でハンドラの rotator を呼び出しますので、こちらで用意した関数 gzip_rotator(src, dst) が呼び出されることになります。
引数 src には "log.txt"、引数 dst には "log.txt.1.gz" が渡されますので、この情報を使用して最後のログローテーションである「log.txt を log.txt.1.gz に変換する」処理を行います。

これで、ログローテーションは完了です。

(4) `FileHandler.emit`

カレントのログファイルの末尾にログを書き込みます（ファイルが無ければ作成して書き込みます）。

改めて `gzip_rotator` が複雑な理由

これでログローテーション処理の全貌が把握できました。

ポイントは、gzip_rotator が呼び出されるときの引数は常に log.txt と log.txt.1.gz であるという点です。単純に後者のファイル名を利用して gzip 圧縮を行うと、内部ファイル名は常に log.txt.1 となってしまうのです。

log.txt.5.gz の中に log.txt.1 が圧縮されているのは気持ちが悪いです。しかし、ローテーション処理、つまりリネーム処理は、外部の gz ファイルに対して行われる操作であり内部ファイル名は連動してくれません。そこで、せめて内部ファイルを log.txt に統一しておくこととし、そのための処理を加えた結果、（一見）必要以上に複雑な関数になっています。

さいごに

Python でログローテーションを行う方法や namer や lotator を利用したカスタマイズの方法は検索すると見つかりますが、その呼び出され方にまで触れている情報は少なそうでしたので、記事にしてみました。

はじめに

コード例

補足説明

gzip_rotator が必要以上に複雑に見えるのは何故か

namer と rotator はどのように呼び出されているのか

ログ出力時の logging モジュール内のコールフロー

(1) 各種ログ出力関数 ～ BaseRotatingHandler.emit

(2) RotatingFileHandler.shouldRollover

(3) RotatingFileHandler.doRollover とリネーム処理の繰り返し

(4) FileHandler.emit

改めて gzip_rotator が複雑な理由