[Python] logging 의 중복 로그 현상

logging 을 사용해서 로그 찍는 루틴을 만들었는데, 로그를 찍을 때 마다 동일한 로그가 계속 하나씩 더 찍히는 현상을 경험했다. 로그1, 로그2, 로그2, 로그3, 로그3, 로그3, ... 이런 식이었다.

사실 현상이라기 보단 코딩을 잘못해서 나타난 문제이다. 하지만 이 문제 해결을 위해 너무나 귀찮은 짓을 다 해 봤기에 기억하자는 의미로 글을 남긴다.

내가 만든 코드는 이런 식이었다.

import logging
import logging.handlers

def get_logger():
    logger = logging.getLogger('my logger')
    logger.setLevel(logging.INFO)
    handler = logging.handlers.RotatingFileHandler("test.log", maxBytes=1024, backupCount=5)
    logger.addHandler(handler)

    return logger

def debuglog(message):
    logger = get_logger()
    logger.info(message)

이 코드를 import해서 debuglog() 함수를 이용해 로그를 찍는 방식이다.

얼핏 보면 문제는 없어보인다. debuglog() 의 역활은 로거 인스턴스를 만들고 여기다 info() 를 이용해 정보성 로그를 찍는 것이다.

그런데 debuglog() 를 쓸 때 마다 찍히는 로그가 하나씩 늘어났다.

대충 생각하기엔 logger를 가져와서 쓰고 버리는 구조다 보니 크게 문제 될 건 없을 것 같지만 아니다. 로거를 만들 때(logging.getLogger) 마다 로거 인스턴스가 생성되어서 메모리에 계속 남게 된다. logging.getLogger() 의 역활은 로거를 생성하거나 혹은 이미 존재하는 로거를 가져오기 위함으로 생각된다. 위 코드에서 'my logger' 라는 문자열이 로거를 구분하는 키이다.

그런데 logging.getLogger() 를 통해 받아온 인스턴스에 매번 addHandler()를 호출하고 있다. 이 핸들러는 리스트 형태로 관리되는 듯 하다. 그래서 debuglog()를 호출 할 때 마다 동일한 로거에 새로운 핸들러(여기서는 RotatingFileHandler)가 계속 등록된다.

그렇다면 addHandler를 한번만 호출하도록 해서 쓰면 된다. 간단하게 이렇게 고쳐봤다.

import logging
import logging.handlers

def get_logger():
    logger = logging.getLogger('my logger')
    logger.setLevel(logging.INFO)
    handler = logging.handlers.RotatingFileHandler("test.log", maxBytes=1024, backupCount=5)
    logger.addHandler(handler)

    return logger

MY_LOGGER = get_logger()

def debuglog(message):
    MY_LOGGER.info(message)

이렇게 고친 뒤 문제는 해결되었다. debuglog() 에서 get_logger() 를 호출하지 않고 전역변수 하나에 미리 get_logger()를 통해 생성한 logger 인스턴스를 보관하도록 한 것이다.

Python의 import는 중복으로 동작하지 않기 때문에 여러군데서 위 모듈을 import해도 문제는 없다.

사족) 사실 이 문제 해결에 힘이 들었던 건 다른 이유가 있다. 이 로그 루틴은 Flask와 SQLAlchemy로 만든 서버에서 사용되었는데, 로그가 계속 추가되면서 찍히는 것을 서버 설정 잘못으로 request가 중복해서 발생하고 있다고 생각했었다. 그래서 로그 관련 루틴은 보지도 않고 애꿎은 Flask 루틴들만 보고 있었다. 부끄럽다 -_-;;;;