MongoDB Primary Stepdown

부하테스트 중에 에러가 갑자기 튀어서 원인을 찾다가, 처음에 확신했던 가설이 로그 앞에서 완전히 무너지는 경험을 했다. 기록해두려고 한다.

상황

부하테스트를 돌리던 중이었다. 트래픽을 계속 올리고 있었는데 어느 순간부터 응답이 느려지고 에러가 확 튀었다. 로그를 보니 stepdown request while waiting for replication 같은 메시지가 반복적으로 찍혀 있었다. MongoDB replica set의 primary가 방금 페일오버됐다는 뜻이다.

여기까지는 다들 동의했다. 문제는 “왜 하필 이 타이밍에 stepdown이 났냐”였다.

유력했던 가설 — 특정 컬렉션의 쓰기 폭주

마침 최근에 크레딧 정산 관련 쓰기를 배치화하는 작업을 하고 있었어서, “정산 관련 컬렉션에 쓰기가 몰려서 primary가 못 버틴 것 아니냐”는 가설이 자연스럽게 나왔다. 부하테스트 중이었으니 쓰기량도 같이 늘었을 거고, 타이밍도 얼추 맞아떨어지는 것처럼 보였다.

근데 이게 은근 그럴듯해서 다들 반쯤 확신하고 넘어가려고 했다. 나도 처음엔 “쓰기 부하 때문이겠지” 하고 생각했다.

로그로 확인해보니

의심되는 컬렉션의 오퍼레이션 수를 그 샤드 로그에서 직접 세봤다. 장애가 난 시간대 전체를 통틀어서 해당 컬렉션 관련 쓰기는 손에 꼽을 정도밖에 안 됐다. 애초에 그 컬렉션은 이 서비스 쪽에서는 읽기만 하고 있었고, 실제 쓰기는 다른 서비스가 맡고 있었다.

즉 부하테스트 트래픽과 이 컬렉션의 쓰기량 사이에는 별 상관이 없었다. 가설이 틀렸다는 걸 확인한 순간이었다.

그럼 진짜 원인은 뭐였을까 싶어서 replica set 로그를 처음부터 끝까지 시간순으로 다시 읽었다.

실제로 로그에 남아있던 것

타임라인을 정리하면 대략 이렇다.

• 특정 멤버가 SECONDARY → PRIMARY → SECONDARY로 몇 초 만에 앞뒤로 뒤집힘 (뭔가 불안정한 징후)
• config version은 그대로인데 term(선거 임기)만 계속 올라감 → 재선거가 반복되고 있었다는 뜻
• 얼마 뒤 config version이 바뀜 — 멤버 하나의 priority가 명시적으로 재설정되어 있었다. 이건 워크로드가 만드는 이벤트가 아니라 누군가(혹은 뭔가) 명령으로 발생시킨 이벤트다
• 그 직후 새 primary가 선출되고, 22초 만에 또 다른 멤버가 새 primary로 다시 선출됨 (연속 재선거)
• 방금까지 primary였던 멤버가 SECONDARY로 내려가면서 ROLLBACK 발생 — 자기가 primary였을 때 받은 쓰기를 되돌리는 것
• 그리고 이 멤버 자체가 "msg":"Shutting down", exitCode: 0으로 완전히 정상적인 순서를 밟으며 종료됨. 크래시가 아니라 정상 종료 요청이었다
• 잠시 후 재기동되어 SECONDARY로 복귀, 다른 멤버가 다시 primary로
• config version이 한 번 더 바뀌면서 다른 멤버의 priority도 조정됨
• 몇 시간 뒤 같은 노드가 또 한 번 같은 패턴(정상 종료 → 재기동)을 반복함

Fatal이나 Error 레벨 로그는 하나도 없었다. OOM killer, SIGKILL, 디스크 부족 같은 흔적도 없었다. 종료되는 동안에도 클러스터 관리용 에이전트 커넥션은 계속 붙어있었다.

이 네 가지를 같이 놓고 보면 결론은 하나였다. 이건 장애가 아니라 관리형 클러스터가 멤버를 하나씩 순차적으로 재시작시키는 계획된 유지보수 작업이었다. 인스턴스 패치나 스케일링 같은 걸로 노드를 하나씩 내렸다 올리는 과정에서, 멤버 하나가 잠깐 빠지니까 남은 멤버끼리 재선거가 반복됐고, 그 와중에 한 번은 실제로 rollback까지 발생한 게 이번 stepdown의 실체였다.

애플리케이션 쪽 피해로 이어진 이유

여기서 끝났으면 그냥 “아 유지보수였구나”로 끝날 일인데, 문제는 이 stepdown이 실사용자 장애로 그대로 직결됐다는 거다. AI 에이전트 백엔드 쪽 체크포인트 저장 코드를 열어보니 MongoDB 클라이언트 연결에 재시도 로직이 전혀 없었다. stepdown 중에 걸린 쓰기는 예외를 그대로 던지고, 그 예외가 그대로 500으로 나가고, 그 순간 처리 중이던 작업은 복구 없이 영구 종료됐다.

반면 다른 쪽 레포는 serverSelectionTimeoutMS, connectTimeoutMS를 명시적으로 설정해서 “정상적인 페일오버(10~12초)는 흡수하고 그 이상만 실패로 처리한다”는 주석까지 달아놓은 상태였다. 같은 클러스터를 쓰는데 한쪽은 stepdown을 감안해서 튜닝돼 있고, 한쪽은 드라이버 기본값 그대로였던 거다.

정리 (라기보다 남는 생각)

replica set의 stepdown은 항상 장애가 아니다. primary가 셧다운되거나, priority 재설정으로 다른 멤버가 우선순위를 갖게 되거나, 네트워크 파티션으로 하트비트가 끊기면 election 프로토콜이 돌면서 term이 올라가고 새 primary가 뽑힌다. 그 사이에 아직 복제 안 된 쓰기가 있었다면 원래 primary가 나중에 secondary로 복귀할 때 그 쓰기는 rollback으로 되돌려진다. 이건 MongoDB replica set의 정상 동작이고, 관리형 클러스터라면 유지보수 때문에 생각보다 자주 일어날 수 있다.

문제는 이걸 애플리케이션이 견디게 짜여있느냐다. stepdown 자체를 막을 수는 없으니, 클라이언트 타임아웃을 stepdown 소요 시간에 맞춰 튜닝하고 짧은 재시도라도 붙여두는 게 맞는 것 같다.

그리고 이번에 제일 크게 배운 건, “쓰기가 몰려서 그런 것 같다”는 감으로 결론 내리기 전에 실제 오퍼레이션 카운트랑 replica set 로그부터 열어봤어야 했다는 거다. 타이밍이 겹친다고 인과관계가 있는 건 아니었다.