Coverage for utils/logger.py: 96.36%

1"""structlogロガー取得モジュール

3プロジェクト共通のstructlogロガーを提供。

4config/settings.pyのLogConfigと連携して動作。

5Sentry統合によりERROR以上のログを自動送信。

7使用例:

8 from utils.logger import get_logger

10 logger = get_logger(__name__)

11 logger.info("処理開始", user_id=123, action="login")

13"""

15from __future__ import annotations

17import os

18import sys

19import threading

20import time

21from types import TracebackType

22from typing import Any, Literal, cast

24import structlog

25from structlog.typing import FilteringBoundLogger, WrappedLogger

27from config.settings import LogFormat, get_settings

29# _sentry_warning_lock: per-process 1 回抑制フラグ群を同一critical sectionで確認・更新するlock。

30# **重要制約**: lock 内はフラグ操作 (_sentry_warnings_emitted への add/in) と

31# 純粋な文字列生成 (事前計算済み値の結合のみ) に限定すること。

32# str(e) / _sentry_debug_detail(e) 等のユーザーコード呼び出しを lock 内に置くと、

33# カスタム例外の __str__ が logging 経由で再帰的に lock 取得を試み

34# threading.Lock (非再入) のデッドロックが発生する。詳細: _emit_permanent_warning docstring。

35_sentry_warning_lock = threading.Lock()

37# 6 つの permanent throttle 状態を 1 つの set に統合 (旧 bool flags 群の代替)。

38# キー: "settings" / "sdk" / "bug" / "outside_except" /

39# "invalid_exc_info" / "safe_error_summary"

40# 新フラグ追加時はキー文字列の追加のみで済む (`add` / `in` のみ)。

41_sentry_warnings_emitted: set[str] = set()

43# _sentry_send_error は permanent flag ではなく timestamp ベースで再警告を許可する

44# (ネットワーク瞬断後の永続サイレント化を防止)。詳細は _emit_sentry_send_error 参照。

45_sentry_send_error_last_warned: float = float("-inf")

46_SENTRY_SEND_ERROR_WARN_INTERVAL: float = 300.0 # 5分

48# event_dict から Sentry extra へ渡す際に除外する予約キー (frozenset で O(1) lookup)

49_SENTRY_EXCLUDED_KEYS: frozenset[str] = frozenset(

50 {

51 "event",

52 "level",

53 "timestamp",

54 "exc_info",

55 "logger",

56 }

57)

59# structlog の "EXCEPTION" レベルを Sentry SDK が受理するレベルへ正規化するマップ。

60# structlog の "exception" は Sentry 側に存在しないため "error" へマップする。

61_SENTRY_LEVEL_MAP: dict[str, Literal["error", "critical"]] = {

62 "error": "error",

63 "critical": "critical",

64 "exception": "error", # structlog "exception" → Sentry "error" へ正規化

65}

67# SENTRY_DEBUG 有効時に stderr へ出力する例外詳細の最大文字数 (CWE-532 対策)

68_SENTRY_DEBUG_DETAIL_MAX_LEN: int = 100

71def _is_sentry_debug_enabled() -> bool:

72 """SENTRY_DEBUG 環境変数が有効か判定

74 環境変数の変更はリアルタイムに反映される（キャッシュなし）。

75 デプロイ後のSENTRY_DEBUG有効化に対応し、プロセス再起動不要。

76 os.environ.get() はO(1)で軽量なため、呼び出しごとのチェックでも

77 通常のホットパスへの影響は小さい。

78 """

79 return os.environ.get("SENTRY_DEBUG", "").lower() in ("true", "1", "yes")

82def _sentry_debug_detail(e: Exception) -> str:

83 # CWE-532: str(e)[:100] でDSN/レスポンスボディ漏洩を防止

84 if _is_sentry_debug_enabled():

85 return f": {str(e)[:_SENTRY_DEBUG_DETAIL_MAX_LEN]}"

86 return ""

89def _emit_sentry_send_error(e: Exception) -> None:

90 """Sentry送信失敗の stderr 警告を timestamp ベースで throttle 出力

92 一時的なネットワーク瞬断 (デプロイ直後等) で永続的にサイレント化される問題を

93 回避するため bool flag ではなく `_SENTRY_SEND_ERROR_WARN_INTERVAL` (5分) 経過後に

94 再警告を許可する。DSN/HTTP レスポンスボディ漏洩防止のため SENTRY_DEBUG 有効時でも

95 str(e) を 100 文字に切り詰める (CWE-532)。

96 """

97 global _sentry_send_error_last_warned

98 # str(e) を lock 外で評価: カスタム例外の __str__ が logging 経由で再帰的に

99 # _sentry_warning_lock (非再入) を取得しようとした場合のデッドロックを防止する。

100 detail = _sentry_debug_detail(e)

101 with _sentry_warning_lock:

102 # timestamp capture/update を lock 内で直列化し、別スレッドの古い `now` が

103 # 新しい書き込みを巻き戻す race を防ぐ。

104 now = time.monotonic()

105 if now - _sentry_send_error_last_warned < _SENTRY_SEND_ERROR_WARN_INTERVAL:

106 return

107 _sentry_send_error_last_warned = now

108 message = f"[SENTRY_ERROR] Failed to send to Sentry: {type(e).__name__}{detail}"

109 print(message, file=sys.stderr)

110

111

112def _emit_permanent_warning(key: str, message: str) -> None:

113 """per-process 1 回限りの stderr 警告 (permanent throttle 共通実装)

114

115 `_sentry_warnings_emitted` set への atomic な check-and-set を行い、既登録なら

116 何もしない。print() は lock 解放後に実行しスタベーションを軽減する。

117

118 `message` を eager string (str) として受け取ることで、lock 内はフラグ操作のみ

119 に限定される。これにより `_sentry_debug_detail(e)` 等を含む文字列生成コードが

120 lock 取得前に評価され、デッドロックリスクが型システムで構造的に排除される。

121 """

122 # 早期リターン (lock 外): set への要素追加は monotonic で戻らないため race-free。

123 # ERROR ストーム時の lock 取得コスト積算を排除し、_emit_import_error_warnings の

124 # 同等パターンと設計整合性を確保する。

125 if key in _sentry_warnings_emitted:

126 return

127 with _sentry_warning_lock:

128 if key in _sentry_warnings_emitted: 128 ↛ 129line 128 didn't jump to line 129 because the condition on line 128 was never true

129 return

130 _sentry_warnings_emitted.add(key)

131 print(message, file=sys.stderr)

132

133

134def _emit_sentry_bug_error(e: Exception) -> None:

135 """Sentry内部バグの stderr 警告を per-process 1 回に throttle 出力

136

137 SDK API 不整合等のバグを通常の Sentry 送信失敗 [SENTRY_ERROR] と区別し、

138 SENTRY_DEBUG ガード + str(e)[:100] 制限で内部状態の log aggregation への漏洩を防止する

139 (CWE-532 対策、_emit_sentry_send_error と同等の防御)。

140 """

141 detail = _sentry_debug_detail(e)

142 _emit_permanent_warning(

143 "bug",

144 f"[SENTRY_BUG] internal error in _sentry_processor: {type(e).__name__}{detail}"

145 "; further [SENTRY_BUG] warnings suppressed until process restart",

146 )

147

148

149def _emit_outside_except_warning() -> None:

150 """logger.exception() を except ブロック外で呼んだ場合の per-process 1 回警告"""

151 _emit_permanent_warning(

152 "outside_except",

153 "[SENTRY_WARN] logger.exception() called outside except block,"

154 " falling back to capture_message",

155 )

156

157

158def _emit_invalid_exc_info_warning(exc_info: object) -> None:

159 """不正な exc_info 型の throttled 警告を出力"""

160 _emit_permanent_warning(

161 "invalid_exc_info",

162 "[SENTRY_WARN] invalid exc_info type for capture_exception: "

163 f"{type(exc_info).__name__}; falling back to capture_message",

164 )

165

166

167def _is_valid_exc_info_tuple(exc_info: tuple[object, ...]) -> bool:

168 """sys.exc_info() 互換 tuple の最小妥当性を検証"""

169 if len(exc_info) != 3:

170 return False

171

172 exc_type, exc_value, exc_tb = exc_info

173 if not (isinstance(exc_type, type) and issubclass(exc_type, BaseException)): 173 ↛ 174line 173 didn't jump to line 174 because the condition on line 173 was never true

174 return False

175 if not isinstance(exc_value, BaseException): 175 ↛ 176line 175 didn't jump to line 176 because the condition on line 175 was never true

176 return False

177 if not isinstance(exc_value, exc_type): 177 ↛ 178line 177 didn't jump to line 178 because the condition on line 177 was never true

178 return False

179 return exc_tb is None or isinstance(exc_tb, TracebackType)

180

181

182def _emit_safe_error_summary_warning(summary_err: Exception) -> None:

183 """_safe_error_summary 内部失敗の throttled 警告を出力"""

184 _emit_permanent_warning(

185 "safe_error_summary",

186 f"[SENTRY_WARN] _safe_error_summary failed: {type(summary_err).__name__}",

187 )

188

189

190def _safe_error_summary(e: BaseException) -> str:

191 """例外を安全にサマリ化 (情報漏洩防止)

192

193 Pydantic ValidationError の場合は errors(include_input=False) で input 値を除外し

194 エラー件数のみ返す。それ以外は型名のみ返す (str(e) は呼び出さない)。

195

196 errors() 呼出失敗時は stderr に型名のみ 1 回出力し、運用時の完全サイレント化を

197 回避する。Pydantic v3 互換性デバッグの足がかりとして使用。

198

199 引数型は `BaseException` を受理 (`Exception` のみならず `KeyboardInterrupt` 等

200 システム例外も型システム上は安全に扱える設計とするため)。実際の呼び出し元では

201 `except Exception` で捕捉した値のみ渡している。

202 """

203 errors_fn = getattr(e, "errors", None)

204 if callable(errors_fn):

205 try:

206 errs = list(errors_fn(include_input=False))

207 return f"{len(errs)} validation error(s)"

208 except (MemoryError, RecursionError): # fmt: skip

209 raise

210 except Exception as summary_err: # noqa: BLE001

211 # errors() 呼出失敗 (Pydantic v3 互換性等) — 型名のみ 1 回通知

212 _emit_safe_error_summary_warning(summary_err)

213 return f"{type(e).__name__} (details sanitized)"

214

215

216def _emit_import_error_warnings() -> None:

217 """sentry-sdk 未インストール時の stderr 警告を throttle 付きで出力

218

219 設計方針: sentry_init.py は startup 時 Fail-Fast (RuntimeError)、

220 logger.py は per-log-call coupling 回避のため警告出力で graceful degrade

221 （本番デプロイ時の未インストール検知可能性を保証）。

222 defensive: get_settings() が reload_settings() 後に ValidationError を

223 発生させる可能性を遮断し log processor 内で例外伝播を防ぐ。

224

225 実装方針 (deadlock-safe / starvation-safe):

226 1. "sdk" マーカーの早期リターンは lock 外で実施 (set への add は monotonic

227 なためダブル評価しても問題なし)

228 2. `get_settings()` は lock 取得前に評価。これにより config/settings.py が将来

229 独自 lock を導入しても循環待ちが発生しない構造を保証する

230 3. `print()` は lock 解放後に実行。lock 内はフラグ操作とメッセージ生成のみ

231 """

232 # 早期リターン (lock 外): set への要素追加は monotonic で戻らないため race-free

233 if "sdk" in _sentry_warnings_emitted:

234 return

235

236 # get_settings() を lock 外で評価 — settings.py 内で lock が追加された場合の

237 # 循環デッドロックを構造的に排除する (TOCTOU は "sdk" マーカー昇格を per-process

238 # 1 回に限定する monotonic 性で吸収)。

239 settings_error: Exception | None = None

240 try:

241 is_prod = get_settings().is_production_like()

242 except Exception as e: # noqa: BLE001 — log processor 内で例外を再送出しない

243 is_prod = True # 本番可能性を排除できないため安全側フォールバック

244 settings_error = e

245

246 # _safe_error_summary() は SENTRY_DEBUG 有効時に内部で print() を実行する可能性が

247 # あるため lock 外で評価する (他の _emit_* 関数の "lock 内はフラグ操作とメッセージ

248 # 生成のみ" 設計方針への整合)。

249 settings_detail: str | None = None

250 if settings_error is not None:

251 # Pydantic ValidationError は str(e) に input_value を平文含むため

252 # 非SecretStr 設定値 (例: API__BASE_URL) が log aggregation に漏洩する。

253 # _safe_error_summary() で input 除外した summary を生成する。

254 settings_detail = _safe_error_summary(settings_error)

255

256 settings_msg: str | None = None

257 sdk_msg: str | None = None

258 # gate: settings_msg / sdk_msg 双方を本番 or SENTRY_DEBUG 有効時のみ stderr 出力。

259 # 設計一貫性: settings_detail は _safe_error_summary() 経由で input 値を除外済み

260 # だが、開発環境で設定ロード失敗ログが無条件に流れる挙動は sdk_msg の throttle と

261 # 非対称であり、ローカル開発時のノイズ源となるため同等のガードを掛ける。

262 should_emit_warnings = is_prod or _is_sentry_debug_enabled()

263 with _sentry_warning_lock:

264 # 二重チェック: lock 取得待機中に他スレッドが昇格させた可能性を吸収

265 if "sdk" in _sentry_warnings_emitted:

266 return

267 if (

268 settings_error is not None

269 and "settings" not in _sentry_warnings_emitted

270 and should_emit_warnings

271 ):

272 settings_msg = (

273 f"[SENTRY_WARN] settings load failed: "

274 f"{type(settings_error).__name__}: {settings_detail}"

275 )

276 _sentry_warnings_emitted.add("settings")

277 # 警告出力有無に関わらず処理済みマークを立てる。

278 # 早期リターン経路を後続呼び出しで発火させ get_settings() 再評価を回避する

279 # (非prod + SENTRY_DEBUG 未設定 path で flag 昇格漏れ → 毎回 lock取得 +

280 # get_settings() 呼び出しが発生する logic gap を解消)。

281 _sentry_warnings_emitted.add("sdk")

282 if should_emit_warnings:

283 sdk_msg = "[SENTRY_WARN] sentry-sdk not installed, skipping Sentry capture"

284

285 if settings_msg is not None:

286 print(settings_msg, file=sys.stderr)

287 if sdk_msg is not None:

288 print(sdk_msg, file=sys.stderr)

289

290

291def _sentry_processor( # noqa: C901

292 logger: WrappedLogger, # noqa: ARG001

293 method_name: str, # noqa: ARG001

294 event_dict: dict[str, Any],

295) -> dict[str, Any]:

296 """Sentry連携プロセッサー

297

298 ERROR以上のログをSentryに送信。

299 sentry-sdk未インストールまたは未初期化時はスキップ

300 （本番環境または SENTRY_DEBUG 有効時は stderr に警告出力）。

301

302 Args:

303 logger: structlogラッパー（structlogプロセッサー規約による必須引数、本実装では未使用）

304 method_name: ログメソッド名（structlogプロセッサー規約による必須引数、本実装では未使用）

305 event_dict: ログイベント辞書

306

307 Returns:

308 変更なしのevent_dict（プロセッサーチェーン継続）

309

310 """

311 # ERROR以上のみ対象

312 log_level = event_dict.get("level", "").upper()

313 if log_level not in ("ERROR", "CRITICAL", "EXCEPTION"):

314 return event_dict

315

316 # _SENTRY_LEVEL_MAP は小文字キー前提のため一度だけ正規化し、後段の

317 # capture_message(level=...) 呼び出し3箇所で再利用する (重複 .lower() 計算回避)。

318 sentry_level: Literal["error", "critical"] = _SENTRY_LEVEL_MAP.get(log_level.lower(), "error")

319

320 # sentry_sdk は sys.modules.get() で参照する (毎回の `import sentry_sdk` で

321 # 発生する CPython の `_ModuleLock` 取得を回避し、ERROR ストーム時の

322 # ロック競合を排除する)。テストの `patch.dict("sys.modules", {"sentry_sdk": ...})`

323 # との互換性も確保される。

324 sentry_sdk = sys.modules.get("sentry_sdk")

325 if sentry_sdk is None:

326 try:

327 _emit_import_error_warnings()

328 except (MemoryError, RecursionError): # fmt: skip

329 # システム例外は再発生させ OOMKilled / 無限再帰検知を妨げない

330 raise

331 except Exception as warn_err: # noqa: BLE001

332 # import warning の失敗は診断補助に限定し、本体のログ処理は止めない

333 print(

334 f"[SENTRY_WARN] Failed to emit import warning: {type(warn_err).__name__}",

335 file=sys.stderr,

336 )

337 return event_dict

338

339 try:

340 # Sentry初期化済みかチェック（SDK 2.x API）

341 client = sentry_sdk.get_client()

342 if not client.is_active():

343 return event_dict

344

345 # イベント情報を取得

346 message = event_dict.get("event", "Unknown error")

347 exc_info = event_dict.get("exc_info")

348

349 # exc_info=True の場合 sys.exc_info() を new_scope() 入場前に snapshot 取得し

350 # TOCTOU を排除する (sys.exc_info() はスレッドローカルだが scope.set_extra() ループや

351 # コンテキストスイッチで例外コンテキストがずれる可能性を防ぐ)。

352 exc_snapshot: tuple[type[BaseException], BaseException, Any] | None = None

353 if exc_info is True:

354 current_exc = sys.exc_info()

355 if current_exc[1] is not None:

356 exc_snapshot = cast(

357 "tuple[type[BaseException], BaseException, Any]",

358 current_exc,

359 )

360

361 # 追加コンテキストをextraとして送信 (exc_info/message 両経路で付与)

362 # frozenset で O(1) lookup

363 extra = {k: v for k, v in event_dict.items() if k not in _SENTRY_EXCLUDED_KEYS}

364 # new_scope() 内で capture_exception/capture_message 双方を実行し

365 # structlog bind された追加コンテキスト (user_id, request_id 等) を Sentry event に付与

366 with sentry_sdk.new_scope() as scope:

367 # set_extra() は user-data の serialization 失敗で AttributeError/TypeError を

368 # 投げる可能性があるため per-key で個別に try 保護し、SDK 内部バグと user-data

369 # エラーを分離する。失敗キーは個別にスキップし他キーの送信を妨げない。

370 for key, value in extra.items():

371 try:

372 scope.set_extra(key, value)

373 except (AttributeError, TypeError): # fmt: skip

374 # user-data serialization failure (e.g. broken __repr__ on Pydantic model)

375 # → 該当キーのみスキップし、追加ログは出さない（PII再露出/再帰防止）

376 continue

377 if exc_info is True:

378 # except ブロック外では sys.exc_info()[1] が None → capture_exception 不可

379 # snapshot 失敗時は capture_message へフォールバック。

380 if exc_snapshot is not None:

381 scope.capture_exception(exc_snapshot)

382 else:

383 _emit_outside_except_warning()

384 scope.capture_message(

385 message,

386 level=sentry_level,

387 )

388 elif exc_info:

389 # 不正な型 (structlog 契約逸脱: BaseException/tuple/True 以外) で

390 # capture_exception が TypeError を raise → 外側 _emit_sentry_bug_error

391 # の throttle 経路で永続silent化する failure mode を回避するため

392 # type guard を入れて capture_message へフォールバックする。

393 if isinstance(exc_info, BaseException):

394 scope.capture_exception(exc_info)

395 elif isinstance(exc_info, tuple) and _is_valid_exc_info_tuple(exc_info):

396 scope.capture_exception(exc_info)

397 else:

398 _emit_invalid_exc_info_warning(exc_info)

399 scope.capture_message(

400 message,

401 level=sentry_level,

402 )

403 else:

404 scope.capture_message(

405 message,

406 level=sentry_level,

407 )

408

409 except (KeyboardInterrupt, SystemExit, MemoryError, RecursionError): # fmt: skip

410 # システム例外は再発生（graceful shutdown/K8s OOMKilled検知対応）

411 raise

412 except (AttributeError, TypeError) as e:

413 # logger 内部または Sentry SDK API 不整合のバグ可能性 — 通常 [SENTRY_ERROR] とは区別

414 _emit_sentry_bug_error(e)

415 except Exception as e: # noqa: BLE001

416 # ネットワーク・SDK 一時障害等の運用エラー

417 _emit_sentry_send_error(e)

418

419 return event_dict

420

421

422def get_logger(name: str | None = None) -> FilteringBoundLogger:

423 """名前付きロガーの取得

424

425 Args:

426 name: ロガー名（通常は__name__を指定）

427

428 Returns:

429 FilteringBoundLogger: structlogのフィルタリング対応BoundLogger

430

431 Example:

432 logger = get_logger(__name__)

433 logger.info("処理完了", elapsed_ms=150)

434 logger.warning("リトライ実行", attempt=2, max_attempts=3)

435 logger.error("API呼び出し失敗", status_code=500, url="/api/users")

436

437 """

438 settings = get_settings()

439

440 # 設定に基づいてstructlogを初期化（初回のみ）

441 if not structlog.is_configured():

442 _configure_structlog(settings.log.format, settings.get_log_level())

443

444 return cast("FilteringBoundLogger", structlog.get_logger(name))

445

446

447def _configure_structlog(log_format: LogFormat, log_level: int) -> None:

448 """structlogの初期化（内部関数）

449

450 Args:

451 log_format: ログフォーマット（console/json）

452 log_level: ログレベル（logging定数）

453

454 """

455 # 共通プロセッサー（Sentry連携を含む）

456 shared_processors: list[Any] = [

457 structlog.contextvars.merge_contextvars,

458 structlog.processors.add_log_level,

459 structlog.processors.TimeStamper(fmt="iso"),

460 structlog.dev.set_exc_info,

461 _sentry_processor, # Sentry連携（ERROR以上を送信）

462 ]

463

464 # フォーマット別レンダラー

465 processors: list[Any]

466 if log_format == LogFormat.JSON:

467 processors = [

468 *shared_processors,

469 structlog.processors.JSONRenderer(),

470 ]

471 else:

472 processors = [

473 *shared_processors,

474 structlog.dev.ConsoleRenderer(colors=True),

475 ]

476

477 structlog.configure(

478 processors=processors,

479 wrapper_class=structlog.make_filtering_bound_logger(log_level),

480 context_class=dict,

481 logger_factory=structlog.PrintLoggerFactory(),

482 cache_logger_on_first_use=True,

483 )

Coverage for utils / logger.py: 96.36%

162 statements