1
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

@yureki_lab

AIエージェントを無人で回す Python プロセスのログを取りこぼさない実装手順 — 複数プロセスのローテーションで前日分が消える・basicConfig が黙って無視される・スレッドの例外が残らない、3つのハマりどころ【2026】

1
Posted at

はじめに / 対象と前提

AI エージェント（Claude Code のヘッドレス実行や、自作のエージェントループ）を夜間に無人で回していると、朝になって「何が起きたか」を追えるのはログだけになる。ところが自分の環境では、ログはちゃんと仕込んだつもりなのに、肝心の時間帯だけ残っていないという事故が 3 回起きた。

この記事は、その 3 つの原因と回避策を再現コード付きでまとめたもの。

  • 想定読者：Python で長時間動くワーカー／エージェントを書いている人
  • 前提：logging 標準モジュールの基本（getLogger / Handler / Formatter）が分かる
  • 動作確認環境：macOS 15 / Python 3.14.3（3.11〜3.13 でも考え方は同じ。ただし後述の通りローテーションの挙動はバージョンで違う）

TL;DR

  • 同じログファイルを 複数プロセスが TimedRotatingFileHandler で書くと、ローテーション後に片方が「昨日のファイル」に書き続ける（古い Python では前日分が消える）。ファイルはプロセスごとに分けるか、WatchedFileHandler + 外部ローテーションにする
  • logging.basicConfig() は ルートにハンドラーが 1 つでもあると何もしない。force=True を付ける
  • 別スレッドで落ちた例外は ログに残らない。sys.excepthook と threading.excepthook の両方を差し替える

手順 / 動かし方

最終的に落ち着いたセットアップがこれ。エージェント本体の一番最初に呼ぶ。

import logging
import logging.handlers
import os
import sys
import threading
from pathlib import Path

def setup_logging(role: str, log_dir: Path = Path("logs")) -> None:
    log_dir.mkdir(exist_ok=True)
    # ① プロセス（役割）ごとにファイルを分ける
    path = log_dir / f"{role}.log"
    handler = logging.handlers.TimedRotatingFileHandler(
        path, when="midnight", backupCount=14, encoding="utf-8"
    )
    fmt = "%(asctime)s %(process)d %(threadName)s %(levelname)s %(name)s: %(message)s"
    # ② 既存ハンドラーがあっても確実に上書きする
    logging.basicConfig(level=logging.INFO, format=fmt,
                        handlers=[handler, logging.StreamHandler()], force=True)

    log = logging.getLogger("uncaught")

    # ③ メインスレッドの未捕捉例外
    def _excepthook(exc_type, exc, tb):
        if issubclass(exc_type, KeyboardInterrupt):
            return sys.__excepthook__(exc_type, exc, tb)
        log.critical("uncaught exception", exc_info=(exc_type, exc, tb))
    sys.excepthook = _excepthook

    # ③' 別スレッドの未捕捉例外（Python 3.8+）
    def _thread_hook(args: threading.ExceptHookArgs):
        log.critical("uncaught exception in thread %s",
                     args.thread.name if args.thread else "?",
                     exc_info=(args.exc_type, args.exc_value, args.exc_traceback))
    threading.excepthook = _thread_hook

使う側：

setup_logging(role=f"worker-{os.getpid()}")
logging.getLogger(__name__).info("agent loop start")

フォーマットに %(process)d と %(threadName)s を入れておくと、並列で動いたときにどのワーカーの出力か後から切り分けられる。

ハマりどころ

1. 複数プロセスで同じファイルをローテーションすると、片方が昨日のファイルに書き続ける

症状：日付が変わった後のログが agent.log に一部しか無い。探したら agent.log.2026-10-13 の末尾に今日の日付の行が延々と追記されていた。

再現（1 秒ごとにローテーションさせ、2 つのハンドラー＝2 プロセス相当で同じファイルを書く）：

import logging, logging.handlers, os, time

def mk(name):
    lg = logging.getLogger(name); lg.propagate = False; lg.setLevel(logging.INFO)
    h = logging.handlers.TimedRotatingFileHandler("agent.log", when="S", interval=1)
    h.setFormatter(logging.Formatter(f"{name} %(message)s"))
    lg.addHandler(h)
    return lg

a, b = mk("A"), mk("B")
a.info("a1"); b.info("b1")
time.sleep(1.2)
a.info("a2-after-rollover")
b.info("b2-after-rollover")
b.info("b3")

実行結果：

== agent.log
A a2-after-rollover
== agent.log.2026-10-14_08-00-56
A a1
B b1
B b2-after-rollover
B b3

原因：ローテーションは「各ハンドラーが自分の判断で」行う。先に A が agent.log をリネームして新しいファイルを開く。B も時刻を過ぎたのでローテーションしようとするが、リネーム先がもう存在するので 何もせず return する（Python 3.14 の doRollover の実装）。B は古いファイルディスクリプタを握ったままなので、書き込みはリネーム後のファイル、つまり「昨日分」に入り続ける。

古いバージョンの実装では、リネーム先が存在すると それを削除してからリネーム していたので、A が退避した前日分のログがまるごと消える。どちらにしても複数プロセスで 1 ファイルを共有する構成は破綻する。

回避策（どれか 1 つ）：

  • ファイルをプロセス（役割）ごとに分ける（上の setup_logging(role=...)。いちばん簡単）
  • Python 側ではローテーションせず logging.handlers.WatchedFileHandler を使い、newsyslog（macOS）や logrotate（Linux）に回させる。WatchedFileHandler はファイルの inode が変わったら開き直すので、外部ローテーションと相性がいい
  • 同じプロセス内の複数スレッドだけなら問題ない（ハンドラー 1 つをロックで共有するため）。非同期処理から書く場合は QueueHandler + QueueListener で書き込みを 1 スレッドに集約する

2. basicConfig() が黙って無視される

症状：level=logging.DEBUG にしたのに DEBUG が出ない。フォーマットも反映されない。

import logging
logging.getLogger().addHandler(logging.StreamHandler())   # どこかで先に付けられた
logging.basicConfig(level=logging.DEBUG, format="X %(message)s")
logging.getLogger().debug("debug visible?")
print("root level:", logging.getLogger().level)
logging.basicConfig(level=logging.DEBUG, format="X %(message)s", force=True)
logging.getLogger().debug("after force")

X after force
root level: 30

原因：basicConfig() は ルートロガーにハンドラーが既にあると何もしない 仕様。エラーも警告も出ない。import したライブラリや、テストランナー、別モジュールの logging.info() 呼び出し（ハンドラー未設定時にルートへ自動で付く）で先にハンドラーが付いていると、レベル設定ごとスキップされる（上の 30 は既定の WARNING）。

回避策：force=True（Python 3.8+）を付けて既存ハンドラーを外してから設定する。dictConfig を使う場合は、既定値 disable_existing_loggers=True によって 設定前に作られたロガーが無効化される ので、"disable_existing_loggers": False を明示するのを忘れないこと。

3. 別スレッドの例外がログに残らない

症状：ハートビート用のスレッドが止まっていたのに、ログには何も無い。プロセス自体は生きているので監視にも引っかからない。

原因：threading.Thread の中で投げられた未捕捉例外は threading.excepthook に渡され、既定では stderr に出るだけ。無人実行で stderr を捨てていると完全に消える。sys.excepthook だけ差し替えても、スレッド側には効かない。

回避策：上のコードの通り sys.excepthook と threading.excepthook の両方をロガーに流す。asyncio を使っている場合は、loop.set_exception_handler() で「回収されなかった Task の例外」も拾っておくと安心。

背景・補足

logging のハンドラーは「1 プロセスの中で 1 つのファイルを管理する」前提で作られている。スレッド間ではロックで守られるが、プロセスをまたぐロックは一切無い。エージェントを並列化してワーカーを増やした瞬間にこの前提が崩れるので、ログ設計は「何プロセスが同じファイルを触るか」から決めるのが安全。

まとめ

  • 複数プロセスで同じファイルを TimedRotatingFileHandler / RotatingFileHandler しない。プロセスごとにファイルを分けるか、外部ローテーション + WatchedFileHandler
  • basicConfig(force=True)、dictConfig なら disable_existing_loggers: False
  • sys.excepthook と threading.excepthook の両方をロガーにつなぐ
  • フォーマットに %(process)d %(threadName)s を入れて、並列実行時の切り分けをしやすくする
1
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
1
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?