로깅은 프로그래밍에서 가장 중요한 것 중 하나입니다. 기록을 하는 것은 비단 프로그래밍 뿐 아니라 다른 작업에서도 중요하지만 휘발성으로 계속해서 새로운 작업이 발생하는 프로그래밍에선 그 의미가 더욱 남다릅니다.

해당 글에서는 파이썬에 로그를 기록하는 방법을 간단히 소개하며 파이썬을 사용한다면 일상적으로 쉽게 구현할 수 있는 게으른 로깅 (Lazy logging)이라는 모범 사례를 소개합니다. 

파이썬 로깅

본격적으로 게으른 로깅을 설명하기 앞서 간단하게 파이썬에서의 로깅을 이해해보겠습니다.

하단의 코드는 로깅을 수행하는 가장 간단한 코드입니다. warning이라는 로그 레벨과 함께 함께 출력될 메세지를 전달하고 있습니다.

>>> import logging
>>> logging.warning("Hello logging")
WARNING:root:Hello logging

warning을 로그 레벨로 설정한 후 지정된 "Hello logging"이라는 에러메세지를 출력하고 있습니다. Python의 기본 로깅 레벨은 warning이며 이는 해당 로그 레벨 이상의 로그들만 출력 혹은 파일에 기록됨을 의미합니다. 때문에 다음과 같은 실행에서는 아무런 결과를 얻을 수 없습니다.

>>> logging.info(“Hello logging”)

info 레벨은 warning 레벨보다 아래 단계에 위치하며 앞서 설명한대로 해당 코드는 로그를 기록하지 않습니다.

우리는 파이썬을 통해 로그를 기록하며 자연스럽게 logging 모듈을 가져옵니다. 우리가 가져오는 logging 모듈은 기본으로 제공되는 로깅 모듈이므로 별도의 설정을 통해 로그 레벨을 바꿀 수 있습니다. 

로그 레벨을 변경하는 방법에는 2가지 방법이 있습니다. 이를 이해해기 위해서는 logger라는 존재에 대해 이해해야 합니다. 

logging 모듈 내의 getLogger라는 메서드는 logger를 반환합니다. 

logger = logging.getLogger("my_logger")

이때 logger는 로깅을 하는데 있어 설정 가능한 다양한 구성들을 담고 있는 하나의 인스턴스입니다. 우리가 설정하고자 하는 로그 레벨도 바로 logger를 통해 설정할 수 있구요.

logger를 이해하셨다면 로깅을 할 수 있는 첫번째 방법을 이해하실 수 있습니다.

logging.basicConfig(level=logging.DEBUG)
logger = logging.getLogger("my_logger")

가장 기본적인 설정 방법이며 basicConfig가 수행된다면 그 이후에 만들어지는 모든 logger의 로깅 레벨이 basicConfig에 명시된 대로 설정되는 것을 알 수 있습니다.

>>> logging.basicConfig(level=logging.DEBUG)
>>> logger = logging.getLogger("my_logger")
>>> logger.info("Hello logging")
INFO:my_logger:Hello logging

basicConfig는 편리하게 루트 Logger를 설정하는 방법을 제공하지만 한 번 설정된 루트 Logger의 설정은 변경되지 않습니다. 쉽지만 그만큼 자유도가 떨어지기에 사용방식이 다소 제한적입니다. (한 번 적용이 된다면 해당 런타임에 영구적입니다)

>>> logging.basicConfig(level=logging.DEBUG)
>>> logger = logging.getLogger("my_logger")
>>> logger.info("Hello logging")
INFO:my_logger:Hello logging
>>> logging.basicConfig(level=logging.ERROR)
>>> logger.info("Hello logging")
INFO:my_logger:Hello logging

두 번째 방식은 setLevel 메소드를 통한 설정 변경입니다.

앞서 설명한 문제는 setLevel이라는 메소드를 통해 해결할 수 있습니다. 먼저 basicConfig의 방식과의 가장 근본적인 차이는 로깅 설정을 일괄적으로 적용시키냐(basicConfig), 개별 logger에 적용시키냐의 차이입니다. 코드로 확인해보시죠.

# 1. basicConfig
>>> logging.basicConfig(level=logging.INFO)
>>> logger.info("Hello logging")
INFO:my_logger:Hello logging

# 2. logger 생성
>>> logger1 = logging.getLogger('my_logger_1')
>>> logger2 = logging.getLogger('my_logger_2')
>>> logger1.info('This is an informational message from logger1')
INFO:my_logger_1:This is an informational message from logger1
>>> logger2.info('This is an informational message from logger2')
INFO:my_logger_2:This is an informational message from logger2

# 3. logger1에 대해서 로깅 레벨 변경
>>> logger1.setLevel(logging.ERROR)
>>> logger1.info('This is an informational message from logger1 - it will not be logged')
>>> logger1.error('This is an error message from logger1')
ERROR:my_logger_1:This is an error message from logger1

# 4. logger2는 로깅 레벨 유지
>>> logger2.info('This is another informational message from logger2')
INFO:my_logger_2:This is another informational message from logger2

먼저 코드에서는 기본적으로 모든 logger에 적용될 기본 레벨을 basicConfig를 통해 명시합니다. 때문에 해당 라인 이후의 모든 logger는 error 로깅 레벨로 설정될 것입니다.

생성된 2개의 logger 중에서 logger1의 경우 중간에 설정을 변경해보았습니다. info 단계에 대한 출력이 이뤄지지 않았으며 설정이 성공적으로 변경되었음을 확인할 수 있습니다. logger2의 경우에는 여전히 Info 단계에 대한 출력이 이뤄짐을 확인할 수 있습니다.

로깅 레벨외에도 로깅을 통해 출력을 할지, 파일에 기록할지, 로그 메세지는 어떻게 구성할지 등 다양한 설정을 logger에 담을 수 있습니다.

게으른 로깅

로깅을 수행할 때 활용하는 warning 함수는 다음의 구조를 갖습니다 (다른 로깅 레벨도 동일합니다).

def warning(msg, *args, **kwargs):

warning에서는 기본적으로 msg를 첫 번째 인수로 요구하는 구조이며 추가적으로 더 많은 인수를 추가할 수 있도록 구성되어 있습니다.

이번에는 별도의 설명없이 코드를 먼저 보여드리면서 글을 이어나가보겠습니다.

>>> import logging
>>> class RaiseWhenPrinted:
...     def __str__(self):
...         raise Exception(“I was printed”)
>>> raise_when_printed = RaiseWhenPrinted()

현재 로깅 레벨은 warning 단계입니다. 앞서 설명한 별도의 로깅을 설정하지 않았기에 루트 logger의 기본설정을 따른 결과입니다.  

이어서 클래스의 __str__ 함수를 재정의합니다. 해당 클래스에서는 별도로 __str__ 에 접근하는 경우 에러를 발생시킬 것입니다.

>>> logging.info(“Logging {}”.format(raise_when_printed))

해당 코드를 실행하면 다음과 같은 결과를 얻습니다.

Traceback (most recent call last):
File “<input>”, line 1, in <module>
File “<input>”, line 3, in __str__
Exception: I was printed

앞서 설명하였듯 루트 logger의 레벨은 warning입니다. 그러나 info 레벨의 로깅에도 __str__ 함수에 접근하여 예외가 발생한 것을 확인할 수 있습니다.

이어서 게으른(Lazy) 방식으로 문자열을 전달해보겠습니다.

>>> logging.info(“Logging %s”, raise_when_printed)

해당 코드에서는 예외가 발생하지 않았습니다.

이는 __str__ 메소드가 호출되지 않았다는 것을 의미함과 동시에 게으른 로깅을 수행하는 경우 실제로 __str__이 요구되지 전까지는 해당 메소드가 사용되지 않음을 의미합니다.

만약 로깅 레벨이 warning으로 설정된 로깅을 수행하면 다음과 같은 결과를 얻을 수 있습니다.

>>> logging.warning("Logging %s", raise_when_printed)
--- Logging error ---
Traceback (most recent call last):
  File "/Users/mook/anaconda3/lib/python3.11/logging/__init__.py", line 1110, in emit
    msg = self.format(record)
          ^^^^^^^^^^^^^^^^^^^
  File "/Users/mook/anaconda3/lib/python3.11/logging/__init__.py", line 953, in format
    return fmt.format(record)
           ^^^^^^^^^^^^^^^^^^
  File "/Users/mook/anaconda3/lib/python3.11/logging/__init__.py", line 687, in format
    record.message = record.getMessage()
                     ^^^^^^^^^^^^^^^^^^^
  File "/Users/mook/anaconda3/lib/python3.11/logging/__init__.py", line 377, in getMessage
    msg = msg % self.args
          ~~~~^~~~~~~~~~~
  File "<stdin>", line 3, in __str__
Exception: I was printed
Call stack:
  File "<stdin>", line 1, in <module>
Message: 'Logging %s'
Arguments: (<__main__.RaiseWhenPrinted object at 0x10a891ed0>,)

실행 결과를 통해 예외가 발생하였으며 실제 __str__에 접근이 이뤄짐을 확인할 수 있습니다.

게으른 로깅의 원리

로그 레벨 함수의 정의를 다시 확인해보겠습니다.

def warning(msg, *args, **kwargs):

만약 우리가 f-string이나 format 메소드를 통해 문자열을 작성하는 경우 인터프리터는 msg 인수를 런타임에 즉시 해석하여 결과를 내놓게 됩니다.

logging.info(f"Logging {raise_when_printed}")

때문에 다음과 같은 호출은 사용여부와 관계없이 즉시 평가되어 메모리에 올라가게 될 것입니다.

여기서 대신 게으른(Lazy) 방식으로 문자열을 처리한다면

logging.info("Logging %s", raise_when_printed)

인터프리터는 해당 코드를 런타임 실행 당시에 바로 해석하지 않고 이후에 등장하는 인수가 인스턴스임을 인터프리터에가 알리기만 합니다. 때문에 해당 시점에서는 __str__ 메소드는 실행되지 않습니다.

프로그램이 실제 해당 라인을 실제로 표준 출력으로 내보야하는 경우 내부적으로 로그 수준이 어떻게 구성되어있는지를 기반으로 호출 여부가 결정됩니다. 만약 호출이 일어나지 않았다면 아무 일도 일어나지 않습니다. 호출이 발생했다면 그제서야 __str__ 메소드에 접근하여 예외가 발생할 것입니다.

퍼포먼스 테스트

퍼포먼스를 확인하기 위해  timeit 라이브러리를 사용합니다. 해당 라이브러리는 명령을 실행하는데 걸리는 시간을 계산하는데 활용됩니다.

>>> import timeit
>>> lazy = “logging.info(‘lazy %s’, ‘logging’)”
>>> not_lazy = “logging.info(‘not lazy {}’.format(‘logging’))”
>>> setup = “import logging”

두 개의 로깅 명령을 생성하고 추가적으로 로깅에 필요한 환경인 logging 모듈을 환경으로 구성합니다.

이를 통해 다음의 테스트를 수행하였습니다.

>>> timeit.timeit(not_lazy, setup=setup)
1.3170759610000005
>>> lazy = "logging.info('lazy %s', 'logging')"
>>> timeit.timeit(lazy, setup=setup)
1.0643428150000034

간단한 로깅 작업이지만 약 30%의 속도 차이가 발생하는 것을 확인할 수 있습니다. 그리 크게 느껴지는 단위가 아닐 수도 있지만, 구현에 비해 얻을 수 있는 이점이 상당하다는 점에 주목해볼 수 있겠습니다.

결론

지연 로깅 자체는 공식 문서에 기록은 되어있지만, 그와 별개로 파이썬의 일반적인 관행이라고 보기에는 모두가 동의하지 않을 수도 있는 방식입니다.

앞서 살펴보았듯 구현은 쉽고 이점은 확실한 방식이라고 할 수 있습니다. 미세한 차이이기에 속도에 민감하지 않다면 수많은 로깅 메소드 호출에 대한 리펙토링을 굳이 수행해야 할까는 의문입니다. 다만 새로 작성될 로깅에서는 지연된 로깅을 쓰는 것이 대부분의 상황에서 옳을 것으로 예상됩니다.  다른 부분에서의 Trade-Off가 있을 수도 있겠지만 어떠한 단점이 있을지에 대해서는 아직 떠오르는 바는 없으며 대부분의 상황에서 모범 사례로 동작할 것이라고 생각합니다.