Kafka 브로커 한 대가 죽으면 쓰기는 몇 초 멈출까?

Q: Kafka 브로커 한 대가 죽으면 쓰기는 몇 초 멈출까?

SIGKILL로 브로커 한 대를 죽이자 리더가 죽은 파티션은 9.40~10.24초, 리더가 살아 있던 파티션도 acks=all 때문에 8.37~8.97초 멈췄다.

이번 시간에는 Kafka 브로커 한 대가 죽는 순간을 Docker로 띄운 브로커 세 대와 컨트롤러 한 대, Python 프로듀서·컨슈머로 재현해 보며 배워가는 시간입니다.

예를 들어서 새벽에 Kafka 브로커 한 대가 내려갔다고 해볼게요. 토픽은 모두 복제본 3개로 만들어 두었으니 괜찮을 거라고 생각했는데, 그 시간 동안 주문 이벤트의 발행 지연이 크게 튀었어요.

죽은 브로커가 리더였던 파티션만 늦어진 것도 아니었어요. 리더가 멀쩡히 살아 있던 파티션도 같은 시간 동안 멈췄습니다.

그래서 여기서는 장애 감지, 리더 재선출, 클라이언트의 메타데이터 갱신이 각각 언제 일어나는지 로그 타임스탬프로 확인하고, 프로듀서와 컨슈머가 멈춘 시간을 실제로 재 볼게요.

브로커를 SIGKILL로 강제 종료할 때와 정상 종료할 때를 비교해 볼게요.

브로커가 죽었다고 판단하는 쪽은 컨트롤러입니다

KRaft 모드(별도 컨트롤러가 클러스터 메타데이터를 관리하는 방식)의 Kafka에서 브로커는 컨트롤러에게 주기적으로 heartbeat를 보내요.

컨트롤러는 정해진 시간 동안 heartbeat가 오지 않으면 그 브로커를 펜싱(fencing)합니다. 펜싱된 브로커는 더 이상 살아 있는 브로커로 치지 않는다고 보시면 됩니다.

컨트롤러는 펜싱과 함께 그 브로커를 모든 파티션의 ISR(in-sync replicas, 리더를 따라잡고 있는 복제본 목록)에서 빼요. 그리고 그 브로커가 리더였던 파티션에는 ISR에 남은 복제본 중에서 새 리더를 정합니다.

이 결정은 메타데이터 로그에 기록되고, 다른 브로커들이 그 기록을 받아 반영해요. 클라이언트는 요청이 실패하면 메타데이터를 다시 받아 새 리더를 찾아갑니다.

펜싱과 리더 이동에 관여하는 브로커 설정의 기본값은 이렇습니다.

broker.heartbeat.interval.ms: 브로커가 컨트롤러에 heartbeat를 보내는 간격이에요. 기본값 2초입니다.
broker.session.timeout.ms: 컨트롤러가 이 시간 동안 heartbeat를 받지 못하면 브로커를 펜싱해요. 기본값 9초입니다.
controlled.shutdown.enable: 정상 종료할 때 리더를 먼저 옮기는 동작이에요. 기본값 true입니다.

실습 준비

이 글의 명령은 모두 실습 코드의 kafka-broker-failure/ 디렉터리에서 실행합니다.

compose.yaml: 브로커 세 대와 컨트롤러 한 대 정의
probe.py: 파티션마다 메시지를 보내고 받으며 시간을 CSV로 남기는 측정 스크립트
gaps.py: CSV에서 파티션별 가장 긴 공백 계산

compose.yaml로 브로커 세 대(k1, k2, k3)와 컨트롤러 한 대(c1)를 띄울게요.

컨트롤러를 따로 둔 건, 브로커만 죽이고 컨트롤러는 장애 내내 살려 두기 위해서예요. 모든 브로커 설정은 기본값 그대로이고, 메모리만 줄였습니다.

이제 컨테이너를 띄우고 셸 함수를 만들어 놓을게요. 함수마다 하는 일은 이렇습니다.

kafka, kafka_at: k2(또는 지정한 노드) 컨테이너 안에서 Kafka 도구를 실행해요. 실습에서 k1을 계속 죽이니까 명령은 k2에서 실행합니다.
desc, wait_for: 토픽의 파티션 상태를 한 줄씩 보여 주고, 원하는 상태가 될 때까지 기다려요.
finished: k1 컨테이너의 프로세스가 끝난 시간을 Docker에서 읽어요. SIGKILL 실습의 장애 시작 시간으로 씁니다.
sigterm_at: k1 로그에서 SIGTERM을 받은 시간을 읽어요. 정상 종료 실습의 장애 시작 시간으로 씁니다.
recover: k1을 다시 켜고 아래에서 만들 orders 토픽의 세 파티션 ISR이 모두 돌아올 때까지 기다려요.
logs_of <노드> <로그 파일> <패턴>: 노드의 로그 파일에서 패턴과 맞는 줄을 "시간 노드 내용"으로 바꿔 보여 줘요.
timeline <probe 출력 이름> <시각>: 컨트롤러 로그, 새 리더의 상태 변경 로그, 클라이언트 디버그 로그에서 장애 전후의 주요 줄을 골라 시간순으로 보여 줘요. 그 시각 이후의 사건만 보여 줍니다.

docker compose -p kbf up -d
export COMPOSE_PROJECT_NAME=kbf PYTHONUNBUFFERED=1

kafka_at() { local n=$1; shift; docker compose exec -T "$n" /opt/kafka/bin/"$@"; }

kafka() { kafka_at k2 "$@"; }

desc() {
  kafka kafka-topics.sh --bootstrap-server localhost:9092 --describe --topic "$1" | tail -n +2 | sed $'s/^\t//'
}

wait_for() {
  until desc "$1" 2> /dev/null | grep -qE "$2"; do sleep 1; done
}

finished() { docker inspect -f '{{.State.FinishedAt}}' kbf-k1-1 | cut -c12-23; }

sigterm_at() {
  docker compose logs --no-log-prefix k1 2> /dev/null | grep "Terminating process due to signal SIGTERM" | tail -1 \
    | sed -E 's/^\[[0-9-]+ ([0-9:]+),([0-9]+)\].*/\1.\2/'
}

recover() {
  docker compose start k1 2> /dev/null
  for p in 0 1 2; do wait_for orders "Partition: $p.*Isr: [0-9],[0-9],[0-9][[:space:]]"; done
}

logs_of() {
  docker compose exec -T "$1" grep -hE "$3" "/opt/kafka/logs/$2" 2> /dev/null \
    | sed -E "s/^\[[0-9-]+ ([0-9:]+),([0-9]+)\] [A-Z]+ /\1.\2 $1 /; s/ \((org|kafka|state)[^)]*\)$//"
}

timeline() {
  {
    docker compose logs --no-log-prefix k1 2> /dev/null | grep -E "Terminating process due to signal" \
      | sed -E 's/^\[[0-9-]+ ([0-9:]+),([0-9]+)\] [A-Z]+ /\1.\2 k1 /; s/ \(org[^)]*\)$//'
    echo "$(docker inspect -f '{{.State.FinishedAt}}' kbf-k1-1 | cut -c12-23) k1 프로세스 종료"
    logs_of c1 controller.log "Fencing broker 1|handleBrokerFenced|controlled shutdown|enterControlledShutdown|to shut down has been granted"
    for b in k2 k3; do logs_of $b state-change.log "Leader orders-0 .* starts at leader epoch"; done
    for c in producer consumer; do
      grep -E "rdkafka#$c.*orders \[0\]: applying leader-id update" "$1-client.log" | awk -v t="$2" '$1 >= t' | head -1 \
        | sed -E 's/ LEADER \[rdkafka#([a-z]+)-[0-9]+\] \[thrd:main\]:/ \1/'
    done
  } | awk -v t="$2" '$1 >= t' | sort \
    | sed -E 's/ with topic id Some\([^)]*\)//; s/ with partition epoch.*//; s/ since the lowest active offset.*//' 
}

python3 -m venv venv && source venv/bin/activate
pip install confluent-kafka

orders 토픽은 파티션 3개, 복제본 3개, min.insync.replicas=2로 만들어요.

--replica-assignment로 파티션마다 리더를 다르게 정해서, k1은 파티션 0의 리더이자 파티션 1, 2의 팔로워가 되게 했어요. single은 k1에만 복제본 하나를 둔 토픽입니다. 이 글의 측정에는 쓰지 않지만, 아래 출력의 파티션 수에 들어가요.

kafka kafka-topics.sh --bootstrap-server k2:9092 --create --topic orders --replica-assignment 1:2:3,2:3:1,3:1:2 --config min.insync.replicas=2
kafka kafka-topics.sh --bootstrap-server k2:9092 --create --topic single --replica-assignment 1
desc orders; desc single

Created topic orders.
Created topic single.
Topic: orders	Partition: 0	Leader: 1	Replicas: 1,2,3	Isr: 1,2,3	Elr: 	LastKnownElr: 
Topic: orders	Partition: 1	Leader: 2	Replicas: 2,3,1	Isr: 2,3,1	Elr: 	LastKnownElr: 
Topic: orders	Partition: 2	Leader: 3	Replicas: 3,1,2	Isr: 3,1,2	Elr: 	LastKnownElr: 
Topic: single	Partition: 0	Leader: 1	Replicas: 1	Isr: 1	Elr: 	LastKnownElr:

멈춘 시간은 probe.py로 잴게요.

이 스크립트는 0.02초마다 파티션마다 메시지를 하나씩 acks=all로 보내고, 같은 프로세스의 컨슈머가 그 파티션들을 읽어요. 메시지마다 보낸 시간, ack를 받은 시간, 컨슈머가 받은 시간을 CSV로 남깁니다.

평소라면 파티션마다 0.02초 간격으로 ack와 수신이 이어져요. 그러니 이 간격이 크게 벌어진 구간이 곧 멈춘 시간이라고 보시면 됩니다.

클라이언트가 새 리더를 언제 알았는지 보려고 librdkafka 디버그 로그(metadata,topic)도 시간과 함께 파일로 남겨요.

gaps.py는 이 CSV에서 파티션마다 장애 시작 무렵에 시작된 가장 긴 공백을 찾아요. 비교를 위해 실행 중 그 밖의 시간에 생긴 가장 긴 공백도 함께 출력합니다.

실습 1: SIGKILL, 컨트롤러가 알아채기까지 8초 넘게 걸렸습니다

probe.py를 30초 동안 돌리고, 8초 뒤 k1을 SIGKILL로 강제 종료해 볼게요.

프로세스가 정리 작업 없이 바로 사라지는 상황이에요. 서버 전원이 나가거나 OOM killer가 프로세스를 죽인 경우와 같습니다.

python probe.py orders 30 probe-kill-1 > probe-kill-1.out &
sleep 8
docker kill -s KILL kbf-k1-1
wait
t0=$(finished)
desc orders

Topic: orders	Partition: 0	Leader: 2	Replicas: 1,2,3	Isr: 2,3	Elr: 	LastKnownElr: 
Topic: orders	Partition: 1	Leader: 2	Replicas: 2,3,1	Isr: 2,3	Elr: 	LastKnownElr: 
Topic: orders	Partition: 2	Leader: 3	Replicas: 3,1,2	Isr: 3,2	Elr: 	LastKnownElr:

파티션 0의 리더가 k2로 바뀌었고, 세 파티션 모두 ISR에서 k1이 빠졌어요.

이제 k1을 다시 켜서 로그를 모은 뒤, 장애 전후의 사건을 시간순으로 볼게요.

recover
timeline probe-kill-1 $t0
python gaps.py probe-kill-1 $t0

03:26:09.115 k1 프로세스 종료
03:26:17.385 c1 [QuorumController id=100] Fencing broker 1 at epoch 14 because its session has timed out.
03:26:17.394 c1 [QuorumController id=100] handleBrokerFenced: changing 54 partition(s)
03:26:17.459 consumer orders [0]: applying leader-id update 1 -> 2 (epoch 1)
03:26:17.460 producer orders [0]: applying leader-id update 1 -> 2 (epoch 1)
03:26:17.476 k2 [Broker id=2] Leader orders-0 starts at leader epoch 1 from offset 445
장애 시작 03:26:09.115, 실패한 전송 0개
p0 ack 공백  9.40초 (03:26:09.100 ~ 03:26:18.497), 그 밖의 가장 긴 공백 0.13초
p1 ack 공백  8.37초 (03:26:09.094 ~ 03:26:17.459), 그 밖의 가장 긴 공백 1.01초
p2 ack 공백  8.37초 (03:26:09.094 ~ 03:26:17.459), 그 밖의 가장 긴 공백 0.10초
p0 수신 공백  9.40초 (03:26:09.094 ~ 03:26:18.497), 그 밖의 가장 긴 공백 0.12초
p1 수신 공백  8.36초 (03:26:09.093 ~ 03:26:17.456), 그 밖의 가장 긴 공백 1.01초
p2 수신 공백  8.37초 (03:26:09.094 ~ 03:26:17.459), 그 밖의 가장 긴 공백 0.10초

출력을 위에서부터 차례로 읽어 보면 이렇습니다.

03:26:09.115에 k1 프로세스가 끝났어요.
8.27초 뒤인 03:26:17.385에 컨트롤러가 k1의 세션이 만료됐다며 펜싱했어요. 이어서 파티션 54개(orders 3개, single 1개, __consumer_offsets 50개)의 리더와 ISR을 한꺼번에 바꿨습니다.
펜싱 0.09초 뒤 k2가 orders-0의 리더가 됐어요. 리더 epoch이 1로 올라갔습니다.
컨슈머와 프로듀서는 펜싱 0.07초 남짓 뒤에 새 리더를 반영했어요. k2의 로그보다 조금 이르죠.

여기서 눈여겨볼 건, 멈춘 시간의 대부분이 2번, 곧 컨트롤러가 장애를 확정하기까지 기다린 시간이라는 점이에요. 리더 선출과 메타데이터 전파는 합쳐서 0.1초 남짓이었습니다.

그런데 이번 실행에서는 9초보다 짧은 8.27초가 나왔어요. 왜 그럴까요?

세션 만료를 프로세스가 끝난 시간이 아니라 마지막 heartbeat를 받은 시간부터 세기 때문이에요. heartbeat는 2초 간격이라서, 마지막 heartbeat는 프로세스가 끝나기 최대 2초 전에 왔을 수 있습니다.

파티션 1과 2도 8.37초 동안 멈췄어요. 두 파티션의 리더 k2와 k3은 살아 있었지만, k1이 팔로워로 ISR에 들어 있었거든요. acks=all은 그 순간의 ISR 전체가 메시지를 받을 때까지 기다리니까, 리더는 오지 않는 k1을 기다린 거죠. 컨트롤러가 펜싱하면서 k1을 ISR에서 빼자 바로 ack가 돌아왔습니다. ack를 받지 못한 메시지는 high watermark(컨슈머가 읽을 수 있는 마지막 위치)도 넘지 못해서 컨슈머 쪽도 같은 시간만큼 멈췄어요.
파티션 0은 9.40초로 1초 남짓 더 멈췄어요. 프로듀서가 새 리더를 반영한 03:26:17.460부터 첫 ack(03:26:18.497)까지 1.04초가 더 걸렸습니다. 브로커 로그와 클라이언트 디버그 로그로는 이 1초의 원인을 가려내지 못했습니다.

실패한 전송은 0개였어요. librdkafka는 메시지를 message.timeout.ms(기본 300초)까지 재시도하기 때문에, 그 사이 쌓인 메시지는 리더가 바뀐 뒤 한꺼번에 전송됐습니다.

같은 순서를 세 번 실행했어요. 회차 사이에는 k1을 다시 켜고 선호 리더 선출(아래에서 보는 리더 되돌리기 명령)로 파티션 0의 리더를 k1에 돌려놓았습니다. 범위로 보면 감지 8.27~8.89초, 선출과 메타데이터 갱신 0.06~0.60초예요. 리더가 죽은 파티션의 공백은 9.40~10.24초, 리더가 살아 있는 파티션의 공백은 8.37~8.97초입니다.

다음 실습 전에 k1을 다시 켜고 ISR이 모두 돌아온 직후의 상태를 보고, 바로 이어서 선호 리더 선출을 실행해 볼게요.

recover
desc orders
kafka kafka-leader-election.sh --bootstrap-server k2:9092 --election-type preferred --topic orders --partition 0
desc orders | head -1

Topic: orders	Partition: 0	Leader: 2	Replicas: 1,2,3	Isr: 1,2,3	Elr: 	LastKnownElr: 
Topic: orders	Partition: 1	Leader: 2	Replicas: 2,3,1	Isr: 1,2,3	Elr: 	LastKnownElr: 
Topic: orders	Partition: 2	Leader: 3	Replicas: 3,1,2	Isr: 1,2,3	Elr: 	LastKnownElr: 
Successfully completed leader election (PREFERRED) for partitions orders-0
Topic: orders	Partition: 0	Leader: 1	Replicas: 1,2,3	Isr: 1,2,3	Elr: 	LastKnownElr:

k1은 ISR에 돌아왔지만 파티션 0의 리더는 여전히 k2예요. 브로커가 돌아와도 리더는 저절로 옮겨 가지 않습니다.

복제본 목록(Replicas)의 첫 번째 브로커를 선호 리더(preferred leader)라고 해요. 파티션 0의 선호 리더는 k1입니다.

kafka-leader-election.sh --election-type preferred는 선호 리더가 ISR에 있으면 리더를 그쪽으로 옮겨요. 실행하자 파티션 0의 리더가 k1로 돌아왔습니다. --all-topic-partitions를 주면 모든 파티션을 한 번에 처리해요.

이 일을 컨트롤러가 알아서 하게 하는 설정이 auto.leader.rebalance.enable이에요. 기본값이 true라서, 컨트롤러는 leader.imbalance.check.interval.seconds(기본 300초)마다 선호 리더가 아닌 파티션을 찾아 되돌립니다.

실습 2: 정상 종료, 리더를 먼저 옮기고 내려갑니다

정상 종료는 순서가 달라요. 브로커가 SIGTERM을 받으면 먼저 컨트롤러에 종료를 요청합니다(controlled shutdown).

컨트롤러는 그 브로커가 맡던 리더를 다른 복제본으로 옮기고 ISR에서도 뺀 뒤에 종료를 허락해요. 프로세스는 그다음에 내려갑니다.

이번에는 같은 상황에서 docker compose stop으로 k1을 내려 볼게요.

Docker는 먼저 SIGTERM을 보내고, 10초 안에 프로세스가 끝나지 않으면 SIGKILL을 보내요.

python probe.py orders 30 probe-stop-1 > probe-stop-1.out &
sleep 8
docker compose stop k1
wait
t0=$(sigterm_at)
desc orders
recover
timeline probe-stop-1 $t0
python gaps.py probe-stop-1 $t0

Topic: orders	Partition: 0	Leader: 2	Replicas: 1,2,3	Isr: 2,3	Elr: 	LastKnownElr: 
Topic: orders	Partition: 1	Leader: 2	Replicas: 2,3,1	Isr: 2,3	Elr: 	LastKnownElr: 
Topic: orders	Partition: 2	Leader: 3	Replicas: 3,1,2	Isr: 2,3	Elr: 	LastKnownElr: 
03:30:58.829 k1 Terminating process due to signal SIGTERM
03:30:58.832 c1 [QuorumController id=100] Unfenced broker 1 has requested and been granted a controlled shutdown.
03:30:58.834 c1 [QuorumController id=100] enterControlledShutdown[1]: changing 54 partition(s)
03:30:58.887 producer orders [0]: applying leader-id update 1 -> 2 (epoch 7)
03:30:58.895 consumer orders [0]: applying leader-id update 1 -> 2 (epoch 7)
03:30:58.902 k2 [Broker id=2] Leader orders-0 starts at leader epoch 7 from offset 5100
03:31:00.920 c1 [QuorumController id=100] The request from broker 1 to shut down has been granted
03:31:01.475 k1 프로세스 종료
03:31:10.532 c1 [QuorumController id=100] Fencing broker 1 at epoch 1009 because its session has timed out.
장애 시작 03:30:58.829, 실패한 전송 0개
p0 ack 공백  1.10초 (03:30:58.868 ~ 03:30:59.969), 그 밖의 가장 긴 공백 0.20초
p1 ack 공백  1.01초 (03:30:58.963 ~ 03:30:59.973), 그 밖의 가장 긴 공백 0.20초
p2 ack 공백  0.03초 (03:30:59.337 ~ 03:30:59.368), 그 밖의 가장 긴 공백 0.20초
p0 수신 공백  1.11초 (03:30:58.861 ~ 03:30:59.969), 그 밖의 가장 긴 공백 0.20초
p1 수신 공백  1.01초 (03:30:58.963 ~ 03:30:59.973), 그 밖의 가장 긴 공백 0.20초
p2 수신 공백  0.03초 (03:30:59.057 ~ 03:30:59.084), 그 밖의 가장 긴 공백 0.20초

이 출력은 SIGKILL을 세 번 실행한 뒤에 잰 회차라서, epoch과 offset 숫자는 이 글 순서대로 따라 하실 때와 다를 수 있어요.

이번에도 출력을 차례로 읽어 볼게요.

03:30:58.829에 k1이 SIGTERM을 받았어요.
0.003초 뒤 컨트롤러가 k1의 종료 요청을 받아들였고, 0.005초 뒤 파티션 54개의 리더와 ISR을 바꿨어요(enterControlledShutdown).
SIGTERM 0.06초 뒤 프로듀서가, 0.07초 뒤 k2가 새 리더를 반영했어요.
리더를 다 옮긴 뒤인 2.09초 뒤에 컨트롤러가 종료를 허락했고, k1 프로세스는 2.65초 뒤에 끝났어요.
마지막 줄의 펜싱은 프로세스가 끝나고 heartbeat가 끊긴 뒤 세션이 만료된 기록이에요. 이때는 옮길 리더가 남아 있지 않아서 파티션은 바뀌지 않았습니다.

리더를 옮기는 일이 프로세스가 내려가기 전에 끝나니까, 멈춘 시간에 감지를 기다리는 9초가 들어가지 않아요.

이번 회차에서 파티션 0과 1은 1.01~1.11초 멈췄고, 파티션 2는 평소와 같은 0.03초였어요. 나머지 두 회차에서는 파티션 0도 0.13초만 멈췄습니다.

정상 종료에서도 이런 1초가 생길 수는 있지만, 감지를 기다리는 8~9초는 세 번 모두 없었습니다.

정리

범위: Kafka 4.3.1(apache/kafka:4.3.1) 브로커 3대와 컨트롤러 1대, 브로커 설정 기본값, confluent-kafka 2.15.1, orders(복제본 3, min.insync.replicas=2)와 single(복제본 1), SIGKILL과 정상 종료 각 3번.

SIGKILL 세 번에서 컨트롤러가 k1을 펜싱하기까지 8.27~8.89초, 그 뒤 선출과 클라이언트 메타데이터 갱신은 0.06~0.60초였습니다. 감지 시간을 줄이려고 broker.session.timeout.ms(기본 9초)를 낮추기 전에, GC 멈춤이나 짧은 네트워크 지연에도 멀쩡한 브로커가 펜싱될 수 있다는 점을 따져 보세요.
리더가 죽은 파티션은 9.40~10.24초, 리더가 살아 있던 파티션도 죽은 k1이 ISR에 남아 있는 동안 acks=all이 기다려 8.37~8.97초 멈췄습니다. 브로커 한 대의 장애가 그 브로커가 리더인 파티션만 멈춘다고 보지 마세요.
정상 종료에서는 SIGTERM 0.07초 뒤 k2가 새 리더가 됐고, 세 번의 파티션 0 공백은 0.13~1.10초였습니다. 롤링 재시작은 브로커를 한 대씩 정상 종료하고, 종료 유예 시간을 controlled shutdown보다 길게 둬서 SIGKILL로 넘어가지 않게 해 주세요.
이 글에 싣지 않은 추가 측정에서는 복제본이 하나인 single이 정상 종료로도 Leader: none이 되어 33.26초 동안 쓰기와 읽기가 모두 멈췄습니다. 복제 계수를 주지 않으면 default.replication.factor(기본 1)를 따르니까, 자동 생성되거나 급하게 만든 토픽의 복제 계수를 확인해 주세요.
브로커가 돌아와 ISR에 들어온 직후에도 리더는 저절로 선호 리더로 옮겨 가지 않았습니다. 바로 고르게 하려면 kafka-leader-election.sh --election-type preferred를 실행하고, 자동 선출을 껐다면 이 명령을 복구 절차에 넣어 두세요.