Python 로그가 두 번 찍힐 때 전파와 핸들러 확인하기

같은 로그 문장이 두 번 보인다면 먼저 한 로거에 출력 핸들러가 여러 개 붙었는지, 자식과 부모 로거가 같은 기록을 각각 출력하는지 나눠 확인합니다. 중앙에서 로그를 모으는 구조라면 자식의 불필요한 핸들러를 없애고 전파를 유지하는 쪽이 맞을 수 있습니다. propagate=False부터 넣으면 중복이 줄어도 필요한 로그 전달까지 끊길 수 있습니다. 이 글은 외부 패키지 없이 두 원인을 따로 재현하고, 수정 전후의 출력 내용과 개수를 검사합니다.

검증 범위: 2026년 10월 10일, CPython 3.12.14 / Linux 6.18.44 / x86_64의 별도 프로세스에서 아래 전체 코드를 실행했습니다. Python 3.12 공식 문서와 대조한 합성 예제입니다. 운영 장애 사례나 Django 서버 검증은 포함하지 않습니다. 문서 조사와 예제 작성·검증에 AI를 활용했습니다.

1. 로그 한 번과 출력 한 번은 다릅니다

로거(logger)는 애플리케이션이 기록을 남기는 창구이고, 핸들러(handler)는 그 기록을 콘솔·파일 같은 목적지로 보내는 객체입니다. zzodosa_demo.worker는 이름의 점을 기준으로 zzodosa_demo 아래에 놓입니다. 자식에서 만들어진 기록은 자식 핸들러를 거친 뒤, 전파 설정에 따라 부모의 핸들러로도 전달됩니다. 따라서 코드에 info() 호출이 하나뿐이어도 출력은 여러 번 생길 수 있습니다.

여기서는 목적지를 메모리의 StringIO 하나로 고정합니다. A는 자식과 부모에 각각 핸들러가 있는 경우, B는 같은 자식 로거에 새 핸들러 객체를 두 번 추가한 경우입니다. 실제 로그 수집기나 파일 권한 같은 변수를 섞지 않고 Python 내부 전달 경로만 비교하려는 구성입니다.

2. 두 원인을 같은 입력으로 재현합니다

아래 내용을 logging_duplicates.py로 저장한 뒤 새 터미널 프로세스에서 python3 logging_duplicates.py로 실행합니다. 필요한 것은 Python 표준 라이브러리의 io와 logging뿐입니다. 게시한 전체 코드와 아래 실제 출력은 CPython 3.12.14에서 검증했으며, 다른 버전의 실행 결과를 확인했다는 뜻은 아닙니다.

logging_duplicates.py

import io
import logging


sink = io.StringIO()
parent = logging.getLogger("zzodosa_demo")
child = logging.getLogger("zzodosa_demo.worker")
parent.setLevel(logging.ERROR)
parent.propagate = False  # Keep the experiment away from root handlers.
child.setLevel(logging.INFO)
child.propagate = True
owned = []


def attach(logger, label):
    handler = logging.StreamHandler(sink)
    handler.setLevel(logging.INFO)
    handler.setFormatter(logging.Formatter(label + ": %(message)s"))
    logger.addHandler(handler)
    owned.append((logger, handler))
    return handler


def check(label, expected):
    sink.seek(0)
    sink.truncate(0)
    child.info("job finished")
    actual = sink.getvalue().splitlines()
    assert actual == expected, (label, actual)
    print(f"{label}: {actual}")


try:
    attach(parent, "parent")
    local = attach(child, "child")
    check("A before", ["child: job finished", "parent: job finished"])

    child.removeHandler(local)
    check("A after", ["parent: job finished"])

    child.propagate = False
    check("A propagation off", [])
    child.propagate = True

    # Each call creates a different handler object.
    first = attach(child, "local")
    extra = attach(child, "local")
    child.propagate = False
    check("B before", ["local: job finished", "local: job finished"])

    child.removeHandler(extra)
    check("B after", ["local: job finished"])
finally:
    for logger, handler in owned:
        logger.removeHandler(handler)
        handler.close()
    sink.close()

print("All checks passed")

실제 실행 결과

A before: ['child: job finished', 'parent: job finished']
A after: ['parent: job finished']
A propagation off: []
B before: ['local: job finished', 'local: job finished']
B after: ['local: job finished']
All checks passed

각 check()는 버퍼를 비운 뒤 info()를 정확히 한 번 호출합니다. assert는 줄 수뿐 아니라 각 줄의 내용과 순서까지 확인합니다. -O 옵션은 assert를 비활성화하므로 검증할 때 붙이지 않습니다. parent.propagate=False는 실험 기록이 프로세스의 루트 로거까지 흘러가지 않게 하는 격리 설정입니다. 서비스 전체의 전파를 끄라는 권고로 읽으면 안 됩니다.

3. A: 자식과 부모가 모두 출력한다면 소유자를 정합니다

A before에는 child와 parent가 한 줄씩 있습니다. 자식 핸들러 local을 removeHandler()로 떼어 낸 A after에는 부모의 한 줄만 남습니다. 중앙 핸들러가 출력을 담당하는 구조를 선택한 결과입니다. 자식의 propagate=True는 그대로 유지합니다.

다음 A propagation off에서는 자식에 직접 붙은 핸들러가 없는 상태로 전파까지 껐습니다. 그 결과 이 예제의 INFO 기록은 수집 버퍼에 한 줄도 들어오지 않았습니다. 중복 제거를 확인할 때는 같은 기록이 한 번 남는지와, 원래 가야 했던 목적지에 도착하는지를 함께 검사해야 합니다. WARNING 이상에는 마지막 대체 핸들러(lastResort)가 관여할 수 있으므로, 이 INFO 결과를 모든 심각도의 출력 규칙으로 확대하지 않습니다.

부모 로거의 레벨을 ERROR로 설정했는데도 부모 핸들러가 INFO를 출력하는 점도 확인할 수 있습니다. 이 예제에서 자식은 자신의 INFO 레벨로 기록을 만들고, 부모에게 전파된 기록은 부모 로거의 레벨 검사를 다시 거치지 않습니다. 부모 핸들러의 INFO 레벨은 적용됩니다. 전파 경로에서 필터링하려면 어느 로거와 어느 핸들러에 설정이 붙었는지를 구분해야 합니다. Python 공식 Logger.propagate 설명

4. B: 전파를 꺼도 남는 중복은 등록 경로를 봅니다

B before에서는 이미 child.propagate=False인데도 같은 줄이 두 번 출력됩니다. attach()를 두 번 호출할 때마다 다른 StreamHandler 객체를 만들었기 때문입니다. 추가 객체 extra만 제거한 B after는 한 줄입니다. 부모로 올라가는 경로를 막는 설정으로는 자식에 직접 붙은 두 핸들러를 하나로 줄일 수 없습니다.

서비스에서는 설정 함수가 요청마다 호출되는지, 같은 초기화가 반복되는지부터 확인합니다. 먼저 구성을 담당하는 한 곳을 정하고, 그 코드가 만든 핸들러의 참조나 이름으로 소유권을 추적하는 편이 좋습니다. 제거할 때도 소유한 핸들러만 대상으로 삼아야 합니다. 위 코드의 finally 역시 이 실험에서 만든 객체만 분리하고 닫습니다.

logger.handlers는 해당 로거에 직접 붙은 목록입니다. 반면 hasHandlers()는 전파 경로의 조상까지 확인하므로, 반환값만으로 “이 로거에 내가 필요한 핸들러를 이미 등록했다”고 판단하면 안 됩니다. 또 logging.basicConfig(force=True)는 루트의 기존 핸들러를 제거하고 닫습니다. 프레임워크가 만든 설정의 소유자를 확인하지 않은 상태에서 중복 제거용으로 적용하기에는 영향 범위가 큽니다. hasHandlers() · basicConfig()

5. 서비스에 적용할 때의 확인 순서

  • 로그 문장의 내용만 비교하지 말고 호출 위치, 로거 이름, 프로세스와 요청 식별 정보를 확인합니다. 같은 요청이 실제로 두 번 실행된 문제라면 핸들러 조정만으로 원인이 해결되지 않습니다. 식별 정보에는 비밀값이나 개인정보를 넣지 않습니다.
  • 해당 로거의 직접 핸들러, 각 조상의 핸들러, 전파가 멈추는 위치를 적습니다. 핸들러가 두 개여도 서로 다른 목적지로 보내는 의도된 구성일 수 있습니다.
  • 중앙 수집을 유지할지, 전용 목적지에서 끝낼지 먼저 정합니다. 중앙 수집이면 자식의 중복 출력 핸들러를 줄이고, 독립 출력이면 필요한 자체 핸들러가 있는지 확인한 뒤 전파를 끕니다.
  • 테스트 환경에서 같은 입력의 INFO·WARNING·ERROR 기록이 의도한 목적지에 각각 몇 번 도착하는지 확인합니다. 초기화를 두 번 수행한 경우와 실제 서버의 재시작 경로도 따로 검사합니다.
  • 필요한 로그가 사라지면 원래 설정으로 되돌린 뒤, 핸들러 소유권과 레벨·필터 조건을 다시 비교합니다. 운영 중 모든 핸들러를 한꺼번에 지우며 탐색하지 않습니다.

재사용 라이브러리는 자체 콘솔 출력을 강제하기보다 애플리케이션이 출력 정책을 정할 수 있게 두는 편이 좋습니다. Python 공식 HOWTO도 라이브러리에는 NullHandler 외의 핸들러를 임의로 추가하지 않도록 권고합니다. Django·Gunicorn·Uvicorn처럼 별도 로그 설정을 가진 환경에서는 이 작은 예제를 그대로 붙이기 전에 해당 구성과 초기화 순서를 확인해야 합니다.

이 실험으로 확인한 것은 한 프로세스 안의 로거 전파와 핸들러 등록입니다. 여러 워커의 중복 실행, 외부 수집기의 재전송, 큐 처리, 로그 파일 회전은 검증하지 않았습니다. 우선 한 번의 호출이 어느 핸들러를 거치는지 좁혀 보고, 수정 뒤에는 남아야 할 출력까지 다시 확인하세요.

참고한 공식 문서 · 2026년 10월 10일 확인

댓글

댓글 쓰기