Django - 로깅

회사 나오기 직전에 장고 서버에 적용한 로깅에 대해서 정리해보려고 한다.

그 전에는 급한대로 Django의 Debug 모드를 사용해서 예상치 못한 Exception, Code Error 등을 확인했었다.

Debug 모드를 사용하면 Gunicorn 작동 로그에 해당 에러와 Traceback가 출력이 되어서 운영 도중 문제가 발생했을 경우에는 Gunicorn 로그를 시간대별로 확인하면서 대응을 해야만했다.

전에 우분투나 임베디드 리눅스 등을 다뤄본 경험으로 인해서 내가 Django 서버를 관리할 때에는 기본적인 리눅스 명령어들을 활용해서 별 문제없이 이슈에 대응할 수 있었는데, 새로 오신분의 경우에는 프로젝트 구조에 대해서 나만큼 잘 알고있지 못하고 리눅스 사용도 어려워하셔서 겸사겸사 Django의 로깅 기능을 적용하기로 하였다.

 

Django 의 로깅

• Django에서 지원하는 기본적인 로깅 기능을 사용하려고 하였다.
• 참고할 수 있는 공식 문서가 있다. - https://docs.djangoproject.com/en/3.2/topics/logging/

Logging | Django documentation | Django

• Django 프레임워크 상에서 로깅이 어떻게 구성되는지는 다음 기회에 정리하겠다.

 

Django 의 로깅 사용하기

• 예제로 사용할 만한 간단한 Django 프로젝트 하나를 만들어보았다.
• 두개의 API를 지원한다. 1개는 Create, 1개는 Read 로 작동
• 프로젝트 세팅 파일에 사용할 로깅에 대해서 작성해주어야 한다.

# 로그 메세지에 날짜를 포함시키기 위해서 사전에 선언
now = datetime.now()
str_now = now.strftime('%y-%m-%d')

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse',
        },
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',
        },
    },
    'formatters': {
        'django.server': {
            '()': 'django.utils.log.ServerFormatter',
            'format': '[%(server_time)s] %(message)s',
        },
        'verbose': {
            '()': 'django.utils.log.ServerFormatter',
            'format': '[{asctime}] {levelname} --> {message}',
            'style': '{',
        },
    },
    'handlers': {
        'console': {
            'level': 'INFO',
            'filters': ['require_debug_false'],
            'class': 'logging.StreamHandler',
        },
        # Custom handler which we will use with logger 'django'.
        # We want errors/warnings to be logged when DEBUG=False
        'django.server': {
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'formatter': 'django.server',
        },
        'mail_admins': {
            'level': 'ERROR',
            'filters': ['require_debug_false'],
            'class': 'django.utils.log.AdminEmailHandler'
        },
        'custom_handler': {
            'level': 'INFO',
            'class': 'logging.handlers.TimedRotatingFileHandler',
            'filename': f'logs/custom_handler.log',
            'when': 'h',
            'formatter': 'verbose',
        },
    },
    'loggers': {
        'django': {
            'handlers': ['console', 'mail_admins', 'custom_handler'],
            'level': 'INFO',
        },
        'django.server': {
            'handlers': ['django.server'],
            'level': 'INFO',
            'propagate': False,
        },
    }
}

•  Django에서 지원하는 로깅 기능은 4가지로 구성된다. 각각의 역할을 간단하게 정리해보았다.
  • Filter : Logger의 작동 조건
  • Formatter : 로그 메세지의 형태
  • Handler : 로그 메세지 기록 또는 표시 방식
  • Logger : 실질적으로 작동하는 로거, 사용할 Handler 및 로그 레벨, Filter 조건 명시
• 대부분은 기본적인 로그 양식이지만 내가 추가한 코드를 좀 더 설명해보겠다.

...

    'formatters': {
        ...
        'verbose': {
            '()': 'django.utils.log.ServerFormatter',
            'format': '[{asctime}] {levelname} --> {message}',
            'style': '{',
        },
    },
    'handlers': {
        ...
        'custom_handler': {
            'level': 'INFO',
            'class': 'logging.handlers.TimedRotatingFileHandler',
            'filename': f'logs/custom_handler.log',
            'when': 'h',
            'formatter': 'verbose',
        },
    },

...

• verbose - Formatter
  • 기본적인 로그 메세지 옵션을 사용하되 로그 형태를 "[<날짜>] <로그 레벨> --> <로그 메세지>"의 형태로 지정하였다.
• custom_handler - Handler
  • 로그 레벨은 INFO 레벨로 설정하였다.
  • 로그 메세지를 파일로 관리하고 시간 흐름에 따른 자동적인 파일 관리를 위해서 TimedRotatingFileHandler 클래스를 사용
  • 파일 이름은 임시로 지정하였다.
  • 시간 단위로 로그 파일이 관리되도록 지정하였다.
  • 사용할 Formatter를 verbose로 지정하였다.

지정한 파일 이름을 접두어로 로그가 기록된 시간이 파일 이름 뒷부분에 조합되어 로그가 생성됨

로그파일 내부 지정한 형태로 기록되는 로그 메세지

일부러 KeyError를 발생시켜보았을 때, Traceback 도 전부 기록된다.

 

API 호출 성공에 따른 로그 기록하기

• 위까지의 설정을 완료하면 API가 호출되고 호출 이후 발생하는 에러 상황에 대해서는 자동적으로 기록이 이루어지게되지만, 호출 후 문제없이 성공했을 경우에는 아무런 기록이 남지 않는다.
• 위의 예제처럼 어떤 예외 발생으로 인한 모든 로그 메세지를 기록하는 것은 가독성을 해칠 수가 있다. 개발 단계라면 몰라도 운영 단계에 접어들게 되면 통일된 양식으로 필요한 정보를 쉽게 파악할 수 있도록 로그가 기록되어야 할 것이라 생각한다.
• 이에 따라서 사용자가 직접 로그를 기록할 수 있는 방법이 있다.

...
import logging
# logging 라이브러리 추가
...

logger = logging.getLoger('django')
# logger 선언 -- 프로젝트 settings.py에 먼저 작성한 logger를 지정해야 함
class CaseView(View):
	def post(self, request):
    	...
        
        logger.info("{} {} {} 200".format(request.method, request.path, request.headers['User-Agent']))
	# 먼저 선언한 logger에 "INFO" 레벨로 메세지 전달
	...
    ...
...

기록된 사용자 정의 로그, HTTP Methd + API Path + User-Agent Headers 로 구성

• 성공했을 경우에 대한 예제로 작성되었고, 여러 예외 상황에도 적용이 가능하다.

...
import logging
# logging 라이브러리 추가
...

logger = logging.getLoger('django')
# logger 선언 -- 프로젝트 settings.py에 먼저 작성한 logger를 지정해야 함
class CaseView(View):
	def post(self, request):
    	...
        
        except KeyError:
        	logger.warning("{} {} {} 400 : KeyError".format(request.method, request.path, request.headers['User-Agent']))
		# 먼저 선언한 logger에 "WARNING" 레벨로 메세지 전달
        	...
	...
    ...
...

지정한 로그 레벨로 로그가 기록되고 이전과 같이 Full Traceback까지 기록되지 않음

 

결론

• 로그는 개발과정에서는 최대한 자세하고 가능한 모든 정보를 담고 있어야 한다고 생각한다. 그래야만 디버깅의 원인을 정확하게 짚어낼 수 있고 그에 따라서 적절한 대응이 이루어질 수 있을 것이기 때문이다.
• 반면에 운영 측면에서 활용할 로그는 당연하겠지만 시스템과 관련된 세부적인 데이터들도 로그에 기록되어 있으면 되려 상황파악에 방해가 될 것이다.
• 이와 같은 상황들을 위해서 대부분의 로그 관련 기능에서는 로그의 레벨을 세분화하여 지정된 레벨의 로그만 기록하는 방식을 사용하는 편이다. 이전 직장에서 간단하게 사용해 본 RTOS의 로그 기능도 전체 시스템의 로그 레벨을 지정한 후에 작동된 로그 관련 함수에서 사용된 로그 레벨이 최초 지정된 전체 로그 레벨보다 상위라면 무시하고, 하위라면 표시하는 형식으로 작동했다.
• 다른 소프트웨어들도 비슷하게 작동하는데 , 보통 Debug 레벨은 정말 상세한 정보까지 표현해주고, 점점 상위 레벨로 올라갈 수록 가려지는 정보들이 많아지게 작동한다. 이를 잘 생각해서 비슷한 구성으로 로그 정책을 구성해놓으면 좋을 것 같다.