[장애 이력 자동 작성 도구10] Redis Sentinel 구조 장애 로그 수집 코드 구현

시간 관계 상 Redis Sentinel 설치 및 구성 부분은 생략(서버 최소 3개 필요, ACL 등록 필요)

redis_의도된_shutdown.log 원본 로그 파일을 파싱하는 형태로 구현

 

복제 구성 환경과 관련된 장애가 발생하면, 원인을 파악하기 위해 조사할 부분

 

싱글 구성에서처럼 마스터의 1. OOM killed(메모리 full), 2. 디스크 full 및 병목, 3. CPU 병목, 4. Too many connections, 5. 내부 로직 segfault 등을 조사

5가지 조사를 동일하게 진행해야 하므로, 5가지 장애 연출 및 스크립트 작성이 모두 완료된 후에 Sentinel 및 복제 구성 장애 상황 대응 진행(실제로는 OOM, Segfault만 진행 완료)

'통신 등 외부 요인 장애'는 이 프로젝트가 커버할 수준이 아니지만, 타임라인을 보고 "네트워크 문제로 추정된다"고 유추하도록 만들기

---

장애 원인 판단 로직

원인	감지 조건
Sentinel Failover	+switch-master 이벤트 존재
Sentinel Failover 실패	+switch-master 없고 -failover-abort-* 존재
Sentinel 장애	위 둘 다 없고 +sdown/+odown 존재

 

태그 설계

태그	감지 키워드
[SDOWN]	+sdown
[SDOWN_RECOVER]	-sdown
[ODOWN]	+odown
[ODOWN_RECOVER]	-odown
[FAILOVER]	+switch-master
[FAILOVER_ABORT]	-failover-abort-*
[REBOOT]	+reboot
[NEW_EPOCH]	+new-epoch
[CONFIG_UPDATE]	+config-update-from

 

failover 시도 후 실패(-failover-abort-*)에 대한 태그 추가

*주어진 로그에는 없지만, 이 경우도 대비함

로그 패턴	의미
-failover-abort-no-good-slave	승격 가능한 슬레이브 없음
-failover-abort-replication-timeout	슬레이브 복제 동기화 타임아웃
-failover-abort-master-is-back	페일오버 중 마스터가 복구됨
-failover-abort-not-elected	리더 선출 실패

 

참고

sdown과 odown에서 각각 s와 o의 의미

• sdown = Subjectively Down. 특정 Sentinel 하나가 마스터에 응답이 없다고 주관적으로 판단한 상태. 한 명의 Sentinel만 이상하다고 느끼는 단계
• odown = Objectively Down. quorum 수 이상의 Sentinel이 동의하여 객관적으로 다운으로 판단한 상태. 이 단계에서 페일오버가 트리거됨

[NEW_EPOCH]: Sentinel 클러스터 내 페일오버 시도가 시작될 때 epoch(판 번호)를 증가시키는 이벤트. 여러 Sentinel이 동시에 페일오버를 시도하는 것을 방지하기 위한 분산 합의 메커니즘으로, epoch가 높은 쪽이 우선권을 가짐

 

[CONFIG_UPDATE]: 다른 Sentinel이 페일오버를 완료하고 새 마스터 정보를 브로드캐스트했을 때, 이를 수신하여 자신의 설정을 업데이트했다는 이벤트. 즉 이 로그의 Sentinel은 페일오버를 직접 수행한 게 아니라 결과를 전달받은 것

---

구현 시 고려한 부분

 

 

장애 묶음에 대한 처리(로그에 2개 이상의 장애 상황이 있을 때, 최근 장애 상황 하나에 대해서만 타임라인 작성)가 잘 이루어지도록 함

 

Sentinel 구조일 때 failover 외 나타날 수 있는 장애 시나리오

1. 일시적인 네트워크 불안정

마스터는 살아있지만 네트워크 단절로 Sentinel이 응답을 못 받아 +sdown을 찍고, 곧 복구되어 -sdown을 찍는 상황이 반복

quorum에 도달하지 못해 +odown으로 넘어가지 않으므로 페일오버가 발생하지 않음

2. quorum 미달

마스터가 실제로 다운됐지만 Sentinel 과반수가 응답하지 않아 quorum에 도달하지 못하는 경우

예를 들어 Sentinel 3대 중 1대만 살아있고 quorum이 2로 설정된 경우, 그 1대만 +sdown을 찍고 +odown으로 진행되지 못함

3. Sentinel 자체가 모니터링하는 슬레이브/다른 Sentinel의 일시적 불안정

마스터가 아닌 슬레이브나 다른 Sentinel 노드가 일시적으로 응답이 없을 때도 +sdown/-sdown이 반복 찍힘

이 경우는 페일오버 트리거 대상 자체가 아님

 

위의 3가지 이벤트가 계속 누적되면, 실제로 failover 이벤트가 발생했을 때 오래된 이벤트까지 모두 포함되는 것이 정리가 안 되고 그대로 반환됨

=> 해결: 가장 최근 +sdown 또는 +odown 기준으로 장애 묶음 구분

 

구체적인 발생 시각 기준: 장애 유형에 따라 다름

• Failover 발생 시: 직전 +new-epoch 또는 +odown 중 이른 시각 (없으면 직전 +sdown fallback)
• Failover 없이 +odown만 있을 시: 가장 최근 +odown 시각
• +sdown만 있을 시: 가장 최근 +sdown 시각

시행착오

모든 상황(failover와 관계없이)에서 가장 최근 +sdown 기준으로 장애 묶음 구분 시 문제 발생

문제: 장애 발생 시각이 01:38:49(+sdown)로 나오는데, 02:58:45(+new-epoch)가 나와야 함

이전: 01:38:49  [SDOWN]   +sdown sentinel .39 @ tfw .38  ← 무관한 이벤트
      02:50:45  [SDOWN_RECOVER] -sdown ...
      02:58:45  [NEW_EPOCH] ...

이후: 02:58:45  [NEW_EPOCH]  +new-epoch 2               ← 실제 페일오버 시작점
      02:58:46  [CONFIG_UPDATE] ...
      02:58:46  [FAILOVER] ...

이유: 01:38:49의 +sdown은 .39 Sentinel 자신이 일시적으로 죽었다가 복구된 사건이고, 실제 페일오버를 유발한 직접 원인은 아님. 진짜 장애 흐름은 +new-epoch(02:58:45)부터 시작된 것으로 봐야 함

=> 구체적인 발생 시각 기준을 위와 같이 설정

 

궁금증

"로그에서 failover보다 +sdown이 먼저 발생해야 하지 않나?"

로그에서 failover가 +sdown(센티널의 마스터 죽음 인지)보다 먼저 발생한 이유

• 이 로그는 이 Sentinel 노드(.39)의 시각으로 기록된 것임
• 페일오버는 다른 Sentinel(.38)이 수행했고, 이 Sentinel은 .38로부터 +config-update-from으로 결과를 전달받아 02:58:46에 마스터 전환을 인지
• 이후 구 마스터(.38)와 Sentinel(.38)이 새 마스터(.37) 기준으로 응답이 없어서 03:01:13과 03:01:35에 +sdown이 찍힘

=> 즉 페일오버 완료 후 구 마스터가 슬레이브로 재편입되는 과정에서 일시적으로 +sdown이 발생한 정상적인 흐름임

 

failover 전 Sentinel 구성 상황 정리

("+switch-master tfw 10.x.x.38 10379 10.x.x.37 10379" 로그 기반 추론)

여기서 .38의 마스터 DB가 다운되자 .38의 Sentinel이 페일오버를 수행해서 .37의 replica를 새 마스터로 승격시킴

페일오버 후에는 구 마스터였던 .38:10379가 새 마스터 .37의 슬레이브로 재편입을 시도하는 과정에서 +sdown/-sdown/+reboot이 찍히게 됨

 

Sentinel 구조의 장점(Replication에 비해)

Replication의 경우, master 장애로 인한 failover 시 replica에서 직접 master 연결 끊기 필요, 애플리케이션 연결 재설정도 필요

Sentinel 구조의 경우, 연결 재설정을 수동으로 할 필요 없음

---

해결 시각(정상화 판단) 기준 설정

 

마지막 fault 이벤트(+sdown, +odown, +switch-master) 시각과 마지막 recover 이벤트(-sdown, -odown) 시각을 비교하여, 마지막 recover가 마지막 fault 이후에 있으면 정상화로 판단

*싱글 구성에서는 재시작 이후 '30초 간' kill이 없어야 정상화를 판단했지만, Sentinel 구성에서는 이런 '30초’를 설정하지 않아도 됨.

Sentinel 구성에서 -sdown은 이미 노드가 응답을 회복했음을 Sentinel이 확인한 결과이므로, -sdown 이후 추가 안정화 대기 없이 정상화로 판단해도 됨

 

deprecated

처음에는 60초 gap을 기준으로 장애 묶음을 구분하려 했으나 실제 output 산출 시 문제가 발생 -> 60초 gap 기준은 Sentinel 구성에선 적합하지 않음

 

처음에 gap을 60초로 설정한 이유

Sentinel의 down-after-milliseconds 기본값이 30초(마스터에 30초간 응답이 없으면 sdown으로 판단)이므로,

두 sdown 이벤트 사이에 정상 운영 구간이 있었는지 판단하려면

직전 -sdown 이후 다음 +sdown까지의 gap이 30초보다 충분히 커야 함

=> 넉넉잡아 60초로 설정

---

최종 Output 설계

싱글 구성과 달리, 장애 타임라인 첫 부분에 '모니터링 마스터 정보’를 추가함. 어떤 마스터에 대한 장애인지 쉽게 파악할 수 있도록 하기 위함

 

실행 방법

센티널 장애 상황에 대한 스크립트 실행 명령은 싱글 구성과 별개의 모드로 동작함

=> --sentinel 옵션으로 구분하고, Sentinel 로그 파일을 직접 파싱

실행 명령어

# conf에 log_path 설정 시 경로 생략 가능
python3 collect_redis_incident.py irteamsu@infa-testsrv-cb801 --sentinel --tunnel 

# 또는 직접 지정
python3 collect_redis_incident.py irteamsu@infa-testsrv-cb801 --sentinel /home1/irteam/redis_의도된_shutdown.log --tunnel

---

궁금증

실제 sentinel 구성에서 장애가 발생했을 땐 어디에서 로그를 수집해야 하나? journalctl? redis 로그 파일?

=> Sentinel 로그 파일에서 Sentinel 프로세스 자체의 장애 감지/페일오버 로그를 수집해야 함

 

Sentinel 로그 파일 확인 방법: sentinel.conf의 logfile 설정 확인

grep "^logfile" /etc/redis/sentinel.conf
# 또는
grep "^logfile" /path/to/sentinel.conf

설치 방식	로그 위치
systemd로 관리 (systemctl start redis-sentinel)	journalctl + Sentinel 로그 파일 둘 다 가능
직접 실행 (현재 cb801 valkey처럼)	Sentinel 로그 파일만 가능

단, journalctl에는 Sentinel 프로세스의 시작/종료만 기록되고 +sdown, +switch-master 같은 Sentinel 내부 이벤트는 기록되지 않음.

즉, 설치 방식과 무관하게 Sentinel 로그 파일이 주된 수집 대상임

---

고도화 아이디어

'어느 Sentinel 노드에서 로그를 수집했는지’

 

지금 코드는 단일 Sentinel 노드의 로그만 수집하는데, 노드마다 보는 관점이 다름

페일오버를 직접 수행한 노드(+new-epoch, +switch-master 기록)와 결과를 전달받은 노드(+config-update-from 기록)의 로그가 서로 다름

실제로 이번 로그에서도 이 Sentinel(.39)은 페일오버를 직접 수행하지 않았고, .38이 수행한 결과를 +config-update-from으로 전달받은 것임

페일오버를 직접 수행한 Sentinel 노드의 로그를 수집하는 것이 가장 좋고, 그러려면 페일오버 수행 노드를 +config-update-from 로그에서 파싱해서 해당 노드 로그도 추가 수집하는 로직이 필요

 

근데 정말로 페일오버를 직접 수행한 Sentinel 노드의 로그를 수집하는 것이 가장 좋을까?

로그를 수집하는 것 자체가 마스터 서버 자체에 부하가 될 수 있으므로, 지금처럼 .39 Sentinel에서 로그를 수집하는 게 낫지 않을까 싶기도 함

---

기타

현재 복제 상태, 기본 정보 등은 DB에서 간단한 명령어로 확인 가능하므로 장애 타임라인에는 따로 추가하지 않았음

 

기본 정보 확인 방법

irteam@infa-testsrv-cb801:~$ rcli10379 ping
PONG

irteam@infa-testsrv-cb801:~$ rcli10379 info server
# Server
redis_version:7.2.4
server_name:valkey
valkey_version:8.1.4
valkey_release_stage:ga
redis_git_sha1:00000000
redis_git_dirty:1
redis_build_id:생략
server_mode:standalone
os:Linux 6.8.0-60-generic x86_64
arch_bits:64
monotonic_clock:POSIX clock_gettime
multiplexing_api:epoll
gcc_version:11.4.0
process_id:2044758
process_supervised:no
run_id:생략
tcp_port:10379
server_time_usec:1772697332341343
uptime_in_seconds:836
uptime_in_days:0
hz:10
configured_hz:10
clients_hz:10
lru_clock:11089652
executable:/home1/irteam/valkey_10379/bin/redis-server
config_file:/home1/irteam/valkey_10379/valkey_10379.conf
io_threads_active:0
availability_zone:
listener0:name=tcp,bind=cb801주소,bind=127.0.0.1,port=10379

irteam@infa-testsrv-cb801:~$ rcli10379 info replication
# Replication
role:master
connected_slaves:0
replicas_waiting_psync:0
master_failover_state:no-failover
master_replid:생략
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:10485760
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0