Python基礎１７：ログ出力(logging)

KIYO

2023年7月5日 22:23

１．概要

　Pythonのloggingモジュールはプログラムの動作について詳細な情報をログとして記録することができます。これはデバッグやエラー解析、システムの監視などの場面で有用です。

２．loggingの用途

２－１．print()とlogging()の違い

　コードの中で何かを出力したい時はprint関数を使用しますが下記問題があります。

情報の消失：printで出力した情報は実行終了後には消え、後から見返すことができない
情報の分類が不明確：print関数で出力した情報は全てが一律に扱われ、情報の種類（エラー、警告、情報）による区別がない
ログ保存が難しい：結果を異なる出力先（ファイル、データベースなど）に出力しにくい

　loggingモジュールは下記特徴があるため上記問題を解決できます。

情報の記憶：ログはファイルに書き込まれるため、プログラムの実行が終了しても情報を保存することが可能
分類が明確：ログには重要度（デバッグ、情報、警告、エラー、クリティカル）を付けて管理することができます。このレベルによって、出力を制御したり後から必要な情報だけをフィルターして閲覧することが可能となります。
ログ保存が簡単：ログは簡単に異なる出力先（コンソール、ファイル、データベース、メール等）に出力できる

２－２．print()とlogging()の使い分け

　大まかな使い分けは下記の通りです。

【print()】
・開発途中の簡易なデバッグや単純な結果の確認する
・開発段階向け

【logging()】
・プログラムの動作履歴を詳細に記録したりエラーメッセージを管理する
・実運用フェーズ向け

　他の使い分けとしてPython公式Docsの比較表が参考になります。

https://docs.python.org/ja/3/howto/logging.html

３．loggingモジュール

　実装前にloggingモジュールの概要について紹介します。

３－１．ログレベル

　loggingモジュールではログの重要性を示すための「ログレベル」という概念が存在します。ログレベルは以下の5つがあり、重要度はDEBUGが最も低くCRITICALが最も高いです。

DEBUG：デバッグ用の詳細な情報
INFO：プログラムが正常に動作していることを確認するための情報
WARNING：プログラムが問題を起こす可能性がある時に使用する情報
ERROR：プログラムが何かしらのエラーに遭遇したことを示す情報
CRITICAL：プログラム自体が実行を続けられないほどの重大なエラー

　例えばデバッグレベルのログは非常に詳細な情報を含むため、システム動作に影響を与えたりセキュリティ上のリスクにもなります。よって開発中のデバック用はlogging.DEBUG()にして、実装用はそれ以上のログレベルにすることで簡単に表示の切り分けが出来ます。

３－２．basicConfig()の概要

　logging.basicConfig()関数はloggingモジュールの基本的な設定を行います。主な引数には以下のものがあります。

[API]
logging.basicConfig(**kwargs)

level：ログのレベルを設定します。設定レベル以上のメッセージが出力されます。
filename：ログを出力するファイルの名前を指定します。指定しない場合、ログはコンソールに出力されます。
filemode：ログを出力するファイルのモードを指定します。
- 'w'を指定すると、前回のログが消去されて新たに書き込まれます。
- 'a'を指定すると、前回のログの後ろに新たなログが追加されます。
format：ログメッセージのフォーマットを設定します。

https://docs.python.org/ja/3/library/logging.html#logging.basicConfig

　なおlogging.basicConfig()関数はログ設定がまだ何も行われていない時のみ、その設定が反映されます。すでに何らかのログ設定が行われている状態でこの関数を呼び出しても設定は変更されません。

４．logging：シンプルな操作

　まずはloggingの基本的なステップから見ていきます。Pythonのloggingモジュールの利用は以下のような流れとなります。

loggingモジュールをインポート
logging.basicConfig()でログの設定
各ログレベルのメソッドを呼び出してログメッセージを記録

４－１．動作の確認

　前述の通り”logging.basicConfig()”で指定したログレベルのみを簡単に出力させることが可能です。

　例として”logging.basicConfig(level=logging.DEBUG)”で設定してすべてのログレベルで実行します。この場合DEBUGレベル以上（つまり全てのログレベル）のログが出力される設定となります。

[IN]
import logging

logging.basicConfig(level=logging.INFO)
logging.debug("This is a debug message")
logging.info("This is an info message")
logging.warning("This is a warning message")
logging.error("This is an error message")
logging.critical("This is a critical message")

[OUT]
DEBUG:root:This is a debug message
INFO:root:This is an info message
WARNING:root:This is a warning message
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

　”logging.basicConfig(level=logging.INFO)”に再設定して実行すると、INFOレベル以上（INFO, WARNING, ERROR, CRITICAL）のログが出力されDEBUGレベルのログは出力されません。
（※3-2節で説明の通りlogging.basicConfig()を1度設定すると設定を記録するため再設定するためにはカーネルの再起動が必要です。）

[IN]
# モジュールのインポート
import logging

# loggingの設定
logging.basicConfig(level=logging.INFO)

# ログメッセージの記録
logging.debug("This is a debug message")
logging.info("This is an info message")
logging.warning("This is a warning message")
logging.error("This is an error message")
logging.critical("This is a critical message")

[OUT]
INFO:root:This is an info message
WARNING:root:This is a warning message
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

　このようにして”logging.basicConfig()”のログレベルを切り替えるだけで簡単に出力したい情報にフィルターをかけることが出来ます。
　またデバッグ用で普段は使わないけどたまに見たいものがあればlogging.debug()に記載しておくことで必要に応じてチェックできます。

４－２．設計思想の考え方

　logging()がログレベルにより出力の表示を変更したり、出力にフィルターをかけることが出来ました。つまりloggingをログレベルで使い分けることで自分が欲しい出力を区別できます。

　前章でも説明済みですが、設計思想を明確化するためログレベルを使い分けの視点から再掲載しました。

DEBUG：デバッグ用の詳細な情報。問題の原因特定するための情報など
INFO：プログラムで情報として知りたい内容、通常の操作の確認など
WARNING：期待する結果が得られない可能性がある場合
- エラーは発生していないが動作に注意が必要なもの
- 下記例では"result=None"であり期待した値で無い。しかしプログラムは動き続けているためWARNING->止まるならCRITICALでもよいかも
ERROR： : エラーが発生したことを示す
- try/except文だとエラーが発生しても動作するのでERRORで設定
CRITICAL：致命的なエラーが発生しプログラムの実行ができない状況
- 今回のサンプルでは致命的なエラーが無いため記載無し

[IN]
import logging

logging.basicConfig(
    level=logging.DEBUG
)

def divide(x, y):
    if y == 0:
        logging.error("division by zero")
        return None
    else:
        return x / y

def main():
    logging.info("Start of the program")

    result = divide(10, 0)
    if result is None:
        logging.debug(result)
        logging.warning("Some parts of the program may not work as expected")

    logging.debug("End of the program")

if __name__ == "__main__":
    main()

[OUT]
INFO:root:Start of the program
ERROR:root:division by zero
DEBUG:root:None
WARNING:root:Some parts of the program may not work as expected
DEBUG:root:End of the program

　以上のように、ログレベルを使い分けることでログメッセージの重要度を区別することができ、ログが大量に出力される状況でも重要なメッセージを見逃すことなく問題の原因を特定しやすくなります。

５．basicConfig()のAPI

　basicConfig()の実装に関する詳細を説明します。

５－１．ログレベルによるフィルター：basicConfig(level)

　"basicConfig(level=<設定値>)"により表示するログレベルを設定できます。設定値は下記の通りです。下記でなく数値でも設定可能であり、その場合は上から50, 40, 30, 20, 10, 0となります。

logging.CRITICAL
logging.ERROR
logging.WARNING（default値）
logging.INFO
logging.DEBUG
NOTSET

【デフォルト：設定値=logging.WARNING】

[IN]
import logging

logging.basicConfig()# loggingの設定

# ログメッセージの記録
logging.debug("This is a debug message")
logging.info("This is an info message")
logging.warning("This is a warning message")
logging.error("This is an error message")
logging.critical("This is a critical message")

[OUT]
WARNING:root:This is a warning message
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

【logging属性で設定：設定値=logging.INFO】

[IN]
import logging

logging.basicConfig(level=logging.INFO)# loggingの設定

# ログメッセージの記録
logging.debug("This is a debug message")
logging.info("This is an info message")
logging.warning("This is a warning message")
logging.error("This is an error message")
logging.critical("This is a critical message")

[OUT]
INFO:root:This is an info message
WARNING:root:This is a warning message
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

【数値で設定：設定値=logging.ERROR】

[IN]
import logging

logging.basicConfig(level=40)# loggingの設定

# ログメッセージの記録
logging.debug("This is a debug message")
logging.info("This is an info message")
logging.warning("This is a warning message")
logging.error("This is an error message")
logging.critical("This is a critical message")

[OUT]
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

【コラム：数値の確認方法】
　数値の確認はgetattr(logging, <ログレベル>)で確認可能です。

[IN]
print(getattr(logging, 'DEBUG'))
print(getattr(logging, 'INFO'))
print(getattr(logging, 'WARNING'))     
print(getattr(logging, 'ERROR'))
print(getattr(logging, 'CRITICAL'))
print(getattr(logging, 'NOTSET'))

[OUT]
0
20
30
40
50
0

５－２．出力形式の設定：basicConfig(format)

　ログの出力形式を変更したい場合は、formatパラメータを使用します。事例の設定内容は下記の通りです。

%(asctime)s：ログの作成日時
%(levelname)s：ログレベル
%(message)s：出力するメッセージ（データ）

[IN]
import logging

logging.basicConfig(level=logging.ERROR,
                    format='%(asctime)s - %(levelname)s - %(message)s'
                    )# loggingの設定

# ログメッセージの記録
logging.debug("This is a debug message")
logging.info("This is an info message")
logging.warning("This is a warning message")
logging.error("This is an error message")
logging.critical("This is a critical message")

[OUT]
2023-07-05 21:31:55,966 - ERROR - This is an error message
2023-07-05 21:31:55,967 - CRITICAL - This is a critical message

５ー３．ログファイルの出力：basicConfig(filename)

　FileHandlerを使用することでログをコンソールだけでなく、ファイルとして出力できます。出力したログファイルはエディタ（メモ帳やVS CODE）で確認可能です。

logging.FileHandler：ファイル名を指定
logging.StreamHandler()：コンソールにも出力を表示

[IN]
import logging

logging.basicConfig(level=logging.ERROR,
                    format='%(asctime)s - %(levelname)s - %(message)s',
                    handlers=[logging.FileHandler('log1.log', 'w', 'utf-8'), 
                              logging.StreamHandler()]
                    )

# ログメッセージの記録
logging.debug("This is a debug message")
logging.info("This is an info message")
logging.warning("This is a warning message")
logging.error("This is an error message")
logging.critical("This is a critical message")

[OUT]
2023-07-05 21:37:14,789 - ERROR - This is an error message
2023-07-05 21:37:14,790 - CRITICAL - This is a critical message

６．高度な使い方

６－１．ハンドラ(Handlers)

　ハンドラは、ログの出力先を制御します。loggingモジュールは標準でいくつかのハンドラを提供しており、ログをコンソールに出力するStreamHandlerや、ログをファイルに出力するFileHandlerなどがあります。

[API]
class logging.Handler

６－２．フォーマッタ(Formatter)

　Formatterはログメッセージのフォーマットを制御します。Formatterを使用することで、ログメッセージの出力形式をカスタマイズできます。

[API]
class logging.Formatter(fmt=None, datefmt=None, style='%', validate=True, *, defaults=None)

７．応用事例

７－１．コンソールからログレベル設定：argparse

　pythonのargparseを用いるとコンソールから引数を渡すことでログレベルを設定することが可能です。
　サンプルモジュールでは下記のように作成しました。

argparseでコマンドラインオプションとしてlogを設定
コマンドラインで渡した引数を大文字変換（文字のゆらぎ防止）し、数値として取得して、basicConfig(<ログレベル値>)で設定

[a.py]
import argparse
import logging

# argparseを用いてコマンドライン引数を受け取る
parser = argparse.ArgumentParser(description="Set logging level.")
parser.add_argument('-l', '--log', default='WARNING', help='Change the level of log')
args = parser.parse_args()

# 受け取った引数を元にloggingの設定を行う
numeric_level = getattr(logging, args.log.upper(), None)
if not isinstance(numeric_level, int):
    raise ValueError(f'Invalid log level: {args.log}')
logging.basicConfig(level=numeric_level)

# 以下はテスト用のログ出力
logging.debug("This is a debug message.")
logging.info("This is an info message.")
logging.warning("This is a warning message.")
logging.error("This is an error message.")
logging.critical("This is a critical message.")

【引数無し】

[TERMINAL]
python a.py

[OUT]
WARNING:root:This is a warning message.
ERROR:root:This is an error message.
CRITICAL:root:This is a critical message.

【引数あり】

[TERMINAL]
python a.py --log ERROR

[OUT]
ERROR:root:This is an error message.
CRITICAL:root:This is a critical message.

７ー２．指定したログレベルだけ抽出

　指定したログレベルだけを抽出する場合、ハンドラとフォーマッタを細かく指定することで実装できます。

[a.py]
import argparse
import logging

class LevelFilter(logging.Filter):
    def __init__(self, level):
        self.level = level

    def filter(self, record):
        return record.levelno == self.level

parser = argparse.ArgumentParser()
parser.add_argument('-l', '--loglevel', default='WARNING', help='Set the logging level')
args = parser.parse_args()

numeric_level = getattr(logging, args.loglevel.upper())
if not isinstance(numeric_level, int):
    raise ValueError(f'Invalid log level: {args.loglevel}')

logger = logging.getLogger(__name__)
if logger.handlers:
    for handler in logger.handlers:
        logger.removeHandler(handler)

handler = logging.StreamHandler()
handler.setLevel(numeric_level)
handler.addFilter(LevelFilter(numeric_level))
formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)

logger.addHandler(handler)
logger.setLevel(numeric_level)

logger.debug("This is a debug message.")
logger.info("This is an info message.")
logger.warning("This is a warning message.")
logger.error("This is an error message.")
logger.critical("This is a critical message.")

【コマンドラインオプション無し】

[TERMINAL]
python a.py

[OUT]
2023-07-05 22:50:41,755 - WARNING - This is a warning message.

【コマンドラインオプション指定】

[TERMINAL]
python a.py --loglevel ERROR

[OUT]
2023-07-05 22:52:38,572 - ERROR - This is an error message.

参考記事

あとがき　

　必要に応じて下記追加

ログレベルを１個だけで抽出の詳細
フォーマッターでより詳細な表示ができるか