PythonのFileHandlerを複数プロセスで同時に使ってはいけない
Python Logging 入門
複数プロセスの例
Django + Gunicorn
Gunicornがworkerプロセスを起動するため、マルチプロセス(複数プロセス)となる
バッチ処理の同時動作
バッチ処理それぞれはシングルプロセスでも、同時に複数のバッチが動作する瞬間がありえる
WHY?
複数のプロセスからの単一ファイルへのログ記録 -- Logging クックブック — Python 3.7.4 ドキュメント
ログ記録はスレッドセーフであり、単一プロセスの複数のスレッドからの単一ファイルへのログ記録はサポート されています が、 複数プロセス からの単一ファイルへのログ記録はサポート されません 。なぜなら、複数のプロセスをまたいで単一のファイルへのアクセスを直列化する標準の方法が Python には存在しないからです。
間違った設定事例と、発生する問題
事例1: django+gunicornのマルチプロセスワーカーで logging.FileHandler を使う
問題: payment.log ファイルへの書き込みがworker A, B から同時に行われ、後勝ちとなり、先に書き込まれた内容が上書きされる。ログの内容が一部欠落するため、見た目上、問題が起きている事が分かりにくい。
事例2: django+gunicornのマルチプロセスワーカーで logging.RotatingFileHandler や logging.TimeRotatingFileHandler を使う
問題: ファイルサイズや特定時刻でログローテートが行われ、複数プロセスから行われると後勝ちとなり、多くのログが失われる
ローテート処理の動作(0時に1日分をローテートする条件の場合)
1プロセスの場合
1. payment.log を payment-20190801.log にrenameする
2. payment.log ファイルを開く(作成される)
3. payment.log ファイルに書き込む
4. payment.log ファイルを閉じる
2プロセスの場合(worker A, B)
1. Aが payment.log を payment-20190801.log にrenameする
2. Aが payment.log ファイルを開く(作成される)
3. Aが payment.log ファイルに書き込む
4. Bが payment.log を payment-20190801.log にrenameする(上書き)
5. Aが payment.log ファイルを閉じる(Aのログ出力が保存される)
6. Bが payment.log ファイルを開く
7. Bが payment.log ファイルに書き込む
8. Bが payment.log ファイルを閉じる(Bのログ出力が追記保存される)
payment-20190801.log に1日分のログが保存されている想定なのに、手順4で、手順2で作ったばかりの空ファイルで上書きしているため、ログは失われる。
対策
複数のプロセスからの単一ファイルへのログ記録 -- Logging クックブック — Python 3.7.4 ドキュメント
複数のプロセスから単一ファイルへログ記録しなければならないなら、最も良い方法は、すべてのプロセスが SocketHandler に対してログ記録を行い、独立したプロセスとしてソケットサーバを動かすことです。ソケットサーバはソケットから読み取ってファイルにログを書き出します。 (この機能を実行するために、既存のプロセスの 1 つのスレッドを割り当てることもできます) この節 では、このアプローチをさらに詳細に文書化しています。動作するソケット受信プログラムが含まれているので、アプリケーションに組み込むための出発点として使用できるでしょう。
syslog時代の対策
SysLogHandler を設定する
systemd 時代の対策
例1: Djangoのログ出力を全て標準出力に送り、gunicornからsystemd(journald)へテキスト情報として流す
例: Django + gunicorn のログ出力設定
例2: python-systemdを使って、Pythonのloggingから直接Journaldへログを構造化データとして流す
例: #TBD
多重起動を防止する
プログラムの多重実行防止