여느 때처럼 평화롭게 개발을 하던 어느날, 프로덕트의 dev 환경에서 502가 계속해서 발생했습니다. 지표도 정상이고 헬스 체크도 정상이고, 도대체 무슨 문제인지 긴가민가 했습니다. 로그를 확인 해 본 결과 처음보는 낯선 에러가 발생하더군요
요약하자면 Python WSGI 애플리케이션 서버인 uWSGI의 buffer-size 설정 값을 초과했기 때문이었습니다. 찾아보니 이 buffer-size는 요청 헤더의 사이즈의 설정 값이라고 하더군요.
Express를 사용했을 때를 떠올려보면 발생하지 않았던 문제였습니다. 요청 헤더가 커서 요청이 Drop된 적이 없었기 때문입니다.
이에 관련된 CS적인 지식은 기초 수준의 간단한 것입니다만, Django 진영의 웹 서버는 왜 이런 방식을 선택했는지 궁금해서, 기록 겸 포스팅을 남깁니다.
원인
위에서 정리했듯이, 원인은 HTTP 요청 헤더의 사이즈 초과입니다.
uWSGI 관련 공식 문서를 보면, 버퍼 사이즈는 매우 작게 설정되어있으며, 로그에서 이상 현상이 감지된다면 더 큰 사이즈로 변경이 필요할 수도 있다고 언급되어 있습니다. 말은 쉽지만 실제 환경에서는 충분히 문제가 발생할 수 있고 저 또한 겪었습니다. 핫픽스로 배포를 나가도 물려있는 CICD 때문에 10여분 넘게 다운타임이 발생할 수 있는 것이죠 (실제로는 서버 다운은 아니고 UX적인 다운타임이겠습니다.)
정확한 원인을 추적하기 위해 좀 더 깊게 파악해보겠습니다.
일반적인 Python 웹 서비스는 요청이 리버스 프록시(nginx)를 통해 uWSGI를 거쳐 Django로 들어오는 흐름입니다. 리버스 프록시는 클라이언트로부터 요청을 받아 uWSGI로 패킷을 전달 할 때 uwsgi 바이너리 프로토콜로 변환해서 보내게 됩니다.
# nginx 설정
location / {
uwsgi_pass unix:///tmp/uwsgi.sock;
include uwsgi_params;
}
uwsgi_pass를 쓰면 nginx가 HTTP 헤더들을 uwsgi 프로토콜의 key-value 쌍으로 변환하고, 이걸 하나의 uwsgi 패킷으로 직렬화해서 전송합니다. uwsgi 프로토콜 스펙 자체가 하나의 패킷을 전달 받아야만 하는 스펙으로 설계가 되어있기 때문입니다. uwsgi 프로토콜은 패킷 헤더에 datasize라는 변수를 16비트 정수로 담습니다.
패킷 헤더의 datasize가 뒤따르는 전체 데이터 크기를 나타내는 구조라서, 요청 메타데이터를 여러 패킷으로 나눠 보내는 개념이 없습니다. 그래서 수신 측인 uWSGI도 이 패킷을 고정 버퍼에 통째로 받는 구조가 됩니다.
즉, 버퍼 사이즈를 초과하는 요청이 들어오면 uWSGI는 Django에 요청을 넘기지 않고 Drop하게 됩니다. 서버가 죽은 것이 아니라 요청이 앱에 도달하기 전에 버려지게 되어 헬스 체크는 200인데 UX는 다운된 것처럼 보였던 것입니다.
Express
이전에 썻던 Node의 Express는 파싱 방식과 기본값에서 차이가 있었습니다.
Node의 HTTP 파서인 llhttp는 헤더를 고정 버퍼에 담지 않습니다. 들어오는 데이터를 바이트 단위로 스트리밍하면서, 누적 크기만 카운터로 추적합니다.
nodejs의 http parser
고정 버퍼에 통째로 담는 uWSGI와 달리 파싱하면서 카운터만 올리는 방식입니다. 그리고 결정적으로 기본 제한값이 16KB로 크기 때문에 대부분의 상황에서 발견하지 못했습니다. 더불어 uwsgi처럼 바이너리 프로토콜 변환 없이 raw HTTP를 직접 파싱하기 때문에 프로토콜 크기의 제약도 없습니다.
즉, Express를 사용했을 때는 같은 요청이여도 서버가 받아들이는 구조가 다르기 때문에 한 번도 겪어본 적이 없었습니다.
해결
원인을 알았으니 해결책은 명확하겠죠..?
근본 원인인 헤더가 커진 이유를 조사하기 시작했습니다. 짐작하시겠지만, 프로덕트가 커져가면서 구워지는(?) 쿠키도 많아졌습니다. 구체적으로는 A/B 테스트나 지표 추적을 위해 이벤트를 심는 양이 늘어남에 따라 쿠키가 같이 늘어났습니다. 디버깅 결과 전체 쿠키의 70% 이상이 해당 지표 추적을 위한 쿠키였고, 계속해서 늘어나고 있었습니다. 브라우저가 요청마다 이 쿠키를 전부 실어 보내는 구조였기 때문에 점점 헤더 사이즈가 커지면서 결국 터져버렸던 것입니다.
저희는 일단 버퍼 사이즈를 늘리는 것으로 선조치를 했습니다. 하지만 쿠키가 계속 늘어난다면 또 터질테니 근본 해결책은 아니겠죠.
CloudFront Origin Request Policy에서 쿠키를 필터링하거나 로컬 스토리지로 쿠키를 마이그레이션, 쿠키 도메인을 분리하는 등의 방안을 고려중에 있습니다. 각각 하나씩 간단히 살펴보면서 마무리하겠습니다.
CloudFront가 오리진(nginx/uWSGI)에 요청을 전달할 때 필요한 쿠키만 화이트리스트로 전달하도록 설정이 가능합니다.
브라우저는 쿠키를 다 보내지만 CF가 걸러줄 수 있도록 설정이 가능하다고 합니다. 프론트 코드 변경 없이 인프라 설정만으로 적용이 가능하지만, CF를 통하지 않고 직접 접근할 때는 효과가 없습니다.
서버에 보낼 필요가 없는 데이터를 쿠키에서 로컬 스토리지로 마이그레이션하는 방법도 있습니다.
이 방법은 서버가 읽어야 하는 쿠키는 이동이 불가능하고, 프론트 코드 변경이 필요할 수도 있습니다.
마지막으로 쿠키 도메인을 분리하는 방법입니다.
.example.com에 쿠키가 설정되면 모든 서브도메인에 전송됩니다. 이걸 api.example.com으로 분리하고 쿠키 도메인을 서브도메인 별로 격리하면, API 요청에는 해당 서브도메인 쿠키만 실리게 되겠죠. 가장 구조적인 해결이 될 것이라 생각하는데, 서드파티 스크립트인 GA나 이벤트 도구 등이 최상위 도메인에 쿠키를 설정해야한다면, 통제가 어려울 수도 있겠습니다. (아직 확인해보진 않았습니다.)
마무리
오랜만에, 정말 오랜만에 AI에서 벗어나 실제 문제를 좀 깊게 파볼 수 있는 시간이었습니다.
내가 어떤 조직에 속하게 되었을 때, 조직에서 관리하는 애플리케이션을 한 번씩 사용자 관점에서 돌아보고, 개발자 관점에서 돌아보고 문제점을 리스트업하는 습관이 있다. 이를 통해 당장의 애플리케이션에 대한 이해를 넘어서, 어느 정도의 주인의식과 우선적으로 해결해야하는 과제는 무엇인지 선정하는 연습(?)을 같이 하고 있다.
이 포스팅은, 속했던 조직에서 가장 먼저 개선해야한다고 판단했던 실시간 채팅 기능의 개선기이며, 2년차인 현재 시점에서 더 개선할 부분은 없었는지가 첨가된 포스팅이다.
모자란 내용에 혹여 더 좋은 의견 남겨주시면 성장에 큰 도움이 됩니다. 감사합니다!
문제 파악하기
속했던 조직은, 커머스 비스무리한(?) 서비스를 운영하고 있었지만, 도메인 특성상 결제는 곧 예약이었다.
결제 후 오프라인으로 상품을 직접 소비(?)하는 특징과 더불어 상품들이 우리가 자주 소비하는 필수 소비재들의 성격이 아닌, 특정 니즈에 따라 대부분 일회성으로 구매하는 상품들이기 때문에 결제 전/후로 채팅을 통한 상담이 서비스의 코어였다.
이런 핵심 기능인 채팅에서 응답 속도가 평균 3초정도로 매우 느리게 동작했고, 이는 시간을 갈아넣어서라도 반드시 해결해야하는 최우선 과제라고 판단했다.
최초에 파악했던, 채팅 전반의 플로우를 그림으로 나타내보았다. 메시지를 전송하면, 기본적인 메시지 관련 데이터베이스 I/O 작업과 더불어 메시지 전송에 처리되어야 할 모든 기능들이 함께 동기적으로 처리 되고 있었다. 근본적으로 응답 속도가 느릴 수 밖에 없는 구조였다.
더불어 아이러니하게도 이 실시간 채팅을 포함해 애플리케이션 내부에서 MyISAM 엔진을 사용하고 있었다. 동시성 제어를 위해 테이블 락 매커니즘을 사용하는 MyISAM의 특성상 쓰기 작업이 느릴 수 밖에 없었다. 여기저기 쓰기 작업을 하게 되는데, 메시지가 많아지면 많아질 수록 여러 테이블에서 서로 쓰기 작업을 위해 기다리는 현상이 기하급수적으로 늘어날 수 밖에 없다.
효과적인 테스트와 구현을 위해, 당시 최대 TPS를 산정해서 예상 최대 지점까지 고려했다면 어땟을까?
여기까지 생각이 미치지 않았다보니, 워커의 처리량보다 큐에 작업 유입량이 많을 때 어떻게 대처할지 등의 비동기 작업의 안전성을 보장하지 못했다고 생각한다.
비동기 처리를 위해
스토리지 엔진의 한계 외에도 단순 하나의 로직에 이리저리 얽혀있는 여러 비즈니스 로직들을 살펴보고, 메시지 전송 과정에서 반드시 수행되어야 할 로직과 아닌 로직들을 분리 했다. 메시지 전송이 성공했다. 라는 의미는 메시지를 저장하는 chat_message 테이블에만 입력을 보장하면 된다고 판단했고, 나머지 로직들을 전부 분리했다.
이 분리한 로직들을 다시 네 개의 구간들로 나눴고, 원자성을 보장해야하는 구간을 추가 DB 입력 구간인 추가 I/O와 업무 알림으로, 실패해도 괜찮다고 판단되는 부분들을 푸시알림과 SMS전송으로 구분했다.
메시지 전송 로직과 분리하여 비동기 처리를 수행하기 위해 BullMQ라는 메시지 큐를 사용했다. Kafka나 RabbitMQ 등도 Nest의 공식 문서에 UseCase등을 문서화해뒀는데 사용하지 않았다. 이들을 사용하기에는 발톱의 때 만큼의(?) TPS였다. 또 Nest에서 기본적인 Queue 사용문서 에 친절하게 언급되어있는 BullMQ의 실패 시 재시도와 스케줄링과의 연동, 이벤트 기반 처리와 이벤트 리스너를 통한 통합 로깅 등을 구현하기에 용이했기 때문에 BullMQ를 사용했다.
TPS를 산정했을 때, 최대 TPS는 1.55였다. 단일 워커에서 DB I/O와 외부 API의 연동 작업들의 평균 latency가 1초대라고 가정하더라도 큐에는 작업이 계속 쌓이게된다. 위에서 언급한 것 처럼, 이러한 상황들을 먼저 가정하고 접근했더라면 워커의 concurrency를 늘리는 등의 동시 처리 방법까지 자연스레 고려할 수 있었을 것 같다.
원자성 보장을 위해
메시지의 추가 I/O는 단일 테이블의 insert라고 하더라도, 업무 알림은 여러개의 테이블을 insert/update하는 연속적인 과정이다.
MyISAM은 항상 auto-commit한 쓰기 작업을 보장한다. 롤백을 무시하며 트랜잭션을 지원하는 엔진이 아니기 때문에, 이런 연속적인 과정에서 트랜잭션을 보장하기 위해서는 소위 transaction-like한 무언가를 직접 구현해야했다.
type InsertRecord = {
table: string;
id: number;
deleteFn: (id: number) => Promise<void>;
};
class JobTransactionContext {
private inserts: InsertRecord[] = [];
recordInsert(record: InsertRecord) {
this.inserts.push(record);
}
async rollback() {
for (const record of this.inserts.reverse()) {
await record.deleteFn(record.id);
}
}
}
이를 해결하기 위해 위처럼 트랜잭션 컨텍스트 객체를 사용해서, 트랜잭션을 보장해야하는 로직에 활용하게 되었다.
실패 후속 처리
워커에서 작업을 실패할 경우 원자성을 보장해야하는 경우는 실패로 간주되지만, 위에서 말했던 것 처럼 실패했을 경우에도 운영 상에 지장이 없다고 판단했던 SMS 발송과 푸시 알림은 실패로 간주되지 않는다.
위 정책에 따라 분리하여 트랜잭션이 롤백되는 상황에서만 실패로 간주하여 작업을 종료시키고, 실패 시 재시도 전략을 수립했다.
재시도는 BullMQ에서 기본으로 구현되어있는 지수 백오프(Exponential Backoff)를 사용했다.
모든 재시도에 지수 백오프만 사용할 경우 모든 실패한 작업들이 동시에 백오프 될 경우도 고려해야한다. 실패한 작업에 대해 재시도를 분산하기 위해 사용하는 전략임에도 재시도 과정에서 다시 요청이 몰리는 것은 똑같다. 이를 해결하기 위해 AWS에서는 지연 변이(Jitter)라는 개념의 추가 전략을 통해 일정의 랜덤 시간을 추가로 부여하여 재시도의 동시성을 분산했다고 한다. (자세한 내용은 AWS의 공식 포스팅1 / 포스팅2 를 참조)
추가 개선
최근에 이 내용들을 복기하면서 추가로 고려하지 못했던 사항들이 무엇이었는지, 내가 1년 반 전과 비교해서 어디까지 고려하는 개발자가 되어있었는지 확인해보고 싶었다. 위에 잠깐 언급했던 트러블 슈팅을 위한 TPS 산정을 포함해서 정리한 피드백 내용은 다음과 같다.
위에서 언급한 TPS를 조기에 산정했더라면
큐에 메시지가 계속 쌓인다면? (처리량보다 유입량이 많은 경우)
BullMQ의 심장(?)인 Redis에 장애가 발생한다면?
위 세 가지 상황이 모두 연관이 있는 것 같다. 1번을 조기에 고려하지 못해서 자연스레 2번 문제를 캐치하지 못했고, 2번 문제를 계속 방치하다보면 결국 최종에는 Redis에도 문제가 생기지 않을까? 추가 개선을 위해, BullMQ는 어떻게 Redis를 활용해서 Job을 입력하는지 알아보는 게 좋겠다.
여기서 생각해보아야할 부분은, Redis의 SET은 중복된 키값이 있다면 내부 데이터를 덮어 쓰는 방식으로 동작 한다는 점이다. 이해를 돕기 위해, 실제 Job 등록에 사용되는 여러 자료구조 중 Hashes를 직접 CLI를 통해 입력해본 결과를 아래에 서술해두었다. 결과를 보면 중복 방지를 디폴트로 수행하지 않는다는 것을 알 수 있다.
127.0.0.1:6379> HSET user-1 name test
(integer) 0
127.0.0.1:6379> HGETALL user-1
1) "name"
2) "test"
127.0.0.1:6379> HSET user-1 name test2
(integer) 0
127.0.0.1:6379> HGETALL user-1
1) "name"
2) "test2"
그렇다면 BullMQ를 사용하는 우리 개발자들은 중복 처리를 사전에 확인하는 모듈을 따로 구성해야할까? 그렇지 않다. BullMQ에서는 편의를 위해 중복된 Job은 등록이 되지 않도록 처리해두었다. 우선 BullMQ의 소스 코드를 실제로 분석해 본 후 동작 과정에 대한 간략한 플로우를 그려봤다.
Redis에 데이터를 등록하기 위해 실행되는 add....Job-*.lua 스크립트에서 입력 전 중복 확인에 대한 로직이 같이 수행된다.
else
jobId = args[2]
jobIdKey = args[1] .. jobId
if rcall("EXISTS", jobIdKey) == 1 then
return handleDuplicatedJob(jobIdKey, jobId, parentKey, parent,
parentData, parentDependenciesKey, KEYS[5], eventsKey,
maxEvents, timestamp)
end
end
추가적으로 priority나 delayed 작업을 위한 ZSET 활용, 작업 로그를 위한 Streams등에 추가로 입력하지만, 이 부분은 현재 주안점에 벗어나니 생략하겠다. 관심 있으신 분들은 BullMQ 소스코드를 참고하면 될 것 같다.
이제 이러한 이해들을 바탕으로, 추가 개선을 어떻게 해야하는지 한 번 생각해보았다.
처리량 < 유입량
우선 처리량보다 유입량이 많은 경우부터 따져보자.
워커의 처리 속도가 생산 속도를 따라가지 못할 경우 큐에는 자연스레 Job이 쌓이게 된다.
이 상황이 지속되면 메모리 부담은 물론이고(Redis) 뒤에 들어온 Job의 처리 시간은 기하급수적으로 증가하게 된다.
위의 비즈니스 흐름을 예시로 절망적인 상황을 들어보자면 고객님이 어제 채팅을 보냈는데, 담당자는 오늘 업무 알림을 받아볼 수도 있다.
큐에 작업이 원활하게 처리되지 못하는 상황을 해결하기 위해 워커에서 동시 처리량을 제어할 수 있다. TPS가 최대 1.55였기 때문에 645ms당 1개의 요청이 발생한다고 가정하고, 워커의 처리 속도는 외부 API에 의해 최대 2초가 걸린다고 가정한다면 concurrency는 3~4정도가 적당할 것이다. 이처럼 적절한 동시 처리나 워커 자체를 늘리는 방향도 고려해볼 수 있다.
하지만 동시성을 제어할 경우에는 현재 사용중인 리소스, 여기서는 데이터베이스의 총 Connection과 평균 활성 Connection, 현재 서버의 Connection Pool과 할당된 메모리 자원 등을 고려하는 것이 필수이다. 이 모든 리소스간의 밸런스를 고려하는 엔지니어링이 개발자의 필수 덕목인 것 같다.
유입량이 많은 경우 중 또 고려해야할 부분은, 처리해야할 메시지가 중복해서 들어오는 경우이다.
하지만 위의 BullMQ의 기본 Job 적재 방식에 대한 이해를 바탕으로 중복 방지에 선 조회 후 early-return하는 코드는 오히려 추가 I/O가 발생할 것이라는 것을 짐작할 수 있다.
Redis 장애 대응을 위해
근본적으로 Redis 장애 발생 시 당연히 BullMQ는 더이상 메시지를 받을 수 없다. 또한 이미 enqueued된 작업조차 Redis의 휘발성이라는 특성 때문에 손실될 수 있다.
개발자로서 이런 현상을 미리 대응할 수 있도록 설계하여 이미 enqueued된 작업을 복구할 수 있도록 구성할 수 있어야한다.
아직까지 서비스에서 사용중인 Redis에 장애가 발생한 적은 없지만, 혹시 모를 Fail Over에 대비한 전략이 하나도 구성되어있지 않다는 것을 인지했다. 서비스 도메인 특성상 트래픽이 엄청나게 성장할 일은 없다고 판단해서 Sentinel로 FailOver 시 노드 승격 전략과 장애 발생 알림 처리를 구성했다. 서비스 레벨에서 Redis 연결 재시도를 허용하여 마스터 노드 전환 시에도 워커가 자동으로 재연결되도록 처리했다.
이와 더불어 꾸준히 큐들의 작업 개수를 주기적으로 수집하여 모니터링하고 대기열이 일정 수치를 초과하면 알림을 받아볼 수 있도록 구성하여 장애 징후를 빠르게 감지할 수 있도록 했다.
마무리
당시의 개선 방향과 현재 시점에서 생각나는 추가 개선 사항들을 정리하여 쭉 정리해보았다.
점진적으로 이런저런 시도를 해보면서 현재 트래픽을 감당하기 여유로운 상황이다보니 엣지 케이스들을 또 고려하지 못했나 싶기도 하다.
조금씩 알면 알수록 더 어려운 빌어먹을 엔지니어링의 세계 ㅡㅡ.. 외부 레퍼런스들을 많이 찾아보면서 실제 개선 사례들을 대입해보면서 무엇을 놓쳤는지, 지금 방식이 최적이었는지 계속 생각해보고있다. 언젠가 이 글을 다시 꺼내먹는 날 예전의 내가 한심해질지도..?
분명 일정한 기준이 있을 텐데 왜 얘기들이 조금씩 다른 것일까? DB의 버전 때문일까 옵티마이저가 무조건적으로 100% 맞다는 보장이 없어서일까? 잘 모르겠다. 그래서 직접 쿼리 튜닝의 경험들을 복기하며 복합 인덱스를 생성할 때에는 어떤 순서로 인덱스를 구성해야 하는지 알아보았다.
서비스 내부에는 모든 유저의 장바구니(앞으로 견적함이라 부름)를 볼 수 있는 기능이 존재하는데 업종으로 필터링할 경우의 집계를 위한 쿼리의 일부이다. (사진과 드레스를 선택했을 경우를 예시로 platform_A 테이블에 대한 인덱스 생성만 예시로 든다.)
SELECT cart_group_no
FROM platform_A.cart c
INNER JOIN service.product p
ON p.no = c.product_no
WHERE p.category IN ("사진", "드레스")
AND c.cart_group_no != 0
AND c.option != 1;
COUNT(DISTINCT) 쿼리로 간단하게 카디널리티를 확인해 본 결과는 위와 같았고, 당연히 나는 아래와 같이 인덱스를 생성했다.
CREATE INDEX IDX_REALTIME_QUOTATION
ON platform_A (cart_group_no, product_no, option_product);
쿼리 실행 시간이 어느 정도 눈에 보이는 수치로 감소했다. 하지만 여전히 Fetch는 비슷했다.
인덱스 생성 전에는, 해당 테이블에서 풀스캔(ALL)을 했다. 전체 테이블 row를 스캔한 것으로 보인다. 인덱스 생성 후에는 INDEX RANGE SCAN을 통해 조회하였고 테이블 row의 스캔 개수도 20%가량 줄어들었다. 추측건대 fetch time이 개선되지 않은 이유는 스캔하는 row가 여전히 많기 때문이라고 판단했다.
쿼리에서는 조인을 먼저 수행하지만 쿼리 실행 계획을 보면 조인 시 인덱스를 효율적으로, 아니 전혀 사용하지 못하는 것처럼 보였다.
왜 이런 결과가 나올까 생각해 보다가 쿼리 실행 순서를 바탕으로 인덱스 순서를 변경해 보았다.
CREATE INDEX IDX_REALTIME_QUOTATION
ON platform_A (product_no, cart_group_no, option_product);
p의 인덱스 길이는 category가 varchar(150)이기 때문인 것 같다
변경 후에도 결과가 다소 개선되었는데 Duration도 개선되었지만 Fetch Time이 대폭 개선되었음을 볼 수 있다. 실제로 스캔하는 row의 수가 100배 가까이 줄었기 때문이라고 유추해 볼 수 있었다. 추가로 c 테이블의 KEY LENGTH가 1이 줄었는데, 이 쿼리의 결과에서 option_product을 참조하지 않았다고 판단할 수 있다. (option_product는 tinyint이다)
카디널리티는 cart_group_no가 두 배 높았지만, 실제로 product_no를 앞에 사용해 줘야 올바르게 튜닝이 된 것을 확인할 수 있었다.
위 쿼리에 대해 모든 인덱스를 참조하게 되는데, 이런 인덱스를 커버링 인덱스라고 한다.
실제 쿼리를 튜닝하는 과정을 통해 카디널리티가 낮더라도 첫 번째 조건 절에서 사용된 컬럼을 인덱스 컬럼으로 사용하지 않는다면 올바르게 동작하지 않는다는 것을 알 수 있었다.
정리하자면 선행 조건 컬럼은 반드시 인덱스 선행 컬럼이 되어야 하고, 다음과 같은 조건절이 있을 때
WHERE col1 = ?
AND col2 = ?
AND col3 BETWEEN ? AND ?
AND col4 = ?
AND col5 = ?
CREATE INDEX ON IDX ON TB1 (col1, col2, col3, col4, col5);
인덱스를 위와 같이 생성했다면 col4, col5는 인덱스를 타지 않고 조건 필터링만 수행하게 되며 쿼리 실행 순서와 마찬가지로 WHERE 조건 절은 ORDER BY 컬럼보다 우선한다.
모든 인덱스를 참조하게 하고 싶다면 col1, col2, col4, col5, col3 순으로 생성해야 한다.
향로님 포스팅 일부 발췌
이왕이면 카디널리티도 위의 규칙을 지키면서 고려하면 좋다고 생각했지만, 카디널리티는 복합 인덱스에서 고려할 사항이 아니라는 자료도 있고 아예 선행 조건절이 일치한다면 후행 조건절에서는 순서가 유의미하지 않다는 글도 있다.
최근엔 이전과 같이 꼭 인덱스 순서와 조회 순서를 지킬 필요는 없는 것 같다. 인덱스 컬럼들이 조회 조건에 포함되어 있는지가 중요하고, 내가 사용하고 있는 데이터베이스 엔진에 맞게 인덱스를 활용하고 튜닝할 줄 아는 게 중요한 것 같다.
언젠가 NestJS 최신버전에서 무엇이 달라졌나요? 라고 물었던 질문에 쭈뼛거리면서 "아마 Node 12버전 이하는 지원하지 않을걸요?" 라는 대답을 했다.
저런 질문을 받을 당시에는 그냥 넘어갔는데, 이 포스팅을 하는 내내 내가 사용하고 있는 모든 기술들에 지속적인 관심을 가지고 변경된 것이 무엇이 있는지에 대해 무관심했구나 라는 반성을 하게 된다. 가야할 길은 멀지만, 앞만 보고 달리는 것이 아닌 지금 내 주변을 단단하게 다질 필요가 있다. 그래서 더 좋은 경험이었다고 생각한다.
언젠가 다른 이슈로 비용절감 포스팅을 더 할 것 같아 (ex. 람다) 제목에 색인을 남겨둔다.
[NestJS] Failed to catch error thrown by guard in nestjs in interceptor / guard의 uncaughtException
삽질/트러블슈팅2024. 4. 9. 16:36
728x90
728x90
Guard에서의 uncaughtException
새 프로젝트를 진행중인데, 에러를 캐치하지 못해서 서버가 뻗어버렸다.
바로 본론으로 들어가서, 프로젝트의 에러 핸들링 설계는 아래처럼 구성했었다.
에러 발생 > 인터셉터에서 에러 로깅 및 필요에 따라 WebHook 전송 > 필터에서 클라이언트에 보낼 에러 포맷 정의
이러한 방식의 설계는, NestJS의 요청 응답 사이클과 각 구성요소의 역할에 대해 완전히 이해하지 못했기 때문에 만들어졌다.
NestJs req-res lifecycle
Interceptor에서 간과한 부분이 있었다.
클라이언트에서 보낸 API 요청이 프로젝트 전역에 설정한 Global Interceptor에서 가로채기 전에 가드에서 에러가 발생했다.
그렇기에 Exception Interceptor을 거치지 않고 바로 Filter으로 에러가 전달되게 된다.
실제로 로그를 찍어봐도 아래처럼, Filter로 바로 전달되는 것을 볼 수 있다. 마찬가지로 인터셉터가 동작한 후에는 인터셉터를 거쳐 필터로 향하는 모습도 볼 수 있다.
또한, Guards쪽을 자세히 보니 아래와 같이, 예외 필터에 의해 처리된다고 한다...
그럼 어떻게?
커스텀 에러를, 일전의 프로젝트였던 채팅 서비스의 샌드버드 전환기에서, 샌드버드의 커스텀 에러 타입이 마음에 들었고, 비슷한 형태로 구현해두었다. 클라이언트단에서는 HttpStatus + Custom Code형태로 반환되게 구현해두었다.
import { ArgumentsHost, Catch, ExceptionFilter, Logger } from '@nestjs/common';
import { Response } from 'express';
import { CustomHttpException } from '../error/custom.error';
@Catch(CustomHttpException)
export class CustomHttpExceptionFilter implements ExceptionFilter {
catch(exception: CustomHttpException, host: ArgumentsHost) {
console.log('CustomHttpException filter');
const ctx = host.switchToHttp();
const response = ctx.getResponse<Response>();
const request = ctx.getRequest();
const status = exception.statusCode;
const stack = exception.stack;
let json = {
errorCode: (status * 1000) + exception.errorCode,
message: exception.message,
timestamp: new Date().toISOString(),
path: request.url,
}
if (exception.sql) {
json['sql'] = exception.sql;
}
if (process.env.NODE_ENV !== 'production') json['stack'] = stack;
if (process.env.NODE_ENV === 'local') {
new Logger().log(stack);
}
response
.status(status)
.json(json);
}
}
그렇기 때문에, 클라이언트에게 보여질 에러를 포매팅하는 Filter를 설정해두고, 반환시켰는데 계속해서 uncaughtException이 발생했다.
나의 경우, 포스팅의 주 목적인 라이프사이클의 복습이나, 요청의 위치에 따른 에러 핸들링이 아니라 전혀 다른곳에서 확인되었다.
import { ExecutionContext, Injectable } from '@nestjs/common';
import { AuthGuard } from '@nestjs/passport';
import { UnauthorizeAccessToken } from 'src/common/error/user.error';
@Injectable()
export class JwtAuthGuard extends AuthGuard('jwt') {
canActivate(context: ExecutionContext) {
console.log(super.canActivate(context))
return super.canActivate(context);
}
handleRequest(err, user, info) {
if(err || !user) {
throw new UnauthorizeAccessToken();
}
return user;
}
}
기본적인 Access Token Strategy를 처리하는 Guard를 작성하면서 canActivate 함수에 Promise | Observable타입의 로깅을 시도했던 흔적이 있는데, 이 부분에서 NestJS의 실행 사이클이 올바르게 동작하지 않은 것 같다.
간략하게 설명하자면, 위의 코드에서는 canActivate는 인증처리, handleRequest는 인증 후처리를 담당한다고 보면 되는데, 요청이 들어올 때, 내부적으로 'jwt'로 명시된 Strategy를 활성화하여 요청에 포함된 토큰의 유효성 검사를 실시한다. handleRequest에서는, 유효성 검사 후처리를 진행한다고 보면 된다.
다시 돌아와서, 단순 Promise객체의 로깅을 시도할 때, 결과를 기다리지 않고 로그를 찍어도 Promise객체 자체가 로그에 찍히기 때문에 문제가 없다. 지식이 여기까지밖에 없어서, AI의 힘을 빌려봤다.
왜 로그를 찍었을 때 에러가 발생하는지 > 처리가 완료되지 않은 객체여도 객체 자체가 로그에 찍혀 상관없지 않는지? > Observable의 로깅 시 에러가 발생할 수 있는지의 순서로 물어보면서 대답을 다듬었고 다음과 같은 결론을 받을 수 있었다.
RxJS도 한번 훑어보기라도 해야할 것 같다.
마무리
콘솔 한 줄 때문에 실제 프로덕션에서 전사 시스템이 뻗어버리는 사태가 발생하지 않은 것에 다행이지만(그럴 일이 없겠지..?)
뭔가 마무리 멘트를 정리를 못한 찝찝한 트러블슈팅이었다. 시작은 사용하는 프레임워크의 생명주기를 더 잘 이해하고 적절히 핸들링할 수 있기를 바라면서 작성한 글이었고, 덕분에 관련한 문서를 보며 다시 다잡았다는 긍정적인 결론을 낼 수 있었지만 무언가 찝찝하달까..
