서버개발자가 되는법 - #9 로그의 중요성, Django에서 Log 남기기

---

목차 - 2020/09/29 - [Study/서버] - 서버개발자가 되는법 - 목차

 

git - tkdlek11112/server_dev at 서버개발자_9 (github.com)

 

 

유튜브 - 

 

 

 

 

 

 

 

 

들어가기 전에

처음 회사에 들어갔을 때 개발자들이 하던 대화가 생각납니다.

 

"XXX TR 응답이 안오는데요?"

"로그 까 봤어?"

"넹 로그에 정상적으로 찍혔는데"

 

요즘엔 개발 관련 교육이 수준이 높아진 건지 제가 학생 때 실력이 없었던 건지 모르겠는데 학생들 수준이 엄청 높더군요. 제가 취업하기 전에는 로그라는 단어가 상당히 생소했습니다. 지금도 취준생들에게는 어떤지 모르겠네요. 물론 회사에 들어가고 나서는 로그 없으면 거의 장님 수준이 되었습니다 ㅋㅋㅋ. 개발할 때 이것저것 input값들, 중간에 변수값들, 배열 값들 다 로그로 찍다가 나중에 배포할 때 안 지워서 운영서버에서 "TEST---"로그가 남은 적도 많습니다. 

 

로그는 우리가 개발하면서 개발한 코드가 어떻게 돌아가는지 기록하는 것을 말합니다. 웬만한 개발 프레임워크들은 알아서 로그를 찍습니다. 예를 들어 nginx의 경우 conf설정에서 경로만 지정해주면 알아서 log를 찍고, uwsgi도 로그를 찍습니다. 서버 개발자가 가장 많이 보는 로그는 뭘까요? 아마 API를 만들면서 클라이언트로부터 들어오는 input과 나가는 output 로그일 겁니다. 이 io로그를 보면 클라이언트가 값을 정상적으로 올렸는지, 서버에서 데이터를 잘 내려줬는지 확인 가능하기 때문에 누가 잘못했는지 한방에 보입니다 ㅋㅋㅋㅋ.

 

이전 블로그에서는 대부분 로컬에서 Django를 실행했기 때문에 print를 통해서 input값이나 output값들을 찍었습니다. 하지만 서버에 돌아가고 있는 프로그램의 값은 이렇게 확인할 수가 없죠. 이번 시간에는 로그파일을 생성해서 거기에 input값과 output값을 찍고, 우리가 원하는 로그를 남길 수 있는 로그 시스템을 만들어보겠습니다.

 

 

Logger 설정하기

Django에서는 기본적으로 loggin이라는 패키지를 제공합니다.

 

Django loggin 공식 문서 - Logging | Django documentation | Django (djangoproject.com)

 

일단 test API를 하나 만들고 거기에 logger를 설정해서 어떻게 로그가 남겨지는지 확인해보도록 하겠습니다.

 

class Test(TodoView):
    def post(self, request):
        print(self.user_id)

        return CommonResponse(0, "success", dict(some_data="some_value"))

 

이전 포스팅에서 만들었던 test용 API입니다. 헤더에 user_id를 넣으면 print를 통해서 콘솔에 찍히는 걸 확인하기 위해 만든 API인데 여기다가 로그를 만들어보겠습니다. 

 

먼저 loggin 패키지를 import 하고 logger를 선언하고, logger를 이용해 에러를 출력하면 됩니다. 말로 하면 어렵고 아래 코드로..

 

import logging

logger = logging.getLogger(__name__)


# Create your views here.
class Test(TodoView):
    def post(self, request):
        print(self.user_id)
        logger.error("log test")

        return CommonResponse(0, "success", dict(some_data="some_value"))

 

이제 API를 한번 날려 볼게요.

헤더에 id필드를 만들고 아무거나 입력해주세요

mychew__라는 id와 log test라는 로그가 찍혔습니다.

log test가 콘솔 창에 찍히는 걸 볼 수 있는데, 우리가 원하는 건 log 파일에 남는 겁니다. logger를 선언할 때 logging.getLogger(__name__)을 사용했는데 여기서 logger에 대한 설정을 해줄 수 있습니다. logger 설정은 setttings.py에서 해줄 수 있습니다.

 

# ~/server_dev/settings.py
LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'file': {
            'level': 'ERROR',
            'class': 'logging.FileHandler',
            'filename': os.path.join(BASE_DIR, 'logs') + "/log",
        },
    },
    'loggers': {
        'django': {
            'handlers': ['file'],
            'level': 'ERROR',
            'propagate': True,
        },
    },
}

 

위에 적힌 게 Django 공식 문서에 나온 표준 로그 포맷인데 handlers와 loggers를 보면 됩니다. handlers에는 'file'이라는 선택지가 하나 있고 loggers에는 'django'라는 선택지가 하나 있습니다. loggers 리스트에 여러 가지 logger설정들을 정의해놓고 사용할 수 있습니다. 여기에서는 'django'라는 logger를 만들어놨기 때문에 logging.getLogger('django')를 사용해서 이 logger 설정을 읽어와서 사용할 수 있습니다. 

 

'django' logger를 보면 handlers라는 필드가 있는데, 여기에 'file'이라는 바로 위에서 선언한 handler를 정의해 주었습니다. logger마다 handler를 지정해서 log를 어떻게 처리할지 정할 수 있습니다. 즉 우리가 logger = logging.getLogger('django')를 하게 되면 이 logger는 settings.py에 'django'로 정의된 logger 설정을 사용하며, handler는 'file'로 설정된 handler가 사용됩니다. 여기서 'file'이라는 handler는 파일 형태로 로그를 저장하는 설정값을 가지고 있고, 그 파일 경로는 os.path.join(BASE_DIR, 'logs') + "/log", 에 저장됩니다. 프로젝트 경로에 logs라는 폴더를 생성해 놓으면 그 안에 log라는 파일로 저장됩니다.

 

logs/log

 

이제 다시 test API를 정의했던 곳으로 돌아가서 logger를 사용해 봅시다.

 

# ~/todo/views.py
import logging

logger = logging.getLogger('django')


# Create your views here.
class Test(TodoView):
    def post(self, request):
        print(self.user_id)
        logger.error("log test - user_id = " + self.user_id)

        return CommonResponse(0, "success", dict(some_data="some_value"))

 

logging.getLogger('django')만 바꿔주고, error 메시지를 조금 바꿨습니다. 테스트 툴을 통해 호출을 한번 해봅니다.

 

한번한다고 했는데 5번 했음

아까와 다르게 빨간색으로 남던 로그가 사라졌네요. 대신 logs에 log파일이 생성되었을 겁니다. 파일을 열어봅시다.

 

1882번째 줄부터 보면 됩니다. 우리가 바꾼 로그 메시지가 제대로 찍혔죠?

 

 

Log 형식 정하기

일단 로그가 파일에 찍히는 걸 확인하긴 했는데, 그냥 데이터만 찍으면 심심합니다. 보통 회사에서는 로그 텍스트 앞단에 어떤 파일에서 로그가 찍혔는지, 몇 시에 찍혔는지를 기록하게 됩니다. 그렇게 하려면 어떻게 해야 할까요?

 

Formatters
Ultimately, a log record needs to be rendered as text. Formatters describe the exact format of that text. A formatter usually consists of a Python formatting string containing LogRecord attributes; however, you can also write custom formatters to implement specific formatting behavior.

 

공식 문서를 보면 Formatters라는 걸 사용하라고 나와있습니다. settings.py에서 Loggin 설정값에 아래 formatters를 추가합니다. 

 

# ~/server_dev/settings.py

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'verbose': {
            'format': '{levelname} {asctime} {module} {process:d} {thread:d} {message}',
            'style': '{',
        },
        'simple': {
            'format': '{levelname} {message}',
            'style': '{',
        },
    },
    'handlers': {
        'file': {
            'level': 'ERROR',
            'class': 'logging.FileHandler',
            'filename': os.path.join(BASE_DIR, 'logs') + "/log",
            'formatter': 'verbose',
        },
    },
    'loggers': {
        'django': {
            'handlers': ['file'],
            'level': 'ERROR',
            'propagate': True,
        },
    },
}

 

formatters에 verbose랑 simple 두 가지를 추가했습니다. 그리고 file handler에 formatter설정을 verbose로 설정해줬습니다. 다시 한번 API를 호출해 볼까요?

 

로그에 우리가 출력하고자 하는 데이터 말고도 정보가 추가되었다.

로그 타입이랑 시간, 모듈 정보, 프로세스 번호 등이 추가된 것을 확인할 수 있습니다. settings.py에서 format을 보면  'format': '{levelname} {asctime} {module} {process:d} {thread:d} {message}'라고 설정되어있는데 이 부분이 출력되고 있는 겁니다. 사실  {process:d} {thread:d} 프로세스 id랑 쓰레드 id는 필요 없어서... 지워보도록 하겠습니다.

 

불필요한 숫자 지우기

이제 뭔가 깔끔해 보이기는 하는데, module 정보가 그냥 views로만 나오니까 확실하지가 않네요. 왜냐하면 대부분 django에서 api를 담당하는 게 views인데 ㅋㅋㅋ 어떤 app의 views.py가 에러인지 모르니까 답답.. 

 

format에 어떤 값을 넣을 수 있을지 리스트를 확인하는 방법은 없을까요? 지난 시간에 얘기했던 것처럼 패키지를 타고 타고 그 안까지 가면 확인할 수 있습니다. 맨 처음 우리는 import logging을 했기 때문에 settings.py에 설정하는 값들이 logging이라는 패키지에 정의돼있을 것이라고 예상할 수 있습니다. logging 패키지를 까 봅시다.

 

logging 타고 이동

 

logging을 타고 이동하면 logging이라는 패키지에 __init__. py라는 소스로 이동됩니다. 여기서 우리가 format에 사용했던 필드로 검색을 해봅니다. 

 

asctime 이놈이 제일 특이하니까 이놈으로 검색을 계속해보면 이런 주석을 볼 수 있습니다. 

찾다보면 이런 주석을 찾을 수 있음

 

위에랑 아래랑 생겨먹은 게 뭔가 옵션으로 우리가 넣을 수 있는 값들 목록인 것 같지 않나요? 그럼 이 주석이 어디에 달려있는지 마우스를 조금만 올려봅니다. 

 

Formatter!!

Formatter라는 클래스에 정의되어있는 주석이네요. 처음부터 Formatter로 검색했으면 쉬웠을 텐데 ㅎㅎㅎ 이제 알았으니 나중에는 class이름으로 검색하는 센스를 발휘해봅시다. 

 

다시 아래 주석으로 가서 우리가 format으로 지정할 수 있는 값이 뭐 뭐 있는지 훑어봅니다. 주석을 읽어보고 여러분이 필요한 거를 settings.py에 추가하면 되는데요, 저는 pathname이랑 lineno가 좋을 것 같아서 두 개를 추가하겠습니다.

 

'format': '{levelname} {asctime} {pathname} {lineno} {message}',

경로랑 코드 라인이 찍히네

 

__init__.py를 더 보시면 formatter가 어떻게 동작하는지도 찾을 수 있습니다. 이렇게 코드를 좀 더 깊숙이 보면 이해도가 올라갑니다. 컨트롤 클릭을 생활화합시다 ㅎㅎ

어떻게 값을 세팅하는지 보입니다

 

 

 

 

어떤 값을 남길지 정의

로그 파일 경로도 정했고, 형식도 정했습니다. 이제 어떤 로그를 찍을까? 고민을 해볼 시간인데요, 보통 우리가 logging을 이용해서 찍는 거는 API안입니다. 즉 통신단에서는 어떻게든 test라는 함수로 들어와서 그 안에서 로그를 찍는 거기 때문에 통신에서 데이터가 어떻게 흘러가는지는 찍을 수 없습니다. (그건 또 그거대로 패키지가 있겠지만...)

 

로직단을 보통 AP라고 부르는데, 여기서 로그를 찍는다고 해서 AP 로그라고 많이 부릅니다. AP로그에는 일반적으로 input과 output값을 찍고 중간에 데이터가 어떻게 처리되고 변경되었는지 찍어볼 수 있습니다.

 

 

input과 output을 찍기 위해서 test api에다가 input과 output을 정의해봅시다. input_value1~3까지를 받고 output_value1~3까지는 내보내는 api로 바꿉니다.

 

class Test(TodoView):
    def post(self, request):
        print(self.user_id)
        input_value1 = request.data.get('input_value1', None)
        input_value2 = request.data.get('input_value2', None)
        input_value3 = request.data.get('input_value3', None)
        logger.error("INPUT HEADER " + self.user_id)
        logger.error("INPUT BODY input_value1 " + input_value1)
        logger.error("INPUT BODY input_value2 " + input_value2)
        logger.error("INPUT BODY input_value3 " + input_value3)


        output_value1 = input_value1 + "output"
        output_value2 = input_value2 + "output"
        output_value3 = input_value3 + "output"

        data = dict(output_value1=output_value1,
                    output_value2=output_value2,
                    output_value3=output_value3)
        
        logger.error("OUTPUT BODY output_value1 " + output_value1)
        logger.error("OUTPUT BODY output_value2 " + output_value2)
        logger.error("OUTPUT BODY output_value3 " + output_value3)

        return CommonResponse(0, "success", data)

 

input이랑 output을 한방에 찍을 수도 있고 위에처럼 하나씩 찍을 수도 있습니다. 이건 개발자 마음 ㅎㅎ 테스트 데이터를 아래와 같이 올리면 로그가 제대로 찍히는지 확인할 수 있습니다.

 

요롷게 올려보자

로그가 잘 찍힌다

 

우리가 원한대로 로그가 잘 찍힙니다. 이렇게 input값과 output값을 로그로 찍으면 개발하면서 테스트하다가 특정값이 이상하다? 값이 안 나온다?라는 문의가 오면 로그를 보고 "아 ~ 이게 잘못 올라왔네요~ ^^"라고 해줄 수 있습니다. (클라이언트가 항상 잘못이라는 고정관념 ㅎㅎㅎ)

 

지금은 로직이 매우 간단해서 로그가 간단하지만, 코드가 길어지고 DB에서 조회도 하고 내부적으로 계산도 하고 하면 어디서 잘못되었는지 트래킹 하는데 매우 편합니다. 따로 디버깅을 하지 않아도 되구요. 다만 너무 많은 로그를 남길경우 로그 용량이 커져서 시스템에 부하가 갈 수 있기 때문에 꼭 필요한 로그만 남기도록 합시다.

 

 

 

정리하면서

아마 여러분이 어떤 회사나 특정 프로젝트를 진행할 때 선임 개발자에게 "로그 어떻게 찍어요?"라고 물어보면, "어 그거 공통 함수에 로그함수 쓰면 돼~"라는 답변을 듣게 될 겁니다. Django에서 logging패키지를 이용한 것처럼 어떤 프레임워크든 각자의 로그 패키지가 있고, 회사마다 그 패키지를 커스터마이징 해서 사용하기 때문에 여러분들이 실제로 개발할 때는 그냥 LOG("여기다가 로그 씀") 이런 식으로 만 사용하면 코드가 알아서 적절한 경로에 로그파일을 남겨주게 됩니다. 따라서 로그가 어떻게 저장되는지 잘 모르는 분들이 많은데요. 실제로 로그가 어떻게 남겨지게 되는지 공통부분을 파보거나, 선임한테 물어보거나, 문서를 찾아서 확실히 알고 넘어가는 자세를 가지도록 합시다. :)

 

요번 시간에는 AP로그밖에 건들지 않았는데, 실제로 로그로 할 수 있는 일들이 아주 많습니다. AP별로 로그를 남겨서 각 API 호출 시간을 통계내서 보거나, 실시간으로 문제가 있는 API가 없는지 확인할 수 있습니다. 요즘에는 엘라스틱서치로 로그를 모아서 통계를 내서 문제가 있을법한 부분을 사전에 탐지하는 시스템을 구축하는 곳도 많습니다. AWS에서도 CloudWatch라는 로그분석 서비스를 운영하고 있기 때문에 관심 있으신 분들은 로그에 대해 더 검색해서 보실 수 있습니다. 

 

원래 이번 포스팅에서 같이 하려고 했던 배치 프로세스는 다음 포스팅으로 넘기도록 하겠습니다. 다음 포스팅에서 만나요~~