TimedRotatingFileHandler のマルチプロセス競合で FileNotFoundError が出る問題：concurrent-log-handler への置換

複数のジョブが同じログファイルに書き込む構成で、深夜の rotate タイミング前後で FileNotFoundError が頻発しました。

原因は Python 標準の TimedRotatingFileHandler が マルチプロセス安全ではない こと。concurrent-log-handler への置換と、移行で踏んだ罠をまとめます。

何が起きるか

症状

毎日 0:00 過ぎに集中して以下のエラーが出る。

1
Traceback (most recent call last):
2
  File ".../logging/handlers.py", line 466, in emit
3
    self.doRollover()
4
  File ".../logging/handlers.py", line 419, in doRollover
5
    os.rename(self.baseFilename, dfn)
6
FileNotFoundError: [Errno 2] No such file or directory: 'app.log' -> 'app.log.2026-05-08'

または

1
PermissionError: [Errno 13] Permission denied: 'app.log.2026-05-08'

ジョブによってはログ自体が出力されなくなり、その日のログが空のファイルとして残ります。

原因：rotate がアトミックでない

TimedRotatingFileHandler.doRollover() は内部で次の処理をしています。

1
# 簡略化した擬似コード
2
def doRollover(self):
3
    self.stream.close()              # 1. 現在のファイルを閉じる
4
    if os.path.exists(dfn):
5
        os.remove(dfn)               # 2. 既存の rotate 先を削除
6
    os.rename(self.baseFilename, dfn)  # 3. リネーム
7
    self.stream = self._open()       # 4. 新しいファイルを開く

複数プロセスが同時にこれをやろうとすると、Process A の Step 3 と Process B の Step 1 が交差して、Process A がリネーム済みのファイルを Process B が close しようとしたり、Process B がリネームしようとした瞬間に Process A が同名のファイルを開こうとしたりして、エラーが出ます。

Python の logging モジュールの設計上、1 プロセス内のスレッド競合は防がれていますが、プロセス間の競合は守備範囲外です。

検出のコツ

ログファイルの inode を見ると、どのプロセスがどのファイルを掴んでいるかが分かります。

1
ls -i app.log app.log.2026-05-08
2
lsof | grep app.log

異なるプロセスが異なる inode の同名ファイルを開いていたら、競合しています。

解決策の選択肢

選択肢 A: ファイルロックで排他

fcntl.flock を使って rotate をシリアライズする。自前実装は罠が多いので非推奨です（lock ファイルの解放忘れ、デッドロック等）。

選択肢 B: SyslogHandler や外部 logger に流す

syslog、journald、fluent-bit などにログを集約する。マルチプロセス安全ですが、設定の重さが上がります。

選択肢 C: concurrent-log-handler

pip install concurrent-log-handler。TimedRotatingFileHandler の API 互換ライブラリで、内部でファイルロックを取って rotate を排他します。

「最小コストでマルチプロセス安全」が目的なら C が現実的です。

移行：concurrent-log-handler に置換

Before

1
from logging.handlers import TimedRotatingFileHandler
2

3
handler = TimedRotatingFileHandler(
4
    "app.log",
5
    when="midnight",
6
    backupCount=7,
7
    encoding="utf-8",
8
)

After

1
from concurrent_log_handler import ConcurrentTimedRotatingFileHandler
2

3
handler = ConcurrentTimedRotatingFileHandler(
4
    "app.log",
5
    when="midnight",
6
    backupCount=7,
7
    encoding="utf-8",
8
)

API はほぼ互換。when や backupCount の挙動も同じなので、1 行置換で済みました。

内部で何をしているか

concurrent-log-handler は portalocker を使ってファイルロックを取得し、rotate 中は他のプロセスが書き込めないようにします。

1
# 簡略化した内部処理
2
def emit(self, record):
3
    with portalocker.Lock(lockfile_path):
4
        self._do_rollover_if_needed()
5
        self.stream.write(self.format(record) + "\n")

書き込みのたびにロックを取るので、スループットは少し落ちます。ロギングが律速になるほどの量を出している場合は、syslog 系のほうが速いです。

移行で踏んだ罠

罠 1: ロックファイルの場所

concurrent-log-handler はロックファイルを app.log.lock のような名前で 同じディレクトリに作ります。デプロイ先が read-only な場合や、ログディレクトリの権限設定が厳しい場合に失敗します。

修正: ロックファイルを別ディレクトリに置く（書込権限のある場所に）。

1
handler = ConcurrentTimedRotatingFileHandler(
2
    "/var/log/myapp/app.log",
3
    when="midnight",
4
    backupCount=7,
5
    use_gzip=False,
6
    # ロック専用ディレクトリ
7
    lock_file=Path("/var/run/myapp/app.log.lock"),
8
)

罠 2: rotate されたファイル名のフォーマットが微妙に違う

TimedRotatingFileHandler は app.log.2026-05-08 のような名前で rotate しますが、concurrent-log-handler のバージョンによっては 接尾辞のフォーマットが違うことがあります。

ログ集約スクリプトが古いファイル名パターンに依存していると壊れます。

修正: rotate 後のファイル名規約を 明示的に指定するか、集約側のパターンを緩める。

1
handler.suffix = "%Y-%m-%d"  # 明示
2
handler.extMatch = re.compile(r"^\d{4}-\d{2}-\d{2}$")

罠 3: gzip 圧縮で速度劣化

concurrent-log-handler の use_gzip=True は rotate 後に古いログを gzip 圧縮しますが、圧縮中もロックを保持するため、その間他のプロセスが書き込めません。

ログ量が多いと、毎日深夜に数十秒〜数分間ログが詰まる現象が起きました。

修正: gzip 圧縮を別プロセス（cron や launchd）で非同期にやる。

1
handler = ConcurrentTimedRotatingFileHandler(
2
    "app.log",
3
    when="midnight",
4
    backupCount=7,
5
    use_gzip=False,  # 圧縮はしない
6
)

1
# 別途、深夜 1:00 に古いログを gzip
2
0 1 * * * find /var/log/myapp -name "*.log.????-??-??" -mtime +0 -exec gzip {} \;

罠 4: dictConfig での書き方

logging.config.dictConfig を使っている場合、handler のクラスパスを差し替えます。

1
{
2
    "handlers": {
3
        "file": {
4
            "class": "concurrent_log_handler.ConcurrentTimedRotatingFileHandler",
5
            "filename": "app.log",
6
            "when": "midnight",
7
            "backupCount": 7,
8
        }
9
    }
10
}

クラス名が長いので typo に注意。設定ファイルだけ変更してアプリコードは変えなくてよい点はメリットです。

効果

学び

1. logging のマルチプロセス安全は標準ではない

Python の logging は 1 プロセス前提で設計されていて、複数プロセスが同じファイルに書く構成は 保証外です。マルチプロセス・マルチコンテナの構成では、最初から concurrent-log-handler や syslog 系を選ぶのが安全です。

2. rotate のタイミングで集中して問題が出る

「普段は問題なく動いているけど rotate 時だけ落ちる」のは、症状の発生タイミングが特殊なので原因特定に時間がかかります。深夜帯のエラーログをまず疑うクセをつけました。

3. ロギング自体がボトルネックになりうる

「ロギングはタダ」と思いがちですが、ロック付きの concurrent-log-handler は 書き込みごとに数百 μsのオーバーヘッドがあります。1 秒に数千行書く処理では無視できません。重要な処理でログ量を絞る判断も必要です。

4. 圧縮は非同期化する

ロックを長く持つ処理（gzip 圧縮など）は、ロガーから切り離して別ジョブにするのが運用上の鉄則でした。

まとめ

「マルチプロセス安全なロギング」は意外に落とし穴の多いトピックでした。

TimedRotatingFileHandler のままで「たまに落ちるけど大丈夫」と思っていたのが、実は ログ自体の信頼性を損ねる問題でした。ログは「消えても気づきにくい」インフラなので、最初から堅いものを選んでおく価値があります。