useing python logger

pythonでloggerを真面目に使っていこうという意気込みを得たので、まとめる(あくまで自分用)。

解決したいこと

いろんなpythonのスクリプトを作っていて、ログ出力がスクリプトごとにバラバラ
ログレベルがプロジェクトで統一されていない
ログの出力先の設定がここで違う
いろんなところにprint文が散見される

この辺を解決するためにpythonのloggerを使っていきます。

コードは

Pythonによるクローラー＆スクレイピング入門設計・開発から収集データの解析まで

のログ部分を参考にしています。

基本的なこと

formamtter, handler, loggerをconfig設定して、settings.pyを作成しておいて、それをログ出力側で読み込む。んで、あとはlogger.info()とかを使って出力する

settings.py

formatter ログの出力フォーマットを指定する(colorlogで色をつけてる)
handler loggerのハンドラを指定するcondole, file, socketなどのハンドラが有る
logger loggerの名前をつける。下のコードはtest1,test2とつけているけど、本来はスクリプトの名前にしておく

import os
BASE_DIR = os.path.realpath(os.path.dirname(__file__))
LOG_DIR = os.path.join(BASE_DIR,'logs')

if not os.path.exists(LOG_DIR):
    os.mkdir(LOG_DIR)

LOGGING_CONF = {
    'version': 1,
    'disable_existing_loggers': True,
    "formatters": {
        'default': {
            #colorlogライブラリを適応
            '()': 'colorlog.ColoredFormatter',
            'format':'\t'.join([
                "%(log_color)s[%(levelname)s]", #ログレベル
                "asctime:%(asctime)s", #ログの出力時間
                "process:%(process)s", #ログ出力が事項されたプロセス名
                "thread:%(thread)s", #ログが出力されたスレッドID
                "module:%(module)s", #ログ出力が実行されたモジュール名
                "%(pathname)s:%(lineno)s", #ログ出力が実行されたモジュールのパスと行番
                "message:%(message)s", #ログされるメッセージ
            ]),
            'datefmt': '%Y-%m-%d %H:%M:%S', 
            'log_colors':{
                "DEBUG"    : 'bold_black',
                "INFO"     : 'white',
                "WARNING"  : 'yellow',
                "ERROR"    : 'red',
                "CRITICAL" : 'bold_red',
            },
        },
        'simple': { #ログ出力を減らしたシンプル版のフォーマット
            '()': 'colorlog.ColoredFormatter',
            'format':'\t'.join([
                "%(log_color)s[%(levelname)s]",
                "asctime:%(asctime)s", 
                "message:%(message)s",
            ]),
            'datefmt': '%Y-%m-%d %H:%M:%S', 
            'log_colors':{
                "DEBUG"    : 'bold_black',
                "INFO"     : 'white',
                "WARNING"  : 'yellow',
                "ERROR"    : 'red',
                "CRITICAL" : 'bold_red',
            },
        },
    },
    'handlers':{
        'file': { #ファイルにログを出力するハンドラ設定
            'level': 'DEBUG', #logger.levelがDEBUG以上で出力
            'class': 'logging.handlers.RotatingFileHandler',
            'filename': os.path.join(LOG_DIR, 'crawler.log'),
            'formatter': 'default', #このハンドラはデフォルトのフォーマットで出力する
            'backupCount': 3, #古くなったログファイルを3世代保持
            'maxBytes': 1024*1024*2, #2MB超えたらローテート
        },
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'default',
        },
        'console_simple': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'simple',
        },
    },
    'root': {
        'handlers': ['file','console_simple'],
        'level': 'DEBUG'
    },
    'loggers':{
        'my_test1': { #my_test1.pyでつかうロガー
            'handlers': ['console','file'],
            'level' : 'CRITICAL',
            'propagate': False,
        },
        'my_test2': { #my_test2.pyでつかうロガー
            'handlers': ['console_simple'],
            'level' : 'DEBUG',
            'propagate': False,
        },
    },
}

test_logging.py

import logging.config
import settings

def get_my_logger(name):
    logging.config.dictConfig(settings.LOGGING_CONF)
    return logging.getLogger(name)

logger = get_my_logger('my_test1')

if __name__ == '__main__':
    logger.debug('DEBUG levelです')
    logger.info('INFO levelです')
    logger.warning('WARNING levelです')
    logger.error('ERROR levelです')
    logger.critical('CRITICAL levelです')

これを実行すると

$ python test_logging.py
[DEBUG] asctime:2020-12-29 19:06:43     process:35100   thread:4595813824       module:my_logging       my_logging.py:11        message:DEBUG levelです
[INFO]  asctime:2020-12-29 19:06:43     process:35100   thread:4595813824       module:my_logging       my_logging.py:12        message:INFO levelです
[WARNING]       asctime:2020-12-29 19:06:43     process:35100   thread:4595813824       module:my_logging       my_logging.py:13        message:WARNING levelです
[ERROR] asctime:2020-12-29 19:06:43     process:35100   thread:4595813824       module:my_logging       my_logging.py:14        message:ERROR levelです
[CRITICAL]      asctime:2020-12-29 19:06:43     process:35100   thread:4595813824       module:my_logging       my_logging.py:15        message:CRITICAL levelです

ログの出力先を分ける方法

settings.pyのlogger内の設定で分ける。この例だと get_my_loggerでtest1でコンソールとファイルに、test2を指定するとコンソールに出力するようになる。

    'loggers':{
        'my_test1': { #my_test1.pyでつかうロガー
            'handlers': ['console','file'],
            'level' : 'CRITICAL',
            'propagate': False,
        },
        'my_test2': { #my_test2.pyでつかうロガー
            'handlers': ['console_simple'],
            'level' : 'DEBUG',
            'propagate': False,
        },
    },

ログレベルで出力を制限する

handlerもしくはloggerのlevelの設定をすることでできる。ただ、handlerでINFOと設定しても、loggerの方でlevelをDEBUGに設定するとそっちが継承されてしまうので注意。

    'handlers':{
        'file': { 
            'level': 'DEBUG', #ここをCRITICALにするとCRITICALのログしか出さなくなる
            'class': 'logging.handlers.RotatingFileHandler',
            'filename': os.path.join(LOG_DIR, 'crawler.log'),
            'formatter': 'default',
            'backupCount': 3, 
            'maxBytes': 1024*1024*2,
        },

loggerの選択を自動でやる

loggerは呼び出し側でgetLogger(__name__) として取得するようにして、 loggerの設定で自動出力を振り分けるようにする。ディレクトリの階層構造がある場合はdotでつなぐ。対象のファイルが存在しなかった場合は上位階層のものが参照される下の例だとmoduleAディレクトリ以下のファイルの場合はmoduleAを参照するようになる。

    'loggers':{
        'moduleA.abc': { 
            'handlers': ['console','file'],
            'level' : 'CRITICAL',
            'propagate': False,
        },
        'moduleB.abc': {
            'handlers': ['console_simple'],
            'level' : 'DEBUG',
            'propagate': False,
        },
    },

大体こんな感じ。ちょい面倒だけど、やっていかないとだめだな〜。

connvoi.com

pythonでのloggingConfigとかloggerの使い方