Pythonでログを出力するコード例【logging】

スポンサーリンク

Pythonでログをファイルに出力する簡単な方法です。

Python標準の logging モジュールを使用して、動作ログエラーログをファイルに記録します。

もちろん、ログに時刻情報実行中の関数名も付けられます。

たくさんのXBRLを読み込んでいると、やはり、いろいろなエラーに遭遇します。XBRLのzipが破損していたり、タグ名に誤りがあったり、自身のプログラムにまずいところがあったり。

そういった例外やエラーは、とりあえずログファイルに記録しておいて、あとからひとつずつ対処していくことになると思います。

そのためのパイソンコード例を紹介します。

ロガーでの書き込みには、logging モジュールを使うのが一般的です。

logging モジュールを使う

Python 標準のモジュールに、ログ記録用の logging モジュールがあります。これを使います。ここでは、ログの「画面表示」と「ファイル出力」をしてくれる、簡単なロガーを作って使ってみます。

決算分析システムで使っているロガーも、このような簡単なロガーがほとんどです。

公式マニュアルのページです。

logging – Python 用ロギング機能
https://docs.python.jp/3/library/logging.html

print()に相当するのが、ストリームハンドラだけのロガーです。

open()でテキスト出力に相当するのが、ファイルハンドラーだけのロガーです。

ストリームハンドラとファイルハンドラを追加すると、画面に出力しながらファイルに出力するロガーになります。

簡単なロガーだけで十分

ロガーは簡単なもので十分です。

ログ記録の開始方法と終了方法は、お決まりのパターンです。あとは、print()の代わりにlg.debug()を使います。

さて、ロガーなんて使わず、自前でファイルを開いてログを記録するのでも、もちろんOKです。ログ出力の手作りです。

しかしながら、画面にも出力したいとなると、print()も一緒に書くことになるし、それらを関数にまとめて便利にしようと作っていったら、結局ロガーモジュールを作るのと同じになりました。

なので、最初からloggingモジュールの簡単なところだけ使うのがおすすめです。

実際のところ、ロギングレベルも DEBUG ひとつで十分です。

Pythonでログ出力するコード例

ファイル名を指定してファイルにログ出力するサンプルです。

Pythonの実行ログをとるのに使います。

ロガー作成 ⇒ ログ記録 ⇒ ロガー終了の例

ロガーを作って、記録して、最後にロガーを終了(ロガーを削除)するコード例です。

ロガーの作成ですが、画面出力のための『ストリームハンドラ』と、ファイル出力のための『ファイルハンドラ』を追加します。

ファイルハンドラには、ファイルパス・書き込みモード・エンコーディングなどを指定します。ログ出力先を指定します。

これらのハンドラは、プログラム終了前に閉じて外しています。そして、ロギングシステムのシャットダウンを呼び出します。これでロガーが完全に終了します。

終了前にハンドラを閉じて外すのは、しなくてもいいのかもしれませんが、一応、行っています。公式のロギングクックブックを見ると、こういうハンドラを閉じたり外したりといった操作は、途中でロガーの設定を変更したりするときに使うようです。

ハンドラの並びを[::-1]で逆順にしているのは、for文を最後まで回すためです。正順だと、1つリムーブした時点でループが終了してしまったので、このようにしています。

import os
import logging

def main():
    """ロガーテスト"""
    print('start')

    # ログフォルダ・ログファイル設定
    log_dir = r'D:\project\data_log'
    log_txt = os.path.join(log_dir, 'log.txt')


    # ロガー作成
    logger_name = __name__
    print('logger_name: "%s"' % logger_name)

    logger = logging.getLogger(logger_name)
    logger.setLevel(logging.DEBUG)


    # ストリームハンドラ作成
    stream_handler = logging.StreamHandler()
    stream_handler.setLevel(logging.DEBUG)
    stream_handler.setFormatter(logging.Formatter('%(message)s'))

    # ロガーに追加
    logger.addHandler(stream_handler)


    # ファイルハンドラ作成 (追記モード & utf-8 で記録)
    file_handler = logging.FileHandler(log_txt, mode='a', encoding='utf-8')
    file_handler.setLevel(logging.DEBUG)
    file_handler.setFormatter(logging.Formatter('%(message)s'))

    # ロガーに追加
    logger.addHandler(file_handler)


    # 記録
    logger.debug('ロギング 開始')

    try:
        raise ValueError('テスト バリューエラー')
    except:
        logger.exception('例外を記録 ここから↓')
        logger.debug('ここまで↑')

    logger.debug('ロギング 終わり')


    # ロガーに追加したハンドラを閉じてリムーブ。
    # [::-1]で逆順にして、リストの後ろからリムーブしていく。
    for handle in logger.handlers[::-1]:
        handle.close()
        logger.removeHandler(handle)

        # (参考) リムーブしたハンドラを表示
        if type(handle) == logging.FileHandler:
            print('Removed %s %s' % (
                str(type(handle)),
                os.path.basename(handle.baseFilename),
                ))
        else:
            print('Removed %s' % str(type(handle)))


    # ロガーをシャットダウンする
    logging.shutdown()

    print('end')
    return


if __name__ == '__main__':
    main()

実行結果です。まずは「画面出力」です。

start
logger_name: "__main__"
ロギング 開始
例外を記録 ここから↓
Traceback (most recent call last):
  File "D:\project\data_log\use_logger.py", line 43, in main
    raise ValueError('テスト バリューエラー')
ValueError: テスト バリューエラー
ここまで↑
ロギング 終わり
Removed <class 'logging.FileHandler'> log.txt
Removed <class 'logging.StreamHandler'>
end

そして「ログファイル」です。logger.debug() と logger.exception() の文字列が記録されています。logger.exception() ですが、渡した文字列に続けてスタックトレースを出力してくれます。

ロギング 開始
例外を記録 ここから↓
Traceback (most recent call last):
  File "D:\project\data_log\use_logger_0.py", line 43, in main
    raise ValueError('テスト バリューエラー')
ValueError: テスト バリューエラー
ここまで↑
ロギング 終わり

こういった例外発生時の情報は、traceback.format_exc() で取得して、logger.debug()に渡すことでも記録できます。単に記録するだけなら logger.exception() が簡潔で便利でした。

ロガーの作成と終了を関数化して簡単に使う

Pythonのloggerでファイル出力するコードです。

ロギングモジュールから作るロガーですが、欲しい機能って、だいたい同じだったりするんですね、どのプログラムでも。

なので、上記のようなお決まりのロガーは、関数化して使っています。

以下、ロガーの作成と終了の部分を関数化したコード例です。ログを取りたいプログラムで、このような MyLogger モジュールをインポートして使います。

"""MyLogger.py"""
import os
import logging


def main():
    """ロガーテスト"""
    print('start')

    # ログフォルダ・ログファイル設定
    log_dir = r'D:\project\data_log'
    log_txt = os.path.join(log_dir, 'log.txt')

    # ロガー作成
    lg = get_logger(__name__, log_txt)


    # 記録
    lg.debug('ロギング 開始')

    try:
        raise ValueError('テスト バリューエラー')
    except:
        lg.exception('例外を記録 ここから↓')
        lg.debug('ここまで↑')

    lg.debug('ロギング 終わり')


    # ロギングシステムを終了する
    shutdown_logging_system(lg)

    print('end')
    return


def get_logger(
    logger_name, log_file, s_fmt='%(message)s', f_fmt='%(message)s'):
    """ロガーを取得"""
    # ロガー作成
    logger = logging.getLogger(logger_name)
    logger.setLevel(logging.DEBUG)


    # ストリームハンドラ作成
    stream_handler = logging.StreamHandler()
    stream_handler.setLevel(logging.DEBUG)
    stream_handler.setFormatter(logging.Formatter(s_fmt))

    # ロガーに追加
    logger.addHandler(stream_handler)


    # ファイルハンドラ作成
    file_handler = logging.FileHandler(log_file, mode='a', encoding='utf-8')
    file_handler.setLevel(logging.DEBUG)
    file_handler.setFormatter(logging.Formatter(f_fmt))

    # ロガーに追加
    logger.addHandler(file_handler)

    return logger


def remove_logger_handlers(logger):
    """ロガーに追加したハンドラーをすべて閉じてリムーブする"""
    # [::-1]で逆順にして、リストの後ろからリムーブしていく。
    for handle in logger.handlers[::-1]:
        handle.close()
        logger.removeHandler(handle)
    return


def shutdown_logging_system(logger):
    """ロガーをシャットダウンする"""
    # すべてのハンドラを閉じてリムーブする
    remove_logger_handlers(logger)

    # ロガーをシャットダウンする
    logging.shutdown()
    return


if __name__ == '__main__':
    main()

画面表示だけのロガーの作り方

ロガーにストリームハンドラ logging.StreamHandler() だけを追加すると、画面表示だけを行うロガーができます。

ログの保存先など指定も不要です。

この場合は、プリント関数 print() とほぼ同じ機能になりますが、表示が速いというメリットがあります。

print()よりもストリームハンドラだけの .debug() で画面表示したほうが、目に見えて高速でした。文字がサラサラと流れていきます。

理由は調べていませんが、print() はストリームハンドラだけの .debug() よりも遅いようです。

なので自分は、プロンプト画面にたくさん情報表示するようなPythonプログラムでは、高速化のために、ストリームハンドラーだけを追加したロガーを使ったりしています。

ファイル記録だけのロガーの作り方

ロガーにファイルハンドラ logging.FileHandler(log_file, mode='a', encoding='utf-8') だけを追加すると、ファイル記録だけを行うロガーができます。

プロンプト画面には何も表示されません。ファイルにだけログが出力されます。

時刻情報や実行中の関数名を出力するロガーの作り方

Pythonのロガーのフォーマットは、ロギングフォーマッター logging.Formatter() を使って設定します。

定番は時刻情報関数名の自動付加ですね。

以下のPython公式マニュアルから、使いたいフォーマットを調べて設定します。

LogRecord 属性(ログレコード属性)
https://docs.python.jp/3.5/library/logging.html#logrecord-attributes

ログに時刻情報を出力

ログに時刻情報を出力するには、'%(asctime)s' を使います。

'%(message)s' のほかに '%(asctime)s' を指定すると、ログを記録した時の時刻が自動で追加されます。

具体的には、セットフォーマッター .setFormatter() の引数に以下を渡します。

logging.Formatter('%(asctime)s %(message)s')

ログに関数名を出力

ログに実行中の関数名を出力するには、'%(funcName)s' を使います。

'%(message)s' のほかに '%(funcName)s' を指定すると、ログを記録したところの関数名が自動で追加されます。

具体的には、セットフォーマッター .setFormatter() の引数に以下を渡します。

logging.Formatter('%(funcName)s %(message)s')

時刻情報と関数名を出力

ログに時刻情報実行中の関数名を同時に追加することもできます。

セットフォーマッター .setFormatter() の引数に以下を渡します。

logging.Formatter('%(asctime)s %(funcName)s %(message)s')

他にも情報を追加したいときは、Pythonマニュアルの『LogRecord 属性』から使いたいフォーマットを選べばOKです。

Pythonのログをローテーションして記録する方法

ログのファイルサイズを指定して、分割しながら記録していく方法です。

ログファイルが巨大化すると開けなくなりますので、指定したサイズになったら新しいファイルに書き込む必要があります。

ログを自動で分割記録するには、ローテーティングファイルハンドラ RotatingFileHandler を使います。

Pythonの公式マニュアルがわかりやすいです。

logging.handlers — ロギングハンドラ RotatingFileHandler
class logging.handlers.RotatingFileHandler(filename, mode='a', maxBytes=0, backupCount=0, encoding=None, delay=False)

maxBytes にファイルの最大サイズを渡して使います。

backupCount には普通、1以上を設定します。backupCountの数だけ、古いログファイルに連番が付いて残ります。

ログファイルがmaxBytesを超えそうになったら、自動的にファイルを閉じて、新しいログファイルに記録してくれます。

ログファイルのローテーション処理を手作りしなくていいのは嬉しいです。

タイトルとURLをコピーしました