Python의 Logging: production을 위한 설정

1. 개요

작은 스크립트를 작성할 때 print()로 충분합니다. 하지만 production에서는 다릅니다: 로그를 level별로 필터링하고, 로그를 중앙화된 시스템으로 수집하고, 여러 로그 라인에서 하나의 request를 추적하고, 로깅이 애플리케이션을 느리게 만들지 않아야 합니다.

이 글은 production을 위한 Python의 표준 logging 모듈을 설정하는 방법을 설명합니다. 이 글을 읽으면 모듈별 logger, dictConfig, JSON 형태의 로그, 자동으로 붙는 request_id, QueueHandler를 사용한 비동기 로깅, pytest의 caplog를 사용한 로그 테스트를 포함한 설정을 구축할 수 있을 것입니다. 모든 예제는 Python 3.12를 사용하며 표준 라이브러리만 필요합니다. 테스트 부분만 pytest를 추가로 필요합니다.

2. print와 basicConfig가 충분하지 않은 이유

주문을 처리하는 서비스를 “빨리 완료”하는 방식으로 작성한 것을 봅시다:

import logging

logging.basicConfig(level=logging.INFO)

def place_order(order_id: str, amount: float) -> None:
    print(f"주문 {order_id}을 처리 중입니다")
    logging.info(f"Order {order_id} amount={amount}")

place_order("ORD-1001", 250_000)

주문 ORD-1001을 처리 중입니다
INFO:root:Order ORD-1001 amount=250000

이 코드는 세 가지 문제가 있습니다:

• print는 level이 없고, timestamp가 없으며, 설정으로 끌 수 없습니다.
• logging.info(...)는 root logger에 기록됩니다. 어느 모듈에서 온 로그인지 알 수 없고, 각 부분별로 level을 조정할 수 없습니다.
• basicConfig는 root logger가 아직 handler를 갖지 않은 첫 호출에만 작동합니다. 어떤 라이브러리가 먼저 호출하면 당신의 설정은 경고 없이 무시됩니다.

3. getLogger(__name__)을 이용한 모듈별 Logger

첫 번째 규칙: 각 모듈마다 고유한 logger를 만들고, __name__에 따라 이름을 지정합니다.

# shop/orders.py
import logging

logger = logging.getLogger(__name__)  # logger 이름: "shop.orders"

class OrderService:
    def place_order(self, order_id: str, quantity: int) -> None:
        logger.info("주문 %s을 처리 중입니다 (수량: %d)", order_id, quantity)
        if quantity > 50:
            logger.warning("대량 주문 %s: 수량=%d", order_id, quantity)

Logger 이름은 점으로 구분된 계층 구조를 형성합니다. shop.orders는 shop의 자식이고, shop은 root의 자식입니다. record는 자식 logger에서 부모 logger로 이동합니다 (propagation). 따라서 root 또는 shop에만 handler를 연결하고, 각 branch별로 level을 조정할 수 있습니다. 예를 들어, shop.payments는 DEBUG로 설정하고 나머지는 INFO로 유지할 수 있습니다.

또한 매개변수 전달 방식에 주목해 주세요: f-string 대신 %s와 함께 인자를 사용합니다. level이 비활성화되면 문자열이 포맷팅되지 않으므로, 절대 출력되지 않는 로그에 대한 비용을 낭비하지 않습니다. 또한 로그 수집 도구가 동일한 message template에 따라 라인을 그룹화할 수 있습니다.

주의: 라이브러리 (다른 사람이 사용하는 패키지)에서는 handler를 설정하지 마세요. getLogger(__name__)만 호출하고 애플리케이션이 결정하도록 하세요. 원하면 logging.getLogger("your_lib").addHandler(logging.NullHandler())를 추가하세요.

4. dictConfig를 이용한 중앙화된 설정

Production에서는 모든 설정을 한 곳에 모아서 애플리케이션 시작할 때 한 번만 호출해야 합니다. logging.config.dictConfig가 이에 적합합니다.

# shop/logging_config.py
import logging.config
import os

def setup_logging() -> None:
    level = os.getenv("LOG_LEVEL", "INFO")
    logging.config.dictConfig({
        "version": 1,
        "disable_existing_loggers": False,
        "formatters": {
            "plain": {
                "format": "%(asctime)s %(levelname)-8s %(name)s - %(message)s",
            },
        },
        "handlers": {
            "console": {
                "class": "logging.StreamHandler",
                "stream": "ext://sys.stdout",
                "formatter": "plain",
            },
        },
        "loggers": {
            "shop": {"level": level},
            "urllib3": {"level": "WARNING"},
        },
        "root": {"level": "WARNING", "handlers": ["console"]},
    })

설정의 주요 요점:

• "disable_existing_loggers": False는 실제로 필수입니다. 기본값인 True는 dictConfig가 실행되기 전에 생성된 모든 logger를 비활성화하며, 여기에는 import한 모듈 맨 앞의 logger도 포함됩니다. 결과적으로 로그가 사라집니다.
• Handler는 root에만 연결됩니다. Logger shop은 level만 설정하고, record는 root로 전파되어 출력됩니다.
• Root는 WARNING으로 설정하여 써드파티 라이브러리의 시끄러운 INFO 로그를 차단합니다. shop branch의 코드는 여전히 INFO로 로깅됩니다.
• Level은 환경 변수 LOG_LEVEL에서 읽습니다. 코드를 수정하지 않고 문제를 조사할 때 DEBUG로 활성화할 수 있습니다.

entry point에서 함수를 호출합니다:

# main.py
from shop.logging_config import setup_logging
from shop.orders import OrderService

setup_logging()
OrderService().place_order("ORD-1001", quantity=80)

2026-10-18 09:15:02,114 INFO     shop.orders - 주문 ORD-1001을 처리 중입니다 (수량: 80)
2026-10-18 09:15:02,114 WARNING  shop.orders - 대량 주문 ORD-1001: 수량=80

stdout에 쓰는 것은 container 내에서 실행할 때 올바른 선택입니다. Docker나 Kubernetes는 이 stream에서 로그를 수집하므로, 파일을 직접 관리하거나 파일 로테이션을 걱정할 필요가 없습니다.

5. JSON 형태의 구조화된 로그

Loki, Elasticsearch, CloudWatch 같은 로그 수집 시스템은 자유 형식 텍스트보다 JSON으로 훨씬 더 잘 검색합니다. 외부 라이브러리 없이 자체 formatter를 작성할 수 있습니다:

# shop/json_formatter.py
import json
import logging
from datetime import datetime, timezone

_RESERVED = set(vars(logging.LogRecord("", 0, "", 0, "", None, None))) | {"message", "asctime"}

class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "ts": datetime.fromtimestamp(record.created, tz=timezone.utc).isoformat(),
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
        }
        for key, value in record.__dict__.items():
            if key not in _RESERVED and not key.startswith("_"):
                payload[key] = value
        if record.exc_info:
            payload["exc"] = self.formatException(record.exc_info)
        return json.dumps(payload, ensure_ascii=False, default=str)

작동 방식:

• _RESERVED는 LogRecord의 기본 속성들을 포함합니다. 예를 들어 pathname, lineno, args.
• 다른 모든 속성은 커스텀 field로 간주되어 JSON에 추가됩니다. 이 field들은 보통 extra= 매개변수나 filter에서 옵니다 (6번 섹션 참조).
• default=str은 json.dumps가 Decimal이나 UUID 같은 타입을 만날 때 오류를 방지합니다.

dictConfig에서 특수 키 "()"를 사용하여 formatter를 선언합니다:

"formatters": {
    "json": {"()": "shop.json_formatter.JsonFormatter"},
},
"handlers": {
    "console": {
        "class": "logging.StreamHandler",
        "stream": "ext://sys.stdout",
        "formatter": "json",
    },
},

extra를 사용하여 비즈니스 field를 추가합니다:

logger.info("결제 완료", extra={"order_id": "ORD-1001", "amount": 250000})

{"ts": "2026-10-18T02:15:02.114+00:00", "level": "INFO", "logger": "shop.payments", "message": "결제 완료", "order_id": "ORD-1001", "amount": 250000}

주의: extra의 key는 LogRecord의 기존 속성명과 중복되면 안 됩니다. 예를 들어 extra={"name": "..."} 또는 extra={"message": "..."}는 KeyError: "Attempt to overwrite 'name' in LogRecord"를 던집니다.

6. contextvars를 이용한 자동 request_id 추가

각 로그 호출에 extra={"request_id": ...}를 전달하는 것은 번거롭고 실수하기 쉽습니다. 더 나은 방법은 ContextVar에 request_id를 저장한 다음, Filter가 모든 record에 자동으로 붙이도록 하는 것입니다.

# shop/request_context.py
import logging
from contextvars import ContextVar

request_id_var: ContextVar[str] = ContextVar("request_id", default="-")

class RequestIdFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        record.request_id = request_id_var.get()
        return True  # 어떤 record도 차단하지 않고, 데이터만 추가

ContextVar는 thread와 asyncio 모두에서 안전합니다. 각 task나 request는 자신의 값을 유지하므로, 한 request가 다른 request의 ID를 “빌리는” 일이 없습니다.

Filter를 handler에 연결하세요, logger에 연결하지 마세요. Logger에 연결한 filter는 해당 logger에서 직접 생성된 record에만 실행되며, logger로부터 위로 전파되는 record에는 실행되지 않습니다.

"filters": {
    "request_id": {"()": "shop.request_context.RequestIdFilter"},
},
"handlers": {
    "console": {
        "class": "logging.StreamHandler",
        "stream": "ext://sys.stdout",
        "formatter": "json",
        "filters": ["request_id"],
    },
},

각 request의 시작점에서 값을 설정하세요. 예를 들어 middleware에서:

import uuid
from shop.request_context import request_id_var

def handle_request(order_id: str) -> None:
    token = request_id_var.set(uuid.uuid4().hex[:12])
    try:
        OrderService().place_order(order_id, quantity=3)
    finally:
        request_id_var.reset(token)

{"ts": "...", "level": "INFO", "logger": "shop.orders", "message": "주문 ORD-1002을 처리 중입니다 (수량: 3)", "request_id": "9f2c1ab07d3e"}

이제 request_id로 필터링하면 하나의 request의 전체 흐름을 볼 수 있습니다.

7. Exception을 올바르게 로깅하기

logger = logging.getLogger("shop.payments")

class PaymentService:
    def charge(self, order_id: str, amount: int) -> bool:
        try:
            raise ConnectionError("게이트웨이 시간 초과")
        except ConnectionError:
            logger.exception("주문 %s의 결제 실패", order_id)
            return False

logger.exception(...)은 ERROR level로 로깅하고 자동으로 stack trace를 첨부합니다. except 블록 내에서만 호출하세요. 다른 level에서 로깅하되 여전히 stack trace를 원하면 logger.warning("...", exc_info=True)를 사용하세요.

흔한 두 가지 실수:

• logger.error(f"결제 실패: {e}")는 stack trace를 잃게 합니다. 조사할 때 “게이트웨이 시간 초과” 한 줄만 보이고 어디서 발생했는지 알 수 없습니다.
• 모든 계층에서 로깅하고 다시 던집니다. 같은 exception이 로그에 5번 나타납니다. Exception을 처리하는 계층, 즉 더 이상 던지지 않기로 결정한 곳에서 로깅하세요.

8. Logging이 애플리케이션을 차단하지 않도록: QueueHandler

StreamHandler는 stdout에 쓰기가 보통 충분히 빠릅니다. 하지만 network를 통해 전송하는 handler (syslog, HTTP, SMTP) 또는 디스크에 쓰는 handler는 느릴 수 있으며, 요청을 처리하는 thread를 차단할 것입니다. 이를 피하려면 record를 queue에 넣고 background thread가 실제 대상에 쓰도록 합니다:

import atexit
import logging
import logging.handlers
import queue

def setup_async_logging(target: logging.Handler) -> None:
    log_queue: queue.Queue = queue.Queue(-1)
    queue_handler = logging.handlers.QueueHandler(log_queue)

    listener = logging.handlers.QueueListener(
        log_queue, target, respect_handler_level=True
    )
    listener.start()
    atexit.register(listener.stop)  # 종료 시 나머지를 flush

    root = logging.getLogger()
    root.handlers = [queue_handler]

처리 흐름은 다음과 같습니다:

• 애플리케이션 thread는 record를 queue에 put하기만 합니다. 이 작업은 거의 즉각적입니다.
• QueueListener는 자신의 thread에서 실행되어 queue에서 record를 꺼내고 target, 예를 들어 SysLogHandler에 전달합니다.
• atexit.register(listener.stop)은 process가 종료되기 전에 마지막 로그가 기록되도록 보장합니다.

주의: RequestIdFilter 같은 filter는 handler 대상에 아닌 QueueHandler에 연결해야 합니다. Handler 대상은 listener의 thread에서 실행되며, 그 thread의 ContextVar는 원래 request의 값을 갖지 않습니다.

9. pytest caplog를 이용한 로그 테스트

비즈니스 경고, 예를 들어 대량 주문 경고는 테스트해야 할 행동입니다. dev dependency에 pytest를 추가하세요:

pip install pytest

# tests/test_orders.py
import logging
from shop.orders import OrderService

def test_large_order_logs_warning(caplog):
    with caplog.at_level(logging.INFO, logger="shop.orders"):
        OrderService().place_order("ORD-2001", quantity=80)

    warnings = [r for r in caplog.records if r.levelno == logging.WARNING]
    assert len(warnings) == 1
    assert warnings[0].name == "shop.orders"
    assert warnings[0].getMessage() == "대량 주문 ORD-2001: 수량=80"

def test_small_order_does_not_warn(caplog):
    with caplog.at_level(logging.INFO, logger="shop.orders"):
        OrderService().place_order("ORD-2002", quantity=2)

    assert all(r.levelno < logging.WARNING for r in caplog.records)

tests/test_orders.py ..                                  [100%]
2 passed in 0.03s

caplog.at_level은 with 블록 범위 내에서 logger shop.orders의 level을 임시로 낮춥니다. caplog.records는 원본 LogRecord 객체를 포함하므로, level, logger 이름, extra field를 포함해 모든 것을 검사할 수 있습니다.

주의: caplog는 root logger에 handler를 연결합니다. 설정에서 logger shop에 "propagate": False를 설정하면 test가 record를 포착하지 못합니다.

10. 흔한 실수와 하지 말아야 할 경우

• 모듈 수준에서 logging 설정 (basicConfig나 dictConfig를 import 시점에 호출). 오직 entry point에서만, 정확히 한 번만 설정하세요.
• Handler가 두 번 연결됨. 예를 들어 shop과 root 모두에 연결하면서 propagate는 여전히 True일 때. 각 로그 라인이 두 번 인쇄됩니다. Handler는 한 수준에만 연결하세요.
• 민감한 데이터 기록: 암호, token, 카드 번호. 원본 request object를 로깅하지 마세요. 필요하면 이러한 field를 마스킹할 Filter를 작성하세요.
• 다중 process 애플리케이션에서 RotatingFileHandler 사용 (Gunicorn with 여러 worker). 여러 process가 같은 파일을 로테이션하면 로그가 손실됩니다. stdout에 쓰거나, 각 worker가 QueueHandler를 통해 단 하나의 writing process로 보내도록 하세요.
• hot loop에서 너무 많이 INFO로 로깅. 저장소 비용과 noise가 빠르게 증가합니다. 이러한 로그는 DEBUG에 두어야 합니다.
• 로컬 개발 시 JSON 사용. JSON은 눈으로 읽기 어렵습니다. 환경 변수에 따라 formatter를 선택하세요: dev는 plain, production은 json.

11. 결론

좋은 production logging 설정은 복잡하지 않으며, 단지 일관성이 필요합니다. 모든 모듈에서 getLogger(__name__)을 사용합니다. 한 번의 dictConfig 호출로 설정을 모으면서 disable_existing_loggers: False를 설정합니다. JSON을 stdout에 쓰고, ContextVar와 Filter를 통해 request_id를 붙이고, logger.exception을 사용하여 stack trace를 유지합니다. Handler 대상이 느리면 QueueHandler와 QueueListener로 전환합니다.

마지막으로, 로그를 시스템의 행동의 일부로 간주하고 caplog로 테스트하세요. 새벽 2시에 문제가 생겼을 때, 이렇게 구조화된 로그들이 원인을 훨씬 더 빠르게 찾는 데 도움이 될 것입니다.