조금 더 체계적인 Python Logging

작성일 Edited on In Disqus:

Introduction

Python으로 코드를 짤 때, 로그를 띄우는 방법으로 print('[*] Message')를 정말 많이 써 왔습니다. 군더더기 없고, 유연하고, dependency 없이 아무 위치에나 넣을 수 있다는 점이 좋았습니다. ‘좋았다’ 보다는 ‘편했다’ 혹은 ‘귀찮았다’가 더 적절한 것 같습니다. 혼자서 사용하는 프로그램을 짤 때는 exception 처리나 로그 처리에 신경을 쓰지 않아도 문제가 없었기 때문인 것 같습니다.

이러한 방법은 문제가 많이 있습니다. 중요도에 따라서 로그를 분류할 수도 없을 뿐더러, 코드를 수정하지 않는 이상 로그를 컨트롤 할 수도 없습니다. 정말로 print 되어야 하는 내용과 로그가 뒤섞여 버려서 화면이 지저분해지는 것도 문제입니다. (Fang’s coding note) 가끔은 조용히 프로그램을 돌리고 싶을 때도 있고, 가끔은 verbose 해지고 싶어질 때도 있잖아요?

Python에서는 logging 모듈을 기본적으로 제공합니다. 이제 print('[*] ...')만 사용하지 말고, logging 모듈을 통해 멋지고 깔끔한 로깅을 해봅시다. 이번 포스트를 통해 Python에서 제공하는 logging 모듈을 어떻게 사용하는지 알아보도록 하겠습니다. 또한, ‘좋은 로그 처리 방법’이 어떤 성질을 지니고 있을 지에 대한 고민도 해보겠습니다.

References

Step 1 : 간단하게 로그 생성해보기

1-1. Log Level : 로그의 ‘심각한 정도’

들어가기에 앞서서, 로그 레벨에 대하여 짚고 넘어갑시다. 로그는 중요도에 따라 서로 다른 레벨을 가지게 되고, 이 중요도에 따라 로그를 관리할 수 있습니다. 아래는 Logging HOWTO에 소개된 로그의 각 레벨과 설명입니다.

Level Value When to use
DEBUG 10 (주로 문제 해결을 할 때 필요한) 자세한 정보.
INFO 20 작업이 정상적으로 작동하고 있다는 확인 메시지.
WARNING 30 예상하지 못한 일이 발생하거나, 발생 가능한 문제점을 명시. (e.g. ‘disk space low’) 작업은 정상적으로 진행.
ERROR 40 프로그램이 함수를 실행하지 못 할 정도의 심각한 문제.
CRITICAL 50 프로그램이 동작할 수 없을 정도의 심각한 문제.

Python의 기본 logging 시스템의 레벨은 WARNING으로 설정되어 있습니다. 따라서 특별한 설정을 하지 않을 경우, WARNING 레벨과 이보다 더 심각한 레벨의 로그만 처리됩니다.

다음은 Logging HOWTO에 소개된 상황에 따른 가장 적합한 로깅 방법입니다.

상황 방법
일반적인 console 출력 print()
프로그램의 실행 중 발생하는 정상적인 이벤트 알림 logging.info()
(진단 등을 위한) 자세한 수준의 로그인 경우에는 logging.debug()
런타임 중 발생한 이벤트와 관련하여 경고 사용자가 프로그램을 수정해서 문제를 해결할 수 있는 경우 warnings.warn()
사용자가 처리할 수 있는 문제가 아닌 경우 logging.warning()
런타임 중 발생한 이벤트와 관련한 에러 예외 처리 (raise Exception)
발생한 예외를 suppress하고 raise 하지 않은 경우 (e.g. long-running 서버 프로세스에서 에러 발생 시) logging.error(), logging.exception(), logging.critical()

이제 본격적으로, 각 레벨의 로그를 어떻게 생성할 수 있는지 알아봅시다.

1-2. Root Logger를 이용하여 로그 생성하기

가장 간단하게 로그를 생성하는 법은, module-level로 정의되어 있는 root logger를 사용하는 방법입니다. 아래와 같이 로그를 생성할 수 있습니다.

1
2
3
4
5
6
7
import logging
logging.warning('This is a warning message')
# 아래와 같은 메시지가 콘솔에 출력됩니다
# WARNING:root:This is a warning message

logging.info('This is an info message')
# 아무 것도 프린트 되지 않습니다

WARNING 로그는 출력이 되었지만, INFO 로그는 아무것도 출력이 되지 않습니다. 이는 root logger의 기본 level이 WARNING 수준으로 설정되어 있어서, 해당 수준 이상의 로그만 처리되기 때문입니다. Logger가 처리하는 로그의 레벨을 조정하는 방법은 아래와 같습니다.

1
2
3
4
5
6
import logging
logging.basicConfig(level=logging.INFO)

logging.info('This is an info message')
# 아래와 같은 메시지가 출력됩니다!
# INFO:root:This is an info message

콘솔로 출력이 되는 로그를 다음과 같은 방법으로 파일에 저장할 수도 있습니다.

1
2
3
4
5
import logging
logging.basicConfig(filename='dummy.log', level=logging.INFO)
logging.debug('this is a debug')
logging.info('this is an info')
logging.warning('this is a warning')

위를 실행할 경우, dummy.log 파일에 다음과 같이 로그가 저장됩니다.

1
2
INFO:root:this is an info
WARNING:root:this is a warning

이렇게 설정을 할 경우, 콘솔에는 로그 메시지가 출력되지 않습니다. basicConfig를 여러번 실행해도 가장 처음 호출된 설정만 유효하고, 나머지는 설정이 적용되지 않습니다. Root logger에 이미 handler가 설정 되어 있다면 basicConfig는 아무런 처리도 하지 않습니다. 여러개의 handler를 등록하고 싶은 경우 handlers 인자로 전달하는 방법이 있지만, 가장 처음의 설정만 유효하다는 점은 변함이 없습니다. 하나의 logger에서 발생한 로그를 여러 handler가 처리하도록 설정하는 방법은 다음 step에서 살펴보도록 합시다.

출력되는 로그를 다음과 같이 formatting 할 수 있습니다.

1
2
3
4
5
6
7
8
9
import logging
logging.basicConfig(
  format = '%(asctime)s:%(levelname)s:%(message)s',
  datefmt = '%m/%d/%Y %I:%M:%S %p',
  level = logging.DEBUG
)
logging.debug('This is a formatted debug message')

# 03/12/2019 05:20:12 PM:DEBUG:This is a formatted debug message

format에 사용되는 속성들은 document (LogRecord attributes)에서, datefmt에 사용되는 속성들은 document (time.strftime(...))에서 확인할 수 있습니다.

Step 2 : 역할 분담하기

로깅 시스템은 다음과 같은 구성요소들로 이루어져 있습니다.

  • Loggers : 어플리케이션 코드가 직접 사용할 수 있는 인터페이스를 제공합니다.
  • Handlers : Loggers에 의해 생성된 LogRecord를 처리하여 적절한 위치로 보냅니다.
  • Filters : 출력되어야 하는 로그를 필터링합니다.
  • Formatters : LogRecord의 출력 형태를 지정합니다.

로그 이벤트는 LogRecord 형태로 Loggers에서부터 Handlers, Formatters 순서로 전달됩니다. 자세한 순서는 document (Logging Flow)에 포함된 아래의 flow chart와 같습니다.

Logging Flowchart

2-1. Loggers

Logger는 세가지 주요 역할을 합니다.

  1. 로그를 생성할 수 있는 method를 제공해줍니다. (Logger.debug(), Logger.info(), …)
  2. 로그 레벨과 Logger에 적용된 filter를 바탕으로 처리해야 할 메시지를 판단합니다.
  3. 적절한 Handler들에게 로그 메시지에 부가정보가 더해진 LogRecord 인스턴스를 전달해줍니다.

Logger 오브젝트는 logging.getLogger(name) method를 통해 사용할 수 있습니다. 이와 관련한 몇 가지 특징을 살펴보겠습니다.

  • name이 주어진 경우, 해당 이름에 해당하는 logger를, name이 주어지지 않은 경우 root logger를 전달받습니다.
  • name은 마침표(.)로 구분되는 계층구조를 가지고 있습니다. 예를 들어, getLogger('foo.bar')는 getLogger('foo')의 자식 logger를 반환합니다.
  • Logger의 레벨이 정해지지 않은 경우 (logger.setLevel(...)을 설정해주지 않은 경우), 자신의 부모 logger의 레벨을 사용합니다. 부모의 로그 레벨이 정해지지 않은 경우, 그 부모의 로그 레벨을 참조하는 식으로 반복됩니다. Root logger는 항상 로그 레벨이 설정되어있습니다. (기본값 WARNING)
  • 자식 logger는 메시지를 자기 부모 logger의 handler에게 propagate합니다. 따라서, 부모 logger에 handler가 설정되어 있는 경우라면, 자식 logger에서 handler를 다시 설정해야 하는 중복 업무를 줄일 수 있습니다. (Logger.propagate = False로 설정해줌으로써, propagation을 막을 수 있습니다.)

로깅 전략에 따라서 다양한 범위를 커버하는 Logger를 선언할 수 있습니다. 아래는 이승현님의 게시글 파이썬 로깅의 모든것에서 소개하는 ‘로거를 만드는 대표적인 범위’에 대한 내용입니다.

  • Module-wise : Python에서는 하나의 파일이 하나의 모듈입니다. 따라서, 파일의 제일 위쪽에서 모듈명(__name__)으로 Logger를 만드는 방법이 있습니다.
  • Instance-wise : __init__() method 내에서 Logger를 생성하는 방법으로, 각 인스턴스마다 고유한 Logger를 가지게 됩니다.
  • Class-wise : __class__.__qualname__에 해당하는 Logger를 생성하는 방법입니다. 클래스별로 고유한 Logger를 가지게 됩니다.
  • Function-wise : 함수 내에서 Logger를 생성할 수도 있습니다. (e.g. main())

생성된 Logger를 설정하는 주요 method들은 다음과 같습니다.

  • Logger.setLevel() : 처리할 메시지의 최소 레벨을 설정합니다. 만약, logging.INFO 값을 설정하면, DEBUG 레벨의 로그는 무시됩니다.
  • Logger.addHandler(), Logger.removeHandler() : Handler 오브젝트를 추가하고 제거합니다. Handler가 없는 경우도 있고, 여러개의 Handler가 하나의 Logger에 추가되는 경우도 있습니다.
  • Logger.addFilter(), Logger.removeFilter() : Filter 오브젝트를 추가하고 제거합니다.

로그를 생성하는 method들은 다음과 같습니다.

  • Logger.debug(), Logger.info(), Logger.warning(), Logger.error(), Logger.critical()
  • Logger.exception() : Stack Trace 정보가 담긴 ERROR 레벨의 로그를 발생시킵니다. Exception handler 안에서만 사용해야합니다.
  • Logger.log() : 로그 레벨을 인자로 전달할 수 있습니다.

2-2. Handlers

Handler는 로그 메시지를 출력하는 역할을 합니다. Useful Handlers에서 Handler의 종류를 확인할 수 있습니다.

Handler를 설정하는 method는 다음과 같습니다.

  • Handler.setLevel() : 처리할 메시지의 최소 레벨을 설정합니다. Logger의 설정 레벨과 다를 수 있습니다. Logger에서는 통과가 된 로그 메시지가 Handler에서 filtering 될 수 있습니다.
  • Handler.setFormatter() : Handler가 사용할 formatter를 설정합니다.
  • Handler.addFilter(), Handler.removeFilter() : Filter 오브젝트를 추가하고 제거합니다.

몇 가지 예시를 살펴봅시다. 스트림으로 로그를 출력하는 StreamHandler는 다음과 같이 사용할 수 있습니다.

1
2
3
4
5
6
7
8
9
import logging
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)

stream_handler = logging.StreamHandler()
logger.addHandler(stream_handler)

logger.info('This is an INFO message')
# This is an INFO message

파일로 로그를 출력하는 FileHandler는 다음과 같이 사용할 수 있습니다.

1
2
3
4
5
6
7
8
import logging
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)

file_handler = logging.FileHandler('dummy.log')
logger.addHandler(file_handler)

logger.info('This is an INFO message. Hello dummy!')

2-3. Formatters

Formatter는 최종적으로 출력 될 로그 메시지의 formatting에 관여합니다. Formatter는 다음과 같이 생성할 수 있습니다.

1
2
3
4
5
6
import logging
logging.Formatter(
  fmt = None, # 메시지 출력 형태. None일 경우 raw 메시지를 출력.
  datefmt = None, # 날짜 출력 형태. None일 경우 '%Y-%m-%d %H:%M:%S'.
  style = '%' # '%', '{', '$' 중 하나. `fmt`의 style을 결정.
)

logging.basicConfig와 마찬가지로, fmt에 사용되는 속성들은 document (LogRecord attributes)에서, datefmt에 사용되는 속성들은 document (time.strftime(...))에서 확인할 수 있습니다.

2-4. Putting all together

좋습니다! 앞서 살펴본 내용들을 응용하여 간단한 로깅 시스템을 만들어 보기로 합시다. 시스템의 요구사항은 다음과 같습니다.

  • INFO 레벨 이상의 로그를 콘솔에 출력합니다.
  • 모든 레벨의 로그를 debug.log에 저장합니다.
  • ERROR 이상의 로그를 error.log에 저장합니다.
  • 모든 Exception을 suppress하고, stacktrace를 error.log에 저장합니다.
  • 로그가 발생한 시간과 로그레벨, 모듈명이 명시되어야합니다.

아래는 해당 로그 시스템을 구현한 예시입니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG) # 모든 레벨의 로그를 Handler들에게 전달해야 합니다.

formatter = logging.Formatter('%(asctime)s:%(module)s:%(levelname)s:%(message)s', '%Y-%m-%d %H:%M:%S')

# INFO 레벨 이상의 로그를 콘솔에 출력하는 Handler
console_handler = logging.StreamHandler()
console_handler.setLevel(logging.INFO)
console_handler.setFormatter(formatter)
logger.addHandler(console_handler)

# DEBUG 레벨 이상의 로그를 `debug.log`에 출력하는 Handler
file_debug_handler = logging.FileHandler('debug.log')
file_debug_handler.setLevel(logging.DEBUG)
file_debug_handler.setFormatter(formatter)
logger.addHandler(file_debug_handler)

# ERROR 레벨 이상의 로그를 `error.log`에 출력하는 Handler
file_error_handler = logging.FileHandler('error.log')
file_error_handler.setLevel(logging.ERROR)
file_error_handler.setFormatter(formatter)
logger.addHandler(file_error_handler)

Step 3 : 실제로 사용해보기

3-1. Logging Configuration File in JSON or YAML

한번 사용된 Logger 설정을 다른 모듈에서 재사용하고 싶은 경우 어떻게 할까요? Logger 설정을 dict 형태를 통해 로드할 수 있습니다. 따라서, JSON 혹은 YAML 형태로 Logger 설정을 저장/관리하고, 필요시에 dict로 로드하여 설정을 적용할 수 있습니다. 한 예시로, (2-4)의 로깅 시스템을 구축하는 JSON 파일을 아래와 같이 나타낼 수 있습니다.

logger.json
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
{
  "version": 1,
  "disable_existing_loggers": false,
  "formatters": {
    "basic": {
      "format": "%(asctime)s:%(module)s:%(levelname)s:%(message)s",
      "datefmt": "%Y-%m-%d %H:%M:%S"
    }
  },
  "handlers": {
    "console": {
      "class": "logging.StreamHandler",
      "level": "INFO",
      "formatter": "basic"
    },
    "file_debug": {
      "class": "logging.FileHandler",
      "level": "DEBUG",
      "formatter": "basic",
      "filename": "debug.log"
    },
    "file_error": {
      "class": "logging.FileHandler",
      "level": "ERROR",
      "formatter": "basic",
      "filename": "error.log"
    }
  },
  "loggers": {
    "__main__": {
      "level": "DEBUG",
      "handlers": ["console", "file_debug", "file_error"],
      "propagate": true
    }
  }
}

위의 JSON 파일을 다음과 같이 Logger 설정에 사용할 수 있습니다.

1
2
3
4
5
6
7
8
import logging
import logging.config
import json

config = json.load(open('./logger.json'))
logging.config.dictConfig(config)

logger = logging.getLogger(__name__)

설정 파일에 특별한 점은 없습니다… 만, disable_existing_loggers 옵션은 뭘까요? logging.fileConfig() 혹은 logging.dictConfig()를 호출할 경우, 기존에 존재하는 logger들이 전부 비활성화됩니다. 이를 방지하기 위하여, 해당 함수 호출 시에 disable_existing_loggers을 False로 설정하는 것입니다.

3-2. Slack Bot으로 로그 전송하기

Slack의 Web API를 사용하면 bot을 제어할 수 있습니다. Bot 생성 후 발급받은 토큰만 있으면, 다음과 같이 x-www-form-urlencoded 형태나 json 형태의 HTTP 요청을 통해 메시지를 게시할 수 있습니다.

Python logging 모듈에서 기본적으로 HTTPHandler를 제공합니다. Logger에 의해 생성된 LogRecord가 HTTPHandler에게 전달되면, mapLogRecord 함수를 통해 메시지가 dict 형태로 전처리됩니다. 특별히 override 하지 않은 경우, record.__dict__을 반환합니다. 이렇게 전처리 된 dict의 key-value pair를 emit 함수가 URL encoding하여 전송합니다.

HTTPHandler의 mapLogRecord를 적절히 overriding하면, slack bot으로 로그를 전달할 수 있는 SlackHandler를 아래와 같이 구현할 수 있습니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
import logging
import logging.handlers

SLACK_TOKEN = 'xoxb-YOUR_BOT_TOKEN-COMES_HERE'

class SlackHandler(logging.handlers.HTTPHandler):
  def __init__(self, token, channel='#general', emoji=True):
    super().__init__(host='slack.com', url='/api/chat.postMessage', secure=True)
    self.token = token
    self.channel = channel
    self.emoji = emoji

  def mapLogRecord(self, record):
    if self.formatter is None:  # Formatter가 설정되지 않은 경우
      text = record.msg
    else:
      text = self.formatter.format(record)
    
    emoji = (
      '' if self.emoji == False else
      ':bug:' if record.levelname == 'DEBUG' else
      ':pencil2:' if record.levelname == 'INFO' else
      ':warning:' if record.levelname == 'WARNING' else
      ':no_entry:' if record.levelname == 'ERROR' else
      ':rotating_light:' if record.levelname == 'CRITICAL' else
      ''
    )
    
    return {
      'token': self.token,
      'channel': self.channel,
      'text': f'{emoji} {text}',
      'as_user': True,
    }

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

formatter = logging.Formatter(
  fmt='%(asctime)s *%(module)s* : %(message)s',
  datefmt='%H:%M:%S',
)

slack_handler = SlackHandler(SLACK_TOKEN)
slack_handler.setFormatter(formatter)
logger.addHandler(slack_handler)

logger.debug('디버깅 로그입니다.')
logger.info('일반 로그입니다.')
logger.warning('경고 로그입니다.')
logger.error('에러 로그입니다.')
try:
  1/0
except:
  logger.exception('예외처리 로그입니다.')

TOKEN에 slack에서 발급받은 bot의 토큰을 입력한 뒤 위의 코드를 실행하면, slack에서 bot이 로그를 출력하는 모습을 볼 수 있습니다.

실행 결과

이모지와 mrkdwn 포맷을 사용하여, 제 취향이 듬뿍 담긴 로거를 만들었습니다. mapLogRecord method를 다듬어서, slack에 출력되는 메시지의 스타일을 커스터마이징 할 수 있겠습니다.