python - python logging 해부!, logger, handler, filter, formatter 그리고 design

정현우·2023년 5월 20일

Python Deep Dive & Design Pattern

목록 보기

9/15

[ 글의 목적: python logging 구조와 원리, 이해를 바탕으로 제대로 설계하는 logging 구조 ]

Python log

python log는 어떻게 이뤄질까? log는 application에서 발생하는 모든 데이터, 개발자에 의한 또는 시스템 자체적으로 기록하는 모든 이벤트에 대한 정보이다. 이 log는 사실 software에서 굉장히 중요하며 잘 다뤄져야 한다. python 기본 라이브러리 logging은 어떻게 설계되었고 python logging을 어떻게 사용해야 하는지 알아보자.

리눅스 로그 글에서 OS level에서의 logging에 대해서도 다뤘다. "log"는 어떻게 다루고 기록하냐에 따라 "쓰레기"가 될 수도, "비즈니스 적으로 엄청난 인사이트"를 줄 수도 있다.

1. python logging module

1) python 기본 module, logging의 design

python logging module을 최초 개발 한 개발자가 쓴 글 PEP-282이 있다. 해당 개발자는 (1)JDK 1.4(일명 JSR047)의 java.util.logging, (2) log4j 등을 많이 참조해서 만들었으며 그래서 그런지 syntax가 camel-case로 이뤄져 있다. (사실 꽤 PEP8 규칙에 어긋나는 면모가 많이 보인다. 하지만 다 사연이 있긴 하다.)
Logger는 Singleton 패턴 이다. getLogger를 한다고 매번 새로운 instance가 return되는게 아니라 이미 그 이름으로 존재하는 Logger를 return한다.
그리고 Observer 패턴 을 동시에 따른다. 로그 레코드가 생성될 때 로그 핸들러(Observer) 객체에 자동으로 알림(event catch)을 보낸다. 로그 레코드 생성자는 로그 레코드가 생성되면 모든 등록된 옵저버(핸들러)에게 보낸다.
메시지를 생성하는 시점에 "thread-safe" 하게 처리된다. 이는 내부적으로 락(lock) 기능 및 동기화 메커니즘에 의해 보장된다. 코어 코드의 _lock = threading.RLock() 에 따라 _acquireLock & _releaseLock() 부분을 보면 파악할 수 있다. 그리고 이렇기 때문에 muti-processing 환경에서 logging은 조금 더 특별하게 다룰 필요가 있다.
print 대신 logging을 써야하는 이유는 위 하나만으로도 얘기를 할 수 있다. print는 I/O가 발생해 runtime에서 print가 끝날때까지 "멈춘다"
logging module의 python core 코드가 궁금하다면 여기에서 살펴보자! 해당 글에서도 여기 있는 core code를 살짝 언급하려고 한다.

2) 전체 구조

전체 log stream flow chart 는 위와같다. 크게 Logger 와 Handler 로 이뤄져 있다. 그리고 기본 로그 흐름은 크게 아래 5가지를 따른다.

logging.getLogger("MyApp").info(...) 로 log를 찍으면 시작되는 다이어그램이다. 먼저 해당 MyApp 이라는 로거가 info level을 찍을 수 있는지 확인한다. (각 로거는 싱클톤 형태)
가능하다면 LogRecord를 만든다. (코어 코드 보기)
Filter가 만들어진 LogRecord를 attached하는 것을 허용하고 있다면 Handler 에게 pass한다. (여기서 옵저버 패턴 형식)
다시 핸들러가 해당 Level을 찍을 수 있는지 확인하고, Filter가 허용하는지 확인한다. 다 가능하다면 Formatting에 맞춰서 emit 된다.
자식 로거에게 propagate(전파)를 하게 되어 있는지 확인한다. 부모가 있다면, 부모 Logger로 다시 핸들러로 패스한다. 부모가 없을 때 까지 반복!

3) class logging.Logger

이 Logger Class는 세 가지 작업을 한다. 사실 이 세 가지 작업 모두 위에서 살펴본 flow chart에 녹아있다.

응용 프로그램이 실행시간에 메시지를 기록 할 수 있도록 여러 메서드를 응용 프로그램 코드에 노출한다. Logger.setLevel(), Logger.addHandler(), Logger.addFilter() 등을 사용할 수 있게 한다.
로거 객체는 심각도 (기본 필터링 장치) 또는 필터 객체에 따라 어떤 로그 메시지를 처리할지 결정한다. Logger.debug(), Logger.info(), Logger.warning(), Logger.error() 그리고 Logger.critical()은 모두 메시지 와 메서드 이름에 해당하는 수준으로 로그 레코드를 만든다.
관련된 로그 메시지를 영향 받는 모든 로그 처리기로 전달한다.

getLogger

지정된 이름을 가진 로거 인스턴스를 리턴한다. 몇 번 언급했듯이 해당 이름을 가진 logger instance는 Singleton object이다. 그리고 .을 기준으로 부모와 자식이 된다. 즉 foo 라는 logger instance가 있다면 foo.bar가 foo의 자식이다. foo.bam 역시 자식이다. foo.bar.baz 역시 foo 자식이면서 foo.bar의 자식이다.
그래서 주로 logging.getLogger(__name__) 로 logging instance를 세팅하는 이유는 "패키지 계층 구조와 같게 하려고" 하는 것이다. __name__ 은 파이썬 패키지 name space의 module name이기 때문이다!
자식 logger는 "전파"에 의해 기록하려는 log를 부모에게 전파할 수 있다! propagate 어트리뷰트를 False 로 설정하여 전파를 하지 않을 수 있다.
더 많고 자세한 method에 대한 정보는 공식 문서 로 대체한다.

4) class logging.Handler

로그 메시지의 심각도를 기반으로 로그 메시지를 처리기의 지정된 대상으로 전달하는 역할을 한다. Logger 객체는 addHandler() 메서드를 사용하여 0개 이상의 처리기 객체를 자신에게 추가 할 수 있다.
Handler는 절대로 직접 인스턴스로 만들어지지 않는다. 이 친구를 상속받는 Sub Class의 instance가 만들어져야 하며, handler.__init__ 이 createLock() 을 호출한다. 즉 이 친구가 I/O 매커니즘에 대한 엑세스를 직렬화 하는 부분이다. 다양한 Handler 처리기 가 이미 존재한다! 가장 대표적으로 StreamHandler 와 FileHandler, RotatingFileHandler, TimedRotatingFileHandler 를 가장 많이 사용한다고 생각한다.
debug, info level의 log는 console, 표준 출력으로 보내고, error 와 같은 특정 level 이상은 로그 파일로 보내고 그 외는 전자 메일 주소로 보내는 등의 행위가 가능하다. 3개의 handler를 만들어서 추가하면 된다.
이 handler에게 setFormatter() 를 통해서 처리기가 사용할 포메터 object를 세팅할 수 있다. 그리고 addFilter() 를 통해 각 처리기에서 사용할 filter를 세팅할 수 있다. 왜? 라고 생각이 된다면, 다시 위에 Log Flow Chart를 살펴보자!
emit 이라는 method를 통해 실제로 로그를 기록하는데 필요한 작업을 수행한다! 그 수행의 주체 class라는 의미다.

5) class logging.Formatter

class logging.Formatter(fmt=None, datefmt=None, style='%', validate=True, *, defaults=None) 로 생성자가 세팅이 되어 있으며, 로그 메시지의 "최종 순서", "구조" 및 "내용"을 구성한다. 이 친구는 instance로 만들 수 있다.
인스턴스는 전체 메시지의 포맷 문자열과 메시지의 날짜/시간 부분에 대한 포맷 문자열로 초기화된다. fmt 가 지정되지 않으면 '%(message)s' 가 사용되고 datefmt 가 지정되지 않으면 formatTime() 포맷이 사용된다. 즉 %Y-%m-%d %H:%M:%S 이 포멧이다.
style 매개 변수로 "사람이 읽을 수 있는 형식의 시간, 메시지의 심각도 및 메시지 내용을 순서대로 기록" 한다. %, { 또는 $ 중 하나의 값이며 "병합되는 방식"을 의미한다. 아래와 같이 세팅이 된다고 이해하면 된다!, 다 직접 출력해보길 바란다 :)

import logging

# 로그 설정
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger()

formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
formatter = logging.Formatter('{asctime} - {levelname} - {message}', style='{')
formatter = logging.Formatter('$levelname: $message', style='$')
formatter = logging.Formatter('{{"level": "{levelname}", "message": "{message}"}}', style='{')

logger.handlers[0].setFormatter(formatter)

6) class logging.Filter

class logging.Filter(name='') 는, 필터를 "통과하도록 허용할 로거(그 자식들도 포함)" 의 이름을 지정한다. name 이 빈 문자열이면, "모든 이벤트를 허용" 한다.
간단하게 filter(record) method가 핵심이며 해당 record가 filter를 통과한다면 return 0 아니면 0이 아닌 값을 return한다.
Handler에 첨부된 Filter는 이벤트를 처리기가 "출력하기 전"에 호출되는 반면, Logger에 첨부된 Filter는 이벤트가 로깅될 때마다 (debug(), info() 등) Handler로 이벤트를 보내기 전에 호출된다. -> 이 뜻은, Child Logger가 만든 이벤트들은 같은 Filter가 Child에게 적용되지 않는 한 Logger의 Filter 설정으로 Filtering이 되지 않는다는 의미다.

2. Configuring Logging 실습

百聞不如一見, 직접 위 내용을 바탕으로 code level에서 바로 세팅해보자! python logging config는 conf, yaml file로 가능하고, code level에서 직접 세팅하는 것도 가능하다.

logging.basicConfig() 에 대해서는 다루지 않는다. 심플하고 빠르게 로깅 세팅하려면 basicConfig() 를 호출하기만 하면 된다. 물론 다양한 파라미터가 존재하지만, 아래 글은 위에서 살펴본 핵심 class를 하나하나 세팅할 것 이다.

1) code level에서 세팅하기

위에서 이미 핵심 4가지 class (Logger, Handler, Formatter, Filter)에 대해 살펴봤다. 이제 위 information을 그대로 code로 구현하면 된다. 만들고 싶은 logger 형태를 먼저 글로 디자인해보자!

"my_app"이라는 이름을 가지는 logger
INFO level 이상의 로거를 기록한다.
File 형태와 Console(Stream) 동시에 필터없이 기록한다.
File형태는 json 처럼, Stream은 default config format을 따르게 하려고 한다.

import logging

mylogger = logging.getLogger("my_app")
mylogger.setLevel(logging.INFO)

stream_hander = logging.StreamHandler()
mylogger.addHandler(stream_hander)

file_handler = logging.FileHandler("./my_app.log")
formatter = logging.Formatter('{{"logger": "{name}", "level": "{levelname}", "message": "{message}", "asctime": "{asctime}"}}', style="{")
file_handler.setFormatter(formatter) # 또는 mylogger.handlers[1].setFormatter(formatter)
mylogger.addHandler(file_handler)

# logging start!
mylogger.debug("debug log!!!")
mylogger.info("info log!!!")
mylogger.warning("warning log!!!")
mylogger.error("error log!!!")
mylogger.critical("critical log!!!")

위와 같이 simple하게 logging config가 가능하다. root를 이렇게 세팅하고, 해당 root의 자식으로 만들어서 logging을 계속한다면, 위 세팅을 그대로 상속받아서 사용 할 수 있는 것이다!
참고로 FileHandler 는 a 모드로 열리는게 default이다. 참고로 format에는 다양한 attribute를 추가할 수 있다. 여기 python repo의 code를 보면 알 수 있듯이 주석에 잘 설명되어 있다. 간략하게 살펴보면 아래와 같다!

속성	설명
asctime	로그가 생성된 시간을 포맷된 문자열로 나타냅니다.
created	로그가 생성된 시간을 실수 값으로 나타냅니다.
filename	로그 레코드가 발생한 소스 파일의 파일 이름을 나타냅니다.
funcName	로그 레코드가 발생한 함수의 이름을 나타냅니다.
levelname	로그 레벨의 이름을 나타냅니다.
levelno	로그 레벨의 숫자 값을 나타냅니다.
lineno	로그 레코드가 발생한 소스 파일 내의 라인 번호를 나타냅니다.
message	로그 메시지의 내용을 나타냅니다.
module	로그 레코드가 발생한 모듈의 이름을 나타냅니다.
msecs	로그가 생성된 시간의 소수점 이하 밀리초 값을 나타냅니다.
msg	로그 메시지의 내용을 나타냅니다. (message와 동일)
name	로거의 이름을 나타냅니다.
pathname	로그 레코드가 발생한 소스 파일의 경로를 나타냅니다.
process	현재 프로세스의 ID를 나타냅니다.
processName	현재 프로세스의 이름을 나타냅니다.
relativeCreated	로그가 생성된 시간을 로깅 시작으로부터 경과한 밀리초로 나타냅니다.
stack_info	스택 추적 정보를 포함한 로깅 레코드의 추가 정보를 나타냅니다.
thread	현재 스레드의 ID를 나타냅니다.
threadName	현재 스레드의 이름을 나타냅니다.

2) CONF & YAML & JSON file로 세팅하기

project가 규모가 커질수록 logging config는 file을 사용하는 경우가 많다. code level에서는 유지보수 측면에서 어려울 수 있기 때문이다. 위 예시를 그대로 이어가면서 각 file로 casting 해보자!

`logging.conf` file 사용하기

# logging.conf file

[loggers]
keys=root, my_app

[handlers]
keys=stream_handler, file_handler

[formatters]
keys=default_formatter

[logger_root]
level=NOTSET
handlers=

[logger_my_app]
level=INFO
handlers=stream_handler, file_handler
qualname=my_app
propagate=0

[handler_stream_handler]
class=StreamHandler
level=NOTSET
formatter=
args=(sys.stdout,)

[handler_file_handler]
class=FileHandler
level=NOTSET
formatter=default_formatter
args=('./my_app_conf.log', 'a')

[formatter_default_formatter]
format={"logger": "%(name)s", "level": "%(levelname)s", "message": "%(message)s", "asctime": "%(asctime)s"}
datefmt=

아래와 같이 logging.conf 를 logging.config.fileConfig 로 세팅해주면, 위 code level에서 세팅한 로깅과 똑같이 된다!

import logging
import logging.config

logging.config.fileConfig("./logging.conf")

# get logger
logger = logging.getLogger("my_app")

logger.debug("debug message")
logger.info("info message")
logger.warning("warn message")
logger.error("error message")
logger.critical("critical message")

`logging.yaml` file 사용하기

python yaml module을 사용할 수 있게 pip install pyyaml로 설치를 해야 한다. 위 conf와 비교해서 보면, 필자가 보기에는 훨씬 가독성이 좋다고 느껴진다.

version: 1
handlers:
  stream_handler:
    class: logging.StreamHandler
    level: NOTSET
    stream: ext://sys.stdout
  file_handler:
    class: logging.FileHandler
    level: NOTSET
    formatter: default_formatter
    filename: ./my_app_yaml.log
    mode: a
formatters:
  default_formatter:
    format: '{"logger": "%(name)s", "level": "%(levelname)s", "message": "%(message)s", "asctime": "%(asctime)s"}'
    datefmt: ''
loggers:
  root:
    level: NOTSET
    handlers: []
  my_app:
    level: INFO
    handlers:
      - stream_handler
      - file_handler
    propagate: false

그리고 yaml.safe_load 를 통해 설정파일을 읽는다. 참고로 safe_load는 일반적인 load 에 비해 !!python/object/apply:os.system ['rm -rf /'] 와 같은 불순하고 악의적인 설정을 읽으면 단순한 문자열로 해석하고 error를 뱉어낸다! ~~그래서 항상 우리는 이런 "safe mode" 에 대한 고려를 해야한다!!~~

import logging.config
import yaml

with open("logging.yaml", "r") as f:
    config = yaml.safe_load(f.read())
    logging.config.dictConfig(config)

logger = logging.getLogger("my_app")

logger.debug("debug message")
logger.info("info message")
logger.warning("warn message")
logger.error("error message")
logger.critical("critical message")

`logging.json` file 사용하기

이쯤되면 머리속에서 handler, formatter, logger가 머리속에 박혀있을 것이다. 필자는 django logging conf는 json file로 하는것을 가장 선호한다.

{
    "version": 1,
    "handlers": {
        "stream_handler": {
            "class": "logging.StreamHandler",
            "level": "NOTSET",
            "stream": "ext://sys.stdout"
        },
        "file_handler": {
            "class": "logging.FileHandler",
            "level": "NOTSET",
            "formatter": "default_formatter",
            "filename": "./my_app_json.log",
            "mode": "a"
        }
    },
    "formatters": {
        "default_formatter": {
            "format": "{\"logger\": \"%(name)s\", \"level\": \"%(levelname)s\", \"message\": \"%(message)s\", \"asctime\": \"%(asctime)s\"}",
            "datefmt": ""
        }
    },
    "loggers": {
        "root": {
            "level": "NOTSET",
            "handlers": []
        },
        "my_app": {
            "level": "INFO",
            "handlers": [
                "stream_handler",
                "file_handler"
            ],
            "propagate": false
        }
    }
}

위 json file을 logging.config.dictConfig 로 세팅만 해주면 된다!

import logging.config
import json

with open("logging.json", "r") as f:
    config = json.load(f)
    logging.config.dictConfig(config)

logger = logging.getLogger("my_app")

logger.debug("debug message")
logger.info("info message")
logger.warning("warn message")
logger.error("error message")
logger.critical("critical message")

위 파일 설정의 logging 세팅을 모두 잘 했다면, console에 찍히는 것, file로 만들어지는 것 모두 같은 형태로 output이 나와야 한다!
사실 이걸 진짜 실제 프로젝트에서 사용하고 싶다면 일단 "root" 부터 제대로 세팅해라! 라고 말하고 싶다. 그리고 root를 상속받으며 만들어질 logger는 logger = logging.getLogger(__name__) 으로 가져와서 로깅을 박는다. 그러면 앞 서 말한대로 "패키지 구조 그대로 가져가는 logger 세팅을 쉽고 빠르게 꽤할수 있다.

짤막 장고(Django)의 logging config

조금 더 디테일하게 접근하면 "프레임워크"에 대한 기본 지식이 필요한데, Django를 예로 들자면, 내부적으로 "django"라는 name을 가지는 logger가 default (최상위) 이다. 그리고 django는 "내부적으로 로깅 시스템을 관리"하여 로거 이름을 계층 구조로 구성 하여 자식 로거를 부모 로거에 연결한다!
django.utils.log 모듈에 있는 configure_logging() 함수를 통해 설정 되며, Django 프로젝트의 manage.py 또는 wsgi.py와 같은 진입점 파일에서 호출된다!

3) Filter 추가해보기

LogRecord에서 "제외" 라는 string이 들어가면 로깅하지 않는 필터를 만들어보자! 일단 code level에서만 다루겠다.

import logging


class ExcludeFilter(logging.Filter):
    def filter(self, record):
        return "제외" not in record.getMessage()

mylogger = logging.getLogger("my_app")
mylogger.setLevel(logging.INFO)

stream_hander = logging.StreamHandler()
mylogger.addHandler(stream_hander)

file_handler = logging.FileHandler("./my_app_filter.log")
formatter = logging.Formatter('{{"logger": "{name}", "level": "{levelname}", "message": "{message}", "asctime": "{asctime}"}}', style="{")
file_handler.setFormatter(formatter) # 또는 mylogger.handlers[1].setFormatter(formatter)
file_handler.addFilter(ExcludeFilter())  # ExcludeFilter 추가
mylogger.addHandler(file_handler)

# logging start!
mylogger.debug("debug log!!!")
mylogger.info("info log!!!")
mylogger.warning("warning log!!!")
mylogger.error("error log!!!")
mylogger.critical("critical log!!!")
mylogger.error("제외 error log!!!")

logging.Filter 를 상속받는 ExcludeFilter class를 만들어서 file_handler 에만 addFilter 를 통해 만든 class를 add 해줬다!

진짜 기가막히게 "제외" 가 들어가는 LogRecord는 log file에서만 필터링 된 결과를 확인할 수 있다.

4) 마무리

한 번 시간들여 Logging 세팅을 해두면, 해당 세팅은 다양한 프로젝트에서 재활용할 수 있다. 특히 그게 file 수준으로 logging config하려는 이유이기도 하다. 사내 syntax와 다른 DevOps와 format을 맞춰놓은 logging config file을 다양한 시스템에서 공유하면서 사용하려고!
그럼에도 logging을 기가 막히게 해놓은 3rd party가 존재한다. https://www.highlight.io/blog/5-best-python-logging-libraries 해당 글에서 다양한 파이썬 로깅 써드파티 라이브러리를 살펴보자.
그리고 multi-processing 환경에서의 logging은 multiprocessing.log_to_stderr(), multiprocessing.get_logger(), QueueListener 등을 활용하는 테크닉이 있다. 특히 QueueListener 는 비동기 처리와 수집 부분, 실제 로깅 처리 부분을 분리하는 최적화 하기 좋은 방법이다. "멀티 쓰레딩 & 멀티 프로세싱 환경에서 로깅"은 따로 다룰 예정이다.

출처

파이썬에서는 logging에 대한 guide가 굉장히 잘 되어 있다. 아래 3가지 글 모두 보는 것을 추천한다.
그 외 추천 및 출처 글이다.
https://www.toptal.com/python/in-depth-python-logging
https://hwangheek.github.io/2019/python-logging/
https://www.highlight.io/blog/5-best-python-logging-libraries
https://coralogix.com/blog/python-logging-best-practices-tips/
https://www.youtube.com/watch?v=DxZ5WEo4hvU

정현우

도메인 중심의 개발, 깊이의 가치를 이해하고 “문제 해결” 에 몰두하는 개발자가 되고싶습니다. 그러기 위해 항상 새로운 것에 도전하고 노력하는 개발자가 되고 싶습니다!

이전 포스트

python - python을 더 pythonic 하게 사용하기, 12가지 TIP

다음 포스트

python - python logging 해부!, logger, handler, filter, formatter 그리고 design

Python Deep Dive & Design Pattern

Python log

1. python logging module

1) python 기본 module, logging의 design

2) 전체 구조

3) class logging.Logger

getLogger

4) class logging.Handler

5) class logging.Formatter

6) class logging.Filter

2. Configuring Logging 실습

1) code level에서 세팅하기

2) CONF & YAML & JSON file로 세팅하기

`logging.conf` file 사용하기

`logging.yaml` file 사용하기

`logging.json` file 사용하기

짤막 장고(Django)의 logging config

3) Filter 추가해보기

4) 마무리

출처

python - python을 더 pythonic 하게 사용하기, 12가지 TIP

python - 날짜와 시간 다루기, datetime 모듈 해부! 그리고 third-party

0개의 댓글

python - python logging 해부!, logger, handler, filter, formatter 그리고 design

Python Deep Dive & Design Pattern

Python log

1. python logging module

1) python 기본 module, logging의 design

2) 전체 구조

3) class logging.Logger

getLogger

4) class logging.Handler

5) class logging.Formatter

6) class logging.Filter

2. Configuring Logging 실습

1) code level에서 세팅하기

2) CONF & YAML & JSON file로 세팅하기

logging.conf file 사용하기

logging.yaml file 사용하기

logging.json file 사용하기

짤막 장고(Django)의 logging config

3) Filter 추가해보기

4) 마무리

출처

python - python을 더 pythonic 하게 사용하기, 12가지 TIP

python - 날짜와 시간 다루기, datetime 모듈 해부! 그리고 third-party

0개의 댓글

`logging.conf` file 사용하기

`logging.yaml` file 사용하기

`logging.json` file 사용하기