前提
本日のお題
14. 自作ロガー & デコレータ
何を作る？
関数の開始/終了時間と引数・戻り値をログ出力するデコレータを作る。
学べること
- デコレータの記法
-
loggingモジュールの使い方 - 高階関数とクロージャ
面白いところ
- 既存の自分のスクリプトに一行足すだけでログが付き始める
- ログフォーマットを工夫して「見やすい実行トレース」を作れる
回答
コード
14_logger.py
"""
自作ロガー & デコレータ
- 関数の開始/終了、引数・戻り値、経過時間を logging で出力する
- 既存関数に @log_call を付けるだけでログが載る
"""
import logging
import time
from functools import wraps
from typing import Any, Callable, TypeVar, cast
F = TypeVar("F", bound=Callable[..., Any])
# ===== ロガー設定（最低限） =====
def setup_logger() -> logging.Logger:
"""
簡易 logger 設定。
実務ではここをプロジェクト共通の設定に差し替えるイメージ。
"""
logger = logging.getLogger("myapp")
logger.setLevel(logging.DEBUG)
if not logger.handlers:
handler = logging.StreamHandler()
fmt = "[%(asctime)s] [%(levelname)s] [%(name)s] %(message)s"
handler.setFormatter(logging.Formatter(fmt))
logger.addHandler(handler)
return logger
LOGGER = setup_logger()
# ===== デコレータ本体 =====
def log_call(
logger: logging.Logger | None = None,
level: int = logging.INFO,
) -> Callable[[F], F]:
"""
関数の開始/終了・引数・戻り値・実行時間をログ出力するデコレータ。
使用例:
@log_call()
def add(a, b):
return a + b
@log_call(logger=my_logger, level=logging.DEBUG)
def slow_func():
...
"""
if logger is None:
logger = LOGGER
def decorator(func: F) -> F:
@wraps(func)
def wrapper(*args: Any, **kwargs: Any) -> Any:
# 引数の短い文字列表現を用意（長すぎるとログがつらいので適当に切る）
def short_repr(obj: Any, max_len: int = 80) -> str:
r = repr(obj)
return r if len(r) <= max_len else r[: max_len - 3] + "..."
args_repr = ", ".join(short_repr(a) for a in args)
kwargs_repr = ", ".join(f"{k}={short_repr(v)}" for k, v in kwargs.items())
joined = ", ".join(x for x in [args_repr, kwargs_repr] if x)
logger.log(
level,
f"CALL {func.__name__}({joined})",
)
start = time.perf_counter()
try:
result = func(*args, **kwargs)
except Exception as e:
elapsed = (time.perf_counter() - start) * 1000
logger.exception(
f"EXCEPTION in {func.__name__} after {elapsed:.1f} ms: {e!r}"
)
raise
else:
elapsed = (time.perf_counter() - start) * 1000
logger.log(
level,
f"RETURN {func.__name__} -> {short_repr(result)} "
f"({elapsed:.1f} ms)",
)
return result
return cast(F, wrapper)
return decorator
# ===== デモ用の関数たち =====
@log_call()
def add(a: int, b: int) -> int:
time.sleep(0.1)
return a + b
@log_call(level=logging.DEBUG)
def concat_words(*words: str, sep: str = " ") -> str:
time.sleep(0.05)
return sep.join(words)
@log_call()
def will_fail(x: int) -> float:
# わざと 0 除算して例外ログを出す
return 10 / x
def main():
add(1, 2)
concat_words("hello", "world", sep="-")
try:
will_fail(0)
except ZeroDivisionError:
pass
if __name__ == "__main__":
main()
実行例
$python 14_logger.py
[2025-12-15 09:11:04,164] [INFO] [myapp] CALL add(1, 2)
[2025-12-15 09:11:04,264] [INFO] [myapp] RETURN add -> 3 (99.6 ms)
[2025-12-15 09:11:04,265] [DEBUG] [myapp] CALL concat_words('hello', 'world', sep='-')
[2025-12-15 09:11:04,316] [DEBUG] [myapp] RETURN concat_words -> 'hello-world' (50.0 ms)
[2025-12-15 09:11:04,316] [INFO] [myapp] CALL will_fail(0)
[2025-12-15 09:11:04,316] [ERROR] [myapp] EXCEPTION in will_fail after 0.0 ms: ZeroDivisionError('division by zero')
Traceback (most recent call last):
File "C:\Users\kokekokko\Documents\Src\chatgpt-challenge-python\14_logger.py", line 76, in wrapper
result = func(*args, **kwargs)
File "C:\Users\kokekokko\Documents\Src\chatgpt-challenge-python\14_logger.py", line 114, in will_fail
return 10 / x
ZeroDivisionError: division by zero
感想
- デコレータでログを仕込むのはありなのかもしれない？と思った
- デコレータの実装に慣れるのが億劫という話は多分ある