あくぽろぐ aqpolog

へなちょこエンジニアの備忘録

python3のloggerでミリ秒を使う、他

ブログスモールスタート第2段。

最近pythonの勉強を始めて、
ロギングには標準モジュールのlogging.loggerを使え!ってのはわかったのだけど色々苦労したのでその辺をメモ。
へなちょこエンジニア(コピペプログラマー)レベルなので、Python初学者で詰まってる人には参考になるかもしれない。

loggerとは

基礎的なところは公式ドキュメントを参照>Logging HOWTO — Python 3.6.5 ドキュメント

まあ一応ざっっっくり説明しておくと、

  1. logging.loggerをセット(ログの取得元を設定)
  2. handlerをセット(出力先を設定)
  3. loggerにhandlerをセット(紐づけ)
  4. print('debug: hogehoge')していたところを、logger.debug('hogehoge')に変える
  5. logger.error('hogehoge!!')みたいに重要度でレベル分けできる

といった感じで使える。
loggerに対してhandlerを複数セットしたりできるので、標準出力とファイル出力同時にするのも簡単。

フォーマッタでミリ秒/ナノ秒を使いたい

handlerに対しては、formatterを設定できる。
デフォルトだと(asctimeに対して)%Y-%m-%d %H:%M:%S形式がセットされているので、
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s') だと
2005-03-19 15:10:26,618 - simple_example - DEBUG - debug message みたいに返ってくる(公式ドキュメントから引用)。

この日付形式に不満がなければそのままでもいいのだけれど、1984/01/24 17:00:56.999形式にしたい。
最初にドキュメントとかを見てdatefmtにstrftimeの形で指定してあげればいいっぽいので次のコードにしたがエラー。
logging.Formatter('%(asctime)s [%(levelname)][%(name)s] %(message)s',datefmt='%Y/%m/%d %H:%M:%S.%f')
%fがだめらしい。 ※今ドキュメントよく見たらpython3.6のstrftimeに%fない?…2.xの方の情報見てたかな

解決法:次のコードを使う
logging.Formatter('%(asctime)s.%(msecs)-3d [%(levelname)-7s][%(name)s] %(message)s',datefmt='%Y/%m/%d %H:%M:%S')
datefmtでは秒まで。(msecs)でナノ秒が取れるので、それを左揃え3桁パディングしてあげればミリ秒が取れる。

独自のLogRecord属性

ログに関数IDや処理中ファイルみたいなのを出したい場合、
これをいちいちlogger.info('[XX-YY-Z001] hogehoge with [sample.csv]')とか

functionId = 'XX-YY-Z001'
filePath = 'sample.csv'
…(略)…
msg = '[{0}] hogehoge with [{1}]'.format(functionId,filepath)
logger.info(msg)

としてもいいけど、書式がズレないように気を使うのがめんどくさいし、
途中で書式変えたくなった時死ぬほどめんどくさい。絶対ヤダ。

というわけで色々調べると、extraオプションで独自設定ができるらしい。
logging.Formatter('%(asctime)s.%(msecs)-3d [%(levelname)-7s] [%(functionId)s] %(message)s with [%(file)s]',datefmt='%Y/%m/%d %H:%M:%S')
みたいに、LogRecord属性にない(functionId),(file)をフォーマッタ時点で入れておく。
logger呼出時に、logger.info('hogehoge',extra={'functionId':'XX-YY-Z001','file':'sample.csv'})とか

functionId = 'XX-YY-Z001'
filepath = 'sample.csv'
ex = {'functionId':functionId,'file':filepath}
…(略)…
logger.info('hogehoge',extra=ex)

してあげれば(extra引数に辞書形式で渡してあげれば)OK。

ただしこのやり方だと、logger呼出時に(functionId)や(file)がないとか、extraオプション自体がないとエラーになってしまうのでそれはそれでめんどくさい。
LogAdapterとやらをなんとかすれば解決できそうな気がするけど、とりあえず現状はここまで。

実際に書いたコード的なもの

適当に改変してるけど大体上記のことを反映したlogger生成関数。

def set_logger():
    from logging import (getLogger,StreamHandler,FileHandler,Formatter,
                         DEBUG,INFO,WARNING,ERROR)
    from datetime import datetime as dt
    import os

    # const的ななにか
    LOGLEVEL = 'DEBUG'
    BASEPATH = os.path.dirname(os.path.abspath(__file__))

    # パス、ファイル名設定
    LOGPATH = BASEPATH + '/log/system_' + dt.now().strftime('%Y%m%d') + '.log'

    # logger設定
    logger = getLogger(__name__)
    logger.setLevel(LOGLEVEL)

    # handler設定
    # フォーマット設定
    handler_format = Formatter('%(asctime)s.%(msecs)-3d' +
                               ' [%(levelname)-7s] [%(functionId)s]' +
                               ' %(message)s with [%(file)s]',
                               datefmt='%Y/%m/%d %H:%M:%S')
    # 標準出力
    stream_handler = StreamHandler()
    stream_handler.setLevel(LOGLEVEL)
    stream_handler.setFormatter(handler_format)
    # ファイル出力
    file_handler = FileHandler(LOGPATH,'a',encoding='utf-8')
    file_handler.setLevel(LOGLEVEL)
    file_handler.setFormatter(handler_format)

    # loggerにhandlerセット
    logger.addHandler(stream_handler)
    logger.addHandler(file_handler)

    return logger

# 呼出時
functionId = 'XX-YY-Z001'
filepath = 'sample.csv'
ex = {'functionId':functionId,'file':filepath}

logger.info('hogehoge',extra=ex)