studiogadget CI-Stable Test: structlogログ検証の安定化パターン
背景と問題
structlog.testing.capture_logs() はローカルでは動作するが、CI環境（特にpytest-xdist並列実行、GitHub Actions ubuntu runner）では以下の理由でログが取得できないことがある。
- モジュールレベルのロガーキャッシュ: 先行テストがロガーをバインド済みだと
capture_logs()のコンテキストマネージャがログを捕捉できない - pytest-xdist並列実行: ワーカー間でstructlogのグローバル設定が競合する
- caplogメッセージのANSI混入: CI環境のstructlogレンダラがANSIエスケープ付きで出力し、
key=valueの単純一致が崩れる - exc_info の表現差異: CI環境では
record.exc_infoがNoneでもメッセージ本文にTracebackが含まれる場合がある
解決パターン: 2段階フォールバック
パターン概要
capture_logs() で構造化ログを取得
├── 取得成功 → 構造化dictで厳密アサーション
└── 取得失敗（空リスト）→ caplog にフォールバック
└── ANSIエスケープ除去 + key=value正規化してアサーション
実装手順
Step 1: ANSI正規化ユーティリティを定義
import re
_ANSI_ESCAPE_RE = re.compile(r"\x1b\[[0-9;]*m")
def _normalize_log_message(message: str) -> str:
"""ANSIエスケープを除去し、key=value比較しやすい形へ正規化する。"""
normalized = _ANSI_ESCAPE_RE.sub("", message)
normalized = re.sub(r"\s*=\s*", "=", normalized)
return normalized
Step 2: フォールバック付きログ抽出ヘルパーを定義
def _find_event_logs(
captured: list[dict[str, object]],
*,
event: str,
caplog: pytest.LogCaptureFixture,
) -> list[dict[str, object]]:
"""capture_logs の結果が空の場合に caplog をフォールバック利用する。"""
structured = [e for e in captured if e.get("event") == event]
if structured:
return structured
fallback: list[dict[str, object]] = []
seen: set[str] = set()
for record in caplog.records:
msg = _normalize_log_message(record.getMessage())
raw = _normalize_log_message(str(record.msg))
if event in msg or event in raw:
merged = msg if event in msg else raw
if merged in seen:
continue
seen.add(merged)
fallback.append({
"event": event,
"log_level": record.levelname.lower(),
"message": merged,
})
return fallback
設計判断:
seenセットで重複メッセージを除外（capture_logsとcaplog両方に同じログが流れるケースへの対策）record.msg（フォーマット前）も確認する（ハンドラチェーンによる差異を吸収）
Step 3: テスト関数でcaplogを併用
@pytest.mark.asyncio
async def test_example(self, tmp_path: Path, caplog: pytest.LogCaptureFixture) -> None:
caplog.clear()
caplog.set_level(logging.WARNING) # 対象ログレベルに合わせる
with capture_logs() as cap:
await some_function()
logs = _find_event_logs(cap, event="my_event", caplog=caplog)
assert len(logs) >= 1
Step 4: アサーションの分岐パターン
log_entry = logs[0]
assert log_entry["log_level"] == "warning"
# 構造化パス（capture_logs成功時）はキーで直接検証
if "detail_key" in log_entry:
assert log_entry["detail_key"] == expected_value
else:
# フォールバックパス: 正規化済みメッセージでkey=value検証
assert "detail_key=expected_value" in log_entry["message"]
判断チェックリスト
テストでstructlogのログ検証を書く際、以下に該当すれば本パターンを適用する。
-
structlog.testing.capture_logs()でログを検証している - CI（GitHub Actions等）でのみテストが失敗する
- pytest-xdist（
-n auto）で並列実行している - ログメッセージの
key=value部分文字列でアサーションしている
exc_info の検証
CI環境では record.exc_info が None でもメッセージ本文にTracebackが埋め込まれることがある。
fallback.append({
# ...
"exc_info": (
record.exc_info is not None
or "Traceback (most recent call last):" in merged
),
})
件数アサーションの注意
CI環境ではハンドラチェーンの差異によりログが複数回記録されることがある。
== 1よりも>= 1を推奨（特にフォールバックパスで）- 複数件を許容する場合は
logs[-1]（最後のエントリ）で検証すると安定する seenセットによる重複除外を入れても、formatter差異で完全一致しない場合がある
やらないこと（スコープ外）
- ログの出力順序の厳密な検証（CI環境では保証されない）
- structlog自体の設定変更やモンキーパッチ
- caplogだけに依存する方式（構造化ログのキーアクセスが失われる）
- プロダクションコードの変更（テスト側のみで吸収する）
参照
- references/troubleshooting.md: CI環境でよくある失敗パターンと対処法
- scripts/find_event_logs.py: コピー用のヘルパー関数テンプレート