[Python] Logger 사용법

Programming/Python

[Python] Logger 사용법

Jonghyuk Baek 2022. 4. 23. 18:34

Introduction

The Hitchhiker's Guide to Python 이란 책에는 다음과 같은 구절이 등장한다.

The only time that print is a better option than logging is when the goal is to display a help statement for a command line application.

Shell과 같은 커맨드 인터페이스에서 --help 옵션을 받아 사용법 도움말을 출력할 때 이외에는 항상 logging이 print보다 낫다는 뜻으로, 사실상 웬만한 상황에서는 print 대신 logging을 사용하는 것이 낫다는 의미이다.

그 이유로는 아래와 같은 내용을 들고 있다.

The log record, which is created with every logging event, contains readily available diagnostic information such as the file name, full path, function, and line number of the logging event.
Events logged in included modules are automatically accessible via the root logger to your application’s logging stream, unless you filter them out.
Logging can be selectively silenced by using the method logging.Logger.setLevel() or disabled by setting the attribute logging.Logger.disabled to True.

정리하자면,

로깅 이벤트를 통해 생성되는 로그 기록에는 파일명, 파일 경로, 함수명이나 라인 넘버 등 로깅 이벤트 발생 시점의 정보가 자세하게 담겨 있어 프로그램 사후 진단이 편하고,
사용하고 있는 하위 모듈에서 발생하는 로깅 이벤트들도 쉽게 접근할 수 있으며,
로깅 레벨 설정 등을 통해 기록될 로그를 선택적으로 필터링 할 수 있다는 것이다.

단순하게 생각해 봐도, 터미널 콘솔 창에 맥락 없이 주르르 떠 있는 print 내용을 보면서 통해 문제를 파악하고 필요에 따라 프린트 구문을 넣었다 지웠다 하기보단, 로거를 통해 체계적으로 어플리케이션 실행 상태를 기록하고 선택적으로 필터링해 볼 수 있게 만드는 편이 장기적으로는 나을 것이다.

오늘은 파이썬에서 기본으로 제공하고 있는 logger 사용법을 정리해 보려고 한다.
예제는 파이썬 도큐멘테이션을 주로 참고했다!

Getting Started

import logging
logging.warning('Watch out!')  # will print a message to the console
logging.info('I told you so')  # will not print anything

logging 빌트인 모듈을 임포트 하고 logging.warning, logging.info 등의 함수를 이용해 로그 메시지를 출력할 수 있다. 로그를 출력할 때 사용되는 메소드 이름인 warning, info는 출력될 로그의 레벨을 의미하는데, 예를 들면 logging.warning 함수로 출력하는 메시지는 logging.WARNING의 로그 레벨을 가지게 된다.

출력 결과를 보기 이전에, 여기서 로그 레벨의 용도는 뭘까?

Log Levels

로그는 아래 목록 중 하나의 레벨을 가지며, 각 레벨의 로그는 각기 다른 용도를 지니고 있다.

DEBUG: 프로그램 작동에 대한 상세한 정보를 가지는 로그. 문제의 원인을 파악할 때에만 이용.
INFO: 프로그램 작동이 예상대로 진행되고 있는지 트래킹하기 위해 사용.
WARNING: 예상치 못한 일이나 추후 발생 가능한 문제를 표시하기 위함.
ERROR: 심각한 문제로 인해 프로그램이 의도한 기능을 수행하지 못하고 있는 상황을 표시.
CRITICAL: 더욱 심각한 문제로 인해 프로그램 실행 자체가 언제라도 중단될 수 있음을 표시.

로거 설정 시 레벨을 지정해 주면 해당 레벨 이상의 (더 심각한 쪽으로) 로그 이벤트만이 기록된다. 디폴트로 설정되는 로그 출력 레벨은 WARNING으로, WARNING 이상의 심각도를 가지는 이벤트만 트래킹 되도록 세팅된다. 따라서 위의 예제를 실행하면, INFO 로그 이벤트는 출력되지 않고 "Watch out!" 구문만이 출력된다.

WARNING:root:Watch out!

Log to File

그런데 위와 같이 출력만 하기보다는 프로그램 실행 중에 로그 이벤트들이 파일의 형태로 저장이 된다면 더 좋을 것이다. 텍스트 파일의 형태로 저장이 되면 터미널 스크롤을 한참 올리거나 원하는 내용을 찾아 헤메는 등의 수고를 덜 수 있다.

import logging
logging.basicConfig(filename="example.log", level=logging.WARNING)
logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')
logging.error('And non-ASCII stuff, too, like Øresund and Malmö')

logger.basicConfig 함수에서 로그가 저장될 위치와 저장할 로그 레벨 임계값을 설정해 두면, 이후의 로그 이벤트들이 필터링되어 로그 파일에 기록된다. 이 함수는 따로 호출해 놓지 않았다면 debug, info 등과 같은 함수들이 불릴 때 디폴트 세팅으로 자동 호출된다.

로거 레벨을 WARNING으로 해 놓았기 때문에 WARNING 이상의 레벨을 가지는 로그들만 골라 기록된 것을 볼 수 있다. 만약 모든 로그를 출력하고 싶다면 level을 logging.DEBUG 로 설정해 주면 된다. 반대로 정말 심각한 이벤트만 기록되게 하고 싶다면 logging.ERROR 이나 logging.CRITICAL로 로거 레벨을 설정하자.

기본 설정에서는 이미 존재하는 동일 경로 로그 파일이 있다면 내용을 덮어쓰지 않고 그 뒤에 쭉 append 되는데, 만약 이전의 기록을 날리고 새로 작성하게 하고 싶다면 filemode="w" 옵션을 제공해 주자.

logging.basicConfig(filename="example.log", filemode="w", level=logging.WARNING)

참고로, logging.basicConfig 함수는 오직 최초 한 번의 호출만이 유효하게 작동하며, 이후의 호출은 아무 기능을 하지 않는다.

Log Formatting

import logging

logging.basicConfig(
    format='%(asctime)s %(levelname)s:%(message)s',
    level=logging.DEBUG,
    datefmt='%m/%d/%Y %I:%M:%S %p',
)

logging.debug("Sample debug message")

logging.basicConfig에서 로그 이벤트의 출력 포맷을 설정하는 것도 가능하다. format 인자에 어떤 식으로 포맷팅 할 지 나타내는 스트링을 하나 제공해 주면 된다. 위 예시에서는 현재 시간과 로그 이벤트 레벨, 그리고 로그 메시지를 출력하도록 세팅했다. 위 코드를 실행시키면 아래와 같이 결과가 출력된다.

04/23/2022 04:33:13 PM DEBUG:Sample debug message

예시에 쓰인 어트리뷰트 이외에도 프로세스 ID 등 다른 정보를 추가해 원하는 대로 로그 포맷을 설정할 수 있다. 사용 가능한 다른 어트리뷰트들은 아래의 표를 참고하자. Python 도큐멘테이션 문서에서 가져왔다.

어트리뷰트 이름	포맷	설명
args	직접 포맷할 필요는 없습니다.	message 를 생성하기 위해 msg 에 병합되는 인자의 튜플. 또는 (인자가 하나뿐이고 딕셔너리일 때) 병합을 위해 값이 사용되는 딕셔너리.
asctime	%(asctime)s	사람이 읽을 수 있는, LogRecord 가 생성된 시간. 기본적으로 ‘2003-07-08 16:49:45,896’ 형식입니다 (쉼표 뒤의 숫자는 밀리 초 부분입니다).
created	%(created)f	LogRecord 가 생성된 시간 (time.time() 이 반환하는 시간).
exc_info	직접 포맷할 필요는 없습니다.	예외 튜플 (sys.exc_info 에서 제공) 또는, 예외가 발생하지 않았다면, None.
filename	%(filename)s	pathname 의 파일명 부분.
funcName	%(funcName)s	로깅 호출을 포함하는 함수의 이름.
levelname	%(levelname)s	메시지의 텍스트 로깅 수준 ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL').
levelno	%(levelno)s	메시지의 숫자 로깅 수준 (DEBUG, INFO, WARNING, ERROR, CRITICAL).
lineno	%(lineno)d	로깅 호출이 일어난 소스 행 번호 (사용 가능한 경우).
message	%(message)s	로그 된 메시지. msg % args 로 계산됩니다. Formatter.format() 이 호출 될 때 설정됩니다.
module	%(module)s	모듈 (filename 의 이름 부분).
msecs	%(msecs)d	LogRecord 가 생성된 시간의 밀리 초 부분.
msg	직접 포맷할 필요는 없습니다.	원래 로깅 호출에서 전달된 포맷 문자열. args 와 병합하여 message 를 만듭니다. 또는 임의의 객체 (임의의 객체를 메시지로 사용하기 를 보세요).
name	%(name)s	로깅 호출에 사용된 로거의 이름.
pathname	%(pathname)s	로깅 호출이 일어난 소스 파일의 전체 경로명 (사용 가능한 경우).
process	%(process)d	프로세스 ID (사용 가능한 경우).
processName	%(processName)s	프로세스 이름 (사용 가능한 경우).
relativeCreated	%(relativeCreated)d	logging 모듈이 로드된 시간을 기준으로 LogRecord가 생성된 시간 (밀리 초).
stack_info	직접 포맷할 필요는 없습니다.	현재 스레드의 스택 바닥에서 이 레코드를 생성한 로깅 호출의 스택 프레임까지의 스택 프레임 정보 (사용 가능한 경우).
thread	%(thread)d	스레드 ID (사용 가능한 경우).
threadName	%(threadName)s	스레드 이름 (사용 가능한 경우).

Advanced Usage

위에서는 간단하게 로깅을 구현하고 싶을 때 사용할 수 있는 high-level 도구들을 소개했고, 여기서부터는 좀 더 구체적인 내용을 다뤄보겠다.

먼저 logging 라이브러리에는 크게 네 가지의 클래스가 존재한다.

Logger
Handler
Filter
Formatter

Logger는 warning, info, setLevel과 같이 프로그램 쪽에서 접근할 수 있는 로깅 관련 인터페이스를 제공한다. Handler는 로그 이벤트 출력을 특정한 파일이나 콘솔 출력, 혹은 네트워크 소켓 등 적절한 곳으로 로그를 보내주는 역할을 한다. Filter는 단순히 레벨 수준을 통한 로그 필터링이 아닌, 더 심화된 로그 필터링을 설정할 때 사용된다. 마지막 Formatter는 로그 이벤트를 사람이 읽을 수 있는 형태로 변환해 주는 역할을 한다.

그리고 로그 이벤트 정보 자체는 라이브러리 내의 LogRecord 클래스 인스턴스의 형태로 각 콤포넌트 사이에서 전달된다.

Setting Up Logger

로깅을 시작하기 위해선 먼저 로거 인스턴스를 생성해 줘야 한다.

logger = logging.getLogger(__name__)

__name__ 자리에는 사용자가 지정하는 로거의 이름이 들어가는데, 일반적으로는 현재 로거가 생성된 네임스페이스를 따라 짓는 것이 관례이며, 마침표 ( . ) 구분자를 사용해 모듈 별 로거의 계층 구조를 표현해 주어야 한다.

예를 들어, skeleton.py 라는 모듈에 skeleton 이라는 로거가 존재하는 상황에서, skeleton.py가 참조하는 하위 모듈 math.py에서 정의하는 로거 이름은 skeleton.math 로 짓는 식이다.

로거 이름이 그 자체로 모듈들의 계층 구조를 나타내고 있기 때문에, 여러 모듈이 함께 쓰이는 상황에서 이벤트 발생 위치를 직관적으로 알 수 있다는 장점이 있다.

만약 __name__ 란을 비워 놓으면 자동으로 root 로거가 생성되며, 출력 시에도 로거 이름 자리에 root가 출력된다. Getting Started 챕터에서 보았던 로그 출력 결과를 다시 보자.

WARNING:root:Watch out!

따로 아무것도 설정해 놓지 않은 상태에서 logging.warning 메소드를 호출했고, 자동적으로 root 이름이 붙어서 로그 메시지가 출력되는 것을 볼 수 있다.

logging 모듈에서 직접 부르는 debug(), info(), warning() 등의 메소드들은 모두 아무런 이름이 설정되지 않은 루트 로거를 이용해 로그 이벤트를 기록하는 함수이다. 항상 동일한 로거를 사용하기 때문에, 상위 모듈과 하위 모듈 각각에서 로그 이벤트를 기록해 놓아도 아무 구분 없이 root 이름으로 로그가 나열되게 된다. 따라서 정말 간단한 코드를 다루는 게 아니라면, 개별 모듈 단위에서 따로 named logger를 생성해 로그를 관리해 주는 것이 좋다.

Logger Level Setting

이렇게 생성한 로거 인스턴스들은 개별적으로 로그 임계 레벨을 지정해 주는 것이 가능하다.

logger = logging.getLogger("postprocessor.skeleton")
logger.setLevel(logging.WARNING)

위 코드에서는 postprocessor 모듈의 하위 모듈인 skeleton에서 로거를 정의했으며, 기록 임계 심각도는 WARNING 수준으로 설정되었다는 것을 알 수 있다.

참고로, 각 로거에는 effective level이라는 속성이 있는데, 로거 이름이 계층 구조를 가지고 있는 상황에서 하위 로거에 따로 레벨 세팅이 되어있지 않다면 (logger.NOTSET), 상위 로거의 레벨 세팅을 반영하도록 되어 있다. 위 예시 기준에서는 두번째 줄을 실행시키지 않으면 postprocessor의 로거 레벨을 찾아본 후, 여기서 valid 하게 설정된 레벨이 있으면 이것이 해당 로거의 effective level이 되는 식이다.

만약 모든 로거 인스턴스의 레벨을 설정해 두지 않았다면 최종적으로 루트 로거까지 탐색하게 되며, 루트 로거는 디폴트가 WARNING으로 설정되어 있기 때문에 하위의 모든 로거들은 WARNING 레벨을 effective level로 사용하게 될 것이다.

import logging

logger = logging.getLogger("postprocessor")
logger.setLevel(logging.DEBUG)

logger = logging.getLogger("postprocessor.skeleton")
logger.setLevel(logging.NOTSET)

print(logger.getEffectiveLevel() == logging.DEBUG)
>>> True

사실 실제 레벨이 effective level로 설정되는 것은 아니기 때문에 이렇게 참조해 올 수 있다 참고만 해 두면 좋겠다.

Logging

logger = logging.getLogger("postprocessor.skeleton")
logger.setLevel(logging.WARNING)
logger.info("Skeleton module logger test!")

로거 생성 이후에는, 앞에서 보았던 logging.warning 과 같은 메소드처럼 logger.warning, logger.info 와 같은 식으로 해당 로거를 통해 이벤트를 기록할 수 있다. 모듈에서 직접 부르는 메소드와의 차이점은, 루트 로거가 아닌 named logger (물론 이름을 지정하지 않았다면 root이긴 하다) 가 로그 이벤트를 처리한다는 것이다.

Adding Handler, Formatter, Filter

Handler는 로그 이벤트를 파일이나 네트워크 소켓 등 적절한 곳으로 보내주는 역할을 한다고 언급했었다. 일반적으로는 StreamHandler 클래스나 FileHandler 클래스를 인스턴스화해 로거에 attach 해 주는 식으로 이용하게 된다.

# 콘솔 출력
logger = logging.getLogger("skeleton")
stream_handler = logging.StreamHandler()
logger.addHandler(stream_handler)

# 파일에 출력
logger = logging.getLogger("skeleton")
file_handler = logging.FileHandler()
logger.addHandler(file_handler)

각 핸들러 인스턴스에도 setLevel() 메소드를 호출해 특정한 심각도 이상의 로그 이벤트만을 처리하도록 설정할 수 있다. 또한 여러 핸들러를 한 로거에 붙여놓는 것도 가능한데, 이를 이용해 CRITICAL 이상의 심각도를 가지는 이벤트만을 파일에 쓰고, 나머지는 콘솔에 출력만 하는 등의 응용도 가능하다.

위의 두 핸들러 클래스 이외에도 다양한 핸들러 클래스가 존재하니, 참고해 보면 좋겠다. logging.Handler 클래스는 모든 핸들러 클래스의 베이스클래스로, 직접 인스턴스를 만들 수 없고 단지 이를 상속받아 사용자 핸들러 클래스를 정의하는 데에 쓰일 수 있다.

Formatter는 핸들러 클래스에 붙여 주면 되는데, 이를 이용해 각 핸들러마다 다른 식으로 출력 형태를 조절할 수 있다.

import logging

# 로거 세팅
logger = logging.getLogger("postprocessor")
logger.setLevel(logging.DEBUG)

# 일반 핸들러, 포매터 세팅
formatter = logging.Formatter("%(asctime)s %(levelname)s:%(message)s")
handler = logging.StreamHandler()
handler.setFormatter(formatter)

# 크리티컬 이벤트에 대한 핸들러, 포매터 세팅
formatter_critical = logging.Formatter("!!!!!%(asctime)s %(levelname)s:%(message)s")
handler_critical = logging.FileHandler("log_event.log")
handler_critical.setLevel(logging.CRITICAL)
handler_critical.setFormatter(formatter_critical)

# 각 핸들러를 로거에 추가
logger.addHandler(handler)
logger.addHandler(handler_critical)

logger.info("Is working well?")
logger.critical("It's not working well.")

2022-04-23 18:07:12,414 INFO:Is working well?
2022-04-23 18:07:12,414 CRITICAL:It's not working well.

모든 로그가 콘솔에 출력되면서, 크리티컬 로그만 별도의 포매팅 형식으로 파일에 쓰여진 것을 볼 수 있다.

마지막으로 Filter 클래스는 로거 계층 구조에서 특정 구조 하위의 로거에서 처리하는 이벤트만을 처리하도록 필터링하는 일을 한다. 예를 들어, data.postprocess.skeleton 의 로거 계층 구조가 있다고 할 때, 아래와 같이 data 를 필터링 네임으로 제공해 주면 data, data.postprocess, data.postprocess.skeleton 계층에 해당하는 모든 로거의 이벤트가 처리되고, 트리 바깥의 다른 로거 이벤트는 처리되지 않는 식이다. 아래의 예시를 보자.

import logging

# 로거 설정
logger_preprocess = logging.getLogger("preprocess")
logger_postprocess = logging.getLogger("postprocess")

# 포매터, 필터 설정
formatter = logging.Formatter("%(asctime)s %(levelname)s:%(message)s")
filter = logging.Filter("postprocess")

# 핸들러 설정
handler = logging.StreamHandler()
handler.setFormatter(formatter)
handler.addFilter(filter)

# 핸들러 추가
logger_preprocess.addHandler(handler)
logger_postprocess.addHandler(handler)

logger_preprocess.critical("Critical from preprocess.")
logger_postprocess.critical("Critical from postprocess.")

>>>
2022-04-23 18:23:58,185 CRITICAL:Critical from postprocess.

두 로거는 같은 핸들러를 쓰고 있지만, 필터 설정에서 postprocess 아래의 이벤트만 처리하도록 되어 있기 때문에 logger_preprocess에서 발생시킨 이벤트는 결과적으로 처리되지 않는다.

Useful Codes

아래에는 개인적으로 로거와 관련해서 유용하다고 생각했던 코드를 몇 개 모아봤다.

Function Logging with Functional Decorator

>>> def foo():
...     print("I am inside foo.")
...
...
...
>>> import logging
>>> logging.basicConfig()
>>>
>>> def logged(func, *args, **kwargs):
...     logger = logging.getLogger()
...     def new_func(*args, **kwargs):
...         logger.debug("calling {} with args {} and kwargs {}".format(
...             func.__name__, args, kwargs))
...         return func(*args, **kwargs)
...      return new_func
...
>>>
>>>
... @logged
... def bar():
...     print("I am inside bar.")
...
>>> logging.getLogger().setLevel(logging.DEBUG)
>>> bar()
DEBUG:root:calling bar with args () and kwargs {}
I am inside bar.
>>> foo()
I am inside foo.

디버그 로깅이 필요한 함수에 대해 간편하게 로그를 기록할 수 있게 도와주는 데코레이터 구현이다. The Hitchhiker's Guide to Python 책에서 참고했다.

Temporary Level Modification using ContextManager

import logging
from contextlib import contextmanager

@contextmanager
def debug_logging(level):
	logger = logging.getLogger()
    old_level = logger.getEffectiveLevel()
    logger.setLevel(level)
    try:
    	yield
    finally:
        logger.setLevel(old_level)

def foo_function():
	logging.debug("Debug info line")
    logging.error("Error info line!")
    logging.debug("Additional debug info line")


>>> logging.getLogger().setLevel(logging.WARNING)
>>> my_function()
ERROR:root:Error info line!

>>> with debug_logging(logging.DEBUG):
...    	my_function()
DEBUG:root:Debug info line
ERROR:root:Error info line!
DEBUG:root:Additional debug info line

>>> my_function()
ERROR:root:Error info line!

컨텍스트 매니저를 이용해 특정 지점에서만 잠깐 로거의 레벨 설정을 바꿔놓는 코드 예제이다. Udemy의 Writing High Performance Python 강좌에서 참고했다.

Disable Logging using ContextManager

import logging 

class DisableLogger():
    def __enter__(self):
       logging.disable(logging.CRITICAL)
    def __exit__(self, exit_type, exit_value, exit_traceback):
       logging.disable(logging.NOTSET)

with DisableLogger():
	...

logging 모듈이나 logger 인스턴스에서 disable 메소드를 사용해 특정 레벨 이하의 로그 이벤트를 무시하도록 만들 수 있다 (글 초반의 logger를 써야 하는 이유에서 언급되었다!).

disable 메소드는 인자로 들어온 로그 레벨 이하 레벨의 로그를 버리게 해 준다. 따라서 위 코드처럼 logging.CRITICAL을 disable 해 주면, 모든 로그 이벤트가 처리되지 않고 무시된다. 단순히 코드 중간에서 메소드를 넣어줄 수 있지만 위 코드처럼 컨텍스트 매니저를 만들어 특정 구간에서 발생하는 로그만을 전부 무시하도록 만들어 줄 수도 있다.

위 코드는 스택 오버플로우에서 참고했다. 레퍼런스 참조.

다음은 참고할 만한 사이트들이다.

References

The Hitchhiker's Guide to Python
https://docs.python-guide.org/writing/logging/#logging
Python documentation - logging
https://docs.python.org/ko/3/library/logging.html
How to disable logging on the standard error stream?
https://stackoverflow.com/questions/2266646/how-to-disable-logging-on-the-standard-error-stream

저작자표시