【Python】logging フォーマットの出力例（１０種類以上）

2019.11.04
Python

ログ出力のフォーマッター logging.Formatter(fmt) で指定可能な、１０種類以上のフォーマットの出力例です。

『どのようなログ表示が出来るのか？』を確認したくて、コードを書いて試しました。

フォーマットの種類は、Python マニュアルの『LogRecord 属性』に載っていたものを試しました。

(Python) LogRecord 属性（ログレコード属性）

日付、時刻、関数名などのほかに、行番号やプロセス ID まで、自動でログに付加することができました。

それらの出力例（実行結果）を紹介します。

logging フォーマットの出力例

実行環境

『app_main.py』という Python ファイルを、以下の場所で実行しました。

F:\apps\data>python "F:\apps\data\app_main.py"

OS は Windows 10 (64 bit) で、Python は 3.8.6 (64 bit) を使用しました。

このときのログ出力の結果です。

ログの画面表示

ログの画面表示です。

ルートロガーに取り付けた StreamHandlerストリームハンドラ が表示した内容です（標準エラー出力 sys.stderr）。

format の種類は『(Python) LogRecord 属性』にあったものを使いました。

start《 LogRecord 属性の出力テスト 》
[ format ]          -> [ 出力 ] -> [ 説明 ]
%(asctime)s         -> 2022-03-30 14:48:06,054 -> 時刻 (人が読める形式)
%(created)f         -> 1648619286.054090 -> 時刻 (time.time()形式)
%(filename)s        -> app_main.py -> ファイル名
%(funcName)s        -> test_formats -> 関数名
%(levelname)s       -> DEBUG -> ロギングレベルの名前
%(levelno)s         -> 10 -> ロギングレベルの数値
%(lineno)d          -> 77 -> 行番号
%(module)s          -> app_main -> モジュールの名前
%(msecs)d           -> 54 -> 時刻のミリ秒部分 (milliseconds)
%(name)s            -> __main__ -> ロガーの名前
%(pathname)s        -> F:\apps\data\app_main.py -> ファイルパス
%(process)d         -> 9848 -> プロセスID (PID)
%(processName)s     -> MainProcess -> プロセス名
%(relativeCreated)d -> 15 -> logging モジュール読み込みからの時刻 (ミリ秒)
%(thread)d          -> 9384 -> スレッドID (TID)
%(threadName)s      -> MainThread -> スレッド名

(Python ファイルの場所)
F:\apps\data\app_main.py

end

ログファイルの内容

ログファイル (log.txt) の内容です（内容は画面表示のものと同じです）。

ルートロガーに取り付けた FileHandlerファイルハンドラ が書き込んだ内容です。

start《 LogRecord 属性の出力テスト 》
[ format ]          -> [ 出力 ] -> [ 説明 ]
%(asctime)s         -> 2022-03-30 14:48:06,054 -> 時刻 (人が読める形式)
%(created)f         -> 1648619286.054090 -> 時刻 (time.time()形式)
%(filename)s        -> app_main.py -> ファイル名
%(funcName)s        -> test_formats -> 関数名
%(levelname)s       -> DEBUG -> ロギングレベルの名前
%(levelno)s         -> 10 -> ロギングレベルの数値
%(lineno)d          -> 77 -> 行番号
%(module)s          -> app_main -> モジュールの名前
%(msecs)d           -> 54 -> 時刻のミリ秒部分 (milliseconds)
%(name)s            -> __main__ -> ロガーの名前
%(pathname)s        -> F:\apps\data\app_main.py -> ファイルパス
%(process)d         -> 9848 -> プロセスID (PID)
%(processName)s     -> MainProcess -> プロセス名
%(relativeCreated)d -> 15 -> logging モジュール読み込みからの時刻 (ミリ秒)
%(thread)d          -> 9384 -> スレッドID (TID)
%(threadName)s      -> MainThread -> スレッド名

(Python ファイルの場所)
F:\apps\data\app_main.py

end

%()s, %()f, %()d は マッピングキー

『% 形式フォーマット文字列』で書かれた %(asctime)s などの丸カッコの中身は、『マッピングキー (mapping key)』と呼ばれるものでした。

LogRecord の便利なマッピングキーは、 LogRecord 属性 の節で与えられます。

(Python) フォーマッタオブジェクト

マッピングキー（マップキー）については、『(Python) printf 形式の文字列書式化』にも説明がありました。

% フォーマットの代わりに {} フォーマット使用することもできました。

そのあたりの説明は『(Python) 固有の書式化スタイルをアプリケーション全体で使う（Logging クックブック）』にありました。

プロセス名とスレッド名の例

マルチプロセス処理やマルチスレッド処理を採用したところ、それらの処理中は、プロセス名やスレッド名が変化していました。以下の記事に Python コードと実行結果を書きました。

マルチスレッド処理で高速化できた例 ⇒ 実験結果

結果だけ書きますと、

『プロセス名 %(processName)s』のログは、たとえば『MainProcess, SpawnProcess-2, SpawnProcess-3, …』のようになりました。

『スレッド名 %(threadName)s』のログは、たとえば『MainThread, ThreadPoolExecutor-0_0, ThreadPoolExecutor-0_1, …』のようになりました。

（結果はプロセスの開始方法の指定などによって変わると思います）

プロセス名とスレッド名の関係については、

  • MainProcess -> MainThread（普通のシングルプロセス）
  • MainProcess -> ThreadPoolExecutor-0_0（マルチスレッド）
  • SpawnProcess-2 -> MainThread（マルチプロセス）

のようになっていました。

プロセス名やスレッド名を出すと、

『本当に狙ったプロセス or スレッドで実行されたか？』

が簡単にわかって便利ですね。

Python コード

ログのフォーマットを試すために書いた Python コード例です。

実行結果は『logging フォーマットの出力例』に載せた通りです。

"""app_main.py
ログのフォーマットを試すコード例です。
"""
import logging, pathlib

#「名前付きロガー」を取得します。
logger = logging.getLogger(__name__)
#「名前付きロガー」取得時のロギングレベルは NOTSET (0) です。

def main():
    """メイン関数です。"""
    # ログファイルの場所を決めます。
    data_dir = pathlib.Path(r'F:\apps\data')
    log_txt = data_dir.joinpath('log.txt')

    #「ルートロガー」を取得します。
    #「ルートロガー」取得時のロギングレベルは WARNING (30) です。
    root = logging.getLogger()
    root.setLevel(logging.DEBUG)

    #「ルートロガー」にストリームハンドラを追加します。
    # どのハンドラも生成時のロギングレベルは NOTSET (0) です。
    sh = logging.StreamHandler()
    sh.setLevel(logging.DEBUG)
    sh.setFormatter(logging.Formatter('%(message)s'))
    root.addHandler(sh)
    
    #「ルートロガー」にファイルハンドラを追加します。
    # どのハンドラも生成時のロギングレベルは NOTSET (0) です。
    fh = logging.FileHandler(log_txt, mode='a', encoding='utf-8')
    fh.setLevel(logging.DEBUG)
    fh.setFormatter(logging.Formatter('%(message)s'))
    root.addHandler(fh)

    # ログのフォーマットを試します。
    test_formats(root)
    return

def test_formats(root):
    """ログのフォーマットを試す関数です。"""
    # LogRecord 属性の フォーマット(fmt) と 説明(ex) のリストを用意します。
    log_formats = [
        ('%(asctime)s', '時刻 (人が読める形式)'),
        ('%(created)f', '時刻 (time.time()形式)'),
        ('%(filename)s', 'ファイル名'),
        ('%(funcName)s', '関数名'),
        ('%(levelname)s', 'ロギングレベルの名前'),
        ('%(levelno)s', 'ロギングレベルの数値'),
        ('%(lineno)d', '行番号'),
        # ('%(message)s', 'ログメッセージ'),
        ('%(module)s', 'モジュールの名前'),
        ('%(msecs)d', '時刻のミリ秒部分 (milliseconds)'),
        ('%(name)s', 'ロガーの名前'),
        ('%(pathname)s', 'ファイルパス'),
        ('%(process)d', 'プロセスID (PID)'),
        ('%(processName)s', 'プロセス名'),
        ('%(relativeCreated)d', 'logging モジュール読み込みからの時刻 (ミリ秒)'),
        ('%(thread)d', 'スレッドID (TID)'),
        ('%(threadName)s', 'スレッド名'),
    ]

    # (フォーマット名が一番長い要素を取得)
    log_format_max = max(log_formats, key=lambda x: len(x[0]))
    # (フォーマット名の長さを取得)
    len_max = len(log_format_max[0])

    logger.debug('start《 LogRecord 属性の出力テスト 》')
    logger.debug(f'{"[ format ]".ljust(len_max)} -> [ 出力 ] -> [ 説明 ]')

    for (fmt, ex) in log_formats:
        # ルートロガーに取り付けた、すべてのハンドラのフォーマッタを変更します。
        for h in root.handlers:
            h.setFormatter(logging.Formatter(f'%(message)s -> {fmt} -> {ex}'))

        # 名前付きロガーで、ログを記録してみます。
        msg = fmt.ljust(len_max)
        logger.debug(msg)
        # (補足) 名前付きロガーのログが、ルートロガーに伝わり、
        # ルートロガーに取り付けたハンドラで記録されます。
        # (ルートロガーへの伝搬は logger.propagate 属性で制御します)
    else:
        # ルートロガーに取り付けた、すべてのハンドラのフォーマッタを元に戻します。
        for h in root.handlers:
            h.setFormatter(logging.Formatter('%(message)s'))

    logger.debug(f'\n(Python ファイルの場所)')
    logger.debug(__file__)

    logger.debug('\nend')
    return

if __name__ == '__main__':
    main()

ロガーの使い方

logging モジュールの使い方を書きました。

⇒ 【Python】ロガーでロギングするコード例【logging】

concurrent.futures でログを記録するコード例。

⇒ ProcessPoolExecutor でログを記録するコード例（プロセスごとに分ける）

⇒ ProcessPoolExecutor でログを記録するコード例（まとめて記録）

multiprocessing でログを記録するコード例。

⇒ multiprocessing.Pool でログを記録するコード例（プロセスごとに分ける）

⇒ multiprocessing.Pool でログを記録するコード例（まとめて記録）

『マルチスレッド』と『マルチプロセス』の両方を使うプログラムでログを記録しているコード例。

⇒ マルチスレッド処理で高速化できた例
（concurrent.futures の ThreadPoolExecutor と ProcessPoolExecutor を使用しました）

Python マニュアル

コード例で使用した Python 機能のマニュアルの場所です。

ロガー

(Python) logging.getLogger(name=None)

(Python) logging.Logger.propagate 属性（ログの伝搬制御に使用します）

(Python) logging.Logger.setLevel(level) 『名前付きロガー』取得時のロギングレベルは NOTSET で、『ルートロガー』取得時のロギングレベルは WARNING である旨の説明がありました。

(Python) logging.Logger.addHandler(hdlr)

(Python) logging.Logger.debug(msg, *args, **kwargs)

ハンドラ

(Python) class logging.StreamHandler(stream=None)

(Python) class logging.FileHandler(filename, mode='a', encoding=None, delay=False, errors=None)

(Python) logging.Handler.setLevel(level) 『ハンドラ』生成時のロギングレベルは NOTSET（すべてのメッセージが処理される）である旨の説明がありました。

(Python) logging.Handler.setFormatter(fmt)

フォーマッタ

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

(Python) LogRecord 属性 %(asctime)s, %(levelname)s, %(message)s, ...

インポート関連のモジュール属性

(Python) __name__

(Python) __file__

パスリブ

(Python) class pathlib.Path(*pathsegments)

(Python) PurePath.joinpath(*other)

文字列リテラル

(Python) r''（raw strings、raw 文字列）（チュートリアル）

(Python) r''（raw strings、raw 文字列）（言語リファレンス）

(Python) f''（f-string、formatted string literal、フォーマット済み文字列リテラル）（言語リファレンス）

文字列の整形に使用した機能

(Python) max(iterable, *[, key, default])

(Python) ラムダ式 lambda

(Python) len(s)

(Python) str.ljust(width[, fillchar])（左寄せ、左揃え）

% フォーマットの機能だけで『みぎ揃え』や『ひだり揃え』にする方法もありました。

『９文字』の範囲で『右寄せ →』や『← 左寄せ』をする Python コード例です。

print('■ print 関数の場合')
text = 'abc'
print('%s' % text)
print('%9s みぎ寄せ' % text)
print('%-9s ひだり寄せ' % text)

print('\n■ ロガーの場合')
import logging

root = logging.getLogger()
root.setLevel(logging.DEBUG)
sh = logging.StreamHandler()
sh.setLevel(logging.DEBUG)
root.addHandler(sh)

logger = logging.getLogger(__name__)
sh.setFormatter(logging.Formatter('%(message)s'))
logger.debug('abc')
sh.setFormatter(logging.Formatter('%(message)9s みぎ寄せ'))
logger.debug('abc')
sh.setFormatter(logging.Formatter('%(message)-9s ひだり寄せ'))
logger.debug('abc')

実行結果です。

■ print 関数の場合
abc
      abc みぎ寄せ  
abc       ひだり寄せ

■ ロガーの場合      
abc
      abc みぎ寄せ
abc       ひだり寄せ

以上です。

スポンサーリンク
シェアする（押すとSNS投稿用の『編集ページ』に移動します）
フォローする（RSSフィードに移動します）
スポンサーリンク
シラベルノート
シラベルノート
タイトルとURLをコピーしました