logger.info가 아무것도 출력하지 않은 이유

문제 발생

디버깅용 로그를 잔뜩 넣었는데 콘솔에 한 줄도 나오지 않았습니다.

import logging

logging.info("요청 처리 시작")     # 안 나옴
logging.warning("주의")            # 나옴

basicConfig를 나중에 호출해봐도 그대로였습니다.

원인 분석

두 가지가 겹쳤습니다.

첫째, 기본 레벨이 WARNING입니다. Python 문서가 그대로 적습니다 — 기본 레벨은 WARNING이며, 로깅 패키지를 달리 설정하지 않는 한 이 심각도 이상의 이벤트만 추적됩니다. 문서의 예제도 같은 결과를 보여줍니다.

logging.warning("Watch out!")   # 콘솔에 출력됨
logging.info("I told you so")   # 아무것도 출력되지 않음

둘째, basicConfig는 아무 때나 통하지 않습니다. 문서가 명시합니다 — basicConfig() 호출은 로거의 debug(), info() 같은 메서드 호출보다 먼저 와야 하며, 그렇지 않으면 그 로깅 이벤트가 원하는 방식으로 처리되지 않을 수 있습니다.

이유는 이 함수가 루트 로거에 핸들러가 이미 설정되어 있으면 아무 일도 하지 않기 때문입니다. logging.info(...)를 먼저 부르면 그 시점에 기본 핸들러가 붙어버려서, 뒤늦은 basicConfig는 조용히 무시됩니다.

해결 방안

1. 진입점에서 가장 먼저 설정합니다.

import logging

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(levelname)s %(name)s %(message)s",
)

2. 모듈 로거를 씁니다. logging.info(...)는 루트 로거를 직접 쓰는 것이라 어디서 난 로그인지 알 수 없습니다.

logger = logging.getLogger(__name__)
logger.info("요청 처리 시작")

이렇게 하면 나중에 logging.getLogger("myapp.db").setLevel(logging.DEBUG)처럼 부분만 켜고 끌 수 있습니다.

3. 라이브러리에서는 설정하지 않습니다. 문서가 강하게 권고합니다 — 라이브러리의 로거에는 NullHandler 외의 핸들러를 추가하지 말 것. 핸들러 구성은 그 라이브러리를 쓰는 애플리케이션 개발자의 권한이기 때문입니다.

4. 레벨이 두 곳에 있다는 걸 기억합니다. 로거의 레벨과 핸들러의 레벨이 각각 필터링합니다. 로거를 DEBUG로 내려도 핸들러가 INFO면 debug는 나오지 않습니다.

5. 프레임워크가 이미 설정했는지 확인합니다. Django, Gunicorn 등은 자체 로깅 설정을 가지고 있어 basicConfig가 통하지 않습니다. 그때는 프레임워크의 설정 지점에서 조정합니다.

공식 문서

• Python: Logging HOWTO
• Python: logging.basicConfig