FastAPI 스터디 준비 - 5주차 Middleware 구현해보기, Log 찍어보기

kanikim·2022년 3월 1일
1

FastAPI

목록 보기
5/5
post-thumbnail

제가 주로 활동하는 커뮤니티 HOLIX의 개발하는 사람들에서 다양한 개발자분들과 이야기를 나누어 보세요!

이번 내용은 https://github.com/kanikim/fastapi 에 수록되어있습니다!


Middleware란 무엇인가?

미들웨어에 대해 다양한 의견과 정의가 있습니다만, FastAPI에서는 다음과 같이 설명하고 있습니다.

A "middleware" is a function that works with every request before it is processed by any specific path operation. And also with every response before returning it.

미들웨어란 함수로, path operation이 이루어지기 전에 모든 리퀘스트를 처리하고, response를 반환하기 전에 처리하는 것을 말한다.

즉 여기서 FastAPI는 미들웨어를 리퀘스트를 받기 전 무언가 처리하고, 리스폰스를 리턴하기 전에 무언가 처리하는 중간자 역할을 한다고 봐주시면 될 것같습니다. 그렇다면 본격적으로 이러한 Middleware가 쓰이는 곳은 어디일지 생각해 봅시다. 일단 생각나는 것은 Log를 찍는 것이라고 볼 수 있겠네요. 그런의미에서 오늘 글은 FastAPI에서 로그를 찍어보는 것을 해보려고 합니다.


FastAPI Middleware

FastAPI Middleware Flow

FastAPI의 미들웨어는 다음과 같은 플로우를 가집니다.

Request

  • 먼저 어플리케이션으로 들어오는 각각의 리퀘스트를 가져간다.
  • 그 후 이 리퀘스트를 가지고 무언가 작성된 코드를 통해 처리한다.
  • 결과를 나머지 어플리케이션 코드들로 넘겨준다.

Response

  • 어플리케이션에서 생성한 리스폰스를 받는다.
  • 그 후 이 리스폰스를 가지고 처리를 한다.
  • 그다음 리스폰스를 리턴한다

위의 간단한 플로우로 실행되게 됩니다. 그러면 어떻게 FastAPI에서 Middleware를 만들까요? 간단합니다. FastAPI에서 제공하는 decorator를 사용하면 됩니다.


FastAPI Middleware Decorator

import time

from fastapi import FastAPI, Request

app = FastAPI()


@app.middleware("http")
async def add_process_time_header(request: Request, call_next):
    start_time = time.time()
    response = await call_next(request)
    process_time = time.time() - start_time
    response.headers["X-Process-Time"] = str(process_time)
    return response

위의 코드에서 @app.midelware("http")부분이 바로 미들웨어로 지정해준 부분입니다. 위의 코드를 잘 살펴보겠습니다. 그중에서도 제일 중요한 parameter 부분입니다.

async def add_process_time_header(request: Request, call_next):

request는 실제 request로 API로 보내진 정보를 담고있습니다. 그렇다면 옆에 있는 call_next는 무엇일까요? call_next는 함수 파라메터로, API 리퀘스트를 API에 해당되는 path에 보내고, response를 리턴하는 역할을 하는 파라메터입니다. 주의할 점은 커스텀 미들웨어를 만들 때 이 두 파라메터를 사용하는 것이 좋습니다.


FastAPI logging

그럼 본격적으로 간단한 프로그램을 작성하여 로그를 찍어보겠습니다. 전체 코드는 다음과 같습니다.

import random
import uuid
import contextvars
from loguru import logger
from fastapi import FastAPI, Request
from fastapi.responses import JSONResponse

app = FastAPI()

request_id_contextvar = contextvars.ContextVar("request_id", default=None)

def divide(a, b):
    print(f"Dividing {a} / {b} ... ")
    result = a / b
    print(f"Result is {result}")


@app.middleware("http")
async def request_middleware(request: Request, call_next):
    request_id = str(uuid.uuid4())
    request_id_contextvar.set(request_id)
    logger.debug("Request Started")

    try:
        return await call_next(request)

    except Exception as e:
        logger.debug(f"Request failed: {e}")
        return JSONResponse(content={"Success": False}, status_code=500)

    finally:
        assert request_id_contextvar.get() == request_id
        logger.debug("Request ended")


@app.get("/")
def read_root():
    a = 100
    b = random.randint(0, 1)
    return {"success": True, "resut": divide(a, b)}

이번 스터디에서는 다른 패키지도 사용할 것입니다. contextvars, loguru 정도입니다. 그러면 차례차례로 하나씩 살펴보겠습니다.

contextvars

contextvars - 컨텍스트 변수는, 로컬 상태를 관리 및 저장, 그리고 액세스를 위한 API입니다. 코드 내에서는

  • contextvars.ContextVar("request_id", default=None)
  • request_id_contextvar.set(request_id)
  • request_id_contextvar.get()

와 같이 사용되는 부분이 있습니다. 각각을 설명하자면, 먼저 contextvars.ContextVar을 통해 변수를 선언해줍니다. 이때 이름은 "request_id"가 됩니다. 그 후 set을 통해 request_id로 새 값을 설정합니다. 그 다음 get을 통해 현재 컨텍스트 변수 값을 반환해줍니다. 그렇다면 이러한 contextvars는 언제 쓰는 것일까요?

import contextvars

def show():
    print('value is', val.get())

val = contextvars.ContextVar("val", default=0)
contexts = list()

for _ in range(5):
    ctx = contextvars.copy_context()
    ctx.run(val.set, val.get()+1)

    contexts.append(ctx)

for ctx in contexts:
    ctx.run(show)

위의 코드를 보겠습니다. 코드만 보면 ctx의 경우 1, 2, 3, 4, 5가 출력될 것 같지만, 출력 결과는 모두 1이 됩니다. 그 이유는 val을 증가시킨 context와 for loop가 실행되는 context가 서로 다른 context이기 때문에 독립적으로 존재합니다. 즉 다른 context에는 다른 값을 사용할 수 있는 것이지요.

이는 비동기 태스크에서 다른 태스크끼리 다른 값을 유지해야할 경우 사용될 수 있습니다.

loguru

loguru는 파이썬 기반의 로깅오픈소스로, 따로 설정 없이 바로 사용할 수 있고, 비동기 태스크도 지원하는 등 강력한 툴입니다. 다음과 같이 간단하게 사용할 수 있습니다.

from loguru import logger
logger.debug("hello world")

코드 분해하기

그럼 본격적으로 코드를 살펴보겠습니다.

app = FastAPI()

request_id_contextvar = contextvars.ContextVar("request_id", default=None)

def divide(a, b):
    print(f"Dividing {a} / {b} ... ")
    result = a / b
    print(f"Result is {result}")

이번 코드는 바로 나눗셈을 로그에 남기는 것으로 위의 divide(a,b)함수를 통해 값을 받아서 a/b를 수행합니다. 이때 a와 b는 정수만 넘겨줄 것이며 b에는 Exception을 위해 0을 넘겨줄 것입니다. 이 부분은 간단한 Application 실행 코드이며 가장 중요한 부분인 @app.middlware("http") 부분을 보겠습니다.

@app.middleware("http")
async def request_middleware(request: Request, call_next):
    request_id = str(uuid.uuid4())
    request_id_contextvar.set(request_id)
    logger.debug("Request Started")

    try:
        return await call_next(request)

    except Exception as e:
        logger.debug(f"Request failed: {e}")
        return JSONResponse(content={"Success": False}, status_code=500)

    finally:
        assert request_id_contextvar.get() == request_id
        logger.debug("Request ended")

먼저 request_id에 uuid.uuid4()를 설정해줍니다. 로그들을 분리하기위해 고유의 Primary Key를 입력하는 것이라고 생각하시면 됩니다. 그 다음 위에서 설명했다시피 context_var를 세팅해줍니다. 그리고 loguru를 통해 debug를 찍어줍니다. 그러면 다음과 같은 화면이 제일 처음 실행됩니다.

2022-03-01 10:11:33.128 | DEBUG | main:request_middleware:28 - Request Started

가 찍힌 것을 알 수 있습니다.

그리고 try구문을 통해 await call_next(request)를 일단 실행시켜 줍니다. 이때 실행되는 코드는 @app.get("/") 부분입니다. 해당 코드가 위의 플로우에서 설명한 applciation단에 해당합니다. 코드를 보시면 a = 100, b = 0 or 1입니다. 이렇게 하면 자연스럽게 강제로 Exception을 발생시킬 수 있습니다.

그렇게 하여 Exception이 발생되면 다음과 같이 로그가 찍힙니다.

잘 보시면 로그가 잘 찍힌 것을 확인할 수 있습니다.

Summary

이번 글에서는 간단하게 로그를 찍어보는 것을 해봤습니다. Middleware를 통해 리퀘스트를 미리 처리하고, 리스폰스도 미리 처리할 수 있습니다 이렇게.

profile
Backend Developer

0개의 댓글