python の TimedRotatingFileHandler での日次ログ切り替え

初めに

ログを日次で切り替えるはず・・・だったが。。。。

python で定期的に実行するスクリプトのログを出力するのに TimeRotatingFileHander を利用し、日毎にログが切り替わるようにした・・・はずだった。

しかし、スクリプトによって切り替わらない日があったり、あるいはまったく切り替わらずに同じログファイルに延々と描き続けるという現象に悩まされていた。

最近になってやっと原因が分かった。

Python のログの仕組みの概要については割愛する。

他を当たってください。このあたりとか。
まぁ、一般的なロギングの機構だと思う。

ロギングハンドラとは

ロギングハンドラとはログの機構で受け取ったログに出力するべき情報を実際に各種デバイスに書き出すオブジェクトである。

標準に用意されているものだけでも「標準出力に出す」「ファイルに出す」の他に「破棄する(NULL デバイスに出力)」「Syslog に出す」「Windows イベントログに出す」「メールに送る」「(マルチプロセスを想定して)キューに書き込む」とかあるし「ファイルに出す」ものも logrotate等で監視されている場合に利用するものやサイズや特定の時間間隔でログファイルをローテートするものもある。

詳しくはこちら。

なお、ログの設定を設定ファイル等から設定をすることを想定した機構があり、それを利用することで設定ファイルでロギングハンドラを切り替えるようにしたりすることができる。
環境設定のための関数

#本題

TimedRotatingFileHandler

TimedRotatingFileHandler は特定の時間間隔でのログローテーションをサポートしたロギングハンドラである。

TimedRotatingFileHandler コンストラクタの when引数に 'D' を指定するのは多分間違い

「日毎にログを切り替えたい」という場合にこのロギングハンドラを利用するのは正しい。
しかしながら

• 1日中動かしているようなデーモンプロセス
• 1日より長い間隔で実行するスクリプト

でない場合、TimedRotatingFileHandler のコンストラクタの when引数に切り替えの間隔を日毎にする 'D' を指定してはいけない。

TimedRotatingFileHandler が(最初に)ログファイルを切り替えるタイミング

TimedRotatingFileHandler は初期化時にログローテートを行う時刻を求め、その後ログを書き出すときにログローテートを行う時刻を過ぎているかのチェックを行い、過ぎているならログのローテートを行う。

この最初のログローテートを行う時刻はwhen引数で指定した値が'S','M','H','D'の場合は次の時刻のうちの早い方になる。

• スクリプトを起動した時刻のwhen引数で指定した単位時間後
• (すでにログファイルがある場合)ログファイルの最終更新日時からwhen引数で指定した単位時間後

TimedRotatingFileHandler コンストラクタの when引数に 'D' を指定してしまった場合の動き

開始・終了のログ出力が無い場合はここに書いたとおりになるとは限らないが、大体次のようになる。

実行間隔が(約)1日のスクリプトの場合

ログの切り替わる日と切り替わらない日が出てくる。ログが切り替わるのは前日よりもスクリプトの実行に時間がかかった場合であり、その場合でも開始時ではなく途中でログが切り替わる。

実行間隔が 1日より短いスクリプトの場合

ログが切り替わらず、ずっと同じファイルに書き続ける

ログを日毎に切り替える場合、TimedRotatingFileHandler コンストラクタの when引数には 'MIDNIGHT' を指定しましょう

日毎にログを切り替えたいというのは通常日付が変わるときに切り替えることを意図していると思われるのでその場合には 'MIDNIGHT'を指定します。

先に挙げた 'D' を指定する可能性がある場合でもやはり通常は 'MIDNIGHT' を指定するべき場合が多いでしょう。

サンプルコード

コードを一切書かずに説明するという空中戦をしてしまったので、最後にサンプルコードを挙げておきます。
あくまで今回の内容に対する説明ですのであまり参考にはせず、他を参照してください。

LoggingSample.py

#!/usr/bin/env python
# coding=utf-8
import logging
import logging.config
import os
import yaml


ENVKEY_LOGCONFIG = 'log_config'

def prepare_logging():
    env_file = os.path.splitext(__file__)[0] + '.yml'
    with open(env_file, 'r', encoding='utf-8') as f:
        env_data = yaml.safe_load(f)
    logconfig_dict = env_data[ENVKEY_LOGCONFIG]
    logging.config.dictConfig(logconfig_dict)


def logging_sample_main():
    log = logging.getLogger(__name__)
    log.info('HogeHoge')


def main():
    prepare_logging()
    logging_sample_main()
    # log を flush する
    logging.shutdown()


if __name__ == '__main__':
    main()

LoggingSample.yml

---
log_config:
  version: 1
  formatters:
    file_log_format:
      format: '[{asctime}][{levelname}][{name}] {message:s}'
      datefmt: '%Y-%m-%d %H:%M:%S'
      style: '{'
  handlers:
    console:
      class : logging.StreamHandler
      level   : DEBUG
      stream  : ext://sys.stdout
    file:
      class : logging.handlers.TimedRotatingFileHandler
      formatter: file_log_format
      filename: LoggingSample.log
      # when: D is MAYBE wrong.
      when: MIDNIGHT
      backupCount: 31
      encoding: utf-8
  root:
      level: DEBUG
      handlers:
        - console
        - file
  disable_existing_loggers: False