본문으로 건너뛰기

7.1 primary 장애

가장 기본적인 시나리오입니다. writer.sh로 쓰기를 계속하는 동안 primary 컨테이너를 docker kill로 멈춥니다. 2노드에서 두 번(run1, run2), 3노드에서 한 번 측정했습니다. 결과는 2노드 51초, 3노드 54초였습니다. 이 중 대부분은 장애 감지에 걸린 시간이 아닙니다. monitor가 옛 primary에 스스로 멈출 기회를 주기 위해 기다리는 시간입니다.

2노드: 타임라인​

run2에서는 node2가 primary이고 node1이 secondary인 상태에서 node2를 kill했습니다. 시각은 monitor의 pgautofailover.event 기록입니다.

구간시각 차측정값
kill → unhealthy 표시05:27:40.263 → 05:27:48.5288.3초
kill → draining / prepare_promotion 지정05:27:40.263 → 05:28:00.46220.2초
kill → stop_replication 도달05:27:40.263 → 05:28:01.75721.5초
stop_replication 지정 → wait_primary 지정05:28:00.586 → 05:28:31.52930.9초
kill → wait_primary 지정05:27:40.263 → 05:28:31.52951.3초
쓰기 공백05:27:40.424 → 05:28:31.59051.2초

run1도 같은 양상이었습니다. kill은 05:09:11.012, unhealthy 표시는 05:09:18.382였습니다. prepare_promotion은 05:09:31.103, wait_primary는 05:10:01.429였습니다. 쓰기 공백은 50.3초(05:09:11.214 → 05:10:01.514)였습니다.

51초는 어떻게 구성되는가​

첫 20초는 pgautofailover.node_considered_unhealthy_timeout(기본 20000ms)입니다. 8.3초에 기록된 "marked as unhealthy"는 health check가 실패했다는 표시일 뿐입니다. 이 시점에는 failover를 시작하지 않습니다. v2.2 소스의 IsUnhealthy()는 두 조건을 모두 확인합니다. health check 결과가 BAD여야 합니다. 또한 keeper의 마지막 node_active() 보고가 node_considered_unhealthy_timeout보다 오래되어야 합니다. kill 직전 마지막 보고로부터 20초가 지난 05:28:00에야 draining이 지정되었습니다. 이 두 조건은 이번처럼 컨테이너 전체가 멈춰 keeper 보고도 끊긴 경우에 적용됩니다. keeper가 살아 있고 PostgreSQL이 멈췄다고(pgIsRunning=false) 보고하면 상황이 다릅니다. IsUnhealthy()는 20초나 health check를 기다리지 않고 곧바로 참을 반환합니다.

/* src/monitor/node_metadata.c, v2.2 */
/* if the keeper isn't reporting, trust our Health Checks */
if (TimestampDifferenceExceeds(pgAutoFailoverNode->reportTime, now, UnhealthyTimeoutMs))
{
    if (pgAutoFailoverNode->health == NODE_HEALTH_BAD && ...)

나머지 30초는 pgautofailover.primary_demote_timeout(기본 30000ms)입니다. monitor는 옛 primary의 목표 상태를 demote_timeout으로 지정합니다. 이후 옛 primary가 demote_timeout 도달을 보고할 때까지 기다립니다. 또는 이 시간이 지나야 새 primary의 쓰기를 허용합니다. 둘 중 하나가 충족되면 monitor는 옛 primary에 demoted를 지정합니다. 새 primary에는 wait_primary를 지정합니다. 죽은 node2는 보고할 수 없으므로 30초를 그대로 기다렸습니다. 두 이름은 비슷하지만 demote_timeout은 FSM 상태입니다. primary_demote_timeout은 monitor GUC입니다.

stop_replication 동안 새 primary는 왜 쓰기를 거부하는가​

node1은 05:28:00에 이미 promote되었습니다. 하지만 writer.sh는 30초 동안 계속 실패했습니다. node1 keeper 로그에서 이유를 확인할 수 있습니다.

05:28:00 10 INFO  FSM transition from "prepare_promotion" to "stop_replication": Prevent against split-brain situations.
05:28:00 10 INFO  Prevent writes to the promoted standby while the primary is not demoted yet, by making the service incompatible with target_session_attrs = read-write
05:28:00 10 INFO  Promoting postgres
05:28:00 10 INFO  Setting default_transaction_read_only to on
05:28:31 10 INFO  FSM transition from "stop_replication" to "wait_primary": Confirmed promotion with the monitor
05:28:31 10 INFO  Setting default_transaction_read_only to off

keeper는 promote 직후 default_transaction_read_only = on을 설정합니다. target_session_attrs=read-write로 접속하는 클라이언트는 이 노드를 쓰기 가능한 서버로 인식하지 않고 다음 후보로 넘어갑니다. 옛 primary가 아직 살아서 쓰기를 받고 있을 수 있습니다. 이때 새 primary까지 동시에 쓰기를 받는 상황을 막는 장치입니다. wait_primary가 지정되는 순간 설정을 되돌립니다. 그 직후 첫 INSERT가 성공했습니다.

경고

keeper는 이 값을 ALTER SYSTEM으로 설정하고 reload합니다. 따라서 직접 접속한 세션을 포함한 모든 세션에서 기본 트랜잭션이 읽기 전용으로 바뀝니다. target_session_attrs=read-write는 이 서버를 연결 후보에서 제외하는 효과도 있습니다. 다만 이는 세션 기본값입니다. 애플리케이션이 SET default_transaction_read_only = off를 명시적으로 실행하면 이 구간에도 쓰기가 가능합니다.

3노드: report_lsn 단계가 추가된다​

node3을 추가해 3노드(number_sync_standbys 1)로 구성한 뒤 primary node2를 kill했습니다.

05:31:55.938|node2|primary|primary|Node node 2 "node2" (node2:5432) is marked as unhealthy by the monitor
05:32:08.911|node2|primary|draining|Setting goal state of node 2 "node2" (node2:5432) to draining after it became unhealthy.
05:32:08.911|node1|secondary|report_lsn|Setting goal state of node 1 "node1" (node1:5432) to report_lsn to find the failover candidate
05:32:08.911|node3|secondary|report_lsn|Setting goal state of node 3 "node3" (node3:5432) to report_lsn to find the failover candidate
05:32:11.338|node3|report_lsn|report_lsn|New state is reported by node 3 "node3" (node3:5432) with LSN 0/9004980: report_lsn
05:32:11.651|node1|report_lsn|report_lsn|New state is reported by node 1 "node1" (node1:5432) with LSN 0/9004980: report_lsn
05:32:11.651|node1|report_lsn|prepare_promotion|Setting goal state of node 1 "node1" (node1:5432) to prepare_promotion after node 2 "node2" (node2:5432) became unhealth
05:32:12.781|node3|report_lsn|join_secondary|Setting goal state of node 3 "node3" (node3:5432) to join_secondary after node 1 "node1" (node1:5432) got selected as th
05:32:43.161|node1|stop_replication|wait_primary|Setting goal state of node 1 "node1" (node1:5432) to wait_primary and node 2 "node2" (node2:5432) to demoted after the d

kill 시각은 05:31:48.962였습니다. draining 지정까지 19.9초가 걸렸습니다. 두 standby가 LSN을 보고하는 데 2.7초가 더 걸렸습니다. 두 노드의 candidate priority(50)와 LSN은 모두 같았고 node1이 선택되었습니다. 둘 다 같을 때 어느 노드가 선택되는지는 문서에서 보장하지 않습니다. wait_primary 지정은 kill 후 54.2초(→ 05:32:43.161)였습니다. 쓰기 공백은 54.1초(05:31:49.159 → 05:32:43.279)였습니다. 2노드보다 3초 더 걸린 이유는 report_lsn 단계입니다. 후보 선출의 자세한 규칙은 3.4에서 다룹니다.

옛 primary 재합류​

kill했던 node2를 docker compose start로 되살리면 keeper가 monitor에서 demoted를 받습니다. 이어서 catchingup을 받아 standby로 돌아옵니다. run2에서는 기동부터 secondary 도달까지 3.8초가 걸렸습니다. 이때 pg_rewind가 실패해 pg_basebackup으로 전체 복사를 진행했습니다. --dbname appdb로 만든 노드에 postgres DB용 HBA 규칙이 없었기 때문입니다.

05:29:03 11 INFO  pg_rewind: error: connection to server at "node1" (172.28.0.11), port 5432 failed: FATAL:  no pg_hba.conf entry for host "172.28.0.12", user "pgautofailover_replicator", database "postgres", SSL encryption
05:29:03 11 WARN  Failed to rewind demoted primary to standby, trying pg_basebackup instead

실습 데이터가 30 MB라 3.8초 만에 끝났습니다. 큰 데이터베이스라면 전체 재복제가 필요합니다. 원인과 대처는 6.5에 정리했습니다.

정리​

기본 설정에서 primary kill 후 쓰기가 재개되기까지 2노드는 약 51초가 걸렸습니다. 3노드는 약 54초가 걸렸습니다. 앞의 20초는 keeper 보고가 끊겼는지 확인하는 시간입니다. 뒤의 30초는 옛 primary가 스스로 강등되기를 기다리는 시간입니다. 뒤쪽 30초 동안 새 primary는 이미 promote되었지만 default_transaction_read_only로 쓰기를 막습니다. 이 두 시간을 줄이는 방법과 그 대가는 7.6에서 다룹니다.