파이썬 로깅에서 여전히 % 템플릿을 쓰는 이유

최근 throttled-py라는 파이썬 오픈소스에 hook 예외 로깅을 추가하였고 머지하며 작업한 내용입니다.

이때, 평소엔 대수롭지 않게 생각하던 로깅 문자열 포맷팅 스타일에 대해 공부해본 내용을 공유하고자 합니다.

# 템플릿 + args
logger.exception("Hook %r raised during on_limit", hook)

# f-string
logger.exception(f"Hook {hook!r} raised during on_limit")

TL;DR

이번 글에선 logging API가 msg와 args를 분리해서 받도록 설계되어 있고, % 템플릿 + args가 그 설계에 맞는 표준 호출 관례를 따르자는 내용을 기술합니다.

Python 공식 문서는 logging의 메시지 포맷팅을 이렇게 설명합니다.^[1]

"Formatting of message arguments is deferred until it cannot be avoided."

이 지연이 가능한 이유는 logging API가 msg와 args를 분리해서 받기 때문입니다. 포맷 문자열과 인자가 따로 전달되므로, 실제로 출력이 필요한 시점까지 합치지 않을 수 있습니다.^[2]

표준 logging은 이렇게 동작합니다

Python 문서는 Logger.debug(msg, *args)를 다음처럼 설명합니다.^[2:1]

• msg는 포맷 문자열
• args는 나중에 msg에 병합되는 인자

그리고 이렇게 덧붙입니다.^[2:2]

"No % formatting operation is performed on msg when no args are supplied."

이 설명은 CPython 구현과 그대로 맞아떨어집니다. LogRecord는 msg와 args를 분리해서 저장하고^[3], getMessage()가 호출될 때 비로소 합칩니다.^[4] Python logging cookbook도 logging package가 내부적으로 % 포맷팅으로 format string과 variable arguments를 합친다고 설명합니다.^[5]

def getMessage(self):
    msg = str(self.msg)
    if self.args:
        msg = msg % self.args
    return msg

그리고 getMessage()는 항상 호출되는 것이 아닙니다. Logger.debug() 같은 메서드는 레벨 체크를 먼저 하고, 통과할 때만 LogRecord를 생성합니다.^[2:3]

def debug(self, msg, *args, **kwargs):
    if self.isEnabledFor(DEBUG):
        self._log(DEBUG, msg, args, **kwargs)

즉, 로그레벨이 특정 레벨보다 더 낮으면 LogRecord 생성도, getMessage()도, msg % args도 전부 일어나지 않습니다. 앞서 말한 공식 문서의 "deferred"가 바로 이 구조입니다.

이 구조적 분리는 레벨이 활성화되어 있을 때도 유지됩니다. % 스타일로 호출하면 LogRecord에 템플릿(record.msg)과 인자(record.args)가 따로 남지만, f-string으로 호출하면 이미 완성된 문자열만 남습니다.

아래 두 코드는 겉보기는 비슷하지만 동작 시점이 다릅니다.

logger.debug("Processing %r", obj)
logger.debug(f"Processing {obj!r}")

첫 번째는 템플릿과 인자를 따로 넘깁니다. 레벨이 꺼져 있으면 repr(obj) 호출이 일어나지 않습니다. 다만 obj 자체는 함수 인자로 평가되어 전달되므로, 인자가 expensive_func()처럼 호출식이라면 % 스타일이든 f-string이든 호출 비용은 동일합니다. deferred formatting이 미루는 것은 문자열 변환(repr(), str() 등) 이지, 인자 표현식 평가가 아닙니다.

두 번째는 f-string이 표현식이기 때문에, logger.debug()가 호출되기 전에 Python이 먼저 repr(obj)를 평가합니다. 레벨과 무관하게 문자열 변환 비용이 발생합니다.

확인해봅시다

저는 스니펫과 실제 테스트코드를 통한 검증으로 내용을 자주 살펴보는 편입니다. 위 내용을 이해하기 위해 짧은 코드로 구동해보면 차이가 드러납니다. 같이 보실까요.

import logging

format_call_count = 0


class ExpensiveObject:
    def __repr__(self) -> str:
        global format_call_count
        format_call_count += 1
        return "ExpensiveObject()"


logger = logging.getLogger("test_lazy")
logger.setLevel(logging.CRITICAL)  # DEBUG 비활성화
logger.addHandler(logging.StreamHandler())

obj = ExpensiveObject()

format_call_count = 0
logger.debug("Processing %r", obj)
print(f"% style, level=CRITICAL: __repr__ called {format_call_count} time(s)")
assert format_call_count == 0

format_call_count = 0
logger.debug(f"Processing {obj!r}")
print(f"f-string, level=CRITICAL: __repr__ called {format_call_count} time(s)")
assert format_call_count == 1

실행 결과는 다음과 같습니다.

% style, level=CRITICAL: __repr__ called 0 time(s)
f-string, level=CRITICAL: __repr__ called 1 time(s)

비활성화된 DEBUG 레벨에서 % 템플릿 + args는 __repr__()를 호출하지 않고, f-string은 호출합니다.

예시로 살펴봅시다

logging API의 msg/args 분리 관례는 널리 사용되는 프로젝트에서도 그대로 나타납니다.

예시 - Django

Django의 데이터베이스 백엔드^[6]는 DDL 실행 시 SQL과 파라미터를 이렇게 로깅합니다.

# django/db/backends/base/schema.py
logger.debug("%s; (params %r)", sql, params)

여기서 중요한 점은 logger.debug()가 msg와 args를 분리해서 받는 표준 시그니처를 그대로 따른다는 것입니다. 이 메서드 안에서 sql은 이미 str(sql)로 변환되지만, params에 대한 %r 변환은 LogRecord가 실제 메시지를 만들 때까지 미뤄집니다. 즉, 이 코드는 "모든 비용을 지연한다"기보다, 표준 logging 관례를 따르면서 문자열 변환 비용을 불필요하게 앞당기지 않는 방식에 가깝습니다.

Django는 이 호출을 단순 문자열 출력으로만 취급하지도 않습니다. 관련 테스트^[7]는 record.sql, record.params, record.getMessage()를 각각 검증합니다. 즉, Django는 이 로그를 "최종 문자열 하나"가 아니라, 구조를 가진 logging 이벤트로 다루고 있습니다. 이런 점에서도 % 템플릿 + args는 오래된 습관이라기보다, LogRecord의 구조를 그대로 살리는 관례라고 볼 수 있습니다.

예시 - urllib3

urllib3도 재시도 로깅^[8]에서 같은 패턴을 씁니다.

# src/urllib3/connectionpool.py
log.warning(
    "Retrying (%r) after connection broken by '%r': %s",
    retries, err, url
)

여기서도 Retry 객체와 예외 객체 err는 템플릿과 분리된 인자로 전달됩니다. 따라서 %r에 해당하는 repr() 평가는 로그 메시지가 실제로 포맷될 때 일어납니다. 이 역시 % 스타일이 특별한 최적화 기법이라기보다, 표준 logging 호출 관례를 그대로 따르는 예라고 보는 편이 정확합니다.

urllib3의 테스트도 이 구조를 전제로 작성되어 있습니다. 깨진 헤더를 주입하는 테스트^[9]는 로그를 순회하면서 record.msg에 "Failed to parse headers"가 포함되는지, record.args가 튜플인지, 그리고 URL이 record.args[0]에 들어 있는지를 검사한 뒤, 필요하면 record.getMessage()에 특정 원문 헤더가 포함되는지까지 확인합니다. 즉, urllib3도 이 로그를 단순 문자열이 아니라, 템플릿과 인자가 분리된 logging 이벤트로 취급하고 있다고 볼 수 있습니다.

즉, 실제 프로젝트들이 % 템플릿 + args를 쓰는 이유를 "성능을 위한 특수한 선택"으로 볼 필요는 없습니다.^[10] 표준 logging API 설계를 따르는 호출 관례가 널리 쓰이고 있고, deferred formatting은 그 결과로 자연스럽게 따라오는 특성이라고 보는 편이 더 정확합니다.

observability 도구에서의 영향

표준 logging의 msg/args 분리는 observability 도구로 넘어갈 때도 의미를 가집니다. 다만 도구마다 활용 방식과 영향 범위가 다르므로, 어떤 경우에 실질적 차이가 있는지 구분할 필요가 있습니다.

Sentry

Sentry Python SDK의 logging integration은 record.msg와 record.getMessage()를 따로 저장합니다.^[11]

event["logentry"] = {
    "message": to_string(message),
    "formatted": record.getMessage(),
    "params": params,
}

message에는 템플릿, formatted에는 완성된 문자열이 들어갑니다. 다만 Sentry의 이벤트 그룹핑 우선순위는 fingerprint → stacktrace → exception type+value → message 순입니다.^[12] logger.exception()처럼 exception과 stacktrace가 포함된 경우, stacktrace가 그룹핑 기준이 되므로 message가 f-string이든 %든 같은 Issue로 묶입니다. message가 그룹핑에 직접 영향을 주는 것은 stacktrace도 exception도 없는 순수 로그 메시지에 한정됩니다.

즉, 이 글의 출발점인 logger.exception() 사례에서는 Sentry 그룹핑에 실질적 차이가 없습니다. 다만 logger.warning()이나 logger.info()처럼 exception 없이 다양한 인자로 호출되는 순수 로그 메시지에서는 % 템플릿이 일관된 그룹핑에 도움이 됩니다.

Logfire

Logfire의 logging integration도 record.msg를 템플릿 fallback으로 사용합니다.^[13]

self.logfire_instance.log(
    msg_template=attributes.pop(ATTRIBUTES_MESSAGE_TEMPLATE_KEY, record.msg),
    ...
)

표준 logging에서 % 스타일을 쓰면 record.msg에 템플릿이 남고, f-string을 쓰면 이미 완성된 문자열이 남습니다. 이 값이 그대로 msg_template으로 넘어갑니다.

Logfire의 직접 API는 Python 3.11+에서 f-string에서도 템플릿을 복원할 수 있으므로, low-cardinality span name 유지가 가능합니다.^[14] 다만 이 복원은 Logfire의 직접 API(logfire.info(...) 등)에서만 동작하고, 표준 logging 호출을 거치는 경우에는 완성된 문자열만 전달되므로 템플릿 정보가 남지 않습니다.

정리하면, observability 도구들이 msg/args 분리를 항상 필요로 하는 것은 아닙니다. 하지만 템플릿과 인자를 분리해서 전달하면, 도구가 이를 활용할 수 있는 여지를 남겨둔다는 점에서 더 호환성 있는 선택입니다.

프로젝트 규칙도 같은 방향입니다

throttled-py는 Ruff의 G 룰셋을 활성화하고 있습니다.^[15]

[tool.ruff.lint]
select = [
    "F",
    "E",
    "W",
    "C90",
    "I",
    "D",
    "UP",
    "SIM",
    "G",
    "LOG",
]

Ruff의 G004 규칙은 logging 호출에서 f-string 사용을 경고합니다.^[16]
이 저장소에서는 표준 logging의 기본 사용법을 따르는 쪽이 문서뿐 아니라 lint 규칙과도 맞습니다.

class BraceMessage:
    def __init__(self, fmt, /, *args, **kwargs):
        self.fmt = fmt
        self.args = args
        self.kwargs = kwargs

    def __str__(self):
        return self.fmt.format(*self.args, **self.kwargs)

__ = BraceMessage
logger.debug(__('Message with {0} {name}', 2, name='World'))

throttled-py에 기여한 방식

위와 같은 이유로 이 저장소에서 hook 예외 로깅을 아래처럼 구현하였습니다.

logger.exception("Hook %r raised during on_limit", hook)

logger.exception()은 ERROR 레벨이므로 프로덕션에서 비활성화될 일이 거의 없고, hook의 repr() 비용도 미미합니다. 이 사례에서 % 템플릿을 쓰는 이유는 성능이 아니라, logging API의 msg/args 분리 설계를 일관되게 따르기 위해서입니다. 프로젝트 전체에서 logging 호출 스타일을 통일하면, logger.debug() 같은 비활성화 가능성이 높은 레벨에서도 자연스럽게 deferred formatting의 이점을 얻습니다.

f-string의 장점도 분명합니다

f-string이 logging에서 deferred formatting을 활용하지 못하는 것은 사실이지만, 일반적인 문자열 포맷팅에서 f-string은 가장 권장되는 방식입니다. Effective Python 3rd Edition은 C-style % 포맷팅이나 str.format() 대신 f-string을 쓸 것을 권합니다.^[17]

• 가독성: f"Hook {hook!r} raised during on_limit"는 "Hook %r raised during on_limit", hook보다 읽기 쉽습니다. 템플릿과 인자가 한 곳에 있으므로 눈이 왔다 갔다 할 필요가 없습니다.
• 표현력: f-string은 % 포맷팅보다 풍부한 표현식을 지원합니다.

정리하면

logging 모듈의 API는 msg와 args를 분리해서 받도록 설계되어 있고, 공식 문서는 이를 "deferred formatting"이라고 설명합니다.

이 설계를 따르면 레벨이 꺼져 있을 때 불필요한 문자열 변환을 피할 수 있고, 일부 observability 도구가 템플릿과 인자를 구분해서 활용할 수 있습니다. f-string은 가독성에서 이점이 있지만, logging 호출에서는 이 분리 구조를 활용하지 않습니다. % 템플릿 + args는 표준 호출 관례와 도구 상호운용성 측면에서 가장 자연스러운 방식이며, 이 저장소에서는 API 설계에 맞는 호출 관례를 일관되게 따르는 쪽을 선택했습니다.

일반 코드에서는 f-string이 여전히 좋은 선택입니다^[18]. 이 글에서 말하는 것은 logging 모듈 호출에 한정된 이야기입니다.

감사합니다.