結局どうする？ラクして無難にPython loggingを使うためのサンプルコードと使用例

こんにちはイチケンです。

Pythonでログを取るのに使っているlogging。調べたところ色々お作法があるようですが、結局ラクして無難に使うにはどうすれば良いのよ？となり、自分で実験してみました。

本記事のサンプルはこんな人向き

• 結局loggingをどう使うかよくわからない。
• モジュール（pyファイル）ごとに違うファイル出力したい。
• 日付、またはファイル容量ごとにファイルを切り替えたい。
• モジュール（pyファイル）をまたいで同じロガーを使いまわしたい。
• 毎回ログの設定コピペするの面倒。
• ログが重複出力される解決方法がわからない。

logging設定の使い回しを簡略化しつつ、モジュールごとに別々のログフォルダに出力する方法がわかります。またロガーのインスタンスを複数作るとログが重複する問題の解決方法も分かります。

前提条件

まず前提条件となる私の環境です。

• VSCode 1.55.2
• Python 3.8.2

サンプルコード

Githubのリポジトリはこちら

https://github.com/ichiken-usa/python-log-test

「log.py」ファイルを作成し、次のコードをコピペします。もちろんファイル名はlog.pyでなくてもかまいません。

プログラミングわかりません！という人にも触ってもらう前提なら設定ファイルとして外出しすると良いと思いますが、私はそんなシーンほぼないのでメソッドで直書きで行きます。

from logging import StreamHandler, DEBUG, INFO, Formatter
from logging.handlers import RotatingFileHandler, TimedRotatingFileHandler
import os

def set_log_config(logger, dir, filename):

    # ---- Prepare log folder ----
    os.makedirs(dir, exist_ok=True) 
    filepath = dir + filename

    # ---- handler1: For terminal ----
    handler1 = StreamHandler()
    handler1.setLevel(DEBUG)
    handler1.setFormatter(Formatter("[%(asctime)s][%(levelname)8s][%(name)s] %(message)s"))

    # ---- handler2: For log file ----
    #handler2 = TimedRotatingFileHandler(filename = filepath, when='midnight', backupCount=30, encoding='utf-8') # If you want to rotate file by time, use this
    handler2 = RotatingFileHandler(filename = filepath, maxBytes = 1048576, backupCount = 10, encoding='utf-8', ) # 1MB, keep 10 files
    handler2.setLevel(INFO)
    handler2.setFormatter(Formatter("[%(asctime)s][%(levelname)8s][%(name)s] %(message)s"))

    # ---- Set log config ----
    logger.setLevel(DEBUG)
    logger.addHandler(handler1)
    logger.addHandler(handler2)
    logger.propagate = False

getLoggerメソッドでインスタンスを作り、set_log_configに渡します。引数は（getLogger, ログフォルダ, ログファイル名）です。

サクサク解説

loggingを直接いじらず、getLoggerメソッドでインスタンス化してね、と公式に書かれています。というわけでそうしましょう。

ロガーを直接インスタンス化することは 絶対に してはならず、常にモジュール関数 logging.getLogger(name) を介してインスタンス化することに注意してください。 同じ name で getLogger() を複数回呼び出すと、常に同じロガー・オブジェクトへの参照が返されます。 引用： logging --- Python 用ロギング機能

同じnameで複数回呼び出すと常に同じオブジェクトが参照される、という点に注意が必要。微妙に通常のオブジェクト指向と違い、そもそもラクに横断して使い回せるように作ってるからヨロシク！てことでいいですかね？

サンプルコード解説

フォルダ作る→ターミナル用の設定→ログファイル出力用設定→セットという流れです。

1MB超えたら次のファイルに移るようにしています。日付でローテーションしてほしいよ！て人はRotatingFileHandlerをコメントアウトし、TimeRotatingFileHandlerを有効にしてください。０時にログファイルが新しいファイルに移動します。

納入されたシステムが「ループで大量にエラーを吐き出して1日でドライブがパンクする」という不具合を過去経験したことがあります。こういったログによる予期せぬトラブルを回避するには、日付よりは容量のほうが良いですね。

以下のケースで実際の挙動を解説します。main.py | sub.py | log.py の3モジュールでテストします。

• １：モジュールごとに出力ファイルを分ける
• ２：全モジュールで共通ロガーを使う
• ３：間違ってログが二重出力されてファイル分けの意味がない例

使用例1：モジュールごとに出力ファイルを分ける

では、まずは私が一番使うであろう使用例です。

main.py

import log
import sub
from logging import getLogger

dir = './python_envs/log_test/Log/'
logger = getLogger(__name__)
log.set_log_config(logger, dir, 'main.log' )

# subのテストメソッド呼び出し
sub.test_method(dir)

# main内のlogger出力
logger.info('--------------------')
logger.info('Main: 完了')

sub.py

import log
from logging import getLogger

def test_method(dir):

    logger = getLogger(__name__)
    log.set_log_config(logger, dir, 'sub.log' )

    for i in range (5):
        logger.info(f'Sub: ループ i={i}')

main.pyを実行するとターミナルにはmainとsubのログが表示され、ファイルは狙い通りそれぞれに別れて保存されています。

各モジュール内で__name__（ '__main__' と 'sub' ）を与えてインスタンスにしています。なので別のロガーとして存在しており、個々にハンドラーの設定を与えています。

今回は一発で設定しちゃいましたが、大規模になってくるとgetLogger(A).getChild(B)として、共通部分を親Aで設定しておき、子Bで個別設定して使うという感じでしょうね。

使用例2：全モジュールで共通ロガーを使う

フィルターすればいいだけなんだからファイル分けなくてよくね？という場合はこっち。

先述したとおりgetLoggerは同じ名前空間だと同じオブジェクトを参照します。つまりインスタンス化の際に同じ名前を与えると、いちいち設定しなくてもモジュールをまたいで共通の設定を使うことが可能。

main.py

import log
import sub
from logging import getLogger

dir = './python_envs/log_test/Log/'
logger = getLogger('test')
log.set_log_config(logger, dir, 'main.log' )

# subのテストメソッド呼び出し
sub.test_method(dir)

# main内のlogger出力
logger.info('--------------------')
logger.info('Main: 完了')

sub.py

import log
from logging import getLogger

def test_method(dir):

    logger = getLogger('test')
    #log.set_log_config(logger, dir, 'sub.log' )

    for i in range (5):
        logger.info(f'Sub: ループ i={i}')

main.pyを実行するとsub.py側のログも同じ設定で出力されます。 つまり、同じ名前を与えると、インスタンスをまたいで同じオブジェクトを参照していることが分かります。

log.set_log_config(logger, dir, 'sub.log' )をコメントアウトしている理由は、つまりそういうこと。sub側のロガーはmainより後で呼ばれていますが、コンフィグ設定しなくても同じように使えています。

サンプルには入れてませんが、フォーマットに %(module)s を入れるとモジュール名を出力、%(funcName)s でメソッド名を出力できるので、ファイルを分けなくてもフィルタ可能。この辺はログで何したいか次第でしょうねー。下のスクショはメソッド名を出力した例。

フォーマットはこちら
https://docs.python.org/ja/3/library/logging.html#logrecord-attributes

使用例3：間違ってログが二重出力されてファイル分けの意味がない例

使用例2のsubのコメントアウトをもとに戻し、sub内でもコンフィグをセットしてみます。モジュールを横断して同じロガーを参照しているので、こいつに再度ハンドラーを設定してしまうことになります。

main.py

import log
import sub
from logging import getLogger

dir = './python_envs/log_test/Log/'
logger = getLogger('test')
log.set_log_config(logger, dir, 'main.log' )

# subのテストメソッド呼び出し
sub.test_method(dir)

# main内のlogger出力
logger.info('--------------------')
logger.info('Main: 完了')

sub.py

import log
from logging import getLogger

def test_method(dir):

    logger = getLogger('test')
    log.set_log_config(logger, dir, 'sub.log' )

    for i in range (5):
        logger.info(f'Sub: ループ i={i}')

実行するとターミナルに同じログが二重出力されます。

出力されたファイルは中身が全く同じものになっちゃいました。これじゃファイル分けした意味がないですね。

つまり、同じ設定でモジュール間でロガーを使いまわしたい場合は、最初にコンフィグ設定を一回だけして、別モジュールではgetLoggerに同じ名前を与えるだけ。設定を二回してはいけません。

最後に

いかがでしたか？

もっとこうした方が良いよ！等アドバイスありましたらぜひお願いします。

Githubのリポジトリはこちら

https://github.com/ichiken-usa/python-log-test

参考サイト

• logging --- Python 用ロギング機能
• pythonのlogger奮闘記 ～簡単な使い方から複数ファイルを跨る使い方まで～
• 【Python】仕組みを理解してログ出力を使いこなす