初めに
Clone で 20分おきに起動している Python のスクリプトがあった。
ログは TimedRotatingFileHandler で when パラメータを 'MIDNIGHT' にして使っていた。つまり、日付が変わるとログが切り替わる。python の TimedRotatingFileHandler での日次ログ切り替え
実行時間は当初 17分くらいだったが、永く稼働していているうちに ときどき20分を超えるようになっていた。あるとき、前日のログファイルが妙にサイズが小さいことがあることに気が付いた。中身を確認するとログがなかった。
「TimedRotatingFileHandler、なんかバグっているな」と思い、検索したら Stackoverflow とかに「そんなもんだ」みたいなやりとりがあったりもした。
さて、別件で新しくシステムを作る際、本来 daemon化するべきところを「(Clone での 1分ごとの起動 + 自己再起動) with 排他制御」という手抜きでスクリプトを運用する方針にした・・・が、ここで「TimedRotatingFileHandler のバグ、致命的になるな。今も治ってないのか？」と調べた。
バグの無いバージョンについて
このバグ、知っている人は知っている知られていたバグではあるようだが、修正されたのは 2024年4月である。
https://github.com/python/cpython/issues/88352
その時点でまだ出ていなかった
- Python 3.13 以降
及び BugFix対応の対象である
- Python 3.12.3 以降
- Python 3.11.9 以降
でバグは修正されている。
一方 Security Fix のみになっていた Python3.10 以前では 2024年4月以降に出ていてもこのバグは修正されていない。
https://devguide.python.org/versions/
バグの内容
バグの内容は「ログを切り替える(Rolloverする)際、現在のログファイルの新しい名前と同じファイルが名のファイルがあった場合は消す」というもの。おそらくRotatingFileHandler のコードを引き継いでしまったために発生したバグだろう。
https://github.com/python/cpython/commit/fee86fd9a422612b39e5aabf2571b8fe4abac770
の Lib/logging/handlers.py の変更前の 439行目の os.remove(dfn) が実際にファイルを削除している箇所である。
バグの発現する状況
このバグが発現するのは同一のスクリプトが二重起動されるなど、TimeRotatingFileHandler で同一のログファイルに書き込みを行っている状態でログ切替(Rollover)が発生したときである。
パラメータ when を MIDNIGHT にしている場合、
-
先のプロセスがログを書き込む際、日が変わっていたら(前日のログ(XXX.log.YYYY-MM-DD)のファイルが無いことをチェックしてから) 現在の File を Rename して XXX.log.YYYY-MM-DD としてから新しいファイルに書き始める
-
後のプロセスがログを書き込む際、日が変わっていたら、前日のログ(XXX.log.YYYY-MM-DD)のファイルがあるので削除を行ってから現在の File を Rename して XXX.log.YYYY-MM-DD とし、新しいファイルに書き始める
となる。
その結果、先のプロセスが切り替えてから後のプロセスが切り替えるまでに先のプロセスが書き込んだログのみが前日のログ(XXX.log.YYYY-MM-DD)として残るのである。
対策案(まだやってない)
バグが治っていないバージョンの Python で対策するなら TimedRotatingFileHandler を wrap するクラス作って doRolloverメソッドを新しいバージョンのコードを参考にして Overrideする形になるかと思います。(丸写しするなら一緒に変更されている computeRollover も Overrideすることになるかと。丸写しで大丈夫かはわからないが。)
そのうちやろう・・・と思ってるがそろそろシステム更新時期なんだよねぇ。。。