2020년 11월 1일 일요일

solving print log twice in python (파이썬에서 로그 두번씩 출력되는 문제 해결)


앞에서 로그를 사용하게 쉽게 작업해보았습니다. 아래 소스를 기반으로 class도 만들어 봤습니다.

https://swlock.blogspot.com/2019/04/python-logging-using-logging-in-python.html

그런데 사용중에 문제가 발생하였습니다.

로그가 두번씩 출력되는 현상입니다. 일단 문제의 상황을 간단하게 예제로 만들어 보았습니다.


customlog.py

import datetime
import sys
import os
import time
import logging
from logging import FileHandler
from logging import handlers

#https://swlock.blogspot.com/2019/04/python-logging-using-logging-in-python.html
class CustomLog:
    def __init__(self):
        pass
        
    def create(self,logfolder='',app_name=__name__,logprefix='log_'):
        LOG_PREFIX = logprefix
        LOG_FOLDER_NAME = logfolder
        # 로그 파일 핸들러
        now = datetime.datetime.now().isoformat()[:10]
        logf = LOG_PREFIX + now + ".log"
        if LOG_FOLDER_NAME!='' and not os.path.exists(LOG_FOLDER_NAME):
            os.makedirs(LOG_FOLDER_NAME)
        logf = os.path.join(LOG_FOLDER_NAME, logf)
        logger = self.getLogger(logf, app_name)
        return logger

    def getLogger(self, filename, app_name, NEED_BACKUP_FILE = True, NEED_SCREEN_AND_FILE = True, level=logging.DEBUG, format='%(asctime)s,%(message)s', maxBytes=10*1024*1024, backupCount = 10, encoding='utf-8'):
        self.logger = logging.getLogger(app_name)
        # log level은 아래 순서에 따른다. setLevel 과 같거나 큰 출력만 나오게 된다.
        # logger.setLevel(logging.CRITICAL) 인 경우 logger.critical() 만 나온다
        #
        # logger.debug("debug")
        # logger.info("info")
        # logger.warning("warning")
        # logger.error("error")
        # logger.critical("critical")
        self.logger.setLevel(level)

        # 포맷을 결정한다. 좀더 자세한 정보는 다음 링크를 참조한다
        # https://docs.python.org/3/library/logging.html#logrecord-attributes
        logFormatter = logging.Formatter(format)

        if NEED_BACKUP_FILE == True:
            rotatingHandler = handlers.RotatingFileHandler(filename=filename, maxBytes=maxBytes, backupCount = backupCount, encoding=encoding)
            rotatingHandler.setFormatter(logFormatter)
            self.logger.addHandler(rotatingHandler)
        else:
            fileHandler = logging.FileHandler(filename)
            fileHandler.setFormatter(logFormatter)
            self.logger.addHandler(fileHandler)

        # StreamHandler 는 self.logger.critical("critical") 이런 형태의 로그가 화면으로도 나오고 file로도 저장이 되도록 한다
        if NEED_SCREEN_AND_FILE == True:
            streamHandler = logging.StreamHandler()
            streamHandler.setFormatter(logFormatter)
            self.logger.addHandler(streamHandler)
        return self.logger

if __name__ == "__main__":
    logger = CustomLog().create('log')
    print("test")
    logger.debug("debug test")
    logger.info("info test")
    logger.warning("warning test")
    logger.error("error test")
    logger.critical("critical test")


logtest2.py

import customlog

test2 = 1
logger = customlog.CustomLog().create('Log')
print("log test2")
logger.debug("debug test")
logger.info("info test")
logger.warning("warning test")
logger.error("error test")
logger.critical("critical test")


logtest1.py

import customlog
import logtest2

logger = customlog.CustomLog().create('Log')
print("logtest1")
print(logtest2.test2)
logger.debug("debug test")
logger.info("info test")
logger.warning("warning test")
logger.error("error test")
logger.critical("critical test")


test 결과

>python logtest1.py
log test2
2020-11-01 13:56:43,674,debug test
2020-11-01 13:56:43,676,info test
2020-11-01 13:56:43,676,warning test
2020-11-01 13:56:43,677,error test
2020-11-01 13:56:43,678,critical test
logtest1
1
2020-11-01 13:56:43,681,debug test
2020-11-01 13:56:43,681,debug test
2020-11-01 13:56:43,682,info test
2020-11-01 13:56:43,682,info test
2020-11-01 13:56:43,684,warning test
2020-11-01 13:56:43,684,warning test
2020-11-01 13:56:43,687,error test
2020-11-01 13:56:43,687,error test
2020-11-01 13:56:43,688,critical test
2020-11-01 13:56:43,688,critical test


logtest1.py에서 출력하는 log들이 두번씩 출력되게 됩니다.


원인

imoprt logtest2에 의해 customlog의 create()가 두번 호출 되었기 때문입니다.

logger = customlog.CustomLog().create('Log')

분석을 해봐도 CustomLog의 instance가 두번 생성되는것은 아닌 상황이고, handler가 두번 붙어있는건 맞지만 handler를 초기화 해줘도 실제 초기화 되지 않았습니다.


해결 방법

propagate 값을 False로 설정하여 계층화된 로그의 내용이 모이지 않도록 합니다.

그리고 log 처리기에 각각의 이름을 붙여줍니다.


전체 소스

propagate = False 추가함

customlog.py

import datetime
import sys
import os
import time
import logging
from logging import FileHandler
from logging import handlers

#https://swlock.blogspot.com/2019/04/python-logging-using-logging-in-python.html
class CustomLog:
    def __init__(self):
        pass
        
    def create(self,logfolder='',app_name=__name__,logprefix='log_'):
        LOG_PREFIX = logprefix
        LOG_FOLDER_NAME = logfolder
        # 로그 파일 핸들러
        now = datetime.datetime.now().isoformat()[:10]
        logf = LOG_PREFIX + now + ".log"
        if LOG_FOLDER_NAME!='' and not os.path.exists(LOG_FOLDER_NAME):
            os.makedirs(LOG_FOLDER_NAME)
        logf = os.path.join(LOG_FOLDER_NAME, logf)
        logger = self.getLogger(logf, app_name)
        return logger

    def getLogger(self, filename, app_name, NEED_BACKUP_FILE = True, NEED_SCREEN_AND_FILE = True, level=logging.DEBUG, format='%(asctime)s,%(message)s', maxBytes=10*1024*1024, backupCount = 10, encoding='utf-8'):
        self.logger = logging.getLogger(app_name)
        self.logger.propagate = False
        # log level은 아래 순서에 따른다. setLevel 과 같거나 큰 출력만 나오게 된다.
        # logger.setLevel(logging.CRITICAL) 인 경우 logger.critical() 만 나온다
        #
        # logger.debug("debug")
        # logger.info("info")
        # logger.warning("warning")
        # logger.error("error")
        # logger.critical("critical")
        self.logger.setLevel(level)

        # 포맷을 결정한다. 좀더 자세한 정보는 다음 링크를 참조한다
        # https://docs.python.org/3/library/logging.html#logrecord-attributes
        logFormatter = logging.Formatter(format)

        if NEED_BACKUP_FILE == True:
            rotatingHandler = handlers.RotatingFileHandler(filename=filename, maxBytes=maxBytes, backupCount = backupCount, encoding=encoding)
            rotatingHandler.setFormatter(logFormatter)
            self.logger.addHandler(rotatingHandler)
        else:
            fileHandler = logging.FileHandler(filename)
            fileHandler.setFormatter(logFormatter)
            self.logger.addHandler(fileHandler)

        # StreamHandler 는 self.logger.critical("critical") 이런 형태의 로그가 화면으로도 나오고 file로도 저장이 되도록 한다
        if NEED_SCREEN_AND_FILE == True:
            streamHandler = logging.StreamHandler()
            streamHandler.setFormatter(logFormatter)
            self.logger.addHandler(streamHandler)
        return self.logger

if __name__ == "__main__":
    logger = CustomLog().create('log')
    print("test")
    logger.debug("debug test")
    logger.info("info test")
    logger.warning("warning test")
    logger.error("error test")
    logger.critical("critical test")


__name__ 추가함

logtest2.py

import customlog

test2 = 1
logger = customlog.CustomLog().create('Log',__name__)
print("log test2")
logger.debug("debug test")
logger.info("info test")
logger.warning("warning test")
logger.error("error test")
logger.critical("critical test")

__name__ 추가함

logtest1.py

import customlog
import logtest2

logger = customlog.CustomLog().create('Log',__name__)
print("logtest1")
print(logtest2.test2)
logger.debug("debug test")
logger.info("info test")
logger.warning("warning test")
logger.error("error test")
logger.critical("critical test")


실행결과

C:\Users\USER\Documents\python\grammer>python logtest1.py
log test2
2020-11-01 14:17:13,104,debug test
2020-11-01 14:17:13,106,info test
2020-11-01 14:17:13,107,warning test
2020-11-01 14:17:13,108,error test
2020-11-01 14:17:13,108,critical test
logtest1
1
2020-11-01 14:17:13,111,debug test
2020-11-01 14:17:13,112,info test
2020-11-01 14:17:13,113,warning test
2020-11-01 14:17:13,114,error test
2020-11-01 14:17:13,117,critical test


추가로 핸들러를 초기화 하는것도 참고 바랍니다.

아래 colored log 에서는 create할때 handler를 clear하는 코드를 넣었습니다.

python 에서 logging 사용하기(using logging in python)

https://swlock.blogspot.com/2019/04/python-logging-using-logging-in-python.html


python logger,colored log (컬러 로거 logger)

https://swlock.blogspot.com/2021/10/python-loggercolored-log-logger.html


python 멀티 로그 레벨을 가지는 로거(how to set multi setlevel in python logger)

https://swlock.blogspot.com/2021/10/python-how-to-set-multi-setlevel-in.html


작성자: 시간:
라벨: ,

댓글 없음:

댓글 쓰기

피드 구독하기: 댓글 (Atom)