はじめての Python logging
入門
「print()
でデバッグしてた頃には戻れない」そんな一段上の開発体験を、今日ここで手に入れましょう。
📋 目次
- この記事で手に入るもの
- ロギングを学ぶ前に押さえる3つのキーワード
- "まず動く"5行サンプル
- レベルを理解する
- 独自 Logger を切る
- Handler & Formatter
- 例外トレースを丸ごと残す
- 設定ファイルで一括管理
- 構造化ログ(JSON出力)
- よくある落とし穴と対策
- 本番テンプレート
- 次のステップと発展的なトピック
- パフォーマンス最適化のコツ
- セキュリティとプライバシーの配慮
- デバッグ専用のログテクニック
- トラブルシューティング完全ガイド
- 実用的なログ分析のヒント
- クイックリファレンス
- サンプルコード
1. この記事で手に入るもの
- 「ログってそもそも何?」が腹落ちする
- 5行で動く最小構成 → 本番レベルまで段階的に強化
- コピペで回るサンプル/失敗しやすいポイント/ベストプラクティス
- 仕事・個人開発どちらにも使える「テンプレート」
2. ロギングを学ぶ前に押さえる3つのキーワード
キーワード | 一言で | 具体例 (イメージ) |
---|---|---|
Level | 重要度のラベル | DEBUG < INFO < WARNING < ERROR… |
Logger | ログの発生源 |
app.auth , app.db.user など |
Handler | どこに書き出すか決める | コンソール / ファイル / Syslog |
これだけ覚えておけば、後は積み木感覚で組み立てられます。
3. “まず動く”5行サンプル
import logging
logging.basicConfig(level=logging.INFO,
format="%(asctime)s %(levelname)s %(message)s")
logging.info("Hello, logging world!")
解説
-
import logging
– 公式モジュールなので追加インストール不要 -
basicConfig()
– “全部 INFO 以上を、決まったフォーマットで、標準出力へ” という一括設定 -
logging.info()
– これでコンソールに時刻・レベル付きメッセージが出る
4. レベルを理解する
メソッド | 何が起きた時に使う? |
---|---|
debug() |
変数の値・関数の入退出など細かすぎる情報 |
info() |
起動・停止、通常完了など“いつもの進行” |
warning() |
成功はしたが気になる (リトライ、遅延) |
error() |
ユーザ影響あり・復旧可能性あり |
critical() |
全サービス停止級。即アラート。 |
💡 レベルが低い (DEBUG
) ほど 騒がしい、高い (CRITICAL
) ほど 深刻。
basicConfig(level=logging.WARNING)
とすれば WARNING 以上だけを出力できます。
5. 独自 Logger を切る – 大規模化への第一歩
import logging
logger = logging.getLogger("app.auth") # 名前を付ける
logger.setLevel(logging.DEBUG) # ここでは DEBUG から拾う
logger.debug("トークン検証開始")
- “名前付き Logger” を作ることで、モジュール単位の出力制御が可能
- 名前はドット区切りで階層化され、親子関係を持つ (
app
→app.auth
)
6. Handler & Formatter – 出力先と見た目を自由自在に
import logging
from logging.handlers import RotatingFileHandler
logger = logging.getLogger("app")
logger.setLevel(logging.INFO)
# コンソールへ
console = logging.StreamHandler()
console.setFormatter(logging.Formatter(
"%(levelname)s | %(name)s | %(message)s"))
logger.addHandler(console)
# ファイルへ (1MB 超えたら世代交代, 3 世代保持)
file = RotatingFileHandler("app.log", maxBytes=1_000_000, backupCount=3, encoding="utf-8")
file.setFormatter(logging.Formatter(
"%(asctime)s | %(levelname)s | %(name)s | %(message)s"))
logger.addHandler(file)
logger.info("Multi-handler logging complete.")
ポイント
- 複数の Handler を同時アタッチできる
-
RotatingFileHandler
でログ肥大化を自動抑制 -
Formatter
で行頭に時刻やモジュール名を柔軟に追加
7. 例外トレースを丸ごと残す
try:
1 / 0
except ZeroDivisionError:
logger.exception("計算失敗: ZeroDivisionError")
-
logger.exception()
はERROR
相当 &exc_info=True
を暗黙指定 - トレースバック付きなので原因特定が秒で終わる
8. 設定ファイルで一括管理 – logging.config
辞書ベースの設定は Python 3.2 以降 で利用可能で、現代的なアプリケーションの標準的な手法です。
# logging_config.py
LOGGING = {
"version": 1,
"disable_existing_loggers": False,
"formatters": {
"default": {
"format": "%(asctime)s [%(levelname)s] %(name)s: %(message)s"
}
},
"handlers": {
"console": {
"class": "logging.StreamHandler",
"formatter": "default",
"level": "INFO"
},
"error_file": {
"class": "logging.handlers.RotatingFileHandler",
"formatter": "default",
"level": "ERROR",
"filename": "errors.log",
"maxBytes": 1048576,
"backupCount": 5,
"encoding": "utf-8"
}
},
"loggers": {
"app": {
"handlers": ["console", "error_file"],
"level": "DEBUG",
"propagate": False
}
}
}
読み込み側:
import logging.config
from logging_config import LOGGING
logging.config.dictConfig(LOGGING)
logger = logging.getLogger("app")
logger.info("dictConfig で INFO")
logger.error("dictConfig で ERROR (ファイルにも出力)")
メリット
- コード量ゼロでレベル変更・ファイル名変更が出来る
- 環境別 (dev/prod) コンフィグを簡単に切替え
9. “構造化ログ” への扉 – JSON 出力
実運用では JSON 形式 で吐く→ Log Analytics / BigQuery で集計、が鉄板です。
人気ライブラリ: python-json-logger
pip install python-json-logger
from pythonjsonlogger import jsonlogger
json_formatter = jsonlogger.JsonFormatter()
json_handler = logging.StreamHandler()
json_handler.setFormatter(json_formatter)
logger = logging.getLogger("app")
logger.setLevel(logging.INFO)
logger.addHandler(json_handler)
logger.info("User login", extra={"user_id": 42, "ip": "203.0.113.1"})
出力例:
{"asctime": "2025-06-16 23:56:00,123", "levelname": "INFO",
"name": "app", "message": "User login", "user_id": 42, "ip": "203.0.113.1"}
- extra で任意キーを付与 → 検索・ダッシュボード化がラク
- 可観測性ツール (Azure Monitor, Datadog 等) との相性抜群
10. よくある落とし穴と対策
症状 | 原因 | 解決策 |
---|---|---|
ログが二重に出力される |
重複 Handler or propagate=True
|
logger.propagate = False ハンドラ重複チェック |
basicConfig() が“効かない” |
既に Logger が生成されていた |
basicConfig() は 最初の import 直後 に呼ぶ |
UnicodeEncodeError (日本語ログ) | ファイルハンドラの encoding 未指定 |
encoding="utf-8" を明示 |
重いループで DEBUG ログが性能劣化 | 不要な文字列結合 |
"値=%s", val の 遅延フォーマット を使う |
11. 本番テンプレート (貼るだけで動く)
# logger_setup.py
import logging
import logging.config
from pathlib import Path
def setup_logging(log_dir: str = "logs"):
Path(log_dir).mkdir(exist_ok=True)
cfg = {
"version": 1,
"disable_existing_loggers": False,
"formatters": {
"default": {
"format": "%(asctime)s [%(levelname)s] %(name)s: %(message)s"
},
},
"handlers": {
"console": {
"class": "logging.StreamHandler",
"level": "INFO",
"formatter": "default"
},
"file_all": {
"class": "logging.handlers.TimedRotatingFileHandler",
"when": "midnight",
"backupCount": 7,
"filename": f"{log_dir}/app.log",
"encoding": "utf-8",
"formatter": "default",
},
"file_err": {
"class": "logging.handlers.RotatingFileHandler",
"level": "ERROR",
"maxBytes": 2_000_000,
"backupCount": 3,
"filename": f"{log_dir}/error.log",
"encoding": "utf-8",
"formatter": "default",
}
},
"loggers": {
"": { # root
"handlers": ["console", "file_all", "file_err"],
"level": "DEBUG",
}
}
}
logging.config.dictConfig(cfg)
呼び出し側:
from logger_setup import setup_logging
import logging
setup_logging()
log = logging.getLogger(__name__)
def main():
log.info("スタート")
try:
42 / 0
except ZeroDivisionError:
log.exception("ゼロ割")
if __name__ == "__main__":
main()
- 日次ローテート+サイズローテートの合わせ技
- ルート Logger に3つの Handler を登録 → サブモジュールは何も考えず
logging.getLogger(__name__)
で OK
12. 次のステップと発展的なトピック
🚀 実践への第一歩
- まずは
basicConfig()
で置換 → 既存print
をlogger.info
に変換 - ログレベルを切り替えながら、**「本番で何を残すべきか」**を考える
- 余裕が出てきたら JSON ログ化 → ダッシュボードで視覚化
🔧 さらに深掘りしたい人へ
-
logging.Filter
でメッセージ選別 (例: リクエスト ID 単位) -
QueueHandler
+QueueListener
でマルチプロセス高速化 - Azure 用なら
opencensus-ext-azure
で Application Insights へ一発送信 - 既存ツールとの統合: structlog, loguru, rich (カラフル出力)
13. パフォーマンス最適化のコツ
本番環境では、ログ出力がアプリケーションの性能に与える影響を最小限に抑えることが重要です。適切な最適化により、数十倍の性能改善も可能になります。
文字列フォーマットの最適化
ログの文字列作成は意外にコストが高い処理です。特にDEBUGレベルが無効な本番環境では、無駄な文字列結合を避けることで大幅な性能向上が期待できます。
import logging
logger = logging.getLogger(__name__)
# ❌ 悪い例: 常に文字列結合される
# DEBUGが無効でも str() や + 演算が毎回実行される
logger.debug("User " + str(user_id) + " performed action: " + action_name)
# ✅ 良い例: DEBUGレベルが無効なら文字列結合されない
# loggingモジュールが内部で遅延評価を行う
logger.debug("User %s performed action: %s", user_id, action_name)
# ✅ さらに良い例: f-stringと条件判定の組み合わせ
# 重い処理を含む場合は明示的にレベルチェック
if logger.isEnabledFor(logging.DEBUG):
logger.debug(f"Complex calculation result: {expensive_function()}")
性能比較(10万回ループでの実測例):
- 文字列結合: 約0.8秒
- 遅延評価: 約0.05秒
- 改善効果: 約16倍高速 🚀
💡 実際の改善効果はログレベル設定と処理内容に依存
大量ログ処理での注意点
Webアプリケーションや高負荷システムでは、ログ書き込みがI/Oボトルネックになる場合があります。非同期処理で劇的に改善できます。
import logging
from logging.handlers import QueueHandler, QueueListener
import queue
import threading
# 🔄 非同期ログ処理で高性能化
log_queue = queue.Queue(-1) # 無制限キュー
queue_handler = QueueHandler(log_queue)
# 実際の書き込みは別スレッドで実行
file_handler = logging.FileHandler('async.log', encoding='utf-8')
listener = QueueListener(log_queue, file_handler)
listener.start() # バックグラウンドスレッド開始
logger = logging.getLogger('async_app')
logger.addHandler(queue_handler)
# メインスレッドはブロックされない
for i in range(10000):
logger.info(f"Processing item {i}") # 即座にreturn
# アプリケーション終了時
# listener.stop() # リスナーの停止を忘れずに
QueueHandler の利点:
- ⚡ メインスレッドがブロックされない
- 🛡️ I/O エラーの影響を局所化
- 📊 キューサイズで負荷状況を監視可能
💡 使用場面: WebAPI、リアルタイム処理、高頻度ログが発生するシステム
14. セキュリティとプライバシーの配慮
ログには意図せず機密情報が出力される危険性があります。GDPR、個人情報保護法などの法規制遵守のためにも、適切な対策が必要です。
機密情報の漏洩防止
以下のフィルタクラスは、ログ出力時に自動的に機密情報をマスクします。正規表現により柔軟なパターンマッチングが可能です。
import logging
import re
class SensitiveDataFilter(logging.Filter):
"""機密情報をマスクするフィルタ"""
def __init__(self):
super().__init__()
# 機密情報のパターンを定義
self.patterns = [
# メールアドレス
(re.compile(r'\b[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+\.[A-Z|a-z]{2,}\b'), '[EMAIL]'),
# クレジットカード番号
(re.compile(r'\b\d{4}-\d{4}-\d{4}-\d{4}\b'), '[CARD]'),
# パスワード(key=value形式)
(re.compile(r'password["\']?\s*[:=]\s*["\']?([^"\'\s,}]+)', re.IGNORECASE), 'password="[MASKED]"'),
# APIキー(32文字の英数字)
(re.compile(r'\b[A-Za-z0-9]{32}\b'), '[API_KEY]'),
# 日本の電話番号
(re.compile(r'\b0\d{1,4}-\d{1,4}-\d{4}\b'), '[PHONE]'),
]
def filter(self, record):
"""ログレコードの内容をフィルタリング"""
# メッセージ内の機密情報をマスク
for pattern, replacement in self.patterns:
record.msg = pattern.sub(replacement, str(record.msg))
# 引数があればそれもマスク
if record.args:
masked_args = []
for arg in record.args:
if isinstance(arg, str):
for pattern, replacement in self.patterns:
arg = pattern.sub(replacement, arg)
masked_args.append(arg)
record.args = tuple(masked_args)
return True
# 使用例
logger = logging.getLogger('secure_app')
logger.addFilter(SensitiveDataFilter())
# 🔒 これらは自動的にマスクされる
logger.info("User login: email=user@example.com, password=secret123")
# 出力: "User login: email=[EMAIL], password=[MASKED]"
logger.warning("Payment failed for card: 1234-5678-9012-3456")
# 出力: "Payment failed for card: [CARD]"
logger.error("API authentication failed: key=a1b2c3d4e5f6g7h8i9j0k1l2m3n4o5p6")
# 出力: "API authentication failed: key=[API_KEY]"
セキュリティフィルタの実装ポイント:
- 包括的なパターン定義: メール、カード番号、パスワード、APIキーなど
-
引数も含めてマスク:
logger.info("User: %s", sensitive_data)
にも対応 - パフォーマンス考慮: 正規表現をコンパイル済みで保持
- カスタマイズ可能: 業務に応じてパターンを追加・変更
💡 運用時の注意:
- 開発環境ではマスクを無効化(デバッグのため)
- 定期的なパターン見直し(新しい機密情報の種類に対応)
- フィルタ自体のテストも重要(マスク漏れの防止)
15. デバッグ専用のログテクニック
開発・保守フェーズでは、効率的なデバッグがプロダクトの品質を大きく左右します。ここでは、ログを活用した高度なデバッグテクニックを紹介します。
関数実行時間の計測
性能問題の特定には、どの関数が時間を消費しているかの把握が不可欠です。デコレータを使えば、既存コードを変更せずに計測が可能です。
import logging
import functools
import time
def log_execution_time(logger_name=None):
"""関数の実行時間をログ出力するデコレータ"""
def decorator(func):
@functools.wraps(func) # 元の関数のメタデータを保持
def wrapper(*args, **kwargs):
logger = logging.getLogger(logger_name or func.__module__)
start_time = time.time()
logger.debug(f"🚀 Starting {func.__name__}")
try:
result = func(*args, **kwargs)
execution_time = time.time() - start_time
# 実行時間に応じてログレベルを調整
if execution_time > 1.0:
logger.warning(f"⚠️ {func.__name__} took {execution_time:.3f}s (slow)")
else:
logger.info(f"✅ {func.__name__} completed in {execution_time:.3f}s")
return result
except Exception as e:
execution_time = time.time() - start_time
logger.error(f"❌ {func.__name__} failed after {execution_time:.3f}s: {e}")
raise
return wrapper
return decorator
# 使用例
@log_execution_time('performance')
def slow_calculation(n):
"""時間のかかる計算のシミュレーション"""
time.sleep(0.1) # 処理時間のシミュレーション
return sum(range(n))
@log_execution_time('performance')
def database_query(query):
"""データベースクエリの例"""
time.sleep(0.05) # DB処理のシミュレーション
return f"Result for: {query}"
# 実行すると自動的に時間が記録される
result = slow_calculation(1000)
data = database_query("SELECT * FROM users")
実行時間デコレータの利点:
- 🎯 非侵入的: 既存コードを変更不要
- 📊 一元管理: 全関数の性能を統一的に監視
- 🚨 閾値アラート: 遅い処理を自動で警告
- 🐛 例外時も計測: エラー時の処理時間も記録
コンテキスト付きログ
マイクロサービスやWebアプリケーションでは、1つのリクエストに関連するログを追跡することが重要です。コンテキスト変数により、自動的にリクエストIDを付与できます。
import logging
from contextvars import ContextVar
import uuid
# リクエストIDを保持するコンテキスト変数
# Python 3.7以降の asyncio 対応の仕組み
request_id_var: ContextVar[str] = ContextVar('request_id', default='no-request')
user_id_var: ContextVar[str] = ContextVar('user_id', default='anonymous')
class ContextFilter(logging.Filter):
"""コンテキスト情報を自動的に追加"""
def filter(self, record):
# ログレコードにコンテキスト情報を追加
record.request_id = request_id_var.get()
record.user_id = user_id_var.get()
return True
# セットアップ
logger = logging.getLogger('context_app')
logger.addFilter(ContextFilter())
handler = logging.StreamHandler()
formatter = logging.Formatter(
'%(asctime)s [%(request_id)s|%(user_id)s] %(levelname)s: %(message)s'
)
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.setLevel(logging.INFO)
logger.propagate = False
# 使用例:Webリクエストの処理をシミュレーション
def process_request(user_id: str):
"""Webリクエスト処理のシミュレーション"""
# リクエスト開始時にコンテキストを設定
request_id = str(uuid.uuid4())[:8] # 短縮ID
request_id_var.set(request_id)
user_id_var.set(user_id)
logger.info("🌐 リクエスト処理開始")
# 各種処理(すべて同じリクエストIDで記録される)
authenticate_user()
fetch_user_data()
generate_response()
logger.info("✅ リクエスト処理完了")
def authenticate_user():
"""認証処理"""
logger.debug("🔐 ユーザー認証中...")
# 何らかの認証ロジック
logger.info("✅ 認証成功")
def fetch_user_data():
"""ユーザーデータ取得"""
logger.debug("📊 ユーザーデータ取得中...")
# データベースアクセス
logger.info("✅ データ取得完了")
def generate_response():
"""レスポンス生成"""
logger.debug("📝 レスポンス生成中...")
# レスポンス作成
logger.info("✅ レスポンス生成完了")
# テスト実行
print("=== 複数リクエストの同時処理デモ ===")
process_request("user123")
print()
process_request("user456")
実行結果例:
2025-06-17 10:30:01 [a1b2c3d4|user123] INFO: 🌐 リクエスト処理開始
2025-06-17 10:30:01 [a1b2c3d4|user123] INFO: ✅ 認証成功
2025-06-17 10:30:01 [a1b2c3d4|user123] INFO: ✅ データ取得完了
2025-06-17 10:30:01 [a1b2c3d4|user123] INFO: ✅ レスポンス生成完了
2025-06-17 10:30:01 [a1b2c3d4|user123] INFO: ✅ リクエスト処理完了
2025-06-17 10:30:02 [e5f6g7h8|user456] INFO: 🌐 リクエスト処理開始
2025-06-17 10:30:02 [e5f6g7h8|user456] INFO: ✅ 認証成功
...
コンテキストログの利点:
- 🔍 リクエスト追跡: 1つのリクエストに関連するログを簡単に抽出
- 🚀 非同期対応:
asyncio
やconcurrent.futures
でも正しく動作 - 👤 ユーザー識別: どのユーザーの操作かも同時に記録
- 🔧 拡張可能: セッションID、処理種別など任意の情報を追加可能
💡 実運用でのポイント:
- ログ分析ツール(ELK Stack、Splunk等)で
request_id
フィールドによる検索・集計が可能 - マイクロサービス間でリクエストIDを受け渡しすることで、分散トレーシングが実現できる
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.setLevel(logging.INFO)
使用例
def process_request(request_id: str):
# リクエストIDをコンテキストに設定
request_id_var.set(request_id)
logger.info("リクエスト処理開始")
logger.info("データベースアクセス")
logger.info("レスポンス送信")
異なるリクエストIDでテスト
process_request("req-001")
process_request("req-002")
16. トラブルシューティング完全ガイド
よくあるエラーと解決方法
エラーメッセージ | 原因 | 解決方法 |
---|---|---|
No handlers could be found for logger "xxx" |
ハンドラが設定されていない |
logging.basicConfig() を呼ぶか、明示的にハンドラを追加 |
PermissionError: [Errno 13] Permission denied |
ログファイルへの書き込み権限がない | ファイルパスの権限確認、または書き込み可能なディレクトリに変更 |
UnicodeEncodeError: 'charmap' codec can't encode |
文字エンコーディングの問題 |
encoding='utf-8' を明示的に指定 |
ログが2回出力される | ハンドラの重複登録またはpropagateの問題 |
logger.handlers.clear() またはpropagate=False を設定 |
デバッグ用ユーティリティ
import logging
def debug_logging_setup():
"""現在のログ設定を詳細表示"""
print("=== Logging Configuration Debug ===")
# ルートロガーから確認
root_logger = logging.getLogger()
print(f"Root Logger Level: {logging.getLevelName(root_logger.level)}")
print(f"Root Logger Handlers: {len(root_logger.handlers)}")
# 全ロガーを確認
logger_dict = logging.Logger.manager.loggerDict
print(f"Total Loggers: {len(logger_dict)}")
for name, logger_obj in list(logger_dict.items())[:5]: # 最初の5個を表示
if isinstance(logger_obj, logging.Logger):
print(f"\nLogger: {name}")
print(f" Level: {logging.getLevelName(logger_obj.level)}")
print(f" Handlers: {len(logger_obj.handlers)}")
print(f" Propagate: {logger_obj.propagate}")
def test_all_levels():
"""全ログレベルのテスト出力"""
logger = logging.getLogger('test')
logger.debug("これはDEBUGメッセージです")
logger.info("これはINFOメッセージです")
logger.warning("これはWARNINGメッセージです")
logger.error("これはERRORメッセージです")
logger.critical("これはCRITICALメッセージです")
# 例外テスト
try:
1/0
except ZeroDivisionError:
logger.exception("例外のテストです")
# 実行例
if __name__ == "__main__":
logging.basicConfig(
level=logging.DEBUG,
format='%(asctime)s [%(levelname)s] %(name)s: %(message)s'
)
debug_logging_setup()
print("\n" + "="*50)
test_all_levels()
17. 実用的なログ分析のヒント
本番環境では大量のログが生成されるため、効率的な分析手法が重要です。ここでは、Python を使ってログファイルを自動分析する実用的な方法を紹介します。
ログ分析用のスクリプト例
以下のスクリプトは、ログファイルの傾向を素早く把握するためのツールです。障害調査や性能改善の第一歩として活用できます。
import re
import json
from collections import Counter, defaultdict
from datetime import datetime
def analyze_log_file(log_file_path: str):
"""ログファイルを分析して統計情報を出力"""
# 各種カウンタを準備
level_count = Counter() # ログレベル別の件数
hourly_count = defaultdict(int) # 時間別の件数
error_patterns = Counter() # エラーパターンの頻度
with open(log_file_path, 'r', encoding='utf-8') as f:
for line in f:
# 1. ログレベルの抽出と集計
# 正規表現で [DEBUG], [INFO] などのパターンを探す
level_match = re.search(r'\[(DEBUG|INFO|WARNING|ERROR|CRITICAL)\]', line)
if level_match:
level = level_match.group(1)
level_count[level] += 1
# 2. 時間別集計(トラフィックパターンの把握)
# "2025-06-17 14:" のような形式から時間を抽出
time_match = re.search(r'(\d{4}-\d{2}-\d{2} \d{2}):', line)
if time_match:
hour = time_match.group(1)
hourly_count[hour] += 1
# 3. エラーパターンの抽出(障害原因の特定)
if 'ERROR' in line or 'CRITICAL' in line:
# エラーメッセージの主要部分を抽出
msg_match = re.search(r'(ERROR|CRITICAL).*?:\s*(.+)', line)
if msg_match:
error_msg = msg_match.group(2)[:50] # 最初の50文字で分類
error_patterns[error_msg] += 1
# 4. 分析結果の表示
print("=== ログ分析結果 ===")
# レベル別統計(システムの健全性確認)
print(f"\n📊 レベル別統計:")
for level, count in level_count.most_common():
percentage = (count / sum(level_count.values())) * 100
print(f" {level}: {count}件 ({percentage:.1f}%)")
# 時間別統計(負荷パターンの把握)
print(f"\n⏰ 時間別統計 (上位5時間):")
for hour, count in sorted(hourly_count.items(), key=lambda x: x[1], reverse=True)[:5]:
print(f" {hour}時台: {count}件")
# エラーパターン(障害の根本原因分析)
print(f"\n🚨 エラーパターン (上位5個):")
for pattern, count in error_patterns.most_common(5):
print(f" {count}回: {pattern}")
# 使用例
# analyze_log_file('app.log')
このスクリプトの活用シーン:
- 障害調査: エラーパターンから根本原因を特定
- 性能監視: 時間別統計でピーク時間を把握
- システム健全性チェック: ログレベル分布で異常を検知
- 運用レポート: 定期的な統計情報として活用
💡 Pro Tip: このスクリプトをcronやタスクスケジューラで定期実行すれば、自動的な健全性レポートが作成できます。
ログローテーションの設定例
本番環境ではログファイルの肥大化対策が必須です。適切なローテーション設定により、ディスク容量を抑えつつ、必要な期間のログを確実に保持できます。
import logging
from logging.handlers import TimedRotatingFileHandler, RotatingFileHandler
import os
def setup_production_logging(app_name: str = "myapp"):
"""本番環境向けのログ設定"""
# ログディレクトリの作成
log_dir = "logs"
os.makedirs(log_dir, exist_ok=True)
# 共通フォーマッタ(詳細情報付き)
formatter = logging.Formatter(
'%(asctime)s [%(levelname)s] %(name)s:%(lineno)d: %(message)s'
)
# 📅 一般ログ(日次ローテーション、7日間保持)
# 利点: 日付でファイルが分かれるため、調査時に特定の日を簡単に確認可能
general_handler = TimedRotatingFileHandler(
filename=f"{log_dir}/{app_name}.log",
when='midnight', # 毎日深夜0時にローテーション
interval=1, # 1日間隔
backupCount=7, # 7世代保持(1週間分)
encoding='utf-8'
)
general_handler.setLevel(logging.INFO)
general_handler.setFormatter(formatter)
# 💾 エラーログ(サイズベースローテーション、5MB × 3ファイル)
# 利点: エラーが大量発生した場合でも確実にファイルサイズを制御
error_handler = RotatingFileHandler(
filename=f"{log_dir}/{app_name}_error.log",
maxBytes=5*1024*1024, # 5MB に達したらローテーション
backupCount=3, # 3世代保持(合計最大15MB)
encoding='utf-8'
)
error_handler.setLevel(logging.ERROR)
error_handler.setFormatter(formatter)
# 🖥️ コンソール出力(開発・運用監視用)
# 本番では WARNING 以上のみ表示し、ノイズを削減
console_handler = logging.StreamHandler()
console_handler.setLevel(logging.WARNING)
console_handler.setFormatter(logging.Formatter(
'%(levelname)s: %(message)s' # コンソールは簡潔に
))
# ルートロガーに全ハンドラを登録
root_logger = logging.getLogger()
root_logger.setLevel(logging.DEBUG)
root_logger.handlers.clear() # 既存ハンドラをクリア(重複防止)
root_logger.addHandler(general_handler)
root_logger.addHandler(error_handler)
root_logger.addHandler(console_handler)
# 設定完了のログ
logger = logging.getLogger(__name__)
logger.info(f"Logging setup completed for {app_name}")
# 使用例
setup_production_logging("my_web_app")
ログローテーション戦略の詳細解説:
1. 時間ベース vs サイズベース
-
時間ベース (
TimedRotatingFileHandler
):- 📅 予測可能なファイル分割
- 🔍 日付での調査が容易
- 📊 定期的な分析に適している
-
サイズベース (
RotatingFileHandler
):- 💾 ディスク使用量の厳密な制御
- 🚨 大量ログ発生時の安全性
- ⚡ エラーログなど不定期な出力に最適
2. 世代管理(backupCount)の考え方
# 例: 日次ローテーション + 30日保持の場合
# myapp.log <- 現在のログ
# myapp.log.2025-06-16 <- 1日前
# myapp.log.2025-06-15 <- 2日前
# ...
# myapp.log.2025-05-18 <- 30日前(これ以前は自動削除)
3. 本番環境でのベストプラクティス
- 一般ログ: 日次 + 30~90日保持
- エラーログ: サイズベース + 長期保持(監査要件に応じて)
- アクセスログ: 日次 + 法的要件に応じた期間
- デバッグログ: 短期間(1~7日)または本番では無効化
💡 運用時の注意点:
- ディスク容量の監視は必須
- ログアーカイブ戦略(S3、外部ストレージ)の検討
- 法的要件(個人情報、監査ログ)の確認が重要
---
## 17. クイックリファレンス
### 基本的なログレベルの使い分け
```python
import logging
logger = logging.getLogger(__name__)
# 開発・デバッグ時の詳細情報
logger.debug("変数の値: user_id=%s, status=%s", user_id, status)
# 正常な処理フロー
logger.info("ユーザー%sの登録が完了しました", username)
# 注意が必要だが処理は継続可能
logger.warning("API応答時間が閾値を超過: %.2f秒", response_time)
# エラーが発生したが処理継続可能
logger.error("外部API呼び出し失敗、リトライします: %s", str(e))
# 即座に対応が必要な致命的エラー
logger.critical("データベース接続が完全に失敗しました")
よく使う設定パターン
最小構成
import logging
logging.basicConfig(level=logging.INFO)
ファイル出力付き
import logging
logging.basicConfig(
level=logging.INFO,
format='%(asctime)s [%(levelname)s]: %(message)s',
handlers=[
logging.FileHandler('app.log', encoding='utf-8'),
logging.StreamHandler()
]
)
本格的な設定
import logging.config
LOGGING_CONFIG = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'detailed': {
'format': '%(asctime)s [%(levelname)s] %(name)s:%(lineno)d: %(message)s'
},
'simple': {
'format': '%(levelname)s: %(message)s'
}
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'level': 'INFO',
'formatter': 'simple'
},
'file': {
'class': 'logging.handlers.RotatingFileHandler',
'level': 'DEBUG',
'formatter': 'detailed',
'filename': 'app.log',
'maxBytes': 1048576,
'backupCount': 3,
'encoding': 'utf-8'
}
},
'root': {
'level': 'DEBUG',
'handlers': ['console', 'file']
}
}
logging.config.dictConfig(LOGGING_CONFIG)
この記事で学んだことを段階的に実践して、保守しやすく、デバッグしやすいコードを書けるようになりましょう。最初はprint()
の置き換えから始めて、徐々に高度な機能を取り入れていけば、いつの間にかログマスターになっているはずです!
Happy Logging! 🚀
19. サンプルコード
#!/usr/bin/env python3
# -*- coding: utf-8 -*-
"""
Python logging 学習用サンプルコード
この記事(log_article.md)で説明した内容を実際に試すためのサンプルコードです。
各セクションごとに実行可能なサンプルが含まれています。
"""
import logging
import logging.config
import time
import functools
import re
from logging.handlers import RotatingFileHandler, TimedRotatingFileHandler
from contextvars import ContextVar
from pathlib import Path
def demo_section_separator(section_title: str):
"""セクション区切り用のデコレータ"""
def decorator(func):
@functools.wraps(func)
def wrapper(*args, **kwargs):
print("\n" + "="*60)
print(f"📖 {section_title}")
print("="*60)
result = func(*args, **kwargs)
print("\n✅ セクション完了: " + section_title)
return result
return wrapper
return decorator
@demo_section_separator("セクション2: 基本的なログ出力")
def demo_basic_logging():
"""基本的なログ出力のデモ"""
# 既存の設定をクリア
logging.getLogger().handlers.clear()
# 基本設定
logging.basicConfig(
level=logging.INFO,
format="%(asctime)s %(levelname)s %(message)s"
)
# 基本的なログ出力
logging.info("Hello, logging world!")
logging.warning("これは警告メッセージです")
logging.error("これはエラーメッセージです")
@demo_section_separator("セクション3: ログレベルの理解")
def demo_log_levels():
"""ログレベルのデモ"""
# 新しいロガーを作成
logger = logging.getLogger("level_demo")
logger.handlers.clear()
# ハンドラを作成
handler = logging.StreamHandler()
formatter = logging.Formatter('%(levelname)-8s: %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)
print("\n🔍 ログレベル: DEBUG (すべて表示)")
logger.setLevel(logging.DEBUG)
logger.debug("🐛 デバッグ: 変数の値をチェック")
logger.info("ℹ️ 情報: 正常な処理フロー")
logger.warning("⚠️ 警告: 注意が必要")
logger.error("❌ エラー: 問題が発生")
logger.critical("🚨 重大: 即座に対応が必要")
print("\n🔍 ログレベル: WARNING (WARNING以上のみ表示)")
logger.setLevel(logging.WARNING)
logger.debug("🐛 デバッグ: これは表示されません")
logger.info("ℹ️ 情報: これも表示されません")
logger.warning("⚠️ 警告: これは表示されます")
logger.error("❌ エラー: これも表示されます")
@demo_section_separator("セクション4: 独自Loggerの作成")
def demo_custom_logger():
"""独自Loggerのデモ"""
# 名前付きロガーの作成
auth_logger = logging.getLogger("app.auth")
db_logger = logging.getLogger("app.database")
# それぞれに個別の設定
for logger_obj in [auth_logger, db_logger]:
logger_obj.handlers.clear()
handler = logging.StreamHandler()
formatter = logging.Formatter(
'%(asctime)s [%(name)s] %(levelname)s: %(message)s'
)
handler.setFormatter(formatter)
logger_obj.addHandler(handler)
logger_obj.setLevel(logging.INFO)
logger_obj.propagate = False
# 異なるモジュールからのログ
auth_logger.info("ユーザー認証を開始")
auth_logger.warning("無効なパスワードが入力されました")
db_logger.info("データベース接続を確立")
db_logger.error("クエリ実行中にタイムアウトが発生")
@demo_section_separator("セクション5: Handler & Formatterの活用")
def demo_handlers_formatters():
"""ハンドラとフォーマッタのデモ"""
# ログディレクトリの作成
log_dir = Path("logs")
log_dir.mkdir(exist_ok=True)
# ロガーの作成
logger = logging.getLogger("multi_handler_demo")
logger.handlers.clear()
logger.setLevel(logging.DEBUG)
# コンソールハンドラ(簡潔な形式)
console_handler = logging.StreamHandler()
console_formatter = logging.Formatter("%(levelname)s | %(name)s | %(message)s")
console_handler.setFormatter(console_formatter)
console_handler.setLevel(logging.INFO)
logger.addHandler(console_handler)
# ファイルハンドラ(詳細な形式)
file_handler = RotatingFileHandler(
log_dir / "demo.log",
maxBytes=1024*1024, # 1MB
backupCount=3,
encoding="utf-8"
)
file_formatter = logging.Formatter(
"%(asctime)s | %(levelname)s | %(name)s | %(funcName)s:%(lineno)d | %(message)s"
)
file_handler.setFormatter(file_formatter)
file_handler.setLevel(logging.DEBUG)
logger.addHandler(file_handler)
# ログ出力テスト
logger.debug("これはDEBUGメッセージ(ファイルのみ)")
logger.info("これはINFOメッセージ(コンソール+ファイル)")
logger.warning("これはWARNINGメッセージ")
logger.error("これはERRORメッセージ")
print(f"📁 ファイルログは {log_dir / 'demo.log'} に保存されました")
@demo_section_separator("セクション6: 例外トレースの記録")
def demo_exception_logging():
"""例外トレースのログ記録デモ"""
logger = logging.getLogger("exception_demo")
logger.handlers.clear()
handler = logging.StreamHandler()
formatter = logging.Formatter('%(asctime)s [%(levelname)s]: %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)
logger.propagate = False
# 例外処理とログ
try:
result = 10 / 0
except ZeroDivisionError as e:
logger.error("ゼロ除算エラーが発生: %s", str(e))
logger.exception("詳細なトレースバック付きログ:")
# カスタム例外の例
try:
def risky_function():
raise ValueError("これはサンプルエラーです")
risky_function()
except ValueError:
logger.exception("カスタム関数でエラーが発生")
@demo_section_separator("セクション13: パフォーマンス最適化")
def demo_performance_optimization():
"""パフォーマンス最適化のデモ"""
print("🚀 このセクションではログ出力の性能最適化を実演します:")
print(" 1. 文字列フォーマットの最適化(遅延評価)")
print(" 2. 条件判定による重い処理の回避")
print(" 3. 実際の性能測定と比較")
print()
logger = logging.getLogger("performance_demo")
logger.handlers.clear()
handler = logging.StreamHandler()
formatter = logging.Formatter('%(levelname)s: %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.setLevel(logging.INFO) # DEBUGは無効
logger.propagate = False
print("🚀 パフォーマンステスト開始")
# 悪い例(常に文字列結合される)
start_time = time.time()
for i in range(10000):
# この文字列結合は毎回実行される(非効率)
logger.debug("Processing item " + str(i) + " with status: " + "active")
bad_time = time.time() - start_time
# 良い例(遅延評価)
start_time = time.time()
for i in range(10000):
# DEBUGレベルが無効なので文字列結合されない(効率的)
logger.debug("Processing item %s with status: %s", i, "active")
good_time = time.time() - start_time
print(f"❌ 悪い例(文字列結合): {bad_time:.4f}秒")
print(f"✅ 良い例(遅延評価): {good_time:.4f}秒")
improvement = bad_time/good_time if good_time > 0 else 1
print(f"🔥 性能改善: {improvement:.1f}倍高速")
# 条件判定を使った例
def expensive_calculation():
time.sleep(0.001) # 重い処理のシミュレーション
return "expensive_result"
# isEnabledForを使った最適化
if logger.isEnabledFor(logging.DEBUG):
logger.debug(f"Expensive result: {expensive_calculation()}")
else:
print("💡 DEBUG無効のため、重い計算をスキップしました")
print("\n💡 最適化のポイント:")
print(" • 遅延評価(%s記法)で無駄な文字列操作を回避")
print(" • isEnabledFor()で重い処理をスキップ")
print(" • 本番環境ではDEBUGレベルを無効化")
@demo_section_separator("セクション14: セキュリティ対策")
def demo_security_features():
"""セキュリティ機能のデモ"""
print("🔒 このセクションでは機密情報の自動マスク機能を実演します:")
print(" 1. 正規表現による機密情報の検出")
print(" 2. ログ出力時の自動マスク処理")
print(" 3. GDPR等の法規制への対応例")
print()
class SensitiveDataFilter(logging.Filter):
"""機密情報をマスクするフィルタ"""
def __init__(self):
super().__init__()
self.patterns = [
(re.compile(r'\b[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+\.[A-Z|a-z]{2,}\b'), '[EMAIL]'),
(re.compile(r'\b\d{4}-\d{4}-\d{4}-\d{4}\b'), '[CARD]'),
(re.compile(r'password["\']?\s*[:=]\s*["\']?([^"\'\s,}]+)', re.IGNORECASE), 'password="[MASKED]"'),
]
def filter(self, record):
for pattern, replacement in self.patterns:
record.msg = pattern.sub(replacement, str(record.msg))
return True
# セキュアロガーの設定
secure_logger = logging.getLogger("secure_demo")
secure_logger.handlers.clear()
handler = logging.StreamHandler()
formatter = logging.Formatter('%(levelname)s: %(message)s')
handler.setFormatter(formatter)
secure_logger.addHandler(handler)
secure_logger.addFilter(SensitiveDataFilter())
secure_logger.setLevel(logging.INFO)
secure_logger.propagate = False
print("🔒 セキュリティフィルタのテスト:")
# 機密情報を含むログ(自動的にマスクされる)
secure_logger.info("User login: email=john.doe@example.com, password=secret123")
secure_logger.warning("Payment failed for card: 1234-5678-9012-3456")
secure_logger.error("API key validation failed: api_key=abc123xyz")
print("\n🛡️ セキュリティフィルタの重要性:")
print(" • 意図しない機密情報の漏洩防止")
print(" • GDPR、個人情報保護法への対応")
print(" • 監査ログでの安全性確保")
print(" • 開発者のヒューマンエラー対策")
@demo_section_separator("セクション15: デバッグテクニック")
def demo_debugging_techniques():
"""デバッグテクニックのデモ"""
print("🔍 このセクションでは以下のテクニックを実演します:")
print(" 1. 関数実行時間の自動計測(デコレータ)")
print(" 2. コンテキスト付きログ(リクエスト追跡)")
print(" 3. 分散システムでのログ相関")
print()
# リクエストIDコンテキストのデモ
request_id_var: ContextVar[str] = ContextVar('request_id', default='no-request')
class ContextFilter(logging.Filter):
def filter(self, record):
record.request_id = request_id_var.get()
return True
# 実行時間測定デコレータ
def log_execution_time(logger_name=None):
def decorator(func):
@functools.wraps(func)
def wrapper(*args, **kwargs):
logger = logging.getLogger(logger_name or func.__module__)
start_time = time.time()
logger.debug(f"Starting {func.__name__}")
try:
result = func(*args, **kwargs)
execution_time = time.time() - start_time
logger.info(f"{func.__name__} completed in {execution_time:.3f}s")
return result
except Exception as e:
execution_time = time.time() - start_time
logger.error(f"{func.__name__} failed after {execution_time:.3f}s: {e}")
raise
return wrapper
return decorator
# ロガーの設定
debug_logger = logging.getLogger('debug_demo')
debug_logger.handlers.clear()
handler = logging.StreamHandler()
formatter = logging.Formatter(
'%(asctime)s [%(request_id)s] %(levelname)s: %(message)s'
)
handler.setFormatter(formatter)
debug_logger.addHandler(handler)
debug_logger.addFilter(ContextFilter())
debug_logger.setLevel(logging.DEBUG)
debug_logger.propagate = False
# テスト関数
@log_execution_time('debug_demo')
def sample_calculation(n):
time.sleep(0.1) # 処理時間のシミュレーション
return sum(range(n))
# コンテキスト付きでテスト実行
def process_request(request_id: str):
request_id_var.set(request_id)
debug_logger.info("リクエスト処理開始")
result = sample_calculation(1000)
debug_logger.info(f"計算結果: {result}")
debug_logger.info("リクエスト処理完了")
print("🔍 デバッグテクニックのデモ:")
process_request("req-001")
print()
process_request("req-002")
print("🎯 デバッグテクニックの利点:")
print(" ✅ 非侵入的な性能監視")
print(" ✅ リクエスト単位でのログ追跡")
print(" ✅ 分散システムでの問題切り分け")
@demo_section_separator("セクション16: トラブルシューティング")
def demo_troubleshooting():
"""トラブルシューティングのデモ"""
def debug_logging_setup():
"""現在のログ設定を詳細表示"""
print("=== ログ設定デバッグ情報 ===")
# ルートロガーの確認
root_logger = logging.getLogger()
print(f"Root Logger Level: {logging.getLevelName(root_logger.level)}")
print(f"Root Logger Handlers: {len(root_logger.handlers)}")
# アクティブなロガーの確認
logger_dict = logging.Logger.manager.loggerDict
print(f"Total Loggers: {len(logger_dict)}")
active_loggers = []
for name, logger_obj in logger_dict.items():
if isinstance(logger_obj, logging.Logger) and logger_obj.handlers:
active_loggers.append((name, logger_obj))
print(f"Active Loggers with Handlers: {len(active_loggers)}")
for name, logger_obj in active_loggers[:3]: # 最初の3個を表示
print(f" 📝 {name}:")
print(f" Level: {logging.getLevelName(logger_obj.level)}")
print(f" Handlers: {len(logger_obj.handlers)}")
print(f" Propagate: {logger_obj.propagate}")
def test_all_levels():
"""全ログレベルのテスト"""
test_logger = logging.getLogger('troubleshoot_test')
test_logger.handlers.clear()
handler = logging.StreamHandler()
formatter = logging.Formatter('%(levelname)-8s: %(message)s')
handler.setFormatter(formatter)
test_logger.addHandler(handler)
test_logger.setLevel(logging.DEBUG)
test_logger.propagate = False
print("\n🧪 全ログレベルのテスト:")
test_logger.debug("DEBUG メッセージ")
test_logger.info("INFO メッセージ")
test_logger.warning("WARNING メッセージ")
test_logger.error("ERROR メッセージ")
test_logger.critical("CRITICAL メッセージ")
# 例外テスト
try:
1/0
except ZeroDivisionError:
test_logger.exception("例外処理テスト")
debug_logging_setup()
test_all_levels()
@demo_section_separator("完全な本番環境設定")
def demo_production_setup():
"""本番環境レベルの設定デモ"""
# ログディレクトリの作成
log_dir = Path("logs")
log_dir.mkdir(exist_ok=True)
# 辞書形式での設定
LOGGING_CONFIG = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'detailed': {
'format': '%(asctime)s [%(levelname)s] %(name)s:%(lineno)d: %(message)s'
},
'simple': {
'format': '%(levelname)s: %(message)s'
}
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'level': 'INFO',
'formatter': 'simple'
},
'general_file': {
'class': 'logging.handlers.TimedRotatingFileHandler',
'when': 'midnight',
'backupCount': 7,
'filename': str(log_dir / 'app.log'),
'encoding': 'utf-8',
'formatter': 'detailed',
'level': 'INFO'
},
'error_file': {
'class': 'logging.handlers.RotatingFileHandler',
'level': 'ERROR',
'maxBytes': 2_000_000,
'backupCount': 3,
'filename': str(log_dir / 'error.log'),
'encoding': 'utf-8',
'formatter': 'detailed'
}
},
'loggers': {
'myapp': {
'handlers': ['console', 'general_file', 'error_file'],
'level': 'DEBUG',
'propagate': False
}
}
}
# 設定の適用
logging.config.dictConfig(LOGGING_CONFIG)
# テスト用のロガー
app_logger = logging.getLogger('myapp')
print("🏭 本番環境レベルの設定が完了しました")
print(f"📁 ログファイル:")
print(f" - 一般ログ: {log_dir / 'app.log'}")
print(f" - エラーログ: {log_dir / 'error.log'}")
# 各レベルのログ出力テスト
app_logger.debug("デバッグ情報(ファイルのみ)")
app_logger.info("アプリケーション開始")
app_logger.warning("設定ファイルが見つかりません、デフォルト値を使用")
app_logger.error("データベース接続エラー")
app_logger.critical("システム全体に影響する重大エラー")
print("✅ 各種ログが出力されました")
def main():
"""メイン実行関数"""
print("🐍 Python Logging デモンストレーション")
print("=" * 60)
print("このプログラムは log_article.md の内容を実際に試すためのデモです。")
print("各セクションが順番に実行されます。\n")
try:
# 各デモセクションを実行
demo_basic_logging()
demo_log_levels()
demo_custom_logger()
demo_handlers_formatters()
demo_exception_logging()
demo_performance_optimization()
demo_security_features()
demo_debugging_techniques()
demo_troubleshooting()
demo_production_setup()
print("\n" + "="*60)
print("🎉 全てのデモが正常に完了しました!")
print("📚 詳細な説明は log_article.md をご覧ください。")
print("📁 ログファイルは logs/ ディレクトリに保存されています。")
print("="*60)
except Exception as e:
# 最上位の例外処理
error_logger = logging.getLogger('demo_error')
error_logger.error(f"デモ実行中にエラーが発生: {e}")
raise
if __name__ == "__main__":
main()