middleware 처리 순서

from fastapi import FastAPI, Request
import time

app = FastAPI()

@app.middleware("http")
async def log_request_time(request: Request, call_next):
    start_time = time.time()
    response = await call_next(request)
    process_time = time.time() - start_time
    print(f"⏰ {request.url.path} 처리 시간: {process_time:.4f} 초")
    return response

@app.get("/")
async def root():
    return {"message": "Hello, World!"}

@app.middleware("http") 
# FastAPI에서 HTTP 요청을 가로채는 미들웨어를 등록하는 데 사용됩니다. 
# "http"는 HTTP 요청에 대해 적용된다는 뜻
async def log_every_request(request: Request, call_next):
# log_request_time이라는 비동기 함수가 미들웨어로 정의
    print(f"📥 요청 URL: {request.url.path}")
    response = await call_next(request)
    # 다음 미들웨어 또는 실제 라우트 핸들러를 호출하는 함수
    print(f"📤 응답 상태 코드: {response.status_code}")
    return response

---

🔁 실행 순서 (요청 URL: /)

FastAPI는 등록된 순서대로 미들웨어를 감쌉니다. 즉:

클라이언트 → log_request_time → log_every_request → 라우트(root) → log_every_request → log_request_time → 클라이언트

⏱️ 시간순 흐름 (시뮬레이션)

1. 클라이언트가 "/"로 요청을 보냄

2. log_request_time 진입
   └ start_time 기록됨

3. log_request_time 안에서 await call_next(request) 호출
   → log_every_request 진입
     └ "📥 요청 URL: /" 출력

4. log_every_request 안에서 await call_next(request) 호출
   → root() 핸들러 진입
     └ {"message": "Hello, World!"} 반환됨

5. root의 결과가 log_every_request로 전달됨
   └ "📤 응답 상태 코드: 200" 출력
   └ response 반환

6. log_every_request의 결과가 log_request_time으로 전달됨
   └ process_time 계산
   └ "⏰ / 처리 시간: 0.000X 초" 출력
   └ response 반환

7. 최종 응답이 클라이언트에게 전송됨

---

근데 왜 출력 순서가 아래와 같이 보일까?

📥 요청 URL: /
⏰ / 처리 시간: 0.0009 초
📤 응답 상태 코드: 200

그런데 우리가 예상했던 순서대로라면:

1. 요청 URL 출력 (log_every_request - 전처리)
2. 응답 상태 코드 출력 (log_every_request - 후처리)
3. 처리 시간 출력 (log_request_time - 후처리)

이 되어야 정상인데, 실제로는 응답 상태 코드보다 처리 시간이 먼저 출력.

---

🔍 왜 이런 일이 발생했을까?

이건 두 미들웨어가 정의된 순서 때문.

코드에서:

@app.middleware("http")
async def log_request_time(request, call_next):  # 이게 먼저 등록됨

@app.middleware("http")
async def log_every_request(request, call_next):  # 이게 나중에 등록됨

FastAPI는 나중에 정의된 미들웨어부터 안쪽으로 감싸는 방식으로 실행.

즉, 등록된 순서 = 감싸는 순서이고
실행 순서 = 거꾸로 해제되는 순서.

✅ 실행 순서 (중첩 구조로 이해하기)

log_request_time(
  log_every_request(
    root()
  )
)

이 구조에서 로그 출력은 다음과 같이 됨:

실행 위치	함수	로그 내용
전처리	log_every_request	📥 요청 URL 출력
전처리	log_request_time	없음 (시간 측정만)
후처리	log_request_time	⏰ 처리 시간 출력
후처리	log_every_request	📤 응답 상태 코드 출력

그래서 처리 시간이 상대적으로 먼저 출력되고, 응답 상태 코드는 나중에 출력되는 것입니다.

---

🧠 비동기(병렬 처리) 관련 설명

• await call_next(request)는 비동기적으로 다음 미들웨어 또는 핸들러의 응답을 기다리는 부분.
• 각 미들웨어는 이전 미들웨어의 작업이 끝나야 다음 작업으로 넘어갈 수 있음.
• 하지만 await 키워드 덕분에, 이벤트 루프는 이 I/O 대기를 기다리는 동안 다른 요청들을 처리할 수 있음.
  즉, 진짜 병렬이 아니라 논블로킹 방식의 동시성 처리

예: 두 요청이 거의 동시에 들어오는 경우

요청1: log_request_time → log_every_request → await root()
                              ⏳ I/O 대기 중
요청2: log_request_time → log_every_request → await root()

두 요청은 루트 함수에서 동시에 대기하고 있을 수 있고, FastAPI는 이를 병렬처럼 처리.

---

---

본 후기는 [한글과컴퓨터x한국생산성본부x스나이퍼팩토리] 한컴 AI 아카데미 (B-log) 리뷰로 작성 되었습니다.

#한컴AI아카데미 #AI개발자 #AI개발자교육 #한글과컴퓨터 #한국생산성본부 #스나이퍼팩토리 #부트캠프 #AI전문가양성 #개발자교육 #개발자취업