KEDA로 SQS 워커 스케일링 했다가 메시지 절반이 사라진 이야기

우리가 깐 구성

지난주 화요일 새벽에 알림이 울렸다. 정확히는 알림이 안 울려서 문제였다. 이미지 변환 워커가 SQS 큐의 메시지를 잘 먹고 있는 줄 알았는데, 다음 날 아침에 보니 "어제 업로드한 썸네일이 안 나와요"라는 CS 티켓이 17건 쌓여 있었다. SQS DLQ에 들어간 것도 아니고 그냥 큐 어디에도 없었다. 처리는 안 됐는데 사라졌다는 게 가장 큰 문제였다.

원인은 KEDA였다. 정확히는 KEDA가 잘못한 건 아닌데, scaleToZero를 너무 공격적으로 설정한 우리 팀이 잘못했다. 이 글은 그 이야기다.

배경부터 정리하면, 우리 팀은 이미지 변환 파이프라인을 KEDA + SQS로 운영하고 있다. 사용자가 이미지를 업로드하면 S3 트리거가 SQS로 메시지를 보내고, 워커 파드가 그걸 받아서 리사이즈/포맷 변환을 한다. 트래픽이 들쭉날쭉이라 평소에는 큐가 비어 있고, 마케팅 캠페인이나 이벤트 때만 폭증한다.

KEDA가 CNCF graduated된 게 2023년 8월이고, 우리 팀은 그 직후부터 써왔으니 한 3년쯤 됐다. 지금까지 큰 문제 없이 잘 돌아갔다. 최근 KubeCon에서도 KEDA가 70개 넘는 scaler를 지원한다는 얘기가 나왔고, 우리도 비슷한 시기에 minReplicaCount를 0으로 바꿔서 비용을 좀 줄여보자는 논의가 있었다. 그게 사고의 시작이었다.

ScaledObject는 대충 이렇게 생겼었다.

apiVersion: keda.sh/v1alpha1
kind: ScaledObject
metadata:
  name: image-worker-scaler
spec:
  scaleTargetRef:
    name: image-worker
  minReplicaCount: 0
  maxReplicaCount: 30
  pollingInterval: 15
  cooldownPeriod: 60
  triggers:
    - type: aws-sqs-queue
      metadata:
        queueURL: https://sqs.ap-northeast-2.amazonaws.com/.../image-jobs
        awsRegion: ap-northeast-2
        queueLength: "5"

cooldownPeriod 60초. 이게 핵심이다.

새벽에 일어난 일

새벽 2시 23분, 캠페인 종료 직후라서 큐에 메시지가 한꺼번에 200개쯤 들어왔다. KEDA가 ScaledObject 메트릭을 보고 워커를 8개로 스케일 업했다. 여기까지는 정상.

새벽 2시 31분, 워커들이 메시지를 빨아들이기 시작했다. 한 메시지당 평균 12초쯤 걸리는 작업이다. 그런데 우리 워커는 SQS 메시지를 받자마자 ack(DeleteMessage)를 하는 게 아니라, 작업이 끝난 뒤에야 DeleteMessage를 보낸다. 그 사이 메시지는 in-flight 상태로 큐에는 보이지 않지만 visibilityTimeout 동안 다른 컨슈머가 못 가져간다. 우리 큐의 visibilityTimeout은 30초였다.

여기서 첫 번째 문제가 생긴다. KEDA의 aws-sqs-queue scaler는 기본적으로 ApproximateNumberOfMessages만 본다. 즉 in-flight 메시지는 카운트에 안 들어간다. 큐에 메시지가 0개로 보이는 순간 KEDA는 "어, 이제 일 없네?"라고 판단한다.

새벽 2시 33분, 워커 8개가 80개쯤 메시지를 in-flight로 잡고 처리 중인 상태에서 큐의 visible 메시지가 0이 됐다. cooldownPeriod 60초가 째깍째깍 흘렀고, 새벽 2시 34분에 KEDA가 워커를 0으로 스케일 다운하기 시작했다.

워커는 SIGTERM을 받았다. 우리 워커의 terminationGracePeriodSeconds는 30초였다. 작업이 평균 12초니까 충분하다고 생각했었다. 문제는 일부 작업이 큰 RAW 이미지였고, ImageMagick 변환이 25초 이상 걸리는 케이스가 있었다는 거다. graceful shutdown 핸들러는 있었지만, SIGKILL이 떨어진 뒤에는 진행 중이던 작업이 그냥 죽었다.

여기서 두 번째 문제. SQS 메시지는 visibilityTimeout이 30초인데, 워커가 죽고 나면 그 메시지는 30초 뒤에 다시 보이게 된다. 정상이라면 다른 워커가 픽업해야 한다. 그런데 워커는 0개로 스케일 다운된 상태였다. 큐에 visible 메시지가 다시 나타나면 KEDA가 또 스케일 업할 텐데, pollingInterval이 15초니까 빨라도 15~30초쯤 걸린다.

그 사이 메시지의 receiveCount가 올라간다. 우리 큐의 maxReceiveCount는 3이었고, DLQ 라우팅이 활성화돼 있었다. 하지만 정작 더 큰 문제는 DLQ도 아니었다.

메시지가 사라진 진짜 이유

DLQ를 까봤더니 텅 비어 있었다. 그게 가장 당혹스러웠다. 메시지가 처리는 안 됐는데 DLQ에도 없으면 어디로 갔단 말인가?

새벽 3시쯤 워커가 다시 0으로 떨어졌다가, 새벽 3시 12분에 메시지가 visible로 돌아오면서 KEDA가 다시 스케일 업했다. 이 사이클이 새벽 동안 4번 정도 반복됐다. 매번 in-flight 메시지가 죽은 워커와 함께 sit-out 됐다가 visible로 돌아오기를 반복했다.

문제는 워커 코드에 있었다. 우리 워커는 메시지를 받자마자 S3에서 원본을 다운로드하는데, 거기서 첫 시도가 실패하면 (보통 IAM credential refresh 타이밍 이슈) 메시지를 그 자리에서 DeleteMessage 호출하고 자체 로직으로 재처리 큐에 넣도록 짜여 있었다. "DLQ보다 우리가 컨트롤하는 재처리 큐가 낫다"는 6개월 전 결정이었다.

근데 SIGTERM 핸들러 안에서 graceful shutdown 도중에 새 메시지를 받지는 않지만, 이미 받아둔 메시지의 처리는 계속 시도한다. S3 다운로드가 SIGKILL 직전에 실패로 떨어지면, 그 catch 블록 안에서 DeleteMessage가 먼저 실행되고 재처리 큐로 보내려는 순간 워커가 죽었다. SQS에서는 이미 메시지가 지워진 뒤다. 재처리 큐로는 안 들어갔다.

이게 17건의 사라진 메시지 정체였다. KEDA의 잘못은 아니다. 워커 코드의 에러 처리 순서가 잘못된 거고, DLQ를 우회한 게 잘못이고, scaleToZero를 도입하면서 in-flight 메시지 시나리오를 다시 검토 안 한 게 잘못이다.

그래서 뭘 고쳤나

당장 한 일은 세 가지다.

첫째, ScaledObject의 scaler 메타데이터에 scaleOnInFlight를 켰다. KEDA 2.10부터 추가된 옵션인데, 이게 켜져 있으면 ApproximateNumberOfMessagesNotVisible까지 합쳐서 카운트한다. 즉 in-flight 메시지가 있으면 스케일 다운을 안 한다.

triggers:
  - type: aws-sqs-queue
    metadata:
      queueURL: https://sqs.ap-northeast-2.amazonaws.com/.../image-jobs
      awsRegion: ap-northeast-2
      queueLength: "5"
      scaleOnInFlight: "true"

이것만 했어도 사고는 안 났을 거다. 솔직히 이 옵션이 디폴트가 아닌 게 좀 야속하긴 한데, KEDA 입장에서는 "큐가 비었으면 0으로 가는 게 맞지 않냐"는 일관성이 있긴 하다.

둘째, terminationGracePeriodSeconds를 90초로 늘렸다. 그리고 워커 코드의 컨텍스트 처리를 다시 짰다. SIGTERM을 받으면 새 SQS poll을 멈추고, 이미 받은 메시지의 visibilityTimeout을 한 번 연장한 뒤(ChangeMessageVisibility), 작업이 끝날 때까지 기다린다. 90초 안에 안 끝나면 ChangeMessageVisibility로 visibilityTimeout을 다시 30초로 줄여서 빠르게 큐로 돌아가게 한다.

셋째, 재처리 큐로 우회하던 로직을 걷어냈다. 그냥 DLQ를 쓰기로 했다. 6개월 전 결정이 만든 함정이었다. DeleteMessage 후 다른 큐로 보내는 패턴은 atomic하지 않다. 죽기 전에 지우면 끝이다. SQS에 transaction이 있는 것도 아닌데 그 사이에 죽으면 끝나는 거다.

미처 못 잡은 것들

cooldownPeriod 60초는 너무 짧았다는 지적이 회고에서 나왔다. 우리 워커의 작업 길이를 생각하면 최소 5분은 줬어야 했다. 하지만 그러면 비용 절감 효과가 떨어진다. 이건 아직 검증 중이고, 일단 180초로 늘려서 보고 있다.

또 하나, KEDA의 idleReplicaCount를 1로 두면 어땠을까. minReplicaCount는 0이지만 메시지가 한 건이라도 있으면 1개는 살려두는 옵션이다. 0과 1의 비용 차이가 우리 케이스에서는 크지 않은데 (워커가 작아서), idleReplicaCount=1을 켰으면 in-flight 시나리오에서도 죽지 않았을 거다. 다음 분기 비용 회고 끝나면 이것도 켜볼 생각이다.

마지막으로, 이런 종류의 사고는 모니터링으로 잡기가 정말 어렵다. SQS의 NumberOfMessagesDeleted와 NumberOfMessagesSent 차이로 메시지 흐름을 보긴 했지만, 우리 워커가 DeleteMessage를 하고 죽는 패턴은 그래프에서 정상으로 보인다. 결국 사용자 CS가 가장 빠른 알림이었다. 부끄러운 일이지만 솔직한 일이다.

정리

KEDA 자체는 잘못이 없다. scaleToZero는 강력한 기능이고, 우리 비용은 실제로 줄었다. 하지만 메시지 큐 기반 워크로드에서 scaleToZero를 켤 때는 in-flight 메시지가 어떻게 다뤄지는지 반드시 확인해야 한다. scaler 메타데이터에 scaleOnInFlight가 있는지, 워커가 SIGTERM에서 in-flight 메시지를 어떻게 처리하는지, 그리고 DeleteMessage의 atomic하지 않은 사용이 어디 숨어 있지는 않은지.

비슷한 구성 쓰시는 분들 한번 ScaledObject 들여다보시면 좋겠다. 우리처럼 새벽에 CS 17건 보고 깨는 일이 없도록.

다음에는 KEDA Operator의 metrics server가 어떻게 HPA와 통신하는지 내부 동작을 한번 정리해볼까 한다. 사실 이번 사고 디버깅하면서 KEDA → HPA 메트릭 파이프라인을 헷갈리는 부분이 좀 있었다.