Pythonのloggingモジュールをまとめてみた。

# Pythonのloggingモジュールをまとめてみた

## はじめに

現場でDjangoRestFrameworkを使用していてログの方式設計を作る必要があった。
公式ドキュメントを参考に以下をまとめてみた。

## 目次
1. loggingモジュールの基本
2. ログレベルとは
3. フォーマッタの設定
4. ハンドラの種類と使い方
5. ロガーの階層構造
6. 設定ファイルによるログ設定
7. 実践的なログ管理パターン
8. よくある質問とトラブルシューティング

## 1. loggingモジュールの基本

### 基本的な使い方

最も単純なloggingモジュールの使い方は次のとおりです

```python
import logging

# デフォルトのログレベルはWARNING
logging.warning('警告メッセージです')
logging.error('エラーメッセージです')

# これらは表示されない（デフォルトではWARNING以上のみ表示）
logging.debug('デバッグメッセージです')
logging.info('情報メッセージです')
```

出力結果
```
WARNING:root:警告メッセージです
ERROR:root:エラーメッセージです
```

### 基本設定を変更する

ログレベルや出力フォーマットを変更するには、basicConfig()を使用します

```python
import logging

# ログの基本設定
logging.basicConfig(
    level=logging.DEBUG,  # ログレベルをDEBUGに設定
    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',  # 出力フォーマット
    filename='app.log',  # ファイルに出力する場合
    filemode='w'  # 'w'は上書き、'a'は追記
)

logging.debug('デバッグメッセージです')
logging.info('情報メッセージです')
logging.warning('警告メッセージです')
```

出力結果（app.logファイル）
```
2025-05-13 12:30:45,123 - root - DEBUG - デバッグメッセージです
2025-05-13 12:30:45,124 - root - INFO - 情報メッセージです
2025-05-13 12:30:45,125 - root - WARNING - 警告メッセージです
```

## 2. ログレベルとは

Pythonのloggingモジュールには、以下の標準ログレベルがあります（数値が大きいほど重要度が高い）

| レベル | 数値 | 使用シーン |
|--------|------|------------|
| DEBUG | 10 | 詳細な診断情報 |
| INFO | 20 | 正常動作の確認 |
| WARNING | 30 | 潜在的な問題の警告 |
| ERROR | 40 | エラーにより機能が実行できなかった |
| CRITICAL | 50 | プログラムが継続できない重大な問題 |

```python
import logging

# ログレベルを設定
logging.basicConfig(level=logging.INFO)

logging.debug('これは表示されません')  # INFOレベル未満なので表示されない
logging.info('アプリケーションを開始しました')
logging.warning('設定ファイルが見つかりません、デフォルト値を使用します')
logging.error('ファイルの処理中にエラーが発生しました')
logging.critical('システムがクラッシュしました！直ちに対応してください')
```

また、カスタムログレベルを追加することも可能です

```python
import logging

# カスタムログレベルの定義（VERBOSE = 15）
VERBOSE = 15
logging.addLevelName(VERBOSE, "VERBOSE")

# カスタムログレベル用のメソッドを追加
def verbose(self, message, *args, **kwargs):
    if self.isEnabledFor(VERBOSE):
        self._log(VERBOSE, message, args, **kwargs)

# Loggerクラスにメソッドを追加
logging.Logger.verbose = verbose

# 設定
logging.basicConfig(level=logging.DEBUG)
logger = logging.getLogger(__name__)

# 使用例
logger.debug("デバッグメッセージ")
logger.verbose("詳細情報")
logger.info("情報メッセージ")
```

## 3. フォーマッタの設定

ログメッセージの形式をカスタマイズするには、Formatterを使用します

```python
import logging

# フォーマッタの作成
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# ハンドラの作成と設定
handler = logging.StreamHandler()
handler.setFormatter(formatter)

# ロガーの作成と設定
logger = logging.getLogger('my_app')
logger.setLevel(logging.DEBUG)
logger.addHandler(handler)

# ログの出力
logger.debug('フォーマットされたデバッグメッセージ')
```

フォーマット文字列で使用可能な主な変数

| フォーマット | 説明 |
|------------|------|
| %(asctime)s | ログ記録時刻 |
| %(name)s | ロガー名 |
| %(levelname)s | ログレベル名 |
| %(levelno)d | ログレベル番号 |
| %(pathname)s | ログ呼び出し元のファイルパス |
| %(filename)s | ファイル名 |
| %(module)s | モジュール名 |
| %(funcName)s | 関数名 |
| %(lineno)d | 行番号 |
| %(message)s | ログメッセージ |
| %(process)d | プロセスID |
| %(thread)d | スレッドID |
| %(threadName)s | スレッド名 |

時刻フォーマットのカスタマイズ

```python
import logging
import datetime

# カスタム時刻フォーマットを持つフォーマッタ
formatter = logging.Formatter(
    '%(asctime)s - %(levelname)s - %(message)s',
    datefmt='%Y-%m-%d %H:%M:%S'  # 時刻フォーマットをカスタマイズ
)

handler = logging.StreamHandler()
handler.setFormatter(formatter)

logger = logging.getLogger('time_formatter')
logger.setLevel(logging.INFO)
logger.addHandler(handler)

logger.info('カスタム時刻フォーマットを使用したメッセージ')
```

## 4. ハンドラの種類と使い方

loggingモジュールには、様々な出力先にログを送るための「ハンドラ」が用意されています。

### 主要なハンドラの種類

1. **StreamHandler** - コンソールに出力
2. **FileHandler** - ファイルに出力
3. **RotatingFileHandler** - サイズベースでローテーションするファイル
4. **TimedRotatingFileHandler** - 時間ベースでローテーションするファイル
5. **SMTPHandler** - メール送信
6. **SysLogHandler** - Syslog出力
7. **HTTPHandler** - HTTP経由で送信

### 複数ハンドラの併用例

```python
import logging
from logging.handlers import RotatingFileHandler

# ロガーの作成
logger = logging.getLogger('multi_handler')
logger.setLevel(logging.DEBUG)

# フォーマッタの作成
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# コンソール出力用ハンドラ（WARNING以上）
console_handler = logging.StreamHandler()
console_handler.setLevel(logging.WARNING)
console_handler.setFormatter(formatter)

# ファイル出力用ハンドラ（すべてのログ）
# 最大1MBで、5ファイルまでバックアップ
file_handler = RotatingFileHandler(
    'app.log', maxBytes=1024*1024, backupCount=5
)
file_handler.setLevel(logging.DEBUG)
file_handler.setFormatter(formatter)

# ハンドラをロガーに追加
logger.addHandler(console_handler)
logger.addHandler(file_handler)

# ログの出力
logger.debug('デバッグ情報（ファイルのみ）')
logger.info('一般情報（ファイルのみ）')
logger.warning('警告（コンソールとファイル）')
logger.error('エラー（コンソールとファイル）')
```

### 日付ベースのローテーション例

```python
import logging
from logging.handlers import TimedRotatingFileHandler

logger = logging.getLogger('timed_rotating')
logger.setLevel(logging.INFO)

# 毎日午前0時にローテーション、30日分保持
handler = TimedRotatingFileHandler(
    'app.log',
    when='midnight',  # 'midnight', 'h'（時間）, 'd'（日）, 'w0'-'w6'（曜日）, 'm'（分）
    interval=1,      # 間隔
    backupCount=30   # 保持するバックアップ数
)
formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
handler.suffix = "%Y%m%d"  # ファイル名のサフィックス形式

logger.addHandler(handler)

logger.info('日付ベースのローテーションテスト')
```

## 5. ロガーの階層構造

loggingモジュールのロガーは階層構造になっており、親子関係を持ちます。これにより、大規模なアプリケーションでもログ管理が容易になります。

```python
import logging

# ロガーの階層設定
logging.basicConfig(level=logging.WARNING)

# 親ロガー
parent_logger = logging.getLogger('app')
parent_logger.setLevel(logging.INFO)

# 子ロガー（名前が'app.module1'となる）
child_logger1 = logging.getLogger('app.module1')
# 子ロガー（名前が'app.module2'となる）
child_logger2 = logging.getLogger('app.module2')
# 特定の子ロガーだけレベルを変更
child_logger2.setLevel(logging.DEBUG)

# ログ出力テスト
parent_logger.info('親ロガーからのINFO')  # 表示される
child_logger1.debug('子1からのDEBUG')     # 表示されない（親のINFOレベルを継承）
child_logger1.info('子1からのINFO')       # 表示される
child_logger2.debug('子2からのDEBUG')     # 表示される（独自にDEBUGレベルを設定）
```

### 伝播（Propagation）の制御

デフォルトでは、子ロガーのログメッセージは親ロガーにも伝播します。この動作を制御するには、`propagate`属性を使用します

```python
import logging

# ハンドラとフォーマッタの設定
console_handler = logging.StreamHandler()
formatter = logging.Formatter('%(name)s - %(levelname)s - %(message)s')
console_handler.setFormatter(formatter)

# 親ロガーの設定
parent_logger = logging.getLogger('parent')
parent_logger.setLevel(logging.INFO)
parent_logger.addHandler(console_handler)

# 子ロガーの設定
child_logger = logging.getLogger('parent.child')
child_logger.setLevel(logging.DEBUG)

# 独自のハンドラを追加
child_handler = logging.StreamHandler()
child_handler.setFormatter(logging.Formatter('CHILD: %(message)s'))
child_logger.addHandler(child_handler)

# 伝播をオフにする
child_logger.propagate = False

# ログ出力
parent_logger.info('親ロガーからのメッセージ')  # 親ハンドラで処理
child_logger.info('子ロガーからのメッセージ')   # 子ハンドラのみで処理（親には伝播しない）
```

## 6. 設定ファイルによるログ設定

大規模なアプリケーションでは、Pythonコード内でログ設定を行うより、設定ファイルから読み込む方が管理しやすいことがあります。

### 設定ファイルの例（logging.conf）

```ini
[loggers]
keys=root,app

[handlers]
keys=consoleHandler,fileHandler

[formatters]
keys=simpleFormatter,detailedFormatter

[logger_root]
level=WARNING
handlers=consoleHandler

[logger_app]
level=DEBUG
handlers=fileHandler
qualname=app
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=INFO
formatter=simpleFormatter
args=(sys.stdout,)

[handler_fileHandler]
class=FileHandler
level=DEBUG
formatter=detailedFormatter
args=('app.log', 'a')

[formatter_simpleFormatter]
format=%(levelname)s - %(message)s

[formatter_detailedFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=%Y-%m-%d %H:%M:%S
```

### 設定ファイルの読み込み

```python
import logging
import logging.config

# 設定ファイルからロガー設定を読み込み
logging.config.fileConfig('logging.conf')

# ロガーの取得
logger = logging.getLogger('app')

# ログ出力
logger.debug('デバッグメッセージ')
logger.info('情報メッセージ')
logger.warning('警告メッセージ')
```

### 辞書形式での設定

設定ファイルの代わりに、辞書を使用して設定することもできます

```python
import logging
import logging.config

# 辞書形式のログ設定
config = {
    'version': 1,
    'formatters': {
        'simple': {
            'format': '%(levelname)s - %(message)s'
        },
        'detailed': {
            'format': '%(asctime)s - %(name)s - %(levelname)s - %(message)s',
            'datefmt': '%Y-%m-%d %H:%M:%S'
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'level': 'INFO',
            'formatter': 'simple',
            'stream': 'ext://sys.stdout'
        },
        'file': {
            'class': 'logging.FileHandler',
            'level': 'DEBUG',
            'formatter': 'detailed',
            'filename': 'app.log',
            'mode': 'a'
        }
    },
    'loggers': {
        'app': {
            'level': 'DEBUG',
            'handlers': ['file'],
            'propagate': False
        }
    },
    'root': {
        'level': 'WARNING',
        'handlers': ['console']
    }
}

# 設定の適用
logging.config.dictConfig(config)

# ロガーの取得と使用
logger = logging.getLogger('app')
logger.debug('デバッグメッセージ（ファイルに記録）')
logger.info('情報メッセージ（ファイルに記録）')

# ルートロガー
root_logger = logging.getLogger()
root_logger.warning('警告メッセージ（コンソールに表示）')
```

## 7. 実践的なログ管理パターン

### 例外情報をログに記録する

```python
import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)

handler = logging.StreamHandler()
formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)

def risky_operation():
    try:
        # 例外が発生する可能性のある操作
        result = 10 / 0
        return result
    except Exception as e:
        # 例外情報をログに記録（スタックトレース付き）
        logger.exception("計算中にエラーが発生しました")
        # または
        # logger.error("計算中にエラーが発生しました", exc_info=True)
        raise  # 例外を再発生させる場合

try:
    risky_operation()
except:
    logger.info("エラーをキャッチしましたが、すでにログに記録されています")
```

### コンテキスト情報の追加

```python
import logging
import uuid
from contextvars import ContextVar

# リクエストIDをコンテキストとして保持
request_id_var = ContextVar('request_id', default=None)

class RequestIdFilter(logging.Filter):
    """ログレコードにリクエストIDを追加するフィルター"""
    def filter(self, record):
        record.request_id = request_id_var.get() or '-'
        return True

# ロガーの設定
logger = logging.getLogger('app')
logger.setLevel(logging.INFO)

handler = logging.StreamHandler()
formatter = logging.Formatter('%(asctime)s [%(request_id)s] - %(levelname)s - %(message)s')
handler.setFormatter(formatter)

# フィルターを追加
request_filter = RequestIdFilter()
handler.addFilter(request_filter)

logger.addHandler(handler)

def process_request(data):
    # リクエストIDを生成
    request_id = str(uuid.uuid4())
    request_id_var.set(request_id)
    
    logger.info(f"リクエスト処理開始: {data}")
    # 何らかの処理
    logger.info("リクエスト処理完了")

# シミュレーション
process_request("テストデータ1")
process_request("テストデータ2")
```

### アプリケーション全体でのログ設定

大規模なアプリケーションでは、モジュールごとに個別のロガーを持ちつつ、全体で一貫した設定を適用すると管理しやすくなります。

例えば、以下のような構造のアプリケーションを考えます

```
myapp/
├── __init__.py
├── main.py
├── config/
│   ├── __init__.py
│   └── log_config.py
├── database/
│   ├── __init__.py
│   └── db.py
└── api/
    ├── __init__.py
    └── routes.py
```

`config/log_config.py`でログ設定を一元管理

```python
import logging
import logging.config
import os

def setup_logging(default_level=logging.INFO):
    """アプリケーション全体のログ設定を行う"""
    log_config = {
        'version': 1,
        'disable_existing_loggers': False,
        'formatters': {
            'standard': {
                'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'
            },
            'detailed': {
                'format': '%(asctime)s [%(levelname)s] %(name)s [%(filename)s:%(lineno)d]: %(message)s'
            },
        },
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'level': 'INFO',
                'formatter': 'standard',
            },
            'file': {
                'class': 'logging.handlers.RotatingFileHandler',
                'level': 'DEBUG',
                'formatter': 'detailed',
                'filename': 'app.log',
                'maxBytes': 10485760,  # 10MB
                'backupCount': 5,
                'encoding': 'utf8',
            },
        },
        'loggers': {
            '': {  # rootロガー
                'handlers': ['console', 'file'],
                'level': default_level,
                'propagate': True
            },
            'myapp': {
                'handlers': ['console', 'file'],
                'level': 'DEBUG',
                'propagate': False,
            },
            'myapp.database': {
                'level': 'INFO',
                'propagate': True,
            },
        }
    }
    
    # 開発環境ではより詳細なログを表示
    if os.environ.get('ENVIRONMENT') == 'development':
        log_config['handlers']['console']['level'] = 'DEBUG'
        log_config['handlers']['console']['formatter'] = 'detailed'
    
    logging.config.dictConfig(log_config)
```

アプリケーションの各部分でロガーを使用

`main.py`:
```python
from myapp.config.log_config import setup_logging
import logging

def main():
    # アプリケーション開始時にログ設定を行う
    setup_logging()
    
    logger = logging.getLogger('myapp')
    logger.info('アプリケーションを開始しました')
    
    # 他のモジュールを呼び出す
    from myapp.database.db import init_db
    from myapp.api.routes import setup_routes
    
    init_db()
    setup_routes()
    
    logger.info('アプリケーションの準備が完了しました')

if __name__ == '__main__':
    main()
```

`database/db.py`:
```python
import logging

# モジュール固有のロガーを取得
logger = logging.getLogger('myapp.database')

def init_db():
    logger.info('データベース初期化を開始します')
    # 処理内容
    logger.debug('接続パラメータを設定しています')
    # 詳細な処理内容
    logger.info('データベース初期化が完了しました')
```

## まとめ
特にハンドラとフォーマッタはあまり意識しないで今まで設定していた。
環境に合わせて、選択しないといけないと思った。
また開発時にはカスタムログレベルを作成してログ出力してみてもいいかも。。


## 参考リンク

- [Python公式ドキュメント - loggingモジュール](https://docs.python.org/ja/3/library/logging.html)
- [Python公式ドキュメント - loggingのクックブック](https://docs.python.org/ja/3/howto/logging-cookbook.html)