Windowsのイベントログのエントリの対応をする前に、asctimeのフォーマットを修正したくなった。なぜならISO8601のフォーマットに馴染んでいるからだ。
asctimeをそのまま使用すると下記のような出力になる。secとmsecの間にあるカンマに違和感を禁じ得ない。
2021−06−26 00:00:00,123
開発環境:
Python 3.9.2
参考情報:
LogRecordのアトリビュートにmsecsが存在するため、formatを指定しよう。
format: '%(asctime)s.%(msecs)d -%(levelname)s- : %(message)s'
すると、ログの出力はこのようになり違和感なく眺められる。
2021-06-26 21:16:31.354 -INFO- MainThread : module:foo.py func:main line:17 all processes completed.
これにタイムゾーンを付与したら良いだろう。datefmtで指定出来たはずだ。
datefmt: '%Y-%m-%dT%H:%M:%S%z'
ところが結果はこうなる。formatの順序通りだ。異なるアトリビュートを結合したため当然の結果だ。不本意ながらlogging.Formatterをカスタマイズするしか手がなさそうだ。
2021-06-26 22:57:35+0900.582
Googleで検索すると、それなりに情報があった。awareかつJSTにするカスタマイズを施してそのまま流用した。シンプルなクラスだ。
class JSTDateFormatter(logging.Formatter):
converter=datetime.fromtimestamp
def formatTime(self, record, datefmt=None):
jst = timezone(timedelta(hours=+9), 'JST')
ct = self.converter(record.created, tz=jst)
if datefmt:
# %msをmsecに置換する処理
if '%ms' in datefmt:
msec = '%03d' % record.msecs
datefmt = datefmt.replace('%ms',msec)
s = ct.strftime(datefmt)
else:
# datefmtがNoneの場合の処理
t = ct.strftime('%Y-%m-%dT%H:%M:%S')
z = ct.strftime('%z')
s = '%s.%03d%s' % (t, record.msecs, z)
return s
以前のエントリにあるように、YAMLにloggingのコンフィグレーションを保存している。このためYAMLで上記のクラスをformattersのブロックで指定する場合の例を挙げよう。難しいことではない。
formatters:
brief:
(): log.JSTDateFormatter # ここがポイント
format: '%(asctime)s -%(levelname)s- : %(message)s'
datefmt: '%Y-%m-%dT%H:%M:%S.%ms%z'
precise:
(): log.JSTDateFormatter # ここがポイント
format: '%(asctime)s -%(levelname)s- %(threadName)s : %(message)s'
datefmt: '%Y-%m-%dT%H:%M:%S.%ms%z'
log.JSTDateFormatterはlog.pyというモジュールのJSTDateFormatterを呼び出すという動作を特殊キーである '()' で実現している。呼び出し可能オブジェクトであるクラスを指定すれば素直に動いてくれる。
ちなみに、'%ms' とあるのはmsecに相当するフォーマットストリングがdatefmtになかったためカスタマイズしている。動作を確認しよう。
2021-06-26T23:16:31.353+0900 -INFO- MainThread : module:myapp.py func:__init__ line:16 MyApp completed.
見慣れたISO8601に則った書式だ。
補足するとformatに記載していないモジュール名、関数名、行数がメッセージに含まれるのはsys._getframeで抽出した情報をメッセージへ出力しているからだ。理由はloggingのラッパーのインスタンスメソッド内でログファイルへの出力を行っているため、何も施さずに出力するとラッパーのインスタンスメソッドが書き込んでいるということしか分からないのだ。下記のformatは役に立たないということだ。
format: '%(asctime)s -%(levelname)s- %(threadName)s [LineNo.: %(lineno)s] %(module)s : %(message)s'
このためloggingのラッパークラスに含んでいる下記のインスタンスメソッドを、インスタンスを生成した側で実行して情報を収集している。
def get_stackinfo(self,msg:Type[Message]) -> Message:
stack_frame = sys._getframe(1)
if stack_frame is not None:
msg.module = 'module:'+os.path.basename(stack_frame.f_code.co_filename)
msg.caller = 'func:'+stack_frame.f_code.co_name
msg.line = 'line:'+str(stack_frame.f_lineno)
msg.message = ' '.join([msg.module,msg.caller, msg.line,msg.message])
return msg
同じようにモジュール内でロギング用の関数を呼び出してロギングすると似たような事象が発生する。このような事象を紐解いていくことは良い経験になると思われる。幾つかトラブルシューティングに取り組んでいると解決するための方法論が自ずと身に付くからだ。
まとめ:
logging.Formatterのカスタマイズは難しいものではない
思惑通りの挙動ではない時、まずはマニュアルに目を通そう
落ち着いてTracebackを読もう