- Python
- 技術 💻
Python loggingの使い方|用途別コピペ設定集と出ない原因
Pythonのloggingとは、プログラムの動きを「いつ・どこで・どの重要度で」記録するための標準ライブラリです。print と違い、重要度(レベル)で出す・出さないを切り替えられ、画面とファイルへの同時出力、ファイルのローテーション(一定サイズや日付で切り替えること)、JSON形式での出力まで、設定だけで変えられます。
この記事は、「スクリプト用」「アプリ用」「ライブラリ用」など用途別に、そのまま貼って使える設定をまとめたものです。すべて Python 3.14.7 で実行し、実際のログ出力を載せています。後半では 「ログが出ない」「二重に出る」原因を、実際に再現して直し方を示します。3.12〜3.14で増えた機能(taskName、dictConfig でのキュー設定、QueueListener の with 対応)も確認しました。
用途別 logging設定の早見表
| やりたいこと | 書き方 | 節 |
|---|---|---|
| 1ファイルのスクリプトで手早く出す | logging.basicConfig(level=logging.INFO, format=...) |
1 |
| アプリの各モジュールで使う | logger = logging.getLogger(__name__) |
2 |
| 画面とファイルの両方に出す | StreamHandler と FileHandler を両方 addHandler |
3 |
| サイズでファイルを切り替える | RotatingFileHandler(maxBytes=, backupCount=) |
4 |
| 日付でファイルを切り替える | TimedRotatingFileHandler(when="midnight", backupCount=) |
4 |
| 設定をファイル(YAML・dict)にまとめる | logging.config.dictConfig(設定) |
5 |
| JSON形式で出す(標準ライブラリのみ) | Formatter を継承して json.dumps |
6 |
| 例外をトレースバックつきで残す | logger.exception("...") / exc_info=True |
7 |
| 項目(リクエストIDなど)を足す | extra={...} / Filter / LoggerAdapter |
8 |
| ライブラリを作る | logging.getLogger(__name__).addHandler(logging.NullHandler()) |
9 |
| マルチスレッドで安全・高速に出す | QueueHandler + QueueListener |
10 |
| 非同期タスク名を出す(3.12+) | %(taskName)s |
11 |
| 設定し直す | logging.basicConfig(..., force=True) |
12 |
本記事の内容は、ご自由にお使いください。
ご利用の際は、出典として本ページへのリンクを記載いただけますようお願いします。
(記載例)出典:株式会社RJC「Python loggingの使い方|用途別コピペ設定集と出ない原因」
loggingの仕組みを1分で
loggingは「ロガー → ハンドラ → フォーマッタ」の3つで動きます。
| 部品 | 役割 | 例 |
|---|---|---|
| ロガー(Logger) | ログを受け付ける窓口。名前で階層になる(app の子が app.db) |
logging.getLogger("app.db") |
| ハンドラ(Handler) | 出力先を決める | StreamHandler(画面)、FileHandler(ファイル) |
| フォーマッタ(Formatter) | 1行の見た目を決める | "%(asctime)s %(levelname)s %(message)s" |
| レベル | 重要度。ロガーとハンドラの両方でしきい値を持つ | DEBUG < INFO < WARNING < ERROR < CRITICAL |
flowchart LR
A["logger.info()"] --> B{"ロガーのレベル以上?"}
B -- いいえ --> X["捨てる"]
B -- はい --> C["自分のハンドラ"]
C --> D{"ハンドラのレベル以上?"}
D -- はい --> E["フォーマットして出力"]
B -- はい --> F{"propagate=True?"}
F -- はい --> G["親ロガーのハンドラへ(最後は root)"]
ロガーは親(最終的には root)のハンドラにもログを渡します(propagate)。この仕組みを知っておくと、後半の「二重に出る」原因がすぐわかります。レベルの使い分けは、ざっくり次のとおりです。
| レベル | 使いどころ |
|---|---|
| DEBUG | 開発中だけ見たい細かい値 |
| INFO | 正常な処理の節目(起動、完了、件数) |
| WARNING | 処理は続くが気にしてほしいこと(既定のしきい値) |
| ERROR | その処理が失敗したこと |
| CRITICAL | アプリ全体が続けられないこと |
1. スクリプト用:basicConfigで最短設定
1ファイルのスクリプトなら、basicConfig を1回呼ぶだけで十分です。
import logging
logging.basicConfig(
level=logging.INFO,
format="%(asctime)s %(levelname)-8s %(name)s: %(message)s",
datefmt="%Y-%m-%d %H:%M:%S",
)
logger = logging.getLogger(__name__)
logger.debug("これは出ない(INFOより低い)")
logger.info("処理を開始します 件数=%d", 3)
logger.warning("在庫が少なくなっています item=%s", "pen")
logger.error("保存に失敗しました")
2026-09-29 13:02:23 INFO __main__: 処理を開始します 件数=3
2026-09-29 13:02:23 WARNING __main__: 在庫が少なくなっています item=pen
2026-09-29 13:02:23 ERROR __main__: 保存に失敗しました
メッセージの値は f文字列ではなく "件数=%d", 3 のように引数で渡すのがおすすめです。レベルで捨てられたログは文字列の組み立て自体が行われないため、DEBUGログを大量に書いても本番では軽く済みます。
2. アプリ用:モジュールごとに getLogger(name)
各モジュールでは logging.getLogger(__name__) でロガーを取り、設定(basicConfigなど)はエントリーポイントで1回だけ行います。__name__ を使うと、ロガー名がモジュールのパス(app.db など)になり、どこから出たログかが一目でわかります。
# app/db.py
import logging
logger = logging.getLogger(__name__) # "app.db"
def save(order_id):
logger.debug("SQLを実行 order_id=%s", order_id)
logger.info("保存しました order_id=%s", order_id)
# app/main.py
import logging
from app import db
logger = logging.getLogger(__name__) # "app.main"
def main():
logging.basicConfig(
level=logging.INFO,
format="%(levelname)s %(name)s %(funcName)s:%(lineno)d %(message)s",
)
logging.getLogger("app.db").setLevel(logging.DEBUG) # db だけ詳しく
logger.info("起動しました")
db.save(101)
if __name__ == "__main__":
main()
$ python -m app.main
INFO __main__ main:12 起動しました
DEBUG app.db save:6 SQLを実行 order_id=101
INFO app.db save:7 保存しました order_id=101
app.db だけ DEBUG にする、といった調整がロガー名で自由にできます。なお、実行したファイル自身の __name__ は __main__ になります。
3. 画面とファイルの両方に出す
出力先ごとにハンドラを作り、それぞれにレベルとフォーマッタを設定します。ファイルには encoding="utf-8" を必ず付けます。
import logging
import sys
fmt = logging.Formatter("%(asctime)s %(levelname)s %(name)s: %(message)s")
console = logging.StreamHandler(sys.stdout)
console.setLevel(logging.INFO)
console.setFormatter(fmt)
file = logging.FileHandler("app.log", encoding="utf-8")
file.setLevel(logging.DEBUG)
file.setFormatter(fmt)
logger = logging.getLogger("app")
logger.setLevel(logging.DEBUG)
logger.addHandler(console)
logger.addHandler(file)
logger.debug("詳細はファイルにだけ出す")
logger.info("画面とファイルの両方に出す")
(画面)
2026-09-29 13:02:32,913 INFO app: 画面とファイルの両方に出す
(app.log)
2026-09-29 13:02:32,913 DEBUG app: 詳細はファイルにだけ出す
2026-09-29 13:02:32,913 INFO app: 画面とファイルの両方に出す
ロガーは DEBUG で全部通し、ハンドラ側で「画面は INFO 以上、ファイルは全部」と分けるのが定番の形です。
4. ログファイルをローテーションする
サイズで切り替える(RotatingFileHandler)
import logging
from logging.handlers import RotatingFileHandler
handler = RotatingFileHandler(
"rotate.log", maxBytes=200, backupCount=3, encoding="utf-8"
)
handler.setFormatter(logging.Formatter("%(levelname)s %(message)s"))
logger = logging.getLogger("rotate")
logger.setLevel(logging.INFO)
logger.addHandler(handler)
for i in range(1, 21):
logger.info("注文を処理しました order_id=%03d", i)
$ ls -1 rotate.log*
rotate.log
rotate.log.1
rotate.log.2
rotate.log.3
$ cat rotate.log
INFO 注文を処理しました order_id=017
INFO 注文を処理しました order_id=018
INFO 注文を処理しました order_id=019
INFO 注文を処理しました order_id=020
$ head -2 rotate.log.3
INFO 注文を処理しました order_id=005
INFO 注文を処理しました order_id=006
backupCount=3 なので、.1〜.3 の3世代より前の分(order_id=001〜004)は自動で削除されています。maxBytes はバイト数です(UTF-8の日本語は1文字3バイト)。本番では maxBytes=10 * 1024 * 1024(10MB)などにします。
日付・時刻で切り替える(TimedRotatingFileHandler)
import logging
import time
from logging.handlers import TimedRotatingFileHandler
# 本番では when="midnight", backupCount=30 など。ここでは確認用に1秒ごと
handler = TimedRotatingFileHandler(
"timed.log", when="S", interval=1, backupCount=5, encoding="utf-8"
)
handler.setFormatter(logging.Formatter("%(asctime)s %(message)s"))
logger = logging.getLogger("timed")
logger.setLevel(logging.INFO)
logger.addHandler(handler)
for i in range(3):
logger.info("tick %d", i)
time.sleep(1.1)
$ ls -1 timed.log*
timed.log
timed.log.2026-09-29_13-02-33
timed.log.2026-09-29_13-02-34
切り替え済みのファイルには日時の接尾辞が付きます。when は "S"(秒)"M"(分)"H"(時)"D"(日)"midnight"(毎日0時)"W0"〜"W6"(曜日)から選べます。
| 選び方 | 向いているハンドラ |
|---|---|
| ディスク容量の上限を決めたい | RotatingFileHandler |
| 「何日分残す」で管理したい、日付で探したい | TimedRotatingFileHandler(when="midnight") |
| 複数プロセスが同じファイルに書く | どちらも非対応。プロセスごとにファイルを分けるか、QueueHandler(節10)で1か所に集める |
5. dictConfigで設定をファイルにまとめる(YAML)
ハンドラが増えてきたら、設定を dictConfig にまとめると見通しがよくなります。YAMLで書く場合は pip install pyyaml が必要です。
# logging.yaml
version: 1
disable_existing_loggers: false
formatters:
simple:
format: "%(asctime)s %(levelname)s %(name)s: %(message)s"
handlers:
console:
class: logging.StreamHandler
level: INFO
formatter: simple
stream: ext://sys.stdout
file:
class: logging.handlers.RotatingFileHandler
level: DEBUG
formatter: simple
filename: yaml_app.log
maxBytes: 1048576
backupCount: 5
encoding: utf-8
loggers:
app:
level: DEBUG
handlers: [console, file]
propagate: false
root:
level: WARNING
handlers: [console]
import logging.config
import yaml # pip install pyyaml
with open("logging.yaml", encoding="utf-8") as f:
logging.config.dictConfig(yaml.safe_load(f))
logging.getLogger("app.order").debug("ファイルだけ")
logging.getLogger("app.order").info("画面とファイル")
logging.getLogger("other").info("rootはWARNING以上なので出ない")
logging.getLogger("other").warning("rootのconsoleに出る")
(画面)
2026-09-29 13:02:46,645 INFO app.order: 画面とファイル
2026-09-29 13:02:46,645 WARNING other: rootのconsoleに出る
(yaml_app.log)
2026-09-29 13:02:46,645 DEBUG app.order: ファイルだけ
2026-09-29 13:02:46,645 INFO app.order: 画面とファイル
disable_existing_loggers: false は必ず書きます。既定の true のままだと、dictConfig より前に import したモジュールのロガーが無効になり、ログが出なくなります。propagate: false は、app のログが root の console にも流れて二重に出るのを防ぐためです。YAMLを使わない場合は、同じ構造の Python の dict をそのまま dictConfig に渡せます(節10に例があります)。
6. JSON形式でログを出す(標準ライブラリだけで)
ログ収集サービスで検索・集計するなら、1行1JSONが扱いやすい形式です。外部ライブラリなしで、Formatter を継承して作れます。
import json
import logging
import sys
from datetime import datetime, timezone
# LogRecord が標準で持つ属性(これ以外を extra とみなす)
STANDARD = set(logging.makeLogRecord({}).__dict__) | {"message", "asctime"}
class JsonFormatter(logging.Formatter):
def format(self, record):
data = {
"time": datetime.fromtimestamp(record.created, timezone.utc).isoformat(timespec="milliseconds"),
"level": record.levelname,
"logger": record.name,
"message": record.getMessage(),
}
# extra= で渡した項目を追加
data.update({k: v for k, v in record.__dict__.items() if k not in STANDARD})
if record.exc_info:
data["exception"] = self.formatException(record.exc_info)
return json.dumps(data, ensure_ascii=False, default=str)
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(JsonFormatter())
logger = logging.getLogger("api")
logger.setLevel(logging.INFO)
logger.addHandler(handler)
logger.info("注文を受け付けました", extra={"order_id": 101, "member": "sato"})
try:
1 / 0
except ZeroDivisionError:
logger.exception("計算に失敗しました", extra={"order_id": 102})
{"time": "2026-09-29T04:05:40.389+00:00", "level": "INFO", "logger": "api", "message": "注文を受け付けました", "order_id": 101, "member": "sato"}
{"time": "2026-09-29T04:05:40.389+00:00", "level": "ERROR", "logger": "api", "message": "計算に失敗しました", "order_id": 102, "exception": "Traceback (most recent call last):\n File \"/work/ex06_json.py\", line 31, in <module>\n 1 / 0\n ~~^~~\nZeroDivisionError: division by zero"}
(ファイルのパスは /work に短縮しています。)トレースバックも1つの文字列に収まるので、複数行に分かれて検索しにくくなることがありません。ensure_ascii=False で日本語をそのまま出しています。
7. 例外をトレースバックつきで記録する
except の中では logger.exception() を使うと、ERRORレベルでトレースバック(どこで失敗したかの履歴)まで残せます。
import logging
logging.basicConfig(level=logging.INFO, format="%(levelname)s %(message)s")
logger = logging.getLogger(__name__)
def load(order_id):
return {"101": 3}[order_id]
try:
load("999")
except KeyError:
logger.exception("読み込みに失敗 order_id=%s", "999") # ERROR + トレースバック
try:
load("999")
except KeyError:
logger.warning("見つからないので既定値を使う", exc_info=True) # WARNING + トレースバック
try:
load("999")
except KeyError as e:
logger.error("読み込みに失敗: %r", e) # トレースバックなし
ERROR 読み込みに失敗 order_id=999
Traceback (most recent call last):
File "/work/ex07_exc.py", line 10, in <module>
load("999")
~~~~^^^^^^^
File "/work/ex07_exc.py", line 7, in load
return {"101": 3}[order_id]
~~~~~~~~~~^^^^^^^^^^
KeyError: '999'
WARNING 見つからないので既定値を使う
Traceback (most recent call last):
(同じトレースバックのため省略)
KeyError: '999'
ERROR 読み込みに失敗: KeyError('999')
| 書き方 | レベル | トレースバック |
|---|---|---|
logger.exception("...") |
ERROR | あり(except の中で使う) |
logger.warning("...", exc_info=True) |
任意 | あり |
logger.error("...: %r", e) |
ERROR | なし(どこで起きたかが残らない) |
原因を調べるときに必要なのは行番号つきのトレースバックです。予期しない例外は logger.exception() で残しておくと、あとから追いやすくなります。
8. extraで項目(リクエストIDなど)を追加する
extra で渡した値は %(名前)s で書式に使えます。ただし、書式に入れた項目を渡し忘れると、ログそのものが出ずにエラーが表示されます。
import logging
logging.basicConfig(level=logging.INFO,
format="%(levelname)s [req=%(request_id)s] %(message)s")
logger = logging.getLogger(__name__)
logger.info("注文を受け付けました", extra={"request_id": "a1b2"})
logger.info("extra を渡し忘れた")
INFO [req=a1b2] 注文を受け付けました
--- Logging error ---
Traceback (most recent call last):
File "…/logging/__init__.py", line 472, in format
(中略)
KeyError: 'request_id'
During handling of the above exception, another exception occurred:
(中略)
ValueError: Formatting field not found in record: 'request_id'
Call stack:
File "/work/ex08_extra.py", line 8, in <module>
logger.info("extra を渡し忘れた")
Message: 'extra を渡し忘れた'
Arguments: ()
毎回渡すのではなく、Filter で全レコードに自動で足す、Formatter の defaults(3.10+)で既定値を決める、LoggerAdapter で固定値を付ける、の3つを組み合わせると漏れがなくなります。
import contextvars
import logging
import sys
request_id = contextvars.ContextVar("request_id", default="-")
class RequestIdFilter(logging.Filter):
def filter(self, record):
record.request_id = request_id.get() # 全レコードに項目を足す
return True
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(logging.Formatter(
"%(levelname)s [req=%(request_id)s] [member=%(member)s] %(message)s",
defaults={"member": "-"}, # 3.10+: 渡されなかったときの値
))
handler.addFilter(RequestIdFilter())
logger = logging.getLogger("api")
logger.setLevel(logging.INFO)
logger.addHandler(handler)
logger.info("起動しました") # 何も渡さなくてもエラーにならない
request_id.set("a1b2")
logger.info("注文を受け付けました", extra={"member": "sato"})
# LoggerAdapter: 決まった項目を毎回付ける(merge_extra は 3.13+)
adapter = logging.LoggerAdapter(logger, {"member": "suzuki"}, merge_extra=True)
adapter.info("在庫を確認しました")
INFO [req=-] [member=-] 起動しました
INFO [req=a1b2] [member=sato] 注文を受け付けました
INFO [req=a1b2] [member=suzuki] 在庫を確認しました
contextvars(処理の流れごとに値を持てる標準ライブラリ)を使うと、Webアプリのリクエストや非同期タスクごとに別のIDを自動で出せます。
9. ライブラリ用:NullHandlerだけを付ける
ライブラリ(他の人が import して使うパッケージ)では、ハンドラやレベルを設定せず、NullHandler だけを付けます。出力先を決めるのは、使う側のアプリだからです。
import logging
# --- ライブラリ側(mylib/__init__.py を想定)---
lib_logger = logging.getLogger("mylib")
def work():
lib_logger.info("内部の処理(INFO)")
lib_logger.warning("設定が見つからないので既定値を使います")
print("① NullHandler なし・アプリ側も未設定")
work()
print("② NullHandler あり")
lib_logger.addHandler(logging.NullHandler())
work()
print("③ アプリ側で設定すると表示される")
logging.basicConfig(level=logging.INFO, format="%(levelname)s %(name)s: %(message)s")
work()
① NullHandler なし・アプリ側も未設定
設定が見つからないので既定値を使います
② NullHandler あり
③ アプリ側で設定すると表示される
INFO mylib: 内部の処理(INFO)
WARNING mylib: 設定が見つからないので既定値を使います
①では、どこにもハンドラがないため「最後の手段」のハンドラ(logging.lastResort)が WARNING 以上を書式なしで標準エラーに出しています。②の NullHandler を付けると、アプリ側が設定するまで何も出ません。③のようにアプリ側で設定すれば、ライブラリのログも同じ書式で出ます。ライブラリの中で basicConfig を呼ばないのも大切です(次の「出ない原因」の②につながります)。
10. マルチスレッド:QueueHandlerで1か所から書き出す
QueueHandler は、ログをキュー(順番待ちの列)に入れるだけの軽いハンドラです。実際の書き出しは QueueListener の専用スレッドが行うため、ファイル書き込みの待ち時間で各スレッドが止まりません。
import logging
import queue
import sys
import threading
from logging.handlers import QueueHandler, QueueListener
q = queue.Queue(-1) # 上限なし
out = logging.StreamHandler(sys.stdout) # 実際に書き出すハンドラ
out.setFormatter(logging.Formatter("%(threadName)s %(levelname)s %(message)s"))
root = logging.getLogger()
root.setLevel(logging.INFO)
root.addHandler(QueueHandler(q)) # 各スレッドはキューに入れるだけ
def worker(n):
logging.getLogger("worker").info("タスク%d 完了", n)
# 3.14+: with で start()/stop() を自動化(3.13以前は listener.start() と listener.stop())
with QueueListener(q, out, respect_handler_level=True):
threads = [threading.Thread(target=worker, args=(i,), name=f"T{i}") for i in range(3)]
for t in threads:
t.start()
for t in threads:
t.join()
T0 INFO タスク0 完了
T1 INFO タスク1 完了
T2 INFO タスク2 完了
同じコードを Python 3.13.7 で実行すると、with の行で次のエラーになります。3.13以前では listener.start() と、終了時の listener.stop() を自分で呼びます。
TypeError: 'QueueListener' object does not support the context manager protocol
Python 3.12 からは dictConfig でも書けます。作られたリスナーは logging.getHandlerByName()(3.12+)で取り出し、自分で開始します。
import logging
import logging.config
logging.config.dictConfig({
"version": 1,
"formatters": {"simple": {"format": "%(levelname)s %(name)s: %(message)s"}},
"handlers": {
"console": {"class": "logging.StreamHandler", "formatter": "simple",
"stream": "ext://sys.stdout"},
"file": {"class": "logging.FileHandler", "formatter": "simple",
"filename": "queue_app.log", "encoding": "utf-8"},
"queue": {"class": "logging.handlers.QueueHandler", # 3.12+
"handlers": ["console", "file"]},
},
"root": {"level": "INFO", "handlers": ["queue"]},
})
qh = logging.getHandlerByName("queue") # 3.12+
print(type(qh.listener).__name__)
qh.listener.start() # リスナーは自分で開始する
logging.getLogger("app").info("キュー経由で出力")
qh.listener.stop() # 終了時に残りを書き出す
QueueListener
INFO app: キュー経由で出力
(queue_app.log)
INFO app: キュー経由で出力
Python 3.11 で同じ設定を読み込むと ValueError: Unable to configure handler 'queue' になりました。キューの dictConfig は 3.12 以降で使います。
11. 3.12〜3.14で増えた便利な機能
| バージョン | 追加されたもの | 使いどころ |
|---|---|---|
| 3.12 | %(taskName)s(asyncio のタスク名) |
非同期処理でどのタスクのログかを出す |
| 3.12 | logging.getHandlerByName() / getHandlerNames() |
dictConfig で作ったハンドラを名前で取り出す |
| 3.12 | dictConfig で QueueHandler / QueueListener を設定 |
節10 |
| 3.13 | LoggerAdapter(..., merge_extra=True) |
固定の項目と呼び出し時の extra を両方出す(節8) |
| 3.14 | QueueListener を with で使える |
節10 |
import asyncio
import logging
logging.basicConfig(level=logging.INFO, format="%(taskName)s %(message)s") # 3.12+
async def fetch(n):
logging.info("取得開始 %d", n)
async def main():
async with asyncio.TaskGroup() as tg:
tg.create_task(fetch(1), name="fetch-1")
tg.create_task(fetch(2), name="fetch-2")
asyncio.run(main())
fetch-1 取得開始 1
fetch-2 取得開始 2
12. ログが出ない・二重に出る原因と直し方(実際に再現)
まずこの表で当てはまるものを探してください。
| 症状 | 原因 | 直し方 |
|---|---|---|
| INFO・DEBUG が出ない(WARNINGは出る) | ① 何も設定していない(既定は WARNING) | basicConfig(level=logging.INFO) かハンドラを設定 |
| basicConfig の設定が効かない | ② すでに root にハンドラがある(2回目の basicConfig は何もしない) | basicConfig(..., force=True) |
| 同じログが2回、3回と増える | ③ 同じロガーにハンドラを何度も追加 | if not logger.handlers: で1回だけ追加 |
| 同じログが書式違いで2回出る | ④ 子ロガーと root の両方にハンドラ(propagate) | 子に propagate = False、またはハンドラを root だけに |
| ロガーを DEBUG にしても出ない | ハンドラのレベルが高い(ロガーを通ってもハンドラで落ちる) | ハンドラ側の setLevel も確認 |
| print とログの順番が入れ替わる | ⑤ print は stdout、ログは stderr(バッファが別) | ログも stream=sys.stdout に、または python -u |
① 何も設定していない
import logging
logger = logging.getLogger(__name__)
logger.info("① 設定なしの INFO") # 出ない
logger.warning("② 設定なしの WARNING") # 書式なしで stderr に出る
logger.setLevel(logging.DEBUG)
logger.info("③ ロガーだけ DEBUG にした INFO") # まだ出ない(ハンドラがない)
② 設定なしの WARNING
ハンドラがどこにもないときは lastResort(WARNING以上だけを出す)が使われます。ロガーのレベルを下げるだけでは足りず、ハンドラの設定が必要です。
② basicConfig が2回目以降に効かない
import logging
logging.warning("先にモジュール関数で1回ログを出す") # ここで暗黙に basicConfig される
logging.basicConfig(level=logging.INFO, format="[%(levelname)s] %(message)s")
logging.info("INFO が出ない・書式も変わらない")
logging.basicConfig(level=logging.INFO, format="[%(levelname)s] %(message)s", force=True)
logging.info("force=True で設定し直すと出る")
WARNING:root:先にモジュール関数で1回ログを出す
[INFO] force=True で設定し直すと出る
logging.warning() などのモジュール関数は、root にハンドラがないと自動で basicConfig() を呼びます。そのあとの basicConfig は何もしません。import したライブラリが先に呼んでいる場合も同じです。force=True(3.8+)で既存のハンドラを外して設定し直せます。
③ ハンドラを何度も追加している
import logging
import sys
def get_logger():
logger = logging.getLogger("app")
logger.setLevel(logging.INFO)
logger.addHandler(logging.StreamHandler(sys.stdout)) # 呼ぶたびに追加される
return logger
get_logger().info("1回目")
get_logger().info("2回目")
print("handlers:", len(logging.getLogger("app").handlers))
def get_logger_fixed():
logger = logging.getLogger("app2")
logger.setLevel(logging.INFO)
if not logger.handlers: # 1回だけ追加
logger.addHandler(logging.StreamHandler(sys.stdout))
return logger
get_logger_fixed().info("修正後 1回目")
get_logger_fixed().info("修正後 2回目")
1回目
2回目
2回目
handlers: 2
修正後 1回目
修正後 2回目
getLogger は同じ名前なら同じロガーを返すため、関数を呼ぶたびにハンドラが増えます。Jupyter でセルを再実行したときも同じことが起きます。
④ 子ロガーと root の両方にハンドラがある(propagate)
import logging
import sys
logging.basicConfig(level=logging.INFO, format="root : %(message)s", stream=sys.stdout)
child = logging.getLogger("app")
h = logging.StreamHandler(sys.stdout)
h.setFormatter(logging.Formatter("app : %(message)s"))
child.addHandler(h)
child.info("二重に出る") # app のハンドラ → 親(root)のハンドラ の順に出る
child.propagate = False
child.info("propagate=False で1回だけ")
app : 二重に出る
root : 二重に出る
app : propagate=False で1回だけ
基本は「ハンドラは root(またはアプリの最上位ロガー)にだけ付け、各モジュールは getLogger するだけ」にすると、二重出力は起きません。
⑤ print とログの順番が入れ替わる
import logging
logging.basicConfig(level=logging.INFO, format="LOG %(message)s") # 既定は stderr
print("PRINT 1")
logging.info("2")
print("PRINT 3")
logging.info("4")
$ python tr5_print.py # 画面ではコードの順
PRINT 1
LOG 2
PRINT 3
LOG 4
$ python tr5_print.py > out.txt 2>&1 ; cat out.txt
LOG 2
LOG 4
PRINT 1
PRINT 3
ファイルやパイプに出すと、stdout(print)はまとめて書き出される(バッファリング)ため、stderr(ログ)が先に出ます。ログも stream=sys.stdout にそろえる、python -u や環境変数 PYTHONUNBUFFERED=1 でバッファリングを止める、そもそも出力をすべて logging に統一する、のいずれかで順番がそろいます(今回の確認環境は PYTHONUNBUFFERED=1 が既定だったため、外して実行しています)。
よくある質問
Q. print ではなく logging を使う利点は何ですか? A. コードを消さずにレベルで出し分けられる、時刻やモジュール名が自動で付く、出力先(画面・ファイル・JSON)を設定だけで変えられることです。開発中の確認は DEBUG で書いておき、本番では INFO 以上だけを出す、といった運用ができます。
Q. f文字列でメッセージを書いてもよいですか?
A. 動きますが、logger.debug("id=%s", x) のように引数で渡す書き方がおすすめです。捨てられるレベルのログでは文字列の組み立てが行われず、ログ収集サービスでも同じメッセージをまとめて集計しやすくなります。
Q. 設定はどこに書けばよいですか?
A. アプリの入口(main() や if __name__ == "__main__": の中)で1回だけ書きます。各モジュールは logging.getLogger(__name__) だけにし、ライブラリには NullHandler 以外を付けません。
Q. 複数プロセスで1つのログファイルに書いても大丈夫ですか?
A. 標準の FileHandler や RotatingFileHandler は、複数プロセスからの同時書き込みを想定していません。プロセスごとにファイルを分けるか、QueueHandler で1つのプロセスに集めて書き出す形にします。
まとめ
- loggingは「ロガー → ハンドラ → フォーマッタ」。レベルはロガーとハンドラの両方で判定される
- スクリプトは
basicConfig、アプリは各モジュールでgetLogger(__name__)、設定は入口で1回 - ローテーションは サイズなら
RotatingFileHandler、日付ならTimedRotatingFileHandler(when="midnight") - 設定が増えたら
dictConfig(YAML可)。disable_existing_loggers: falseを忘れずに - 例外は
logger.exception()でトレースバックごと残す - ライブラリは
NullHandlerだけ。出力先はアプリ側が決める - 出ない・二重に出るときは レベル、basicConfig の2回目(
force=True)、ハンドラの重複、propagate の順に確認する
本記事の内容は、ご自由にお使いください。
ご利用の際は、出典として本ページへのリンクを記載いただけますようお願いします。
(記載例)出典:株式会社RJC「Python loggingの使い方|用途別コピペ設定集と出ない原因」
株式会社RJCでは、動いているシステムの様子をログから読み取り、改善につなげる力を、プロジェクトの中で仲間と学び合っています。こうした知識を共有しながら、日々技術を磨いています。
株式会社RJC ― SI事業・SES事業・AI駆動開発。RJCは一緒に成長を楽しめる会社です。
WE ARE HIRING
RJCで一緒に開発しながら、
成長を楽しみませんか?
RJCは、Web・モバイル・AIを活用した開発プロジェクトで、テックリードやPM・PMOも活躍するシステム開発会社です。会社を知る、待遇を確かめる、話を聞いてみる。気になるところ見てみてください!
- 127日年間休日
- 12時間平均残業時間
- 毎日ガチャ遊びココロも大切にする福利厚生。アマギフなどの賞品ラインナップ!
ほかにも、チケットレストラン、書籍読み放題、2年ごとの慰労報奨(休暇 or 金一封)、11期連続の黒字決算。