Python logging 設計｜ログが出ない・ローテーションが壊れるを実測で潰す

import logging, logging.handlers, sys
from pathlib import Path

# exe（onefile）では __file__ は一時展開先。exe の隣を基準にする
base = Path(sys.executable).parent if getattr(sys, "frozen", False) \
       else Path(__file__).parent
log_dir = base / "logs"                         # 相対パスにしない
log_dir.mkdir(parents=True, exist_ok=True)
fmt = logging.Formatter("%(asctime)s [%(levelname)s] %(name)s: %(message)s")
fmt.default_msec_format = "%s.%03d"             # datefmt を渡すとミリ秒が消える

h = logging.handlers.TimedRotatingFileHandler(
    log_dir / "app.log", when="midnight", backupCount=14,
    encoding="utf-8",                           # 未指定だと日本語 Windows は cp932
    errors="backslashreplace")                  # 書けない文字で行を落とさない
h.setFormatter(fmt)
# h には setLevel しない＝root のレベルに従う（INFO で固定すると 4 章の症状 3 を自作する）

root = logging.getLogger()
root.setLevel(logging.INFO)                     # ここ 1 か所でファイルも画面も変わる
root.handlers.clear()
root.addHandler(h)
if sys.stderr is not None:                      # exe の --noconsole では None
    console = logging.StreamHandler(sys.stderr)
    console.setFormatter(fmt)                   # 画面もファイルと同じ書式にする
    root.addHandler(console)

logging.getLogger(__name__).info("app started")

2026 年 9 月 1 日更新: 全面的に書き直しました。初版のテンプレート自体に地雷が 4 つあったため修正し、症状別早見表・ローテーション破損の実測・dictConfig を新設。初版の記述 4 つも実測と食い違ったので撤回しています（一覧は 14 章）。

1. print と logging の使い分け

公式 HOWTO の指針は明快です。画面へ出すだけなら print()、正常動作の記録は logger.info()、エラーは原則例外を送出。崩れる場面は 1 つだけ——長時間動くプログラムで、処理を止めないためにエラーを握って続行するときは logger.exception() です。24 時間動くアプリでは、例外を握るなら証拠を残す義務がセットになります。

ロガーは logging.getLogger(__name__) で取るのが公式の規約です。名前がモジュール階層と一致し、「通信まわりだけ DEBUG」の絞り込みができます。

2. レベル判定は 2 段ある

構成要素は Logger（どこから）、Handler（どこへ）、Formatter（整形）、Filter（追加判定）の 4 つ。ハマるのはその先で、足切りは Logger と Handler の 2 か所で別々に行われます。

②にも注記を。propagate で渡る先は祖先のハンドラだけで、公式 logging いわく "neither the level nor filters of the ancestor loggers ... are considered"。親を WARNING にしても子の INFO は止まりません。①は NOTSET（既定）なら祖先までさかのぼるので、setLevel しないのは「親に従う」という意味です。

3. 起動時に 1 回だけ設定する

設定はアプリの入口で 1 回だけ。各モジュールは getLogger(__name__) で取ります。「各モジュールで basicConfig を呼べばいい」は成立しません。公式 logging の basicConfig の項は "This function does nothing if the root logger already has handlers configured ..." としており、2 回目以降はエラーも警告も出さずに無視されます（force=True での上書きは 4 章の症状 4）。

# app/log_setup.py
import logging
import logging.handlers
import sys
from pathlib import Path


def setup_logging(log_dir: Path, app_name: str = "app",
                  level: int = logging.INFO) -> None:
    """アプリの入口で 1 回だけ呼ぶ。2 回呼んでも増殖しない。"""
    log_dir = Path(log_dir).resolve()          # 相対パスの事故を防ぐ
    log_dir.mkdir(parents=True, exist_ok=True)

    # datefmt は渡さない（渡すとミリ秒が消える）。区切りをピリオドにするだけ。
    fmt = logging.Formatter(
        "%(asctime)s [%(levelname)s] %(name)s: %(message)s"
    )
    fmt.default_msec_format = "%s.%03d"

    # 1) 本体ログ: 日次ローテーション、14 日分保持
    file_handler = logging.handlers.TimedRotatingFileHandler(
        filename=log_dir / f"{app_name}.log",
        when="midnight",
        backupCount=14,
        encoding="utf-8",              # 未指定だと日本語 Windows では cp932
        errors="backslashreplace",     # 書けない文字が来ても行ごと消さない
    )
    file_handler.setFormatter(fmt)
    file_handler.setLevel(level)       # INFO で固定すると LOG_LEVEL=DEBUG が効かない

    # 2) エラー専用ログ: ERROR 以上だけを集める
    err_handler = logging.handlers.RotatingFileHandler(
        filename=log_dir / f"{app_name}-error.log",
        maxBytes=10 * 1024 * 1024,
        backupCount=10,
        encoding="utf-8",
        errors="backslashreplace",
    )
    err_handler.setFormatter(fmt)
    err_handler.setLevel(logging.ERROR)

    handlers = [file_handler, err_handler]

    # 3) コンソール: sys.stderr がある時だけ足す（理由は 7 章）
    if sys.stderr is not None:
        console_handler = logging.StreamHandler(sys.stderr)
        console_handler.setFormatter(fmt)
        console_handler.setLevel(logging.DEBUG)
        handlers.append(console_handler)

    root = logging.getLogger()
    root.setLevel(level)
    for h in root.handlers[:]:         # 二重登録を防ぐ（閉じてから外す）
        h.close()
        root.removeHandler(h)
    for h in handlers:
        root.addHandler(h)

# main.py
from pathlib import Path
import logging
from app.log_setup import setup_logging

setup_logging(Path(__file__).parent / "logs")   # __file__ 基準の絶対パス
logging.getLogger(__name__).info("app started")
# -> 2026-09-01 15:46:21.413 [INFO] __main__: app started

要点はエラー専用だけ ERROR 固定、本体ログは level に追随させること。ここを INFO で固定すると LOG_LEVEL=DEBUG（6 章）がファイルに効きません。root に付ける構成なので外部ライブラリのログも流れ込みます。うるさいものは logging.getLogger("urllib3").setLevel(logging.WARNING) で絞ります。

3.1 初版のテンプレートが踏んでいた 4 つの地雷

① datefmt を指定するとミリ秒が消える。公式 logging の Formatter.formatTime は、datefmt があれば time.strftime() で整形し、無いときだけ %Y-%m-%d %H:%M:%S,uuu の uuu（ミリ秒）を付けます。自宅検証機で並べた結果です。

datefmt 未指定                 : 2026-09-01 15:38:59,142
datefmt="%Y-%m-%d %H:%M:%S"   : 2026-09-01 15:38:59          ← ミリ秒が消える
default_msec_format="%s.%03d" : 2026-09-01 15:38:59.142      ← 上のテンプレート

障害調査は「どちらが先に起きたか」の勝負です。同じ秒に 10 行並ぶと順序が読めず、調査時間が延びます。

② StreamHandler(sys.stderr) を無条件に足していた。--noconsole の exe では sys.stderr が None になり、足すとログ 1 行ごとに AttributeError が起きて握り潰されます（実測は 7 章）。exe 化は PyInstaller の記事へ。

③ encoding と errors の指定漏れ。省くと日本語 Windows では cp932 に。表現できない文字が 1 つ混ざったときの実測です。

同じ書き忘れでも、FileHandler を直接作ったときだけ行が丸ごと消えます。実測で出たエラーです。

--- Logging error ---
Traceback (most recent call last):
  File "...\Lib\logging\__init__.py", line 1163, in emit
    stream.write(msg + self.terminator)
UnicodeEncodeError: 'cp932' codec can't encode character '\U0001f321'
in position 14: illegal multibyte sequence

PEP 686 が Final になり Python 3.15 から UTF-8 モードが既定になりますが、PYTHONUTF8=0 で無効化できます。今から明示するのが確実です（原理は cp932 と UTF-8 の記事）。

④ 相対パスのまま Path("logs") を渡していた。相対パスの基準となるカレントディレクトリは、タスクスケジューラや NSSM では呼び出し元が決めます。Path(__file__).parent 基準ならどこから起動しても同じ場所。ただし onefile の exe では __file__ が一時展開先を指すので、exe の隣に出すなら sys.executable の親を使います（PyInstaller 記事の 6 章）。

4. ログが出ない — 症状別早見表（11 症状）

「ログが出ない」「logging が出力されない」は、原因が分かれば数分、分からないと半日溶けます。最初に打つ 1 手はこれです。調査したいアプリの中（設定関数を呼んだ直後）に貼ってください。別ファイルで動かすと設定の無いプロセスになり、必ず「ハンドラなし」と出ます。

import logging
root = logging.getLogger()
print("root level     :", logging.getLevelName(root.level))
print("root handlers  :", root.handlers)
for h in root.handlers:
    print("  ", type(h).__name__, logging.getLevelName(h.level),
          getattr(h, "baseFilename", ""))
print("disable        :", logging.root.manager.disable)   # 0 以外なら 7 番

2 番の lastResort は切り分けが速くなります。ハンドラが無いとき、logging は最後の手段として WARNING 以上だけを sys.stderr に素の書式で出します（実測でも info は届かず後ろ 2 行だけ）。「INFO を出しているのに WARNING から上しか見えない」なら設定コードが実行されていません。

8 番も実測しました。同じハンドラオブジェクトを 2 回 addHandler しても重複チェックで 1 行のまま。設定関数を 2 回呼んで FileHandler を毎回作ると 2 行に。犯人はほぼ設定関数の二重呼び出しです。

5. ハンドラの選び方

WatchedFileHandler が Windows で使えないのは、手元の 3.12.10 の Lib/logging/handlers.py にそう書いてあるからです。

"This handler is not appropriate for use under Windows ... open files cannot be moved or renamed - logging opens the files with exclusive locks."

これは 8 章の伏線です。logging は排他ロックでファイルを開く——開いたままのファイルは改名できず、ローテーションは失敗しうるのです。

ネットワーク系ハンドラには共通の危険があります。公式 Cookbook いわく "almost any network-based handler can block"。「ERROR が出たら通知サービス（例: Slack）へ投げる自前ハンドラ」を素直に書くと、通知先の応答が遅い日は業務スレッドがログのたびに止まります。通知系は 9 章の QueueHandler で別スレッドに逃がしてください。

NTEventLogHandler について、初版の「登録に管理者権限が要る」を撤回します。自宅検証機（一般ユーザー権限・pywin32 312）では例外は出ず、イベント自体は Application ログに記録されました。ただし登録キーが作られず、本文はプレースホルダ表示のまま。正確には「管理者権限が無いと登録が黙って失敗し、記録は残るが本文が読めない」です。

6. レベル設計と無停止での切り替え

基準はシンプルです。DEBUG は調査時だけ、INFO は正常時の記録、WARNING は再接続やしきい値への接近、ERROR は機能の一部の失敗、CRITICAL はアプリ全体への影響。本番は INFO 以上にし、トラブル時だけ DEBUG へ落とせる仕掛けを入れます。

import logging, os
from pathlib import Path
from app.log_setup import setup_logging

# .strip() が地味に重要（下の cmd の罠対策）
LEVEL = os.environ.get("LOG_LEVEL", "INFO").strip().upper()
setup_logging(Path(__file__).parent / "logs",
              level=getattr(logging, LEVEL, logging.INFO))

cmd なら set LOG_LEVEL=DEBUG のあと app.exe、PowerShell なら $env:LOG_LEVEL = "DEBUG"。どちらもそのウィンドウ限りです。1 行にまとめると罠があります（os.environ.get("LOG_LEVEL") の中身を表示して確認）。

set LOG_LEVEL=DEBUG && python check.py    ->  'DEBUG '   ← 末尾にスペース
set LOG_LEVEL=DEBUG&& python check.py     ->  'DEBUG'
（.bat で 2 行に分ける）                   ->  'DEBUG'

&& の前のスペースが値に入ります。getattr(logging, "DEBUG ", ...) は見つからず INFO にフォールバックし、「DEBUG にしたのに出ない」となります。24 時間止められないアプリでは、設定ファイルを定期的に読み直して実行中に setLevel(...) を呼びます（ハンドラ側は 3.12 の getHandlerByName()）。

7. 例外の配線と、logging が黙る仕組み

この章が本記事で一番重要です。logging は、自分が失敗したことをアプリに教えません。

7.1 例外をログに流し込む 4 つの口

try で囲んだ範囲は logger.exception() で済みます（ERROR＋スタックトレース）。問題は囲っていない場所で、フックを 3 つ差し替えます（自宅検証機で 3 つとも発火を確認）。

# app/log_hooks.py — プロセス全体の例外を logging に流し込む
import logging
import sys
import threading

logger = logging.getLogger("app.unhandled")


def _on_exception(exc_type, exc_value, exc_tb):
    if issubclass(exc_type, KeyboardInterrupt):      # Ctrl+C は素通し
        sys.__excepthook__(exc_type, exc_value, exc_tb)
        return
    logger.critical("未捕捉の例外でプロセスが終了します",
                    exc_info=(exc_type, exc_value, exc_tb))


def _on_thread_exception(args):
    if issubclass(args.exc_type, SystemExit):
        return
    logger.error("スレッド %s で未捕捉の例外", args.thread.name,
                 exc_info=(args.exc_type, args.exc_value, args.exc_traceback))
    # args を保持しないこと（例外オブジェクトを溜めると参照循環になる）


def _on_unraisable(args):
    logger.error("デストラクタ等で例外が出ました: %r", args.object,
                 exc_info=(args.exc_type, args.exc_value, args.exc_traceback))


def install_hooks() -> None:
    sys.excepthook = _on_exception               # メインスレッドの未捕捉例外
    threading.excepthook = _on_thread_exception  # 別スレッドの未捕捉例外
    sys.unraisablehook = _on_unraisable          # __del__ など報告できない例外

setup_logging() の直後に install_hooks() を呼ぶだけです。別スレッドが死んでもメインは動き続けるので、threading.excepthook が無いと「なぜか収集だけ止まっている」という一番厄介な症状になります。4 つ目の口は GUI——tkinter のコールバック内の例外は上の 3 つのどれにも流れません（tkinter 記事の 6 章）。

7.2 logging 自身が失敗したときは、黙る

ローテーション失敗、文字コードで書けない、ディスク満杯——どれもアプリには伝わりません。ローテーション系ハンドラの emit は手元の 3.12.10 でこうです。

def emit(self, record):
    try:
        if self.shouldRollover(record):
            self.doRollover()
        logging.FileHandler.emit(self, record)
    except Exception:
        self.handleError(record)

失敗はすべて handleError に吸い込まれ、その docstring に設計意図が書いてあります。

"If raiseExceptions is false, exceptions get silently ignored. This is what is mostly wanted for a logging system - most users will not care about errors in the logging system."

「ログの失敗でアプリを止めない」という判断自体は正しいものです。問題は、代わりに何が起きているかを誰も見ていないこと。しかも handleError の入口は if raiseExceptions and sys.stderr:——sys.stderr が None なら raiseExceptions が True でも何も出ません。実測でも sys.stderr = None で例外も出力もゼロでした。

3 つ並べるとこうです——ログの失敗は例外にならない、握った内容は sys.stderr にしか出ない、--noconsole の exe には sys.stderr が無い。つまり現場に配った exe では、logging 自身から壊れた事実を知る手段が残りません。だから対策は①開発中はコンソール付きでビルドして --- Logging error --- を目視する、②ログの更新時刻とサイズを別系統で監視するの 2 つが要です。

8. マルチプロセスでローテーションは黙って壊れる

プロセスは別々に起動したアプリ、スレッドは 1 つのアプリの中の並行処理です。logging はスレッドセーフですが、プロセスセーフではありません——マルチプロセスで同じファイルに書く構成は公式に非対応です。

"logging to a single file from multiple processes is not supported, because there is no standard way to serialize access ..."（公式 Cookbook）

ただ「非対応です」で終わると何がどう壊れるか分かりません。実際に測りました。

8.1 壊れ方 1: 後発プロセスが、以後ずっとログを書かなくなる

同じ TimedRotatingFileHandler(when="S", interval=5, backupCount=50) を持つプロセスを 2 つ（先発 A・1 秒遅れて B）立ち上げ、同じファイルへ 30 秒間・毎 0.25 秒 1 行ずつ書かせました（両方とも 120 行）。6 回繰り返した結果です。

6 回中 5 回で、片方のプロセスは最初のローテーションを境に 1 行も書けなくなりました。消えた 100 行以上に、アプリ側へは例外も戻り値も返っていません。残る 1 回も 52 行が消えています。毎回結果が違い、6 回とも何らかの行が失われました（n=6）。安定して再現する壊れ方ではない点がやっかいです。

なぜ「以後ずっと」なのか。手元の 3.12.10 の doRollover は末尾がこうです。

    self.rotate(self.baseFilename, dfn)          # ← ここで失敗すると
    if self.backupCount > 0:
        for s in self.getFilesToDelete():
            os.remove(s)
    if not self.delay:
        self.stream = self._open()
    self.rolloverAt = self.computeRollover(currentTime)   # ← ここまで到達しない

次回ローテーション時刻の更新は関数の一番最後です。self.rotate() が例外を投げると rolloverAt は過去の時刻のまま固定され、次の 1 行でも shouldRollover は True、また失敗、という無限ループに入ります。しかも emit の try は doRollover() で抜けるため本来の書き込みに一度も到達しません。

--- Logging error ---
Traceback (most recent call last):
  File "...\Lib\logging\handlers.py", line 74, in emit
    self.doRollover()
  File "...\Lib\logging\handlers.py", line 446, in doRollover
    self.rotate(self.baseFilename, dfn)
  File "...\Lib\logging\handlers.py", line 115, in rotate
    os.rename(source, dest)
PermissionError: [WinError 32] プロセスはファイルにアクセスできません。
別のプロセスが使用中です。: '...\app.log' -> '...\app.log.2026-09-01_15-33-15'

8.2 壊れ方 2: 例外すら出さずに、ローテーションだけが永久に止まる

エラーが 1 行も出ない壊れ方もあります。doRollover の冒頭にはこの早期 return があります（3.12.10 で確認。3.11・3.13 も同じ構造）。

dfn = self.rotation_filename(self.baseFilename + "." +
                             time.strftime(self.suffix, timeTuple))
if os.path.exists(dfn):
    # Already rolled over.
    return

退避先のファイル名が既にあれば「もう誰かがローテーション済み」とみなして戻ります。この return も rolloverAt を更新する前にあります。退避先を先回りして作り、時刻を過ぎさせてから 3 行書いた結果です。

rolloverAt(前) : 15:38:40
  emit0: rolloverAt=15:38:40  now=15:38:41  shouldRollover=True
  emit1: rolloverAt=15:38:40  now=15:38:42  shouldRollover=True
  emit2: rolloverAt=15:38:40  now=15:38:43  shouldRollover=True
--- 結果 ---
r.log                       35 bytes  'before\nafter-0\nafter-1\nafter-2\n'
r.log.2026-09-01_15-38-35    0 bytes  ''

rolloverAt は 1 ミリも動かず、退避も起きず、全部が r.log に書かれ続けます。例外も --- Logging error --- も出ません。画面上は正常に見え、ファイルだけが backupCount を無視して伸びます。「ある日を境にローテーションだけが止まった」の正体です。

8.3 壊れ方 3: 別のプログラムがファイルを掴んでいる

プロセスが 1 つでも、他のプログラムがログファイルを開いていると改名に失敗します。RotatingFileHandler(maxBytes=200, backupCount=3) で測りました。ここで初版の記述を 1 つ撤回します。

初版では「犯人の定番は tail 系ツール（Get-Content -Wait 等）」と書いていましたが、自宅検証機では妨げませんでした。撤回します。実態は開いたときの「共有モード」次第で、Python の open() は既定で改名を許さないため読み取りで開いただけでも壊します。ウイルス対策ソフトのスキャンは当サイトでは検証できていません。

8.4 単一プロセスでもハマる仕様

• 初回のローテーション時刻は、既存ログファイルの更新時刻が基準です（公式: "the last modification time of an existing log file ... is used to compute when the next rotation will occur"）。実測では更新時刻を 3 日前にした app.log があると、1 行目を書いた瞬間にローテーションが走りました。
• 出力が無ければローテーションも起きません（公式: "rollover occurs only when emitting output"）。夜間ログを出さないアプリの日付が飛ぶ理由です。
• maxBytes か backupCount が 0 だと回りません。実測でどちらも退避ファイルが作られず本体が伸び続けました。
• 「毎日 0:00」が夜勤の真っ最中になるなら atTime=time(6, 0) で生産の切れ目に寄せられます（公式は初回計算にだけ使うとするが、実測では次回もその 24 時間後）。
• 再現しなかったもの: 前方一致する 2 系統で退避ファイルが誤削除される報告（CPython gh-93205）は 3.12.10 で再現しませんでした。

NSSM でサービス化しているなら、ローテーションの主体が二重になっていないかも確認を。AppRotateFiles は NSSM がリダイレクトした標準出力・標準エラーの機能で、アプリが自前に開いたファイルとは別系統です。1 つのファイルのローテーションを担当する主体は 1 つに絞る——これが 8 章の結論です（Windows サービス化の記事）。

8.5 もう壊れているときは、止めずに直せる

すでに壊れているなら --- Logging error --- の有無で型を見分けます（sys.stderr にだけ出ます。コンソール起動か NSSM の AppStderr で見ます・7.2）。出れば 8.1・8.3 型、出ないのに伸び続けていれば 8.2 型。前者は掴んでいる側を閉じる（業務アプリや監視ソフトのこともあるので、稼働中の PC では担当部門の確認を）、後者は同名の退避ファイルを改名すると、実測では次の 1 行で退避が走り rolloverAt も更新されました（再起動は不要）。壊れていた間の行は戻りません。

9. マルチプロセスのログを 1 ファイルに集約する — QueueHandler

8 章の結論を実装に落とすと、子プロセスはキューに積むだけ、ファイルを開くのは 1 プロセスだけになります。

import logging
import logging.handlers
import multiprocessing as mp
from pathlib import Path


def worker(log_queue: mp.Queue) -> None:
    """子プロセス側: ハンドラは QueueHandler だけにする"""
    root = logging.getLogger()
    root.handlers.clear()
    root.addHandler(logging.handlers.QueueHandler(log_queue))
    root.setLevel(logging.INFO)
    logging.getLogger(__name__).info("worker started")
    # ... 業務処理 ...


if __name__ == "__main__":
    mp.freeze_support()            # exe 化するなら必須。無いと子プロセスが無限に増える
    log_queue: mp.Queue = mp.Queue(-1)          # -1 は上限なし（詰まると際限なく溜まる）

    log_dir = Path(__file__).parent / "logs"
    log_dir.mkdir(parents=True, exist_ok=True)
    file_handler = logging.handlers.TimedRotatingFileHandler(
        log_dir / "app.log", when="midnight", backupCount=14,
        encoding="utf-8", errors="backslashreplace")
    file_handler.setFormatter(logging.Formatter(
        "%(asctime)s [%(levelname)s] %(processName)s %(name)s: %(message)s"))

    listener = logging.handlers.QueueListener(
        log_queue, file_handler, respect_handler_level=True)
    listener.start()
    try:
        procs = [mp.Process(target=worker, args=(log_queue,), name=f"worker-{i}")
                 for i in range(3)]
        for p in procs:
            p.start()
        for p in procs:
            p.join()
    finally:
        listener.stop()          # ← try/finally で必ず呼ぶ（9.1）

%(processName)s でどのプロセスの行かが分かります。respect_handler_level=True（3.5+）はリスナー側の各ハンドラのレベルを尊重する指定で、エラー専用ファイルを分けるなら必須です。親子関係のない別アプリ同士なら、プロセスごとにファイルを分けるのが最も確実です。

9.1 落とし穴 1: stop() を呼ばないと大量に消える

公式は "there may be some records still left on the queue, which won't be processed." と注意しています。「some records」がどれくらいか、2 万行を積んで即座に終了して測りました。

「some records」どころかほぼ全部でした。logging.shutdown() は atexit で自動登録されますが、QueueListener.stop() は自動では呼ばれません。異常終了まで守るなら atexit.register(listener.stop) も。落ちる直前の数千行は調査で最も価値が高い部分です（3.14 では with 文に対応。当サイトは 3.14 環境が無く未検証）。

9.2 落とし穴 2: リスナー側では例外情報が失われている

QueueHandler.prepare() はキューに載せる前にピクルできないものを消します。公式 logging.handlers は "sets the args, exc_info and exc_text attributes to None ..."。リスナー側から見えた値です。

exc_info=None  exc_text=None
msg='センサー読み出しに失敗\nTraceback (most recent call last):\n ...
     ZeroDivisionError: division by zero'

トレースバックは失われず msg に文字列として合体しています。ただし exc_info が None なので、10 章の JSON フォーマッタをリスナー側に置くと exc フィールドが出力されません。JSON へ整形するフォーマッタはキューに載せる前に付けるのが対処です。その場合はリスナー側のハンドラに Formatter を付けないこと。9 章のように asctime 付きのままだと前置きが被り、10.1 の ConvertFrom-Json が落ちます。

9.3 QueueHandler は「速くする道具」ではない

ここも初版を撤回します。初版には「業務スレッドはキューに積むだけで即時返るため、ログ起因の遅延がほぼゼロになります」と書いていました。ローカルファイル相手では成り立ちません。2 万行を 3 回ずつ測った中央値です。

キューを挟んだほうが 1.3 倍遅くなりました。ローカルのファイル書き込みはもともと速く、キューへの詰め込みと受け渡しのコストが上回るためです。QueueHandler を使う理由は速度ではなく、①複数プロセスを 1 ファイルへ集約する、②遅いハンドラで業務スレッドを止めない——この 2 つです。

3 行目は公式 HOWTO の Optimization 節の設定で、1 行あたり 2.3 µs（13%）削れました。毎秒 1,000 行を超える高頻度でしか意味がありません。logging._srcfile = None にすると %(filename)s や %(lineno)d が使えません。

import logging
logging._srcfile = None            # 呼び出し元のファイル名・行番号を取らない
logging.logThreads = False         # スレッド ID を取らない
logging.logProcesses = False       # プロセス ID を取らない
logging.logMultiprocessing = False
logging.logAsyncioTasks = False    # 3.12 以降

10. JSON Lines と PowerShell 集計

ログを集計対象として扱うなら、1 行 1 JSON の JSON Lines が扱いやすくなります。

import json
import logging
import logging.handlers
from pathlib import Path

log_dir = Path(__file__).parent / "logs"
log_dir.mkdir(parents=True, exist_ok=True)


class JsonFormatter(logging.Formatter):
    default_time_format = "%Y-%m-%dT%H:%M:%S"
    default_msec_format = "%s.%03d"          # これが無いとミリ秒が消える

    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "ts": self.formatTime(record),   # datefmt を渡さないのが要点
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
        }
        # extra={"ctx_xxx": ...} で渡された追加フィールドを拾う
        for key, value in record.__dict__.items():
            if key.startswith("ctx_"):
                payload[key[4:]] = value
        if record.exc_info:
            payload["exc_type"] = record.exc_info[0].__name__
            payload["exc"] = self.formatException(record.exc_info)
        # default=str: datetime 等の非 JSON 型が来ても落ちないように
        return json.dumps(payload, ensure_ascii=False, default=str)


handler = logging.handlers.RotatingFileHandler(
    log_dir / "app.jsonl", maxBytes=10 * 1024 * 1024, backupCount=5,
    encoding="utf-8")
handler.setFormatter(JsonFormatter())        # ← 忘れると JSON にならず、素の message だけが書かれる
logging.getLogger().addHandler(handler)
logging.getLogger().setLevel(logging.INFO)

logger = logging.getLogger("app.boot")
logger.info("machine started", extra={"ctx_lot": "L0001", "ctx_machine": "M-01"})
# -> {"ts": "2026-09-01T15:46:47.862", "level": "INFO", "logger": "app.boot",
#     "message": "machine started", "lot": "L0001", "machine": "M-01"}

ctx_ プレフィクスには理由があります。公式 logging は "The keys ... should not clash with the keys used by the logging system." と警告しており、予約済みの名前を extra で使うと例外になります。

extra={'message': ...}  ->  KeyError: "Attempt to overwrite 'message' in LogRecord"
extra={'name':    ...}  ->  KeyError: "Attempt to overwrite 'name' in LogRecord"
extra={'asctime': ...}  ->  KeyError: "Attempt to overwrite 'asctime' in LogRecord"
extra={'args':    ...}  ->  KeyError: "Attempt to overwrite 'args' in LogRecord"
extra={'ctx_lot': ...}  ->  OK

message や name は業務コードで自然に使いたくなる名前です。プレフィクスを 1 つ決めれば、この地雷を構造的に踏みません。

10.1 Windows 標準の道具で集計する

閉域網の現場 PC で jq や pandas が使えなくても、PowerShell だけで集計できます。ただし日本語を含むログでは -Encoding UTF8 が必須です。

Get-Content logs\app.jsonl -Encoding UTF8 | ConvertFrom-Json |
  Where-Object level -eq "ERROR" | Group-Object machine

Windows PowerShell 5.1（自宅検証機は 5.1.26100.9168）で設備ごとのエラー件数が出ました。省いた場合も測りました。

1 行目は初版のコマンドです。ASCII だけなら動きますが、日本語が 1 つ入ると ConvertFrom-Json : ':' または '}' ではなく無効なオブジェクトが渡されました。 になります（5.1 の Get-Content が既定で UTF-8 として読まないため）。製造現場のログには日本語が入るので -Encoding UTF8 は必須です。PowerShell 7 系は未確認です。

線引きを 1 つ。数値は SQLite、事象（起動・接続・失敗・復旧）はログ。「10 秒ごとの温度」をログに流すと、集計のたびにテキスト解析になります（グラフ化は pandas と Matplotlib の記事）。外部ライブラリが使えるなら structlog（26.1.0）や python-json-logger（4.2.0・import 名 pythonjsonlogger）が定番。loguru は 2026-09-01 時点で最新が 0.7.3（2024-12-06）です。

11. 肥大化と保管

初版の「毎秒 1 行のログを延々と書くと、1 ヶ月で数 GB に達します」を撤回します。出典も計算根拠も無い数字でした。3 章の書式で 2 万行を出力し、サイズを行数で割った実測値は 1 行 = 89.2 バイト（日本語なし。日本語を混ぜれば 1.5〜2 倍程度）。

※ 容量は 1 KB = 1,024 バイト換算（Windows のエクスプローラ表示と同じ基準）です。

毎秒 1 行なら月 220 MBで、「数 GB」は 1 桁大げさでした。数 GB に届くのは 10 Hz を 1 ヶ月か、1 Hz を 1 年放置したときです。この表があれば backupCount を勘で決めずに済みます（1 Hz・日次・14 世代なら常時 100 MB 程度）。量を減らす手は 3 つです。

• サマリ集約: 1 件ずつではなく「1 分ごとに件数・エラー数・最大値」に。これが最も効きます
• 退避ファイルを gzip 圧縮する: 公式 Cookbook の namer / rotator を使います。上の書式の 2 万行（1.70 MiB）が 198 KiB（11%・約 9 分の 1）になりました（文言の種類が少ないほどよく縮みます）
• ディスク残量を別系統で監視する: タスクスケジューラ ＋ shutil.disk_usage() の数行で十分です

DEBUG を出すと肥大化する、出さないと障害時に手がかりが無い——答えが MemoryHandler です。直近のレコードをメモリに溜め、指定レベル以上が来たときだけまとめて吐き出します。

import logging
import logging.handlers
from pathlib import Path

log_dir = Path(__file__).parent / "logs"
log_dir.mkdir(parents=True, exist_ok=True)     # 無いと FileNotFoundError

target = logging.handlers.RotatingFileHandler(
    log_dir / "app-debug.log", maxBytes=10 * 1024 * 1024, backupCount=3,
    encoding="utf-8", errors="backslashreplace")

# 直近 1000 件を保持し、ERROR が出た瞬間にまとめて書き出す
buffer = logging.handlers.MemoryHandler(
    capacity=1000, flushLevel=logging.ERROR, target=target)
buffer.setLevel(logging.DEBUG)
logging.getLogger().addHandler(buffer)

# 要点: ロガー側（2 章①の段）を DEBUG にしないと buffer に 1 行も届かない
lg = logging.getLogger("app.press")
lg.setLevel(logging.DEBUG)      # root ではなく、このロガーだけ下げる
                                # → 3 章のテンプレ（level=INFO）と併用しても app.log は INFO 以上のまま

実測では DEBUG 5 行の時点でファイルは 0 バイト、ERROR を 1 行出した瞬間に DEBUG 5 行 ＋ ERROR 1 行がまとめて書き込まれました。障害時だけ直前の詳細が残ります。ただし capacity 到達時と logging.shutdown() 時にも書き出され、最大 1000 件分のメモリを使います。

12. 設定を YAML / JSON に外出しする — dictConfig

配ったあとの「ログレベルだけ変えたい」に再ビルドは重すぎます。YAML か JSON に出せばテキストエディタで済みます。公式 logging.config は "future enhancements to configuration functionality will be added to dictConfig()" として fileConfig より dictConfig を勧めています。

# logging.yaml
version: 1
disable_existing_loggers: false      # ← 既定は true。ライブラリのログが消える
formatters:
  plain:
    format: "%(asctime)s [%(levelname)s] %(name)s: %(message)s"
handlers:
  file:
    class: logging.handlers.TimedRotatingFileHandler
    filename: logs/app.log           # 相対パス。下のローダーで絶対パスに差し替える
    when: midnight
    backupCount: 14
    encoding: utf-8
    errors: backslashreplace
    formatter: plain
    level: INFO
  queue:                             # 3.12 以降: 9 章の構成を宣言で書ける
    class: logging.handlers.QueueHandler
    handlers: [file]                 # ← リスナーに渡すハンドラを名前で指定
    respect_handler_level: true
loggers:
  urllib3:
    level: WARNING
root:
  level: INFO
  handlers: [queue]

import logging
import logging.config
from pathlib import Path

import yaml                      # PyYAML が入らないなら json で書いて json.load()

log_dir = Path(__file__).parent / "logs"
log_dir.mkdir(parents=True, exist_ok=True)    # dictConfig はフォルダを作ってくれない

with (Path(__file__).parent / "logging.yaml").open(encoding="utf-8") as f:
    cfg = yaml.safe_load(f)
cfg["handlers"]["file"]["filename"] = str(log_dir / "app.log")   # 絶対パスに差し替える
logging.config.dictConfig(cfg)

listener = logging.getHandlerByName("queue").listener   # 自動生成される（3.12 以降）
listener.start()                                        # ← 自動では開始しない
# 終了時: listener.stop()  ← 9.1 のとおり必須

最大の落とし穴は disable_existing_loggers です。公式は "If absent, this parameter defaults to True."——省略すると、それまでに作られた root 以外のロガーが全部無効化されます。実測でも既定のまま呼んだ直後に disabled が True に。設定ファイルには、まず disable_existing_loggers: false を書いてください。

queue キーは自宅検証機の 3.12.10 で確認しました。QueueListener は自動生成されますが、自動では開始されません（start() を呼ぶまでキューに溜まったままでした）。この YAML では default_msec_format を指定できず、ミリ秒は 3 章の .413 ではなく ,413 になります（実測）。logging.config.listen() は公式が "may open its users to a security risk" と明記しており、現場 PC では使わないこと。

13. 何を残し、どう調べるか

24 時間動くアプリで最低限そろえたいのは次の 6 種類。どれも「あとから時系列で突き合わせられるか」を基準に選びました。

粒度で迷ったら再接続は WARNING、失敗し続けたら ERROR（通信クライアントや シリアル通信で効きます）。ほかに守るのはロガー名をモジュール単位で分ける・絵文字や色を入れない・1 メッセージ 1 イベントの 3 つ。

障害時は Get-Content logs\app-error.log -Encoding UTF8 -Tail 50 → Select-String -Path logs\app.log -Pattern "15:33:" -Encoding UTF8 -Context 5,5 の順にたどり、最後に必ず --- Logging error --- を確認してください（sys.stderr にだけ出ます）。犯人が logging 自身のこともあります（7 章）。

14. おわりに — 検証範囲と撤回した記述

logging の難しさは API ではなく、失敗しても何も言わないという設計思想に尽きます。レベル判定が 2 段あることも、ローテーションが黙って止まることも「アプリを止めないため」の代償です。だからこそログが壊れたことに気づく仕掛け——更新時刻の監視・--- Logging error --- の確認・開く主体を 1 つに絞ること——を先に組み込みます。

検証範囲: 実測はすべて自宅検証機（Windows 11 Pro ビルド 26200 / Python 3.12.10 / Windows PowerShell 5.1.26100.9168 / pywin32 312）での 2026-09-01 時点の結果です。未検証は、PowerShell 7 系、Python 3.14 の QueueListener、ウイルス対策ソフトのファイルロック、Linux 環境です。

次に読む 1 本はここで設計したログを持ったまま現場 PC に配る話です → PyInstaller で exe 化して配布する（7 章で塞いだ sys.stderr is None がそのまま次のテーマになります）。

⚠️ 実機適用時の注意: 本記事のコードと数値は自宅検証機での確認に基づくもので、ログの取得はアプリの動作を保証する仕組みではありません。実際の設備・現場 PC に適用するときは、①対象の PC とネットワークについて設備保全部門・情報システム部門の承認を得る、②ログ出力先ディスクの残量とアクセス権を確認する（満杯でもアプリは落ちず、ログだけが静かに欠けます）、③記録内容に個人情報・取引先情報が混入していないか社内規程と照合する、④死活監視はログの有無に頼らず別系統でも行う、⑤本番投入前に 1 週間以上の連続稼働でローテーションが 7 回とも成功することを確認する——この 5 点が前提です。ログ設計は、安全インターロック・安全 PLC・法定の警報装置の代替にはなりません。適用による設備の停止・データ欠損・機会損失について、筆者・GenbaPy は責任を負いません。