9.3 로그 읽기
FAQ의 한 항목은 "로그를 읽어야 하나요?"라는 질문입니다. 답은 "네"입니다. pg_auto_failover는 판단 근거를 로그에 자세히 남깁니다. 장애 원인을 찾으려면 세 곳을 함께 확인해야 합니다. keeper와 monitor의 pg_autoctl 로그, 각 노드의 PostgreSQL 로그, monitor의 event 테이블입니다.
로그가 남는 곳
pg_autoctl은 로그를 표준 오류에 기록합니다. systemd로 운영하면 journal이 로그를 받습니다. 따라서 journalctl -u pgautofailover로 확인합니다. 서비스 이름은 pg_autoctl show systemd가 제안하는 unit 파일 이름을 따릅니다. 실습처럼 컨테이너에서 실행하면 docker compose logs로 확인합니다.
PostgreSQL 로그는 pg_autoctl create가 만든 설정에 따라 $PGDATA/log에 남습니다. 실습 노드의 postgresql-auto-failover.conf에는 다음 값이 있었습니다.
logging_collector = on
log_destination = stderr
log_directory = log
log_min_messages = info
log_lock_waits = on
한 줄의 형식
05:10:42 10 INFO FSM transition from "demoted" to "catchingup": A new primary is available. First, try to rewind. If that fails, do a pg_basebackup.
앞에서부터 시각(HH:MM:SS), 프로세스 id, 레벨(TRACE, DEBUG, INFO, WARN, ERROR, FATAL), 메시지입니다. 날짜는 없으므로 journald나 컨테이너 로그의 타임스탬프와 함께 확인합니다. 프로세스 id를 보면 어느 하위 서비스가 기록한 줄인지 구분할 수 있습니다. pg_autoctl run은 supervisor 아래에서 postgres 서비스와 node-active 서비스를 실행합니다.
05:10:42 6 INFO Started pg_autoctl postgres service with pid 9
05:10:42 6 INFO Started pg_autoctl node-active service with pid 10
이 경우 pid 10이 monitor와 통신하며 FSM 전이를 수행한 줄입니다. pid 9는 PostgreSQL 프로세스를 관리한 줄입니다.
자주 보는 메시지
실습 로그에서 추출한 메시지와 그 뜻입니다.
| 메시지 | 뜻 |
|---|---|
Monitor assigned new state "demoted" | monitor가 목표 상태를 바꿨음 |
FSM transition from "X" to "Y": <사유> | keeper가 전이를 시작함. 사유는 전이별 고정 문구 |
Transition complete: current state is now "Y" | 전이 완료 |
We lost the monitor, but still have a standby: we're not in a network partition, continuing. | primary가 monitor에 접속하지 못하지만 standby 연결이 있어 계속 서비스 |
Network in not healthy, switching to state demote_timeout | primary가 네트워크 분리로 판단하고 스스로 강등 |
Failed to rewind demoted primary to standby, trying pg_basebackup instead | pg_rewind 실패, 전체 복사로 대체 |
Failed to transition to state "catchingup", retrying... | 전이 실패, keeper가 재시도 중 |
FSM transition 줄의 사유 문구를 보면 어떤 전이를 시도하는지 알 수 있습니다. Prevent against split-brain situations(stop_replication), Demote timeout expired(demoted) 같은 문구가 있습니다.
상세 로그와 PG_AUTOCTL_DEBUG
명령에 -v를 붙이면 로그 양이 달라집니다. v2.2 소스(cli_root.c)에서 -v는 INFO, -vv는 DEBUG, 그 이상은 TRACE입니다. -q는 ERROR만 남깁니다. 실습 로그에서는 keeper가 하위 서비스를 pg_autoctl do service node-active ... -v로 실행하는 모습이 보입니다.
PG_AUTOCTL_DEBUG 환경 변수는 로그 레벨을 설정하지 않습니다. 문서에 따르면 이 변수를 설정할 때 pg_autoctl이 추가 명령(do 계열의 내부 명령 등)을 허용합니다. 또한 "운영 클러스터를 파괴할 수 있는 기능"이 활성화된다고 경고합니다. 공식 demo compose 파일은 monitor에 이 값을 설정하지만, 운영 서비스 정의에는 적용하지 않습니다.
show events와 함께 읽기
keeper 로그는 한 노드의 관점을 보여 줍니다. event 테이블은 monitor의 관점을 보여 줍니다. 두 로그를 시각 순으로 합치면 한 번의 failover 과정이 재구성됩니다. 네트워크 분리 실측(7.4)의 예입니다.
# monitor event
05:36:24.793|node2|primary|primary|Node node 2 "node2" (node2:5432) is marked as unhealthy by the monitor
05:36:38.534|node2|primary|demote_timeout|Setting goal state of node 2 ... to demote_timeout ...
05:37:08.890|node1|stop_replication|wait_primary|Setting goal state of node 1 ... to wait_primary ...
# 고립된 node2의 keeper 로그
05:36:15 11 WARN We lost the monitor, but still have a standby: we're not in a network partition, continuing.
05:37:04 11 INFO Network in not healthy, switching to state demote_timeout
05:37:04 11 INFO FSM transition from "primary" to "demote_timeout": A failover occurred, no longer primary
node2는 monitor가 목표 상태를 바꾼 사실을 전달받지 못했습니다. 그래도 05:37:04에 스스로 강등했습니다. 이후 05:37:08에 monitor가 새 primary를 열었습니다. 양쪽 로그를 함께 확인해야 이 순서가 파악됩니다. 노드 간 시계가 어긋나면 비교 결과도 틀립니다. 따라서 NTP 동기화가 전제 조건입니다.
정리
pg_autoctl 로그는 시각, pid, 레벨, 메시지로 구성된 한 줄 형식이며 날짜가 없습니다. FSM 전이 줄의 사유 문구와 monitor event 테이블을 시각 순으로 합쳐 읽으면 장애 경과가 재구성됩니다. 상세 로그는 -vv로 활성화하고, PG_AUTOCTL_DEBUG는 운영에서 사용하지 않습니다.