Pythonのロギングを覚えた

いつも忘れてしまうので・・・

簡単なスクリプトを書くときでも、きちんとloggingしておくとあとあと便利だと思うのですが、いつもやり方を忘れてしまいます。
なので、Loggingクックブックを参考に、ロガー作成の要素を整理してみました。また、毎回ファイルの冒頭に同じことを書くのもアレなので、setup_loggerという関数にしました

loggerを初期化する関数

def setup_logger(name, logfile='LOGFILENAME.txt'):
    logger = logging.getLogger(name)
    logger.setLevel(logging.DEBUG)

    # create file handler which logs even DEBUG messages
    fh = logging.FileHandler(logfile)
    fh.setLevel(logging.DEBUG)
    fh_formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(filename)s - %(name)s - %(funcName)s - %(message)s')
    fh.setFormatter(fh_formatter)

    # create console handler with a INFO log level
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)
    ch_formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s', '%Y-%m-%d %H:%M:%S')
    ch.setFormatter(ch_formatter)

    # add the handlers to the logger
    logger.addHandler(fh)
    logger.addHandler(ch)
    return logger

使い方

# 各モジュールの最初のほうで、グローバルに宣言しておく
logger = setup_logger(__name__)

ロガー作成のポイント

自分なりに理解したポイントは以下の3点。

1. loggingというルートにあるロガーではなく、getLoggerして個別のを作るほうがよい
2. logger全体のレベルを設定（とりあえずDEBUGに設定）
3. loggerにハンドラーを追加する

この3つの手順を覚えておき、あとは必要なハンドラ（logging.handlers）を設定し追加していくだけです。おぉ、整理してみると簡単！。

loggerを作成している部分

    logger = logging.getLogger(name)
    logger.setLevel(logging.DEBUG)
    ...
    logger.addHandler(fh)
    logger.addHandler(ch)

ハンドラ作成のポイント

ハンドラ作成時のポイントは以下の3点。

1. ハンドラを選ぶ : logging.handlers から自分に必要なものを探す
2. ハンドラのログレベルを設定する : ログレベルとその使い時は、基本ロギングチュートリアルを参照

• ハンドラのformatterを設定する : logging.Formatterを使う

ログに表示する内容のテンプレートの詳細な設定は フォーマッタオブジェクトを読むとよいでしょう。
テンプレートに使える変数はLogRecord属性の表から選びます。
また、2つめの引数に日付フォーマット（datefmt）を指定できることも知っておくと便利。

今回は、ファイル用のログ出力は冗長にし、コンソール用のログ出力はシンプルにしたかったので、それぞれ別のフォーマッタを設定しました。

ハンドラを作成している部分

    # create file handler which logs even DEBUG messages
    fh = logging.FileHandler(logfile)
    fh.setLevel(logging.DEBUG)
    fh_formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(filename)s - %(name)s - %(funcName)s - %(message)s')
    fh.setFormatter(fh_formatter)

    # create console handler with a INFO log level
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)
    ch_formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s', '%Y-%m-%d %H:%M:%S')
    ch.setFormatter(ch_formatter)

ログの出力結果

実際のログ出力を載せておきます。

ログファイルへの出力

## Formatter('%(asctime)s - %(levelname)s - %(filename)s - %(name)s - %(funcName)s - %(message)s')

2019-06-03 11:12:38,692 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 16 - 1.82 MB
2019-06-03 11:12:40,860 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 17 - 1.82 MB
2019-06-03 11:12:42,832 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 18 - 1.82 MB
2019-06-03 11:12:45,220 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 19 - 1.82 MB
2019-06-03 11:12:47,006 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 20 - 1.82 MB
2019-06-03 11:12:48,396 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 21 - 1.82 MB
2019-06-03 11:12:49,767 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 22 - 1.82 MB

コンソールへの出力

## Formatter('%(asctime)s - %(levelname)s - %(message)s', '%Y-%m-%d %H:%M:%S')

2019-06-03 11:11:58 - INFO - --------------------------------------------------
2019-06-03 11:11:58 - INFO - In  : data/weblogs/ssl_access_log.20190601.gz
2019-06-03 11:11:58 - INFO - Out : data/parsed/ssl_access_log_20190601.parsed.gz
2019-06-03 11:11:58 - INFO - --------------------------------------------------
2019-06-03 11:11:58 - INFO - Read data/weblogs/ccprod02_ssl_access_log.20190601.gz with chunks (size=10000)

おまけ：ログファイルのローテーション

プログラムを作成＆デバッグしている段階から、そこそこ常用する段階になってくると、（正常時はほとんど確認する必要のない）ログファイルがどんどんと肥大化してしまうのが少し気になっていました。これまでは、気づいたときにログファイルを削除して、プログラムを実行していたのですが、今回、ハンドラについて理解したので、きちんとログファイルをローテーションするように変更しました。

今回はRotatingFileHandlerを使って100kBのファイルを10個まで保管するようにしました。

1. RotatingFileHandlerはlogging.handlersの下にあるのでimport logging.handlersを追記
2. ファイル出力用ハンドラfhをlogging.FileHandlerからlogging.handlers.RotatingFileHnadlerに変更
3. ログファイルのサイズを100kB（maxBytes=100000）に設定
4. ログファイルを保存する数は10個（backupCount=10）に設定

ハンドラの種類を変更

import logging.handlers

#fh = logging.FileHandler(logfile)
fh = logging.handlers.RotatingFileHandler(logfile, maxBytes=100000, backupCount=10)
fh.setLevel(logging.DEBUG)
fh_formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(filename)s - %(name)s - %(funcName)s - %(message)s')
fh.setFormatter(fh_formatter)

下は何回かログを出力させた結果です。
最も新しいのがlog_rotate.txtで、100kBを目安にファイルがバックアップが作成されていることが確認できました。

ログローテーションできていることを確認

95K Jun  4 09:45 log_rotate.txt
98K Jun  4 08:26 log_rotate.txt.1
98K Jun  4 09:08 log_rotate.txt.2
98K Jun  3 16:06 log_rotate.txt.3
98K Jun  3 14:49 log_rotate.txt.4

おわりに

よし、これでロギングも怖くない！

おわりのおまけ

この記事がぽつりぽつりとストック／いいねされているようなので、最近はもっぱらLoguruを使っていることを追記しておきます。（2023/06/22）

from loguru import logger

logger.debug("これだけでいいかんじ！")

この記事の設定はfrom loguru import loggerのたった一行にほぼ置き換えられるくらい簡単で便利なパッケージです。ありがたや✨

参考ページ

1. logging --- Python用ロギング機能
2. Loggingクックブック
3. Logging HOWTO