【Python3】loggerを使ってログをファイルに出力したりちゃんと扱ったりする

さようならprint。

ログ出力、ちゃんとしないと後が面倒

pythonでデバッグ用のコメント類を標準出力に出したいときは一般にprintを使いますが、デバッグ用コメントならまあまあそれでもいいとして、バッチのログなどをprintに出していると、ログが残らなくてエラーを追えなくて難儀します。
今しています。
なので、ちゃんとしたログ出力メソッドを使ってファイルに出力したいと思います。あとついでに、お行儀のいいログの書き方を学びます。

先に結論

・myLogger.pyファイルを作って、ログ出力の最低限の設定をする関数を作る
・main.pyからログ設定関数を実行する（1回だけ）
・main.pyを含む各ファイルから、getLogger(__name__)して、各ファイル用のLoggerインスタンスを作ってログを書き込む

# myLogger.py

from logging import getLogger, handlers, Formatter, DEBUG
def set_logger():
    # 全体のログ設定
    # ファイルに書き出す。ログが100KB溜まったらバックアップにして新しいファイルを作る。
    root_logger = getLogger()
    root_logger.setLevel(DEBUG)
　  rotating_handler = handlers.RotatingFileHandler(
        r'./log/app.log',
        mode="a",
        maxBytes=100 * 1024,
        backupCount=3,
        encoding="utf-8"
    )
    format = Formatter('%(asctime)s : %(levelname)s : %(filename)s - %(message)s')
    rotating_handler.setFormatter(format)
    root_logger.addHandler(rotating_handler)

# main.py
from myLogger import set_logger, getLogger
set_logger()
logger = getLogger(__name__)

# ログを書き込むとき
logger.debug("デバッグ用ログ")
logger.info("普通のログ")
logger.warning("やば目のログ")

# moduleA.py
from myLogger import getLogger
logger = getLogger(__name__)

# 以下main.pyと同じようにログ記述

今回は「自分とせいぜい数人が使うだけの小規模プログラムだからそんなにちゃんとしなくていい」「でも最低限はちゃんとしたい、ちゃんとしなきゃいけなくなったときに困らないようにしておきたい」という想定の「ちゃんと」です。ちゃんとしてる度は低めです。おまじない行ができるだけ少なくなるように作っています。

「ちゃんとした」ログ出力メソッドlogging.logger

pythonにはちゃんとしたログ管理用のプラグインがあります。
標準ライブラリからimportできる「logging」がそれです。
ログのレベル（「DEBUG(デバッグの時くらいしか用がない詳細)」「WARNING（動くけどヤバい）」「CRITICAL（動かない）」など、ヤバさレベル）を指定してログを吐いたり、指定レベル以上のログだけを表示させたり、などができます。便利な世の中です。

一番簡単なloggingによるログ出力

とりあえず標準出力へ出力

import logging
logging.warning('警告があるよ') 
logging.info('想定通りに動いてるよ') 

※一番簡単だけど、このまま使うのはよくないです。ファイル１つで完結する小さなプログラムならこれでいいけど、それならprintでいい。
loggingはデフォルトだとWARNING以上のログだけを表示するようになっているので、これを実行すると「警告があるよ」だけが表示されます。

とりあえずファイルに出力

import logging
logging.basicConfig(filename='example.log', encoding='utf-8', level=logging.DEBUG)
logging.debug('デバッグ用のメッセージ')
logging.info('順調に実行中のメッセージ')
logging.warning('ちょっとヤバいメッセージ')
logging.error('だいぶマズい時のメッセージ')

logging.basicConfigでファイルの出力先を指定します。その際にlevelを指定しているので、そのレベル以上のログだけがファイルに出力されます。
この例ならDEBUG以上なので要するに全部が出力されます。
開発中はDEBUGにしておいて、稼働が始まったらINFOやWARNINGにするのがよい気がします。

変数の中身を出力

変数の中身も出力できます

logging.error("キーが存在しません :: %s ", key)

「f"キーが存在しません{key}"」 式でも良いような気がしますが、互換性の問題で公式記事が古い記法推奨していたので……

複数モジュールからのログを出力する

ログを出力したいすべてのモジュールでimport loggingして、loggingを使ってログを出力させるだけでOKです。らくちん。
らくちんですが、要するにこれグローバル変数なので、全てのモジュールから送出されたログが同じインスタンスで処理されるような形になります。

なので、どのモジュールから送出されたエラーなのかはこのままだとわかりません。ちょっと不便。
さらには、複数モジュールが絡んでくるプログラムでは相互に影響しあっちゃって不便（メインモジュールはWARNING以上、呼び出されるモジュールはINFO、不安定な所はDEBUG……みたいなことが出来ず、どこかで設定変えると全部変わっちゃう）

loggingそのまま使うのは不便なので、子クラスのloggerを使う

上記のloggingをそのまま方法はらくちんですが、もうちょっと便利に使いたいと思います。
loggingの子クラスであるloggerのインスタンスをモジュールごとに作って使うのがよさそうです。

logger = logging.getLogger(__name__)

を各モジュールごとに宣言すると、「ファイル名を識別子（ロガーの名前）として持つloggingの子供（＝logger）」が生成されます。
各モジュールで作ったloggerから送出したログは、内部でどんどん処理されて、最終的に、loggingがプログラム起動時に勝手に作るlogger＝ルートロガーへと送られて、最終的な処理をされます。

で、これにファイルの出力先やらレベルやらの設定を加えて使うのですが、全モジュールで設定するのは大変なので、ちゃんと楽な方法が用意されています。

loggingにbasicConfigを設定すれば全部に設定が波及する

ログ出力の設定方法は、コード内にハードコーディングしちゃう方法と、別の設定ファイルを用意する方法があるのですが、今回はハードコーディングしちゃいます。

ハードコーディングはベストな方法とは言えませんが、とりあえず「自分だけ～数人のチームでごにょごにょする程度のプログラムのログをファイルに出したい」くらいの用途なら、これくらいかなと……後々プログラムが大きくなってしまったときに、設定ファイルを使う方法とも比較的容易に差し替えられますし。

で、loggingを直接使うのは本来あんまり良くないんですが、「ログはとりあえず全部ファイルに出してくれ」と、全体へ命令する際は、大元のクラスであるloggingに命令するのが手っ取り早いです。
logging.loggerを使って送出したログ情報はどんどこ送られてルートロガーに集まる仕組みになっています。なので、「根元の設定を変更してしまうと全体に影響する」訳ですが、逆に言えば全体の設定変えたいときは根元を変えて上げればオッケー、という話。ものは使いようってやつです。

basicConfigの設定方法

import logging
logging.gasicConfig(filename="application.log",level=logging.DEBUG)

超絶乱暴ですがこれでひとまず「ログは全部ファイルへ出せ」が叶います。
勿論ここでlevelを変更すれば必要なログだけ出力できます。

ログローテーションさせる

ただ、ひとつのファイルに永遠にログを出させ続けると、ログファイルが無限大に大きくなってしまうので、ある程度の大きさが溜まったらアーカイブするようにします（＝ログローテーション）。

from logging import getLogger, handlers, DEBUG

root_logger = getLogger()

logging.setLevel(DEBUG)
rotatingfilehandler = handlers.RotatingFileHandler(
    r'./log/application.log',
    encoding = 'utf-8',
    maxBytes = 100 * 1024,
    backupCount = 1
)
logging.addHandler(rotatingfilehandler)

rotatingFileHandlerを使って、ログローテーションの設定をしてあげ、そのハンドラをloggingにセットし、たいんですが、loggingには直接addHandlerができないので、二行目のgetLoggerに何の引数も与えず呼びだして、ルートロガーを呼びだしてセットします。

※あと、大元のloggingをimportしちゃうと、いらん設定の変更をしちゃったり、折角ルートロガーに色々設定してあげてたのにlogging.info()でログ出力しちゃうと無意味になったりするので、ヒューマンエラー回避のため、loggingを直接importするのは割けた方が無難らしい。

ログのフォーマットを指定する

このままだとせっかくloggerくんがいろいろな情報を持っているのに、メッセージ部分しか出力されません。なので、日付とかログレベルとかも出力してあげます。

from logging import getLogger, handlers, Formatter

root_logger = getLogger()
rotatingfilehandler = handlers.RotatingFileHandler("略")
    
format = Formatter('%(asctime)s : %(levelname)s : %(filename)s - %(message)s')
rotating_handler.setFormatter(format)
root_logger.addHandler(rotating_handler)

3行目までは上記と同じで、ローテティングファイルハンドラを作ります。
で、新たにFormatterのインスタンスを作り、フォーマットを指定します。
フォーマッタをsetFormatterメソッドを使ってハンドラに登録します。
最後にハンドラをロガーに登録して完了です。うーんややこしい。

以上を踏まえて、取り合えず使いやすくファイル分割したりしたのが冒頭サンプルになります。
冒頭でも言った通りちゃんとしてる度は低めですが、とりあえずloggerを使ってあればここから先の発展性が大きく変わるはずなので、ログ出力のためのprintからの卒業を目指したいところです。