[Kafka] 카프카 중복 메시지 발생 원인 삽질노트

어떠한 문제가 발생하였고, 그 원인을 찾아 헤맬때는 왜 이런 현상이 발생했는지 이해가 되지 않고 막막할 때가 많다. 하지만 문제가 발생한 원인을 생각하면서 차근차근 하나씩 의심가는 부분들을 확인하다보면 의외로 아주 간단하고, 아주 창피하고, 아주 어이없는 실수인 경우가 대부분이다.

오늘은 내가 겪은 창피하면서도 어이없는 실수를 기록해보려 한다.

상황 설명

상황을 아주 디테일하게 설명하진 못하지만, 아래 같은 기능을 갖는 시스템이 있다.

• A시스템에서 B시스템을 호출하는 API가 있다.
• B시스템에서는 장애가 자주 나기 때문에, 응답값을 받지 못하는 경우 별도의 Front화면에서 사람이 재시도를 할 수 있는 기능이 있다.
• Front에서 실패한 API건을 체크하여 재시도 버튼을 클릭하면 B시스템이 제공하는 API의 Request 파라미터로 생성하여 별도의 TOPIC에 넣는 역할을 수행한다.
• A시스템에서는 Front화면에서 프로듀스한 TOPIC Message를 컨슘하여, B시스템 API를 호출한다.

문제 발생

마침 3건 정도의 API 호출 실패가 발생하였고, 4/1일에 재시도를 하였다고 가정해보자.
4/1일 3건의 실패건들은 TOPIC에 적재가 되었고 컨슘도 잘되어서 API호출이 성공하였다.

그런데, B시스템 담당자에게 4/1일날 보낸 3건이 4/3일에도 요청이와서 중복처리되었다고 연락이 왔다.

• 로그를 살펴보니 Front에서 Topic에서 적재를 한 이력은 없었다. (당연히, API호출이 성공하면 재시도가 불가능하게 되어있다.)
• A시스템을 확인해보니 4/1일 재시도한 데이터를 또다시 consume하여 API를 호출한 이력이 발견되었다. ?잉
• 이 API 호출 시간을 보니, 우연의 일치인가? 서버가 재기동하는 시간과 같았다.

자.. 무엇이 잘못되었고 어떤 것 부터 의심을 해봐야할까?

이 상황을 맞닥들였을 때 엄청난 멘붕에 빠졌었는데, 일단 해당 코드는 이미 배포가 나가있었고 이상없이 동작했던 코드였기 때문이다. 이 코드는 문제가 없어!라는 생각에 빠져있어서 원인을 찾는데 조금 늦게 걸렸던게 아닐까 싶다.

원인 분석하기

왜 중복해서 consume이 됬을까?

이해가 되지 않지만, 어쨋든 중복해서 consume이 됬다. TOPIC 설정값과 Consume 설정값을 확인해보기 시작했다. (일부만 기재한다.)

TOPIC Config

• partition : 1 (실제 produce되는 일이 많지 않았고, 순서가 필요한 message라서 파티션을 1개로 지정했었다.)
• retntion.ms : 432000000(5일)

Consumer Config

• enable.auto.commit : false
• ackMode : MANUAL_IMMEDIATE

설정에는 별다른 이상이 없었다. 설정에 이상이 있었다면 다른 consumer에서도 이와 동일한 현상이 발생해야 했다. 무엇을 확인해볼까 하다 topic의 offset을 확인해보니, lag이 존재하는걸 확인하였다.

왜 Lag이 발생했는가?

• Lag은 consumer가 메시지를 처리할 때, 처리 속도가 메시지 생산 속도보다 느릴 때 발생한다. 실제 commit된 offset과 produce된 offset의 차이이다.

해당 topic의 메세지는 거의 발생하지 않는다. 그리고 우리는 수동으로 3개의 메시지를 발생시켰고 3개의 lag이 생겼다. (그 이후에 메시지가 발행된 이력이 없다.) 이미 consume해서 메시지를 처리했는데 왜 lag이 남아있지?

코드를 확인해 본다. auto_commit이 false, Ack모드가 MANUAL_IMMEIDATE이기 때문에 개발자가 수동으로 메세지 처리가 성공했다고 Consumer에게 알리고 오프셋을 커밋해야 한다.(ack.acknowledge());

일단 Lag이 발생한 원인을 찾았다. 아래는 코드의 일부다.

메시지를 컨슘한 후 API를 호출해라.

if (API 호출이 성공했으면) {
   성공했다고 테이블을 업데이트 해라.
   return;
}

if (재시도가 가능하다면) {
   kafka에 적재(produce)해라.
}

ack.acknowledge(); // offset을 커밋한다.

그렇다.. API 호출이 성공하면 return이 되어 offset commit이 되지 않는다. 그러다보니 kafka는 offset갱신을 시키지 않아 재시도한 3개의 message는 lag으로 남게 된다. 그리고 서버가 재기동되면 다시한번 처리한 메시지를 consume한 후 API를 호출하게 된다. 서버를 재기동한 횟수만큼 API가 중복 호출되었을 것이다.

결론은 코딩을 잘못한 것이다.

if (API 호출이 성공했으면) {
   성공했다고 테이블을 업데이트 해라.
   return;
}

리팩토링하면서 위의 코드가 추가되었고, 의도치 않은 방향으로 동작하고 있었다. 그런데!! 해당 코드는 오래전에 배포가 됬었고, 여태까지 이와 같은 이슈가 발생하지 않았었다. 중복된 API 호출말이다..

그렇다면 왜 이제야 문제가 확인되었는가?

retntion.ms때문이었다. 해당 메시지는 5일간 보관된다. lag이 쌓여도, 5일이 지난 후에 서버를 재기동하면 메시지가 삭제되어 컨슘이 되지 않는다는 말이다. 그런데 메시지가 삭제되어도 lag은 계속 표시가 되어있어야 정상인데 실제 배포환경에서 lag은 없었다.

메시지를 컨슘한 후 API를 호출해라.

if (API 호출이 성공했으면) {
   성공했다고 테이블을 업데이트 해라.
   return;
}

if (재시도가 가능하다면) {
   kafka에 적재(produce)해라.
}

ack.acknowledge(); // offset을 커밋한다.

위의 코드에서 API 호출이 실패하면 offset을 커밋하게 된다. 재시도 성공으로 lag이 쌓였고 && 재시도가 실패했었으면(commit) commit으로 인하여 lag도 0으로 만들어준다. 즉 완벽범죄가 되는 것이다. 운영에서는 서버의 재기동이 빈번하지 않고, API호출 실패가 거의 나지 않았기 때문에 발생하지 않았던 것이다. (물론 재시도를 했었지만, 재기동시 메시지가 생성된지 5일이 지났기 때문에 해당 상황이 오지 않았던 듯 하다. 또한 lag은 평상시에 확인을 안하다보니..^^;)

일단 코드는 황급히 finally를 추가하여 offset을 커밋하게 하였고, 배포 시점에 메시지가 남아있을 수 있으니 retention.ms를 1분으로 줄였다.(메시지가 존재한다면 서버 재기동 수 만큼 consume이 진행되어 중복 메시지를 마구마구 사용하게 된다.) 코드 배포가 나간 후 rention.ms를 조정할 수 있겠다.

원인을 찾느라 고생을 했었는데, 생각치도 못한 곳에서 원인을 찾게 된 케이스다. 코드 부분은 전혀 생각치 못한 부분이라 시간이 더 오래걸린듯 하다. 쓸모없는 경험은 없다고 했다. 이런 경험들이 쌓이다보면 장애 상황에서 더 빠르게 원인을 캐치할 수 있지 않을까? 라는 자기 위로를 하면서 자러 가본다.