채널톡 탐정사무소

들어가며

안녕하세요, 백엔드팀 개발자 두기입니다 👋

이번 글은 저희 팀에서 최근 경험했던 여러 버그와 트러블슈팅 과정을 이야기하는 글로, 셀 내에서 CT (Committee) 문화를 통해 주기적으로 공유했던 내용을 스토리로 풀어내 보았습니다.

실제로 발생한 상황과는 디테일에서 차이가 있을 수 있고, 자세히 설명하지 못하고 넘어가는 부분에 대해서는 이해해주시면서 읽어주시면 감사하겠습니다.

Thread-safe하지 않은 redis transaction

두기는 한 여름날 갑자기 간단한 counter를 application에 구현해야 할 일이 생겼습니다. 사용자가 일정 횟수 이상 잘못된 액션을 시도하면, 더 이상의 액션을 막는 메커니즘을 빠르게 적용해야 했기 때문입니다. 간단히 머리를 굴려 보니, 이것을 만들기 위해 RDB나 DynamoDB에 테이블을 만들기에는 너무 손이 많이 갔습니다. 기존의 사용례에서도 간단한 데이터형을 가지고 있고, 데이터 휘발이 치명적이지 않은 경우 Redis를 이용하고 있었기 때문에 두기는 counter의 값을 Redis에 저장하기로 했습니다.

좀 급한 작업이었기 때문에, 정신없이 아래와 같은 코드를 써내려갔습니다.

간단한 테스트 코드도 함께 작성한 두기는 CounterService 가 잘 작동한다고 판단하고 production에 이 코드를 배포했습니다. 동료 개발자의 리뷰와 테스트 코드를 통과했으니 production에서도 잘 작동했습니다. 에러 감지 도구에서 이 로그를 발견하기 전까지는 말이에요.. 🙀

ClassCastException

class java.lang.String cannot be cast to class java.lang.Long (java.lang.String and java.lang.Long are in module java.base of loader 'bootstrap')

이 에러는 CounterService 의 (int) trxResult.get(0) 부분에서 발생한 것이었습니다. 이 에러 문구를 본 두기는 혼란에 빠졌는데요, increment 와 decrement 에는 분기도 없는 간단한 코드였기 때문에 trxResult.get(0) 은 항상 MULTI-EXEC 의 첫 번째 command인 INCR나 DECR의 결과를 가지고 있어야 하기 때문입니다. 만약 커맨드에 문제가 있었다면 이것은 테스트 과정에서 발견되었어야 했습니다. CounterService 는 하루에도 수만 번 호출되기 때문에 에러가 항상 발생했어야 하는데, 이 에러는 이틀에 한 번 정도로 드물게 발생하는 경우였습니다.

일주일 정도 두고 보니, CounterService 에서 위와 다른 여러 종류의 exception 로그가 한 두 건 정도 추가로 발견되었습니다. 이 때까지만 해도 모르는 사이에 lettuce (redis client library) 버전 업데이트가 있었고 그 버전에 버그가 있나 의심하기도 했습니다.

—

사건이 미궁에 빠져들 즈음, 백엔드 개발자로 일하면서 학생이기도 했던 두기는 동시성 프로그래밍에 관한 전공 수업을 듣고 있었습니다. 이 수업에서는 동시성 프로그래밍의 어려움에 대한 만악의 근원으로 “Shared Mutable State” 를 지적합니다. 당연히 그날 강의에서도 이 단어가 여러 번 나왔는데요, 점점 다른 생각에 빠져든 두기는 어느 순간 무릎을 탁 치고 맙니다.

Redis client에서 수행하는 transaction이 바로 shared mutable state였던 것입니다.. CounterService 는 singleton이기 때문에 여러 thread에서 동시에 동일한 RedisCommand 객체에 접근하게 됩니다. RedisCommand 에서 MULTI 커맨드를 통해 transaction을 실행하게 된다면..? 이 객체는 어딘가에는 지금까지 실행한 커맨드를 queueing 해두고 EXEC 커맨드가 호출될 때 flush해주어야 합니다. 이 queue가 바로 여러 thread에서 접근하는 mutable state가 됩니다. 따라서, 여러 thread에서 동일한 queue에 커맨드를 push하거나 flush한다면 단일 thread의 실행에서는 예상할 수 없는 결과를 볼 수 있습니다. 이것의 결과가 바로 앞서 관측할 수 있던 여러 종류의 exception이었습니다.

두기는 바로 lettuce 문서를 찾아봤고 확인사살 당했습니다 💥🔫

다행히 다른 service class에서 사용하고 있던 redis client와는 엮여 커맨드의 interleaving이 일어나지는 않았습니다. (의도인지는 확실하지 않지만) 서비스마다 redis connection을 따로따로 사용하고 있기 때문입니다. 만약 전역적으로 동일한 connection을 공유하거나, connection pooling을 이용하고 있었다면 다른 service와 커맨드 순서가 엮여 예측하기 힘든 결과가 발생했을 것입니다.

—

• Lettuce documentation에서 설명하는 것처럼, redis transaction (MULTI-EXEC) 은 아무 조치도 없이 사용하면 thread-safe하지 않습니다. Thread별로 별도의 connection을 할당하거나, synchronization 메커니즘을 적용해야 합니다.

• CounterService 의 경우 transaction이 꼭 필요한 semantic은 아니었습니다. MULTI-EXEC을 제외하고 INCR 따로, EXPIRE 따로 실행해도 괜찮은 경우였습니다.

• Redis transaction은 일반적인 데이터베이스의 transaction이 가지고 있는 성질인 atomicity를 만족하지 않습니다. 커맨드 중 일부가 실패해도 transaction에서 앞서 실행한 커맨드가 롤백되는 것이 아니기 때문입니다. 또, MULTI-EXEC을 통해 커맨드를 실행하면 EXEC까지 실행해야 앞선 커맨드의 결과를 볼 수 있기 때문에 한 커맨드의 결과에 따라 뒤쪽 커맨드를 다르게 실행하는 분기는 작성할 수 없습니다. 이러한 패턴은 redis scripting을 통해 작성해야 합니다.

두기는 increment 와 decrement 의 로직을 Lua script로 옮기고, 여러 스레드에서 CommandService 에 여러 thread가 동시에 접근하는 테스트 케이스를 추가했습니다. 조치를 취하니 간헐적으로 발생하던 에러 로그가 사라졌습니다. redis.multi() 는 그냥 사용하지 않는 편이 낫겠네요.

Backpressure를 고려하지 않은 internal job queue

저희 팀에서 관리하는 서비스에는 실시간으로 사용자의 api 요청을 처리하는 컴포넌트도 있지만, job queue에 쌓인 작업을 처리하는 컴포넌트도 있습니다. 다른 컴포넌트가 job queue에 비동기적인 작업을 넣으면, queue를 polling해서 작업을 가져오고 처리하는 것을 반복합니다.

이전에는 in-memory 상의 queue를 사용했지만, 예상할 수 있듯 서버 프로세스가 죽으면 작업이 모두 손실되기 때문에 팀에서는 점점 queue를 외부로 분리하도록 방향성을 가지고 있습니다. 대표적으로 이용하고 있는 managed queue service 중 AWS SQS를 도입한 이야기에 대해서는 이전에 작성한 글을 읽어보셔도 좋을 것 같네요.

일부 경우에는 아래 그림과 같이 외부와 내부의 queue를 동시에 이용하기도 합니다. 외부 queue에서 작업을 가져와 internal queue에 쌓는 상하차 업무를 하는 worker thread가 있고, internal queue에서 작업을 가져와 실제로 수행하는 thread pool을 따로 구성하는 구조입니다. (이 구조가 필요해진 이유는 외부 queue에서 제공하는 인터페이스 상 단일 worker가 polling하는 것을 요구하는 경우가 있기 때문입니다.)

대부분의 경우에 잘 동작하는 구조입니다. 하지만 간혹(이라기엔.. 3일에 한 번 정도) consumer 서비스를 굴리고 있는 프로세스가 OOM으로 죽는 경우가 있었고 이러한 케이스가 줄어들 기미를 보이지 않자 두기는 이 원인을 조사해 보기로 했습니다.

두기는 OOM이 일어난 시점과, 그 시점의 여러 metric도 비교해보고, consumer 서비스에서 발생한 에러 로그를 찾아보았습니다. 그 결과 in-memory queue를 이용하는 부분에서 문제가 있음을 발견했는데요, 특히 queue에 쌓인 작업의 개수를 보니 OOM의 직접적인 원인을 알 수 있었습니다. 인스턴스의 메모리 지표가 툭툭 튀는 지점이 queue에 쌓인 작업 개수가 증가하는 지점과 일치했고, queue에 수십만 개 이상 작업이 쌓여버려 OOM 에러가 발생하는 것이었습니다.

—

자연스럽게, 두기가 다음으로 궁금해진 것은 왜 queue에 작업이 수십만 개나 쌓여버리냐는 것이었습니다. 이것에 대한 의문은 문제가 있었던 시간대의 에러 로그를 찾아보니 풀렸습니다. Queue에 쌓인 작업을 처리하는 도중 외부 서비스에 대한 요청을 하는 경우가 있었는데, 해당 서비스에 대해 socket timeout, 즉 일시적인 네트워크 오류로 인한 연결 실패가 발생하고 있었습니다. 일시적인 네트워크 단절은 당연히 있을 수 있는데, 왜 작업이 수십만 개나 쌓여버리는 것일까요? 바로 아래와 같은 retry 코드를 읽어보니 해답이 있었습니다.

callWithRetry 는 외부 서비스에 대한 요청이 실패할 경우를 대비하여 retry 로직을 구현하는데, 요청이 실패하면 backoff() 만큼 Thread.sleep 을 통해 현재 실행중인 thread를 block합니다. 바로 이 block이 문제인데요, queue로부터 작업을 처리하는 worker는 thread pool을 이루고 있기 때문에 pool 내의 thread가 sleep해버리게 되면 그 동안 작업을 전혀 처리할 수 없는 상태가 되는 것입니다. 외부 서비스에 대한 네트워크 단절 상황의 경우, thread pool의 거의 모든 worker가 연결 실패를 경험하고 sleep 상태로 들어가게 됩니다.

외부 queue로부터 작업을 가져오는 worker는 in-memory queue에 작업이 쌓이는 것도 모르고 성실하게 계속 메시지를 가져오고 있기 때문에, 실제로 작업을 처리하는 worker가 전부 낮잠을 자면 메모리에 계속 작업이 쌓이게 됩니다… 🙀

—

• Message queue도 저장소이기 때문에, 무한한 양의 메시지를 저장할 수 없다는 사실을 기억해야 합니다. 특히 이번 조사를 통해 in-memory queue의 경우 수만 개 정도의 작업을 넘어가면 위험하다는 것을 파악할 수 있었습니다.

• 외부 queue로부터 작업을 가져오는 worker는 backpressure를 고려하여 가져와야 합니다. 즉, in-memory queue에 이미 메시지가 많이 쌓여 있다면 polling 속도를 늦추거나 멈추는 메커니즘이 적용되어야 합니다.

• Thread.sleep API를 이용하는 것은 상당히 좋지 않은 패턴입니다. Thread가 자는 동안 (물론 OS에서 스케줄링을 하지는 않아 CPU cycle이 낭비되지는 않더라도) 유용한 일을 할 수 없는 상태가 되고, 특히 이 경우처럼 그 thread가 pool에 속해있다면 pool에서 가용 가능한 자원이 사라지는 것이기 때문입니다.

• Node.js의 async-await, Promise 또는 setTimeout, Kotlin의 koroutine을 사용한다면 sleep과 같은 작업이 실행되는 동안 thread가 자는 것이 아니라 다른 task를 수행할 수 있습니다. 이 경우, task는 멈춰야 할 상황에서 thread를 sleep시키는 것이 아니라 다른 task에게 thread를 양보 (yield) 하는 메커니즘입니다. Java에서 이러한 구조를 만들려면 CompletableFuture와 같은 API를 사용하여 비동기 작업의 continuation을 예약하는 형태로 작성할 수 있습니다.

두기는 backpressure를 만들어 적용하는 것도 좋지만, 일단 일시적인 네트워크 단절이 발생했을 때 worker가 막혀버리는 것을 해결하는 것이 더 직접적인 해결 방법이라고 생각했습니다. 그래서 callWithRetry 의 내부 로직을 CompletableFuture 를 타도록 변경했습니다.

메시지가 유령처럼 사라지는 message queue

릴리즈를 앞둔 어느 날 오후, 두기는 팀원들이 어떤 모니터 앞에서 웅성웅성 하고 있는 것을 보았습니다. 3명 이상 모니터를 보고 있으면 뭔가 심각한 문제가 있는 것이 국룰이기 때문에, 두기는 모여있던 대열에 합류했습니다.

이야기를 들어보니, 작업을 비동기적으로 처리하기 위해 외부 인프라 상에 구성된 메시지 큐에 작업을 퍼블리시하고, consumer에서 작업이 처리하여 DB에 결과가 쌓이기를 기대하고 있었습니다. 그런데 정작 DB에 처리된 결과를 보니 그 중 일부만 처리되었던 것입니다. 작업이 실패했다는 로그도 없고, 실패했다면 dead-letter queue에 들어갔어야 하는데 비어 있고, 퍼블리시하는 쪽에서 queue에 넣는 요청이 실패했다는 로그도 없었습니다. 더 이상하게도 queue의 metric을 살펴보니 트래픽의 예상량 만큼 메시지가 publish되었고, 같은 양만큼 consume 되었다고 나와 있는 것 아니겠습니까 😵‍💫 메시지는 다 consume되었는데, 작업의 결과는 없으니 정말 이상했습니다.

결국 그날 릴리즈하기로 했던 사항은 일단 원인을 알 수 없으니 롤백되고… 두기는 집에 가면서 이 문제에 대해 곰곰이 생각해 보니 원인을 추측할 수 있었습니다.

—

두기는 다음 날 팀 미팅 자리에서 개발 stage의 DB가 아니라 feature stage (특정 기능 작업을 위해 한시적으로 운영하는 stage) 의 DB를 열어보자고 알려주었습니다. 그러자 누락되었던 결과 데이터가 그쪽에 있었습니다.

• 개발 stage와 feature stage에서 consumer application의 환경 설정을 잘못하여 동일한 message queue를 바라보고 있던 문제였습니다.

• 메시지 큐도 저장소이기 때문에, stage별로 환경을 잘 구분하여 각각 생성하고 application의 환경도 잘 연결해주어야 합니다. 잘 구분하지 않으면 한 쪽 stage의 데이터가 다른 쪽으로 넘어가 개발자의 입장에서는 queue에서는 메시지가 잘 빠져나갔는데 데이터만 사라지는 상황을 겪게 됩니다.

• 개발자가 로컬에서 application을 실행할 때 개발 stage의 환경 설정을 이용해 직접 붙어서 테스트하는 경우도 문제가 될 수 있습니다. 큐의 메시지가 그쪽으로 빨려들어가 예상하지 못한 결과가 일어날 수 있기 때문입니다. 특히 개발 stage가 아니라 production stage라면 메시지 손실이 발생할 수 있어 큰 문제겠죠… 🙀 메시지 큐의 ACL을 잘 관리하여 허용된 경우가 아니라면 메시지 퍼블리시 및 가져오기가 불가능하도록 설정해두어야 합니다.

마무리

앞서 살펴본 3가지 사건은 저희 백엔드 팀에서 실제로 경험한 트러블슈팅을 각색한 사례입니다. 일반적으로 마주치게 되는 문제보다는 살짝 더 tricky하고, 풀면서 재미있었던 버그를 중심으로 소개했습니다. 역시 코드가 점점 복잡해지고, 트래픽도 많고, 여러 인스턴스에 분산된 서비스가 늘어나고 다양한 인프라를 사용하는 만큼 까다로운 문제점도 점점 늘어가는 것 같습니다.. 🥲

하지만 서비스의 성장과 함께 꼭 풀어나가야 할 문제가 아닐까 생각합니다. 저는 문제를 다양한 각도로 바라볼 수 있는 관점과 CS 배경 지식, 문제를 해결해본 경험이 중요하다고 보고 있습니다. 만약 문제를 해결하는 과정을 함께 따라오시면서 공감하셨다면, 채널톡과 저희 백엔드 팀에 많은 관심 가져주시면 감사하겠습니다. 탐정사무소의 다음 리포트도 기대해주세요!