Django와 ALB의 502 오류 대모험

Django와 ALB가 만나 502 오류를 내뱉던 장애를 어떻게 극복했는지 정리하였습니다.

Django와 ALB의 502 오류 대모험
502 Bad Gateway 스크린샷

인덴트코퍼레이션에서는 장애를 해결한 후 비슷한 문제를 대물림하지 않고자 포스트모템을 작성하고 있습니다. 그 중 하나를 소개해봅니다.

브이리뷰 서비스의 백엔드는 Django와 gunicorn 웹 서버를 도커 이미지에 넣어 AWS ECS Fargate에서 운영하고 있습니다. 도커 이미지의 표준출력(stdout)은 CloudWatch로 보내고 있고요.

어느날 서버를 새로 배포했는데 API 두 개가 CORS 오류를 일으키며 제대로 작동하지 않았습니다. 잘 작동하는 대다수 API가 GETPOST 메서드를 사용하는 반면, 작동하지 않는 API는 PUTDELETE 메서드를 사용하고 있더군요. 그래서 이 부분을 힌트 삼아 디버깅을 시작했습니다.

1. PUT과 DELETE 메서드만의 문제인가?

저희가 제공하는 API 중 또다른 DELETE, PUT 메서드가 문제를 일으키는지 확인해보기로 했습니다. 공교롭게도 DELETE 메서드는 다른 곳에서 사용하지 않았고, PUT 메서드는 한 군데가 더 있더군요. 그런데 이 API는 잘 작동해서 HTTP 메서드 문제는 아니라고 판단했습니다.

그런데 API 작동 여부를 살피다보니 ECS의 로그가 잘 쌓이지 않는 상황을 발견했습니다. 정확하게는 ECS 외부에서 들어오는 요청의 로그는 보이질 않고, ECS 자체적으로 서비스 활성 여부를 확인하는 ping 요청에 대한 로그만 보이더군요. ECS의 CloudWatch 설정은 문제가 없었고요. 그래서 혹시 ALB가 ECS와 제대로 연결되지 않나? 라는 의문이 생겼습니다.

2. ALB와 ECS 연결 문제인가?

원래 ECS 로그는 바로바로 보이지 않는 이상한 특징(?)이 있습니다.

예를 들어 로그 탭에서 기본으로 선택된 All 상태에서는 로그가 보이지 않지만

All 상태에서는 로그가 보이지 않아요

30초 동안의 로그를 보여주는 30s를 선택하면 로그가 잘 보입니다.

30s를 누르면 그때에야 로그가 보이죠

처음엔 이 문제일까 싶어 확인을 해봤지만 30초 동안의 로그도 제대로 보이지 않더라고요. 그래서 CloudWatch의 Logs Insights에서 API 경로에 대한 쿼리를 작성하여 로그를 찾아봤는데요.

Logs Insights로 CloudWatch를 꼼꼼하게 검색할 수 있습니다

다행히 API 로그가 잘 쌓이고 있었습니다. (ECS 쪽에 로그가 잘 안 보이는 문제에 대해서는 해결책을 얻지 못했지만요.) 아무튼 이렇게  ALB와 ECS는 잘 연결돼있다는 사실을 알게 되어 또 다른 힌트를 찾아 헤메기 시작합니다.

(ALB 설정에 자신이 있었다면 이 시점에 이미 문제가 아님을 확신했겠지만, 그렇지 않아서 이후로도 멀리 돌아갑니다.)

3. 환경변수에 따라 작동 여부가 달라진다?

브이리뷰의 ECS는 실행과 동시에 AWS 파라미터 스토어에서 필요한 환경변수를 가져와서 애플리케이션 설정 값들을 선언하는데요. 문득 이 값들(특히 데이터베이스 주소)을 이리저리 바꾸다보니 API가 제대로 작동하는 경우가 있더라고요.  이걸 보며 Django 문제겠다는 생각이 들었습니다. (아래의 참고자료에 적어 둔 AWS 공식문서에서도 같은 힌트를 얻었습니다.)

4. Django의 어디가 문제일까?

Django 문제라면 로컬에서 문제를 재현하는 게 가장 빠르겠다 싶었습니다. 그래서 bastion 터널링을 사용하여 AWS의 RDS에 접속한 후, 로컬 환경의 데이터베이스 설정을 바꿔주었지요. 그리고 두근거리는 마음으로 API를 호출해보니 TIMEOUT 오류!

마음 철렁한 TIMEOUT 오류지만 문제를 찾았다는 기쁨도

gunicorn이 오류를 한 번 감싸고 있어서 Django의 runserver로 바꿔서 재시도해보았습니다. 그런데도 Django의 디버깅 화면이 보이질 않고 TIMEOUT 오류가 발생하더라고요.

이런 상황이면 API의 처리 속도가 정말로 느리다는 이야기겠고, 해당 API는 내부적으로 데이터베이스에 접근하므로 쿼리가 느릴 것 같더군요.

5. 느린 쿼리를 찾아서

어떤 SQL 쿼리가 느린지 확인하고자 Django runserver 명령에 --print-sql 옵션을 추가했습니다. 그랬더니 데이터를 아주 많이 가져가는 SQL 쿼리가 하나 보이더라고요. 원인을 확인해보니 if문의 평가식 부분에 Django의 쿼리셋을 쓴 탓이었습니다.

queryset = super().get_queryset()
if not queryset:  # 여기가 문제
    return None
return queryset.filter(id=mall_id)

Django는 queryset을 최대한 늦게 평가(lazy evaluation)하지만, if 문에서 True/False를 확인하려다보니 queryset을 바로 실행해버린 것이죠. 그리고 이 queryset에는 데이터가 아주 많이 들어 있어서 API 응답 속도를 느리게 만들었던 겁니다. (이런 경우 Django에서는 queryset.count()를 사용하라고 권고한다는 걸 깜박했죠.)

6. AWS 서포트 경험

디버깅 2번과 3번 사이를 진행하던 중 도무지 원인을 찾기 어려워 AWS 서포트 티켓을 남겨 봤는데요. 신통치 않은 답변일 거라는 기대와는 달리 꽤 상세한 안내문과 보고서를 보내주었습니다. (문제를 해결한 뒤에 답이 와서 조금 아쉬웠네요.)

아래 보고서에는 ALB가 요청을 처리한 속도, ALB가 연결해 준 API가 요청을 처리한 속도, 최종 응답 결과(-1은 응답 없음 혹은 TIMEOUT)가 적혀 있습니다.

request_processing_time | target_processing_time | response_processing_time
                  0.002                    6.428                         -1
                  0.003                    2.652                         -1
                  0.000                    1.512                         -1

결론

해당 코드를 고치고 다시 배포하니 문제는 잘 해결됐답니다.

이렇게 gunicorn부터 ALB까지를 의심했던 저희의 대모험은 코드 오류로 판명됐는데요. (역시나 그들은 잘못하지 않네요. 다 우리 잘못...) 그래도 이 경험을 통해 if 평가식에 queryset을 직접 넣으면 안 된다는 점과 로그를 잘 볼 수 있는 방법이 필요하다는 점, AWS 서포트를 자주 사용해도 되겠다는 교훈을 얻었답니다.

작지만 이런 경험들이 쌓여 더 단단한 팀을 만들어가리라 기대하며, 오늘도 장애 처리로 고생하는 모든 분들께 응원을 보냅니다.

참고자료

- [AWS 공식 문서] Application Load Balancer 문제 해결
- [AWS 공식 문서] Classic Load Balancing을 사용하도록 구성된 EC2 인스턴스에서 실행 중인 웹 서버에 연결할 때 HTTP 5xx 오류가 발생합니다. 이러한 오류를 해결하려면 어떻게 해야 합니까?
- [AWS 공식 문서] Classic Load Balancer를 통해 요청하면 HTTP 502 오류가 발생합니다. 이러한 오류를 해결하려면 어떻게 해야 합니까?