[Python] Uvicorn 일자별 로그 쌓기(with. FastAPI)

Python의 ASGI(Asynchronous Server Gateway Interface) web server인 Uvicorn을 활용하여 서버를 실행 중, 일자별로 로그 파일을 생성하여 쌓는 방법을 기록합니다.

 

1. log.ini 파일 생성

[loggers]
keys=root

[handlers]
keys=logfile,logconsole

[formatters]
keys=logformatter

[logger_root]
level=INFO
handlers=logfile, logconsole

[formatter_logformatter]
format=[%(asctime)s.%(msecs)03d] %(levelname)s [%(thread)d] - %(message)s

[handler_logfile]
class=handlers.TimedRotatingFileHandler
level=INFO
args=('log','midnight')
formatter=logformatter

[handler_logconsole]
class=handlers.logging.StreamHandler
level=INFO
args=()
formatter=logformatter

 

2. 명령어로 기동시 log.ini 설정 + Dockerfile

# In Linux
uvicorn app.main:app --host 0.0.0.0 --port 8000 --workers 10 --log-config log.ini

# In Dockerfile
CMD ["uvicorn", "app.main:app", "--host", "0.0.0.0", "--port", "8000", "--workers", "20", "--log-config", "log.ini"]

3. 결과

일자별로 자정에 새로운 파일이 생성됩니다.

 

4. (2022.08.15 - 추가) 멀티 프로세스 환경에서의 제어 오류

멀티 프로세스 환경(worker가 여럿)에서 로그파일 관리에 대한 논리 오류 해결 방법을 추가 기록합니다.

오류가 발생한 원인은 아래와 같이 Worker끼리 TimeRotating을 각자 실행하여 발생하는 현상입니다.

아래와 같이 파일들을 수정 및 생성하였습니다.

 - log.ini 파일 수정

[loggers]
keys=root

[handlers]
keys=logfile,logconsole

[formatters]
keys=logformatter

[logger_root]
level=INFO
handlers=logfile, logconsole

[formatter_logformatter]
format=[%(asctime)s.%(msecs)03d] %(levelname)s [%(thread)d] - %(message)s

[handler_logfile]
# Class 수정
class=app.common.logger_handler.SafeRotatingFileHandler
level=INFO
args=('log','midnight')
formatter=logformatter

[handler_logconsole]
class=handlers.logging.StreamHandler
level=INFO
args=()
formatter=logformatter

 - logger_handler.py 코드 생성

import os
import time
from logging import FileHandler
from logging.handlers import TimedRotatingFileHandler

# 참고 : https://ko.n4zc.com/article/programming/python/hr8m47f3.html


class SafeRotatingFileHandler(TimedRotatingFileHandler):
    def __init__(self, filename, when='h', interval=1, backup_count=0, encoding=None, delay=False, utc=False):
        TimedRotatingFileHandler.__init__(self, filename, when, interval, backup_count, encoding, delay, utc)
    """
    Override doRollover
    lines commanded by "##" is changed by cc
    """
    def doRollover(self):
        """
        do a rollover; in this case, a date/time stamp is appended to the filename
        when the rollover happens. However, you want the file to be named for the
        start of the interval, not the current time. If there is a backup count,
        then we have to get a list of matching filenames, sort them and remove
        the one with the oldest suffix.
            Override,  1. if dfn not exist then do rename
                2. _open with "a" model
        """
        if self.stream:
            self.stream.close()
            self.stream = None
        # get the time that this sequence started at and make it a TimeTuple
        current_time = int(time.time())
        dst_now = time.localtime(current_time)[-1]
        t = self.rolloverAt - self.interval
        if self.utc:
            time_tuple = time.gmtime(t)
        else:
            time_tuple = time.localtime(t)
            dst_then = time_tuple[-1]
            if dst_now != dst_then:
                if dst_now:
                    addend = 3600
                else:
                    addend = -3600
                time_tuple = time.localtime(t + addend)
        dfn = self.baseFilename + "." + time.strftime(self.suffix, time_tuple)
        # if os.path.exists(dfn):
        #     os.remove(dfn)

        # Issue 18940: A file may not have been created if delay is True.
        # if os.path.exists(self.baseFilename):
        if not os.path.exists(dfn) and os.path.exists(self.baseFilename):
            os.rename(self.baseFilename, dfn)
        if self.backupCount > 0:
            for s in self.getFilesToDelete():
                os.remove(s)
        if not self.delay:
            self.mode = "a"
            self.stream = self._open()
        new_rollover_at = self.computeRollover(current_time)
        while new_rollover_at <= current_time:
            new_rollover_at = new_rollover_at + self.interval
        # If DST changes and midnight or weekly rollover, adjust for this.
        if (self.when == 'MIDNIGHT' or self.when.startswith('W')) and not self.utc:
            dst_at_rollover = time.localtime(new_rollover_at)[-1]
            if dst_now != dst_at_rollover:
                if not dst_now:  # DST kicks in before next rollover, so we need to deduct an hour
                    addend = -3600
                else:  # DST bows out before next rollover, so we need to add an hour
                    addend = 3600
                new_rollover_at += addend
        self.rolloverAt = new_rollover_at

Rollover발생 시 이미 같은 파일의 이름이 존재한다면 실행하지 않도록 로직을 override 합니다.

 

참고 1 : 링크

참고 2 : 링크