[python] 일정 시간마다 순환하는 로그 파일 만들기

Development/python

[python] 일정 시간마다 순환하는 로그 파일 만들기

mkdir 2021. 3. 15. 16:02

개발환경
- python 3.9.1
- pycharm

개발에 있어 로그는 굉장히 중요한 덕목이다. 여기서 에러가 뜨는지 안뜨는지, 조건문 내부로 진입이 되는지 안되는지, 무수히 많은 라이브러리와 클래스와 함수를 통과한 이 값이 어떻게 나타나는지는 진짜로 돌려보기 전까지는 아무도 모른다.

물론 이것을 위한 방법으로 print 문이 있다. 바로 print("val=",{value}). 간단한 한 줄로 함수 값 확인, 조건문 진입, 각 분기를 통과했음을 알려주는 알림 역할까지. 더해서 System.out.println에 비해 얼마나 간단하고 심플한가. 찬양하라, python. Viva 반 로섬.

그러나 만능같은 print에도 한계는 있다. 라이브러리 한두 개 가져와서 사용하는 연습용 예제라면 상관지만, 모듈이 열개가 넘어가고 코드 줄 수가 200줄, 300줄씩 줄줄히 늘어지게 되면 이야기가 좀 달라진다. jupyter notebook 이용자에게는 조금 와닿지 않을지도 모르지만, pycharm 이용자에게는 굉장히 머리아픈 사태가 도래한다.

젤나가 맙소사. 저 많은 모듈의 값을 어떻게 일일히 확인할것이며, 또 어느 print문이 어느 모듈의 몇번 줄에서 발생했는지 어떻게 검색할 것인가.

이를 위해 있는 디버깅 툴이지만, 실제 서비스를 운영하다보면 짧게는 수 시간에서 수 개월 분량의 운영 기록이 필요하기도 한다. 디버깅은 본격적인 서비스를 배포하기 전, 개발 단계에서 사용하는 방법이다.

이를 위해 등장한 것이 바로 로그이다. 디버깅, 혹은 테스트 러닝 때도 모든 출력이 기록으로 남으며, 약간 설정을 만져야 하지만 어떤 모듈의 몇번 줄에서 발생한 문제인지도 확인 가능하다. 그래서 대부분의 언어는 자체 logging 클래스를 지원하며, IDE에 따라서는 추가적인 기능이 있는 경우도 있다고 한다(직접 확인하지는 못했다).

그럼 로그의 기본적인 형태를 알아보자. 로그는 기본적으로 다섯 단계로 나뉜다. 각 단계는 DEBUG, INFO, WARN, ERROR, CRITICAL의 5단계로 이루어지며, 각 단계는 int값으로 레벨이 결정된다.

그럼 이 로그는 어떻게 사용하는 걸까? 가장 쉬운 예시는 마치 print문처럼 사용하는 것이다. 단 두줄로 출력이 끝난다.

import logging

logging.info('Protoss Zealot')

그러나 이대로 실행하면 터미널 창에는 아무것도 나타나지 않을 것이다. 실행법은 분명히 맞다. 하지만 왜 나타나지 않을까? 그건 logging의 설정 기본값이 warn 이하의 메세지는 출력하지 않도록 하고 있기 때문이다.

import logging

logging.basicConfig(level=logging.DEBUG)
logging.info('Zerg Zergling')

이렇게 .basicConfig를 통해 로깅 수준을 DEBUG로 내려주면 메세지가 출력되는 것을 볼 수 있다. 여기에 이 로그 내역을 파일로 저장하고 싶다면 basicConfig에 속성 하나를 추가해주면 된다.

import logging

logging.basicConfig(level=logging.INFO, filename='alleat.log')
logger=logging.getLogger()
logger.setLevel(1)
logger.debug('33')

filename에 경로 및 파일 이름을 설정해주면 해당 위치에 alleat.log 파일이 생성되고, 내부에 로그 발생 내역이 적히게 된다.

하지만 이대로는 아쉽다. 조금 더 고차원적인 로깅을 위해서는 조금 알아두어야 할 것이 있다.

바로 logger 객체, handler 객체와 formatter 객체다. 이 객체들에 대해서 정말 길고 자세하게 설명해놓은 문서는 파이썬 공식 문서에 있으니 원하신다면 이쪽을 참고해주시길 바란다. 간단하고 심플한 설명을 원한다면 3단 아이스크림으로 표현 가능하다. 1층에는 logger 객체가 기본 골조가 되고, 2층에 handler 객체가, 3층에는 formatter 객체가 있는 것이다. 핸들러 위에 포매터, 로거 위에 핸들러를 얹는 구조라고 생각하면 된다.

import logging
import logging.handlers

바로 로깅 모듈의 하위 경로인 handlers 모듈이다. 참고로 저 handlers를 from logging import handlers로 호출하려고 하면 호출되지 않는다. 파이썬의 패키지와 경로에 관한 이야기인데, 자세한 이야기는 나중에 다루도록 한다.

저 두 라이브러리를 호출하고 나서는 logger 객체를 선언해야 한다. 로거 객체의 선언은 다음과 같다.

logger = logging.getLogger()
hdlr = logging.handlers.TimedRotatingFileHandler(filename='server.log', encoding='utf-8', when='midnight', interval=1)
formatter = logging.Formatter('%(name)s :: %(levelname)s - %(asctime)s - %(message)s :: %(filename)s , %(lineno)s')
hdlr.setFormatter(formatter)
logger.addHandler(hdlr)
logger.setLevel(logging.DEBUG)

logger 변수에는 로그의 기본 뼈대인 로거 객체를 담고, hdlr 변수에는 로그의 성격을 결정할 핸들러 객체를 담는다. 마지막으로 formatter 변수에는 로그 파일 내부에 적힐 로그의 형태를 담는다.

이제는 아까 말한대로 3단 아이스크림처럼 척척 쌓아올리면 끝. 그럼 저 로거는 파일명이 server.log이고(filename='server.log'), 자정마다 새 파일이 생성되며('when='midnight'), 간격은 하루(interval=1)인 로거가 되고 형태꼴은 {로거이름, 로깅레벨, 발생시간, 메세지, 발생한파일명, 발생한줄}의 정보가 담긴 로그를 적게 된다.

그리고 마지막으로 아까 로깅 클래스의 수준이 warn이라고 했었다. 이제 우리는 이것을 DEBUG 수준까지 낮춰주면 logging.info로 로그 내역을 적을 수 있다.

그럼 이렇게 효율좋게 완성된 로그를 매 파일마다 일일히 써내야 할까? 귀찮고, 그럴 필요도 없다. 우리는 새로 set_log.py 파일을 만들어 로거를 생성하는 메소드(혹은 클래스)를 정의해 원하는 파일에서 import만 행하면 된다. 이게 바로 객체 지향 프로그래밍의 장점이 아니겠는가?

utils/set_log.py

import logging
import logging.handlers
import os
import time


def define_logger(prog='logger'):
    if not os.path.isdir('logs'):
        os.mkdir('logs')

    logger = logging.getLogger(name=prog)
    hdlr = logging.handlers.TimedRotatingFileHandler(
        filename='logs/' + prog + '_{}.log'.format(time.strftime('%Y%m%d')),
        encoding='utf-8', when='midnight', interval=1)
    logger.setLevel(level=logging.DEBUG)
    formatter = logging.Formatter('%(name)s :: %(levelname)s - %(asctime)s - %(message)s :: %(filename)s , %(lineno)s')
    hdlr.setFormatter(formatter)
    logger.addHandler(hdlr)
    return logger

위 파일은 실제로 필자가 회사에서 사용하는 로그 포맷이다. 그렇게 복잡하지는 않으니 이해가 어렵진 않을 것이다.

이제 이 set_log.py를 원하는 파일에 import해서 사용하면 끝.

from utils.set_log import define_logger as df

logger=df()
logger.info('로깅 성공!')

이렇게 하면 logger 변수에는 set_log.py 파일의 로거가 담겨있다. 그리고 아까의 길고 복잡한 과정을 거쳐 로그 파일에는 "로깅 성공!" 이라는 글자가 적히게 된다.

조금 재미있는 용법으로 다음과 같은 용법이 있다.

try:
    print(에러가발생합니다)
except NameError as e:
    logger.info(str(e))

어떤 오류가 발생할 지 미리 알고 있다면 사용할 수 있는 방법이다. 아니면 여러 에러중 한 분기로 진입했을 경우 로그를 남기도록 할 수도 있고. 하지만 assert문을 이용한다면 한줄로 정리할 수 있다는 점이 함정.