New primary stuck at unhealthy state after network issues between original primary and the monitor

[rmondegar]

We faced a network issue which caused communication failure between our original primary node and our monitor node. pg_auto_failover triggered a switchover and the old secondary, became the new primary.
Hours after this event, the new primary, has started to be constantly marked as unhealthy by the monitor without an apparent reason. Despite been marked as unhealthy, no automatic switchover happened. In this state, the new primary was reachable but unable to do write operations.

postgres_version: 16.6-1.pgdg22.04+1
pg_auto_failover version:

pg_autoctl version 2.1-3.pgdg22.04+1
pg_autoctl extension version 2.1
compiled with PostgreSQL 17rc1 (Ubuntu 17~rc1-1.pgdg22.04+2) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, 64-bit
compatible with Postgres 11, 12, 13, 14, 15, and 16

Monitor state:

Name |  Node |          Host:Port |           TLI: LSN |   Connection |      Reported State |      Assigned State
--------------+-------+--------------------+--------------------+--------------+---------------------+--------------------
original_primary_ip |     3 |  original_primary_ip:5433 |   2: 1A92/75FBE3F0 |    read-only |           secondary |           secondary
new_primary_ip |     5 | new_primary_ip:5433 |   2: 1A92/75FBE3F0 | read-write ! |             primary |             primary

Old primary logs:

Jan 22 03:46:20 prodpgdata03 pg_autoctl[1086340]: 03:46:20 1086340 ERROR Connection to database failed: connection to server at "monitor_ip", port 5433 failed: timeout expired
Jan 22 03:46:20 prodpgdata03 pg_autoctl[1086340]: 03:46:20 1086340 ERROR Failed to connect to monitor database at "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover", see above for details
Jan 22 03:46:20 prodpgdata03 pg_autoctl[1086340]: 03:46:20 1086340 ERROR Failed to get the current version for extension "pgautofailover", see previous lines for details.
Jan 22 03:46:20 prodpgdata03 pg_autoctl[1086340]: 03:46:20 1086340 ERROR Failed to get the goal state from the monitor
Jan 22 03:46:20 prodpgdata03 pg_autoctl[1086340]: 03:46:20 1086340 WARN  Checking for network partitions...
Jan 22 03:46:20 prodpgdata03 pg_autoctl[1086340]: 03:46:20 1086340 WARN  We lost the monitor, but still have a standby: we're not in a network partition, continuing.
Jan 22 03:46:20 prodpgdata03 pg_autoctl[1086340]: 03:46:20 1086340 INFO  Network is healthy
<...>
Jan 22 03:47:03 prodpgdata03 pg_autoctl[1086340]: 03:47:03 1086340 WARN  Failed to connect to "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover?", retrying until the server is ready
Jan 22 03:47:03 prodpgdata03 pg_autoctl[1086340]: 03:47:03 1086340 ERROR Connection to database failed: connection to server at "monitor_ip", port 5433 failed: timeout expired
Jan 22 03:47:03 prodpgdata03 pg_autoctl[1086340]: 03:47:03 1086340 ERROR Failed to connect to "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover?" after 1 attempts in 2002 ms, pg_autoctl stops retrying now
Jan 22 03:47:03 prodpgdata03 pg_autoctl[1086340]: 03:47:03 1086340 WARN  Lost connection.
Jan 22 03:47:03 prodpgdata03 pg_autoctl[1086340]: 03:47:03 1086340 WARN  Failed to fetch current replication properties from standby node: no standby connected in pg_stat_replication.
Jan 22 03:47:03 prodpgdata03 pg_autoctl[1086340]: 03:47:03 1086340 WARN  HINT: check pg_autoctl and Postgres logs on standby nodes
Jan 22 03:47:03 prodpgdata03 pg_autoctl[1086340]: 03:47:03 1086340 WARN  Failed to update the keeper's state from the local PostgreSQL instance.
Jan 22 03:47:05 prodpgdata03 pg_autoctl[1086340]: 03:47:05 1086340 ERROR Connection to database failed: connection to server at "monitor_ip", port 5433 failed: timeout expired
Jan 22 03:47:05 prodpgdata03 pg_autoctl[1086340]: 03:47:05 1086340 ERROR Failed to connect to monitor database at "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover", see above for details
Jan 22 03:47:05 prodpgdata03 pg_autoctl[1086340]: 03:47:05 1086340 ERROR Failed to get the current version for extension "pgautofailover", see previous lines for details.
Jan 22 03:47:05 prodpgdata03 pg_autoctl[1086340]: 03:47:05 1086340 ERROR Failed to get the goal state from the monitor
Jan 22 03:47:05 prodpgdata03 pg_autoctl[1086340]: 03:47:05 1086340 WARN  Checking for network partitions...
Jan 22 03:47:05 prodpgdata03 pg_autoctl[1086340]: 03:47:05 1086340 INFO  Failed to contact the monitor or standby in 48 seconds, at 20 seconds we shut down PostgreSQL to prevent split brain issues
Jan 22 03:47:05 prodpgdata03 pg_autoctl[1086340]: 03:47:05 1086340 INFO  Network in not healthy, switching to state demote_timeout
Jan 22 03:47:05 prodpgdata03 pg_autoctl[1086340]: 03:47:05 1086340 INFO  Reaching new state "demote_timeout"
Jan 22 03:47:05 prodpgdata03 pg_autoctl[1086340]: 03:47:05 1086340 INFO  FSM transition from "primary" to "demote_timeout": A failover occurred, no longer primary
Jan 22 03:47:05 prodpgdata03 pg_autoctl[185607]: 03:47:05 185607 INFO  Stopping pg_autoctl postgres service
Jan 22 03:47:05 prodpgdata03 pg_autoctl[185607]: 03:47:05 185607 INFO  /usr/lib/postgresql/16/bin/pg_ctl --pgdata /var/lib/postgresql/16/main_cluster --wait stop --mode fast
Jan 22 03:47:05 prodpgdata03 pg_autoctl[1086340]: 03:47:05 1086340 INFO  Transition complete: current state is now "demote_timeout"
Jan 22 03:47:05 prodpgdata03 pg_autoctl[1086340]: 03:47:05 1086340 INFO  Updated the keeper's state from the local PostgreSQL instance, which is not running
Jan 22 03:47:07 prodpgdata03 pg_autoctl[1086340]: 03:47:07 1086340 ERROR Connection to database failed: connection to server at "monitor_ip", port 5433 failed: timeout expired
Jan 22 03:47:07 prodpgdata03 pg_autoctl[1086340]: 03:47:07 1086340 ERROR Failed to connect to monitor database at "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover", see above for details
Jan 22 03:47:07 prodpgdata03 pg_autoctl[1086340]: 03:47:07 1086340 ERROR Failed to get the current version for extension "pgautofailover", see previous lines for details.
Jan 22 03:47:07 prodpgdata03 pg_autoctl[1086340]: 03:47:07 1086340 ERROR Failed to get the goal state from the monitor
Jan 22 03:47:09 prodpgdata03 pg_autoctl[1086340]: 03:47:09 1086340 WARN  Failed to connect to "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover?", retrying until the server is ready
Jan 22 03:47:09 prodpgdata03 pg_autoctl[1086340]: 03:47:09 1086340 ERROR Connection to database failed: connection to server at "monitor_ip", port 5433 failed: timeout expired
Jan 22 03:47:09 prodpgdata03 pg_autoctl[1086340]: 03:47:09 1086340 ERROR Failed to connect to "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover?" after 1 attempts in 2002 ms, pg_autoctl stops retrying now
Jan 22 03:47:09 prodpgdata03 pg_autoctl[1086340]: 03:47:09 1086340 WARN  Lost connection.
<...>
Jan 22 03:48:00 prodpgdata03 pg_autoctl[1086340]: 03:48:00 1086340 ERROR Connection to database failed: connection to server at "monitor_ip", port 5433 failed: timeout expired
Jan 22 03:48:00 prodpgdata03 pg_autoctl[1086340]: 03:48:00 1086340 ERROR Failed to connect to monitor database at "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover", see above for details
Jan 22 03:48:00 prodpgdata03 pg_autoctl[1086340]: 03:48:00 1086340 ERROR Failed to get the current version for extension "pgautofailover", see previous lines for details.
Jan 22 03:48:00 prodpgdata03 pg_autoctl[1086340]: 03:48:00 1086340 ERROR Failed to get the goal state from the monitor
Jan 22 03:48:01 prodpgdata03 pg_autoctl[1086340]: 03:48:01 1086340 WARN  Failed to connect to "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover?", retrying until the server is ready
Jan 22 03:48:03 prodpgdata03 pg_autoctl[1086340]: 03:48:03 1086340 ERROR Connection to database failed: connection to server at "monitor_ip", port 5433 failed: No route to host
Jan 22 03:48:03 prodpgdata03 pg_autoctl[1086340]: 03:48:03 1086340 ERROR         Is the server running on that host and accepting TCP/IP connections?
Jan 22 03:48:03 prodpgdata03 pg_autoctl[1086340]: 03:48:03 1086340 ERROR Failed to connect to "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover?" after 2 attempts in 3164 ms, pg_autoctl stops retrying now
Jan 22 03:48:03 prodpgdata03 pg_autoctl[1086340]: 03:48:03 1086340 WARN  Lost connection.
<...>
Jan 22 03:48:10 prodpgdata03 pg_autoctl[1086340]: 03:48:10 1086340 ERROR Connection to database failed: connection to server at "monitor_ip", port 5433 failed: No route to host
Jan 22 03:48:10 prodpgdata03 pg_autoctl[1086340]: 03:48:10 1086340 ERROR         Is the server running on that host and accepting TCP/IP connections?
Jan 22 03:48:10 prodpgdata03 pg_autoctl[1086340]: 03:48:10 1086340 ERROR Failed to connect to monitor database at "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover", see above for details
Jan 22 03:48:10 prodpgdata03 pg_autoctl[1086340]: 03:48:10 1086340 ERROR Failed to get the current version for extension "pgautofailover", see previous lines for details.
Jan 22 03:48:10 prodpgdata03 pg_autoctl[1086340]: 03:48:10 1086340 ERROR Failed to get the goal state from the monitor
Jan 22 03:48:12 prodpgdata03 pg_autoctl[1086340]: 03:48:12 1086340 INFO  Successfully got the goal state from the monitor
Jan 22 03:48:12 prodpgdata03 pg_autoctl[1086340]: 03:48:12 1086340 INFO  Monitor assigned new state "demoted"
Jan 22 03:48:12 prodpgdata03 pg_autoctl[1086340]: 03:48:12 1086340 INFO  FSM transition from "demote_timeout" to "demoted": Demote timeout expired
Jan 22 03:48:12 prodpgdata03 pg_autoctl[1086340]: 03:48:12 1086340 INFO  Transition complete: current state is now "demoted"
Jan 22 03:48:12 prodpgdata03 pg_autoctl[1086340]: 03:48:12 1086340 INFO  Monitor assigned new state "catchingup"
Jan 22 03:48:12 prodpgdata03 pg_autoctl[1086340]: 03:48:12 1086340 INFO  FSM transition from "demoted" to "catchingup": A new primary is available. First, try to rewind. If that fails, do a pg_basebackup.
Jan 22 03:48:12 prodpgdata03 pg_autoctl[1086340]: 03:48:12 1086340 INFO  Rewinding PostgreSQL to follow new primary node 5 "new_primary_ip" (new_primary_ip:5433)
Jan 22 03:48:13 prodpgdata03 pg_autoctl[1086340]: 03:48:13 1086340 INFO   /usr/lib/postgresql/16/bin/pg_rewind --target-pgdata /var/lib/postgresql/16/main_cluster --source-server 'application_name=pgautofailover_standby_3 host=new_primary_ip port=5433 user=pgautofailover_replicator db>
Jan 22 03:48:13 prodpgdata03 pg_autoctl[1086340]: 03:48:13 1086340 INFO  pg_rewind: connected to server
Jan 22 03:48:13 prodpgdata03 pg_autoctl[1086340]: 03:48:13 1086340 INFO  pg_rewind: servers diverged at WAL location 1A92/59CA34B0 on timeline 1
Jan 22 03:48:13 prodpgdata03 pg_autoctl[1086340]: 03:48:13 1086340 INFO  pg_rewind: rewinding from last common checkpoint at 1A92/59CA3400 on timeline 1
Jan 22 03:48:13 prodpgdata03 pg_autoctl[1086340]: 03:48:13 1086340 INFO  pg_rewind: reading source file list
Jan 22 03:48:13 prodpgdata03 pg_autoctl[1086340]: 03:48:13 1086340 INFO  pg_rewind: reading target file list
Jan 22 03:48:13 prodpgdata03 pg_autoctl[1086340]: 03:48:13 1086340 INFO  pg_rewind: reading WAL in target
Jan 22 03:48:13 prodpgdata03 pg_autoctl[1086340]: 03:48:13 1086340 INFO  pg_rewind: need to copy 667 MB (total source directory size is 200572 MB)
Jan 22 03:48:13 prodpgdata03 pg_autoctl[1086340]: 03:48:13 1086340 INFO       0/683201 kB (0%) copied
Jan 22 03:48:14 prodpgdata03 pg_autoctl[1086340]: 03:48:14 1086340 INFO   18367/683201 kB (2%) copied
Jan 22 03:48:15 prodpgdata03 pg_autoctl[1086340]: 03:48:15 1086340 INFO  113725/683201 kB (16%) copied
Jan 22 03:48:16 prodpgdata03 pg_autoctl[1086340]: 03:48:16 1086340 INFO  202402/683201 kB (29%) copied
Jan 22 03:48:17 prodpgdata03 pg_autoctl[1086340]: 03:48:17 1086340 INFO  317083/683201 kB (46%) copied
Jan 22 03:48:18 prodpgdata03 pg_autoctl[1086340]: 03:48:18 1086340 INFO  430747/683201 kB (63%) copied
Jan 22 03:48:19 prodpgdata03 pg_autoctl[1086340]: 03:48:19 1086340 INFO  534171/683201 kB (78%) copied
Jan 22 03:48:20 prodpgdata03 pg_autoctl[1086340]: 03:48:20 1086340 INFO  648603/683201 kB (94%) copied
Jan 22 03:48:20 prodpgdata03 pg_autoctl[1086340]: 03:48:20 1086340 INFO  683201/683201 kB (100%) copied
Jan 22 03:48:20 prodpgdata03 pg_autoctl[1086340]: 03:48:20 1086340 INFO  pg_rewind: creating backup label and updating control file
Jan 22 03:48:20 prodpgdata03 pg_autoctl[1086340]: 03:48:20 1086340 INFO  pg_rewind: syncing target data directory
Jan 22 03:48:40 prodpgdata03 pg_autoctl[1086340]: 03:48:40 1086340 INFO  pg_rewind: Done!
Jan 22 03:48:40 prodpgdata03 pg_autoctl[1086340]: 03:48:40 1086340 INFO  Creating the standby signal file at "/var/lib/postgresql/16/main_cluster/standby.signal", and replication setup at "/var/lib/postgresql/16/main_cluster/postgresql-auto-failover-standby.conf"
Jan 22 03:48:40 prodpgdata03 pg_autoctl[1086340]: 03:48:40 1086340 INFO  Contents of "/var/lib/postgresql/16/main_cluster/postgresql-auto-failover-standby.conf" have changed, overwriting
Jan 22 03:48:40 prodpgdata03 pg_autoctl[753559]: 03:48:40 753559 INFO   /usr/lib/postgresql/16/bin/postgres -D /var/lib/postgresql/16/main_cluster -p 5433 -h *
Jan 22 03:49:00 prodpgdata03 pg_autoctl[185607]: 03:49:00 185607 WARN  PostgreSQL was not running, restarted with pid 753559
Jan 22 03:49:01 prodpgdata03 pg_autoctl[1086340]: 03:49:01 1086340 INFO  Dropping replication slots (to reset their xmin)
Jan 22 03:49:01 prodpgdata03 pg_autoctl[1086340]: 03:49:01 1086340 INFO  Transition complete: current state is now "catchingup"
Jan 22 03:49:02 prodpgdata03 pg_autoctl[1086340]: 03:49:02 1086340 INFO  Monitor assigned new state "secondary"
Jan 22 03:49:02 prodpgdata03 pg_autoctl[1086340]: 03:49:02 1086340 INFO  FSM transition from "catchingup" to "secondary": Convinced the monitor that I'm up and running, and eligible for promotion again
Jan 22 03:49:02 prodpgdata03 pg_autoctl[1086340]: 03:49:02 1086340 INFO  Reached timeline 2, same as upstream node 5 "new_primary_ip" (new_primary_ip:5433)
Jan 22 03:49:02 prodpgdata03 pg_autoctl[1086340]: 03:49:02 1086340 INFO  Creating replication slot "pgautofailover_standby_5"
Jan 22 03:49:02 prodpgdata03 pg_autoctl[1086340]: 03:49:02 1086340 INFO  Transition complete: current state is now "secondary"
Jan 22 03:49:02 prodpgdata03 pg_autoctl[1086340]: 03:49:02 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 22 03:57:41 prodpgdata03 pg_autoctl[1086340]: 03:57:41 1086340 ERROR Connection to database failed: connection to server at "monitor_ip", port 5433 failed: timeout expired
Jan 22 03:57:41 prodpgdata03 pg_autoctl[1086340]: 03:57:41 1086340 ERROR Failed to connect to monitor database at "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover", see above for details
Jan 22 03:57:41 prodpgdata03 pg_autoctl[1086340]: 03:57:41 1086340 ERROR Failed to get the current version for extension "pgautofailover", see previous lines for details.
Jan 22 03:57:41 prodpgdata03 pg_autoctl[1086340]: 03:57:41 1086340 ERROR Failed to get the goal state from the monitor
<...>
Jan 22 03:58:45 prodpgdata03 pg_autoctl[1086340]: 03:58:45 1086340 INFO  Successfully got the goal state from the monitor
Jan 22 03:58:48 prodpgdata03 pg_autoctl[1086340]: 03:58:48 1086340 WARN  Failed to connect to "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover?", retrying until the server is ready
Jan 22 03:58:48 prodpgdata03 pg_autoctl[1086340]: 03:58:48 1086340 ERROR Connection to database failed: connection to server at "monitor_ip", port 5433 failed: timeout expired
Jan 22 03:58:48 prodpgdata03 pg_autoctl[1086340]: 03:58:48 1086340 ERROR Failed to connect to "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover?" after 1 attempts in 2002 ms, pg_autoctl stops retrying now
Jan 22 03:58:48 prodpgdata03 pg_autoctl[1086340]: 03:58:48 1086340 WARN  Lost connection.
Jan 22 03:58:50 prodpgdata03 pg_autoctl[1086340]: 03:58:50 1086340 ERROR Connection to database failed: connection to server at "monitor_ip", port 5433 failed: timeout expired
Jan 22 03:58:50 prodpgdata03 pg_autoctl[1086340]: 03:58:50 1086340 ERROR Failed to connect to monitor database at "postgres://autoctl_node@monitor_ip:5433/pg_auto_failover", see above for details
Jan 22 03:58:50 prodpgdata03 pg_autoctl[1086340]: 03:58:50 1086340 ERROR Failed to get the current version for extension "pgautofailover", see previous lines for details.
Jan 22 03:58:50 prodpgdata03 pg_autoctl[1086340]: 03:58:50 1086340 ERROR Failed to get the goal state from the monitor
Jan 22 03:58:52 prodpgdata03 pg_autoctl[1086340]: 03:58:52 1086340 INFO  Successfully got the goal state from the monitor
Jan 22 21:38:38 prodpgdata03 pg_autoctl[1086340]: 21:38:38 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 22 21:39:16 prodpgdata03 pg_autoctl[1086340]: 21:39:16 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 22 21:39:55 prodpgdata03 pg_autoctl[1086340]: 21:39:55 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 22 22:05:36 prodpgdata03 pg_autoctl[1086340]: 22:05:36 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 00:52:26 prodpgdata03 pg_autoctl[1086340]: 00:52:26 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 00:52:33 prodpgdata03 pg_autoctl[1086340]: 00:52:33 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 06:20:53 prodpgdata03 pg_autoctl[1086340]: 06:20:53 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 08:32:13 prodpgdata03 pg_autoctl[1086340]: 08:32:13 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 08:45:34 prodpgdata03 pg_autoctl[1086340]: 08:45:34 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 09:02:13 prodpgdata03 pg_autoctl[1086340]: 09:02:13 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 09:02:19 prodpgdata03 pg_autoctl[1086340]: 09:02:19 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 09:05:27 prodpgdata03 pg_autoctl[1086340]: 09:05:27 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 09:05:34 prodpgdata03 pg_autoctl[1086340]: 09:05:34 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 10:32:13 prodpgdata03 pg_autoctl[1086340]: 10:32:13 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 10:32:19 prodpgdata03 pg_autoctl[1086340]: 10:32:19 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 12:02:13 prodpgdata03 pg_autoctl[1086340]: 12:02:13 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 12:02:19 prodpgdata03 pg_autoctl[1086340]: 12:02:19 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 12:05:27 prodpgdata03 pg_autoctl[1086340]: 12:05:27 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 12:05:34 prodpgdata03 pg_autoctl[1086340]: 12:05:34 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 13:37:48 prodpgdata03 pg_autoctl[1086340]: 13:37:48 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 13:37:55 prodpgdata03 pg_autoctl[1086340]: 13:37:55 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 18:32:39 prodpgdata03 pg_autoctl[1086340]: 18:32:39 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 18:44:53 prodpgdata03 pg_autoctl[1086340]: 18:44:53 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary
Jan 23 18:46:03 prodpgdata03 pg_autoctl[1086340]: 18:46:03 1086340 INFO  New state for node 5 "new_primary_ip" (new_primary_ip:5433): primary ➜ primary

New primary logs:

Jan 22 03:46:40 prodpgdata04 pg_autoctl[169903]: 03:46:40 169903 INFO  Monitor assigned new state "prepare_promotion"
Jan 22 03:46:40 prodpgdata04 pg_autoctl[169903]: 03:46:40 169903 INFO  FSM transition from "secondary" to "prepare_promotion": Stop traffic to primary, wait for it to finish draining.
Jan 22 03:46:40 prodpgdata04 pg_autoctl[169903]: 03:46:40 169903 INFO  Transition complete: current state is now "prepare_promotion"
Jan 22 03:46:40 prodpgdata04 pg_autoctl[169903]: 03:46:40 169903 INFO  Monitor assigned new state "stop_replication"
Jan 22 03:46:40 prodpgdata04 pg_autoctl[169903]: 03:46:40 169903 INFO  FSM transition from "prepare_promotion" to "stop_replication": Prevent against split-brain situations.
Jan 22 03:46:40 prodpgdata04 pg_autoctl[169903]: 03:46:40 169903 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
Jan 22 03:46:40 prodpgdata04 pg_autoctl[169903]: 03:46:40 169903 INFO  Setting default_transaction_read_only to on
Jan 22 03:46:40 prodpgdata04 pg_autoctl[169903]: 03:46:40 169903 INFO  Reloading Postgres configuration and HBA rules
Jan 22 03:46:40 prodpgdata04 pg_autoctl[169903]: 03:46:40 169903 INFO  Promoting postgres
Jan 22 03:46:40 prodpgdata04 pg_autoctl[169903]: 03:46:40 169903 INFO  Waiting for postgres to promote
Jan 22 03:46:41 prodpgdata04 pg_autoctl[169903]: 03:46:41 169903 INFO  Cleaning-up Postgres replication settings
Jan 22 03:46:41 prodpgdata04 pg_autoctl[169903]: 03:46:41 169903 INFO  Disabling synchronous replication
Jan 22 03:46:41 prodpgdata04 pg_autoctl[169903]: 03:46:41 169903 INFO  Reloading Postgres configuration and HBA rules
Jan 22 03:46:41 prodpgdata04 pg_autoctl[169903]: 03:46:41 169903 INFO  Transition complete: current state is now "stop_replication"
Jan 22 03:47:10 prodpgdata04 pg_autoctl[169903]: 03:47:10 169903 INFO  Monitor assigned new state "wait_primary"
Jan 22 03:47:10 prodpgdata04 pg_autoctl[169903]: 03:47:10 169903 INFO  FSM transition from "stop_replication" to "wait_primary": Confirmed promotion with the monitor
Jan 22 03:47:10 prodpgdata04 pg_autoctl[169903]: 03:47:10 169903 INFO  Setting default_transaction_read_only to off
Jan 22 03:47:10 prodpgdata04 pg_autoctl[169903]: 03:47:10 169903 INFO  Reloading Postgres configuration and HBA rules
Jan 22 03:47:10 prodpgdata04 pg_autoctl[169903]: 03:47:10 169903 INFO  Fetched current list of 1 other nodes from the monitor to update HBA rules, including 1 changes.
Jan 22 03:47:10 prodpgdata04 pg_autoctl[169903]: 03:47:10 169903 INFO  Checking for HBA rules for node 3 "original_primary_ip" (original_primary_ip:5433)
Jan 22 03:47:10 prodpgdata04 pg_autoctl[169903]: 03:47:10 169903 WARN  Skipping HBA edits (per --skip-pg-hba) for rule: hostssl replication "pgautofailover_replicator" original_primary_ip/32 trust
Jan 22 03:47:10 prodpgdata04 pg_autoctl[169903]: 03:47:10 169903 WARN  Skipping HBA edits (per --skip-pg-hba) for rule: hostssl "postgres" "pgautofailover_replicator" original_primary_ip/32 trust
Jan 22 03:47:10 prodpgdata04 pg_autoctl[169903]: 03:47:10 169903 INFO  Transition complete: current state is now "wait_primary"
Jan 22 03:48:12 prodpgdata04 pg_autoctl[169903]: 03:48:12 169903 INFO  New state for node 3 "original_primary_ip" (original_primary_ip:5433): demote_timeout ➜ demoted
Jan 22 03:48:12 prodpgdata04 pg_autoctl[169903]: 03:48:12 169903 INFO  New state for node 3 "original_primary_ip" (original_primary_ip:5433): demoted ➜ demoted
Jan 22 03:48:12 prodpgdata04 pg_autoctl[169903]: 03:48:12 169903 INFO  New state for node 3 "original_primary_ip" (original_primary_ip:5433): demoted ➜ catchingup
Jan 22 03:49:01 prodpgdata04 pg_autoctl[169903]: 03:49:01 169903 INFO  New state for node 3 "original_primary_ip" (original_primary_ip:5433): catchingup ➜ catchingup
Jan 22 03:49:02 prodpgdata04 pg_autoctl[169903]: 03:49:02 169903 INFO  New state for node 3 "original_primary_ip" (original_primary_ip:5433): secondary ➜ secondary
Jan 22 03:49:02 prodpgdata04 pg_autoctl[169903]: 03:49:02 169903 INFO  Monitor assigned new state "primary"
Jan 22 03:49:02 prodpgdata04 pg_autoctl[169903]: 03:49:02 169903 INFO  FSM transition from "wait_primary" to "primary": A healthy secondary appeared
Jan 22 03:49:02 prodpgdata04 pg_autoctl[169903]: 03:49:02 169903 INFO  Setting synchronous_standby_names to 'ANY 1 (pgautofailover_standby_3)'
Jan 22 03:49:02 prodpgdata04 pg_autoctl[169903]: 03:49:02 169903 INFO  Reloading Postgres configuration and HBA rules
Jan 22 03:49:02 prodpgdata04 pg_autoctl[169903]: 03:49:02 169903 INFO  Waiting until standby node has caught-up to LSN 1A92/59CB9C48
Jan 22 03:49:02 prodpgdata04 pg_autoctl[169903]: 03:49:02 169903 INFO  Standby reached LSN 1A92/59CB9C48, thus advanced past LSN 1A92/59CB9C48
Jan 22 03:49:02 prodpgdata04 pg_autoctl[169903]: 03:49:02 169903 INFO  Transition complete: current state is now "primary"
Jan 22 03:49:03 prodpgdata04 pg_autoctl[169903]: 03:49:03 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): wait_primary ➜ primary
Jan 22 03:49:03 prodpgdata04 pg_autoctl[169903]: 03:49:03 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 22 21:09:42 prodpgdata04 pg_autoctl[169903]: 21:09:42 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 22 21:38:11 prodpgdata04 pg_autoctl[169903]: 21:38:11 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 22 21:39:16 prodpgdata04 pg_autoctl[169903]: 21:39:16 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 22 22:04:40 prodpgdata04 pg_autoctl[169903]: 22:04:40 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 22 22:05:36 prodpgdata04 pg_autoctl[169903]: 22:05:36 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 00:52:26 prodpgdata04 pg_autoctl[169903]: 00:52:26 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 00:52:33 prodpgdata04 pg_autoctl[169903]: 00:52:33 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 06:20:53 prodpgdata04 pg_autoctl[169903]: 06:20:53 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 06:21:04 prodpgdata04 pg_autoctl[169903]: 06:21:04 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 08:32:13 prodpgdata04 pg_autoctl[169903]: 08:32:13 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 08:32:24 prodpgdata04 pg_autoctl[169903]: 08:32:24 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 08:45:34 prodpgdata04 pg_autoctl[169903]: 08:45:34 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 08:45:41 prodpgdata04 pg_autoctl[169903]: 08:45:41 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 09:02:13 prodpgdata04 pg_autoctl[169903]: 09:02:13 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 09:05:27 prodpgdata04 pg_autoctl[169903]: 09:05:27 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 09:05:34 prodpgdata04 pg_autoctl[169903]: 09:05:34 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 10:32:13 prodpgdata04 pg_autoctl[169903]: 10:32:13 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 10:32:19 prodpgdata04 pg_autoctl[169903]: 10:32:19 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 12:02:19 prodpgdata04 pg_autoctl[169903]: 12:02:19 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 12:05:27 prodpgdata04 pg_autoctl[169903]: 12:05:27 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 12:05:34 prodpgdata04 pg_autoctl[169903]: 12:05:34 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 13:37:48 prodpgdata04 pg_autoctl[169903]: 13:37:48 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 13:37:55 prodpgdata04 pg_autoctl[169903]: 13:37:55 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 17:32:13 prodpgdata04 pg_autoctl[169903]: 17:32:13 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 17:32:24 prodpgdata04 pg_autoctl[169903]: 17:32:24 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 18:32:39 prodpgdata04 pg_autoctl[169903]: 18:32:39 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 18:32:55 prodpgdata04 pg_autoctl[169903]: 18:32:55 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 18:44:53 prodpgdata04 pg_autoctl[169903]: 18:44:53 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary
Jan 23 18:46:03 prodpgdata04 pg_autoctl[169903]: 18:46:03 169903 INFO  New state for this node (node 5, "new_primary_ip") (new_primary_ip:5433): primary ➜ primary

Monitor logs:

2025-01-21 16:52:38.693998+00 |    0/3 |             primary |             primary | Node node 3 "original_primary_ip" (original_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-21 18:23:09.935008+00 |    0/3 |             primary |             primary | Node node 3 "original_primary_ip" (original_primary_ip:5433) is marked as healthy by the monitor
 2025-01-22 02:46:39.917977+00 |    0/3 |             primary |             primary | Node node 3 "original_primary_ip" (original_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-22 02:46:39.977794+00 |    0/5 |           secondary |   prepare_promotion | Setting goal state of node 3 "original_primary_ip" (original_primary_ip:5433) to draining and node 5 "new_primary_ip" (new_primary_ip:5433) to prepare_promotion after node 3 "original_primary_ip" (original_primary_ip:5433) became unhealthy.
 2025-01-22 02:46:39.977794+00 |    0/3 |             primary |            draining | Setting goal state of node 3 "original_primary_ip" (original_primary_ip:5433) to draining and node 5 "new_primary_ip" (new_primary_ip:5433) to prepare_promotion after node 3 "original_primary_ip" (original_primary_ip:5433) became unhealthy.
  2025-01-22 02:46:40.11916+00 |    0/5 |   prepare_promotion |   prepare_promotion | New state is reported by node 5 "new_primary_ip" (new_primary_ip:5433): "prepare_promotion"
  2025-01-22 02:46:40.11916+00 |    0/5 |   prepare_promotion |    stop_replication | Setting goal state of node 3 "original_primary_ip" (original_primary_ip:5433) to demote_timeout and node 5 "new_primary_ip" (new_primary_ip:5433) to stop_replication after node 5 "new_primary_ip" (new_primary_ip:5433) converged to prepare_promotion.
  2025-01-22 02:46:40.11916+00 |    0/3 |             primary |      demote_timeout | Setting goal state of node 3 "original_primary_ip" (original_primary_ip:5433) to demote_timeout and node 5 "new_primary_ip" (new_primary_ip:5433) to stop_replication after node 5 "new_primary_ip" (new_primary_ip:5433) converged to prepare_promotion.
 2025-01-22 02:46:41.369814+00 |    0/5 |    stop_replication |    stop_replication | New state is reported by node 5 "new_primary_ip" (new_primary_ip:5433): "stop_replication"
 2025-01-22 02:47:10.725248+00 |    0/5 |    stop_replication |        wait_primary | Setting goal state of node 5 "new_primary_ip" (new_primary_ip:5433) to wait_primary and node 3 "original_primary_ip" (original_primary_ip:5433) to demoted after the demote timeout expired.
 2025-01-22 02:47:10.725248+00 |    0/3 |             primary |             demoted | Setting goal state of node 5 "new_primary_ip" (new_primary_ip:5433) to wait_primary and node 3 "original_primary_ip" (original_primary_ip:5433) to demoted after the demote timeout expired.
 2025-01-22 02:47:10.935176+00 |    0/5 |        wait_primary |        wait_primary | New state is reported by node 5 "new_primary_ip" (new_primary_ip:5433): "wait_primary"
  2025-01-22 02:48:12.70609+00 |    0/3 |      demote_timeout |             demoted | New state is reported by node 3 "original_primary_ip" (original_primary_ip:5433): "demote_timeout"
 2025-01-22 02:48:12.854283+00 |    0/3 |             demoted |             demoted | New state is reported by node 3 "original_primary_ip" (original_primary_ip:5433): "demoted"
 2025-01-22 02:48:12.854283+00 |    0/3 |             demoted |          catchingup | Setting goal state of node 3 "original_primary_ip" (original_primary_ip:5433) to catchingup after it converged to demotion and node 5 "new_primary_ip" (new_primary_ip:5433) converged to wait_primary.
 2025-01-22 02:49:01.134763+00 |    0/3 |          catchingup |          catchingup | New state is reported by node 3 "original_primary_ip" (original_primary_ip:5433): "catchingup"
 2025-01-22 02:49:02.321268+00 |    0/3 |          catchingup |           secondary | Setting goal state of node 3 "original_primary_ip" (original_primary_ip:5433) to secondary after it caught up.
 2025-01-22 02:49:02.476898+00 |    0/3 |          catchingup |           secondary | Node node 3 "original_primary_ip" (original_primary_ip:5433) is marked as healthy by the monitor
 2025-01-22 02:49:02.599222+00 |    0/3 |           secondary |           secondary | New state is reported by node 3 "original_primary_ip" (original_primary_ip:5433): "secondary"
 2025-01-22 02:49:02.693251+00 |    0/5 |        wait_primary |             primary | Setting goal state of node 5 "new_primary_ip" (new_primary_ip:5433) to primary now that we have 1 healthy  secondary nodes in the quorum.
 2025-01-22 02:49:02.949721+00 |    0/5 |             primary |             primary | New state is reported by node 5 "new_primary_ip" (new_primary_ip:5433): "primary"
 2025-01-22 20:09:42.321119+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
  2025-01-22 20:38:11.92872+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-22 20:38:38.070166+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-22 20:39:16.959188+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-22 20:39:55.982502+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-22 21:04:40.836179+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-22 21:05:36.961389+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-22 23:52:26.985367+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-22 23:52:33.120091+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-23 05:20:53.265439+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-23 05:21:04.393987+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-23 07:32:13.505281+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-23 07:32:24.646026+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
  2025-01-23 07:45:34.92446+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-23 07:45:41.053129+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-23 08:02:13.541188+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-23 08:02:19.666145+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-23 08:05:27.506282+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-23 08:05:34.524093+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-23 09:32:13.538641+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-23 09:32:19.662254+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-23 11:02:13.542455+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-23 11:02:19.675164+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-23 11:05:27.526667+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-23 11:05:34.503797+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-23 12:37:48.975769+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-23 12:37:55.100487+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-23 16:32:13.833009+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-23 16:32:24.965394+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-23 17:32:39.204358+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-23 17:32:55.342062+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor
 2025-01-23 17:44:53.928113+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as healthy by the monitor
 2025-01-23 17:46:03.019313+00 |    0/5 |             primary |             primary | Node node 5 "new_primary_ip" (new_primary_ip:5433) is marked as unhealthy by the monitor

[rmondegar]

We have managed to recover the cluster now, after performing "pg_autoctl perform switchover" twice on the monitor node, forcing the new primary into a health state again.

First switchover (new_primary => original_primary):

postgres@prodpgmon02 ~ $ pg_autoctl perform switchover
18:11:53 1208445 INFO  Waiting 60 secs for a notification with state "primary" in formation "default" and group 0
18:11:53 1208445 INFO  Listening monitor notifications about state changes in formation "default" and group 0
18:11:53 1208445 INFO  Following table displays times when notifications are received
    Time |          Name |  Node |          Host:Port |       Current State |      Assigned State
---------+---------------+-------+--------------------+---------------------+--------------------
18:11:53 | new_primary_ip |     5 | new_primary_ip:5433 |             primary |            draining
18:11:53 |  original_primary_ip |     3 |  original_primary_ip:5433 |           secondary |   prepare_promotion
18:11:53 |  original_primary_ip |     3 |  original_primary_ip:5433 |   prepare_promotion |   prepare_promotion
18:11:53 |  original_primary_ip |     3 |  original_primary_ip:5433 |   prepare_promotion |    stop_replication
18:11:53 | new_primary_ip |     5 | new_primary_ip:5433 |             primary |      demote_timeout
18:11:53 | new_primary_ip |     5 | new_primary_ip:5433 |            draining |      demote_timeout
18:11:54 | new_primary_ip |     5 | new_primary_ip:5433 |      demote_timeout |      demote_timeout
18:11:56 |  original_primary_ip |     3 |  original_primary_ip:5433 |    stop_replication |    stop_replication
18:11:56 |  original_primary_ip |     3 |  original_primary_ip:5433 |    stop_replication |        wait_primary
18:11:56 | new_primary_ip |     5 | new_primary_ip:5433 |      demote_timeout |             demoted
18:11:56 | new_primary_ip |     5 | new_primary_ip:5433 |             demoted |             demoted
18:11:56 |  original_primary_ip |     3 |  original_primary_ip:5433 |        wait_primary |        wait_primary
18:11:57 | new_primary_ip |     5 | new_primary_ip:5433 |             demoted |          catchingup
18:11:58 | new_primary_ip |     5 | new_primary_ip:5433 |          catchingup |          catchingup
18:11:58 | new_primary_ip |     5 | new_primary_ip:5433 |          catchingup |          catchingup
18:11:59 | new_primary_ip |     5 | new_primary_ip:5433 |          catchingup |           secondary
18:11:59 | new_primary_ip |     5 | new_primary_ip:5433 |           secondary |           secondary
18:11:59 |  original_primary_ip |     3 |  original_primary_ip:5433 |        wait_primary |             primary
18:11:59 |  original_primary_ip |     3 |  original_primary_ip:5433 |             primary |             primary

postgres@prodpgmon02 ~ $ pg_autoctl show state
         Name |  Node |          Host:Port |           TLI: LSN |   Connection |      Reported State |      Assigned State
--------------+-------+--------------------+--------------------+--------------+---------------------+--------------------
original_primary_ip |     3 |  original_primary_ip:5433 |   3: 1A92/7604AD38 |   read-write |             primary |             primary
new_primary_ip |     5 | new_primary_ip:5433 |   3: 1A92/7604AD38 |    read-only |           secondary |           secondary

Second switchover (original_primary => new_primary):

postgres@prodpgmon02 ~ $ pg_autoctl perform switchover
18:17:58 1211229 INFO  Waiting 60 secs for a notification with state "primary" in formation "default" and group 0
18:17:58 1211229 INFO  Listening monitor notifications about state changes in formation "default" and group 0
18:17:58 1211229 INFO  Following table displays times when notifications are received
    Time |          Name |  Node |          Host:Port |       Current State |      Assigned State
---------+---------------+-------+--------------------+---------------------+--------------------
18:17:58 |  original_primary_ip |     3 |  original_primary_ip:5433 |             primary |            draining
18:17:58 | new_primary_ip |     5 | new_primary_ip:5433 |           secondary |   prepare_promotion
18:17:58 | new_primary_ip |     5 | new_primary_ip:5433 |   prepare_promotion |   prepare_promotion
18:17:58 | new_primary_ip |     5 | new_primary_ip:5433 |   prepare_promotion |    stop_replication
18:17:58 |  original_primary_ip |     3 |  original_primary_ip:5433 |             primary |      demote_timeout
18:17:59 |  original_primary_ip |     3 |  original_primary_ip:5433 |            draining |      demote_timeout
18:17:59 |  original_primary_ip |     3 |  original_primary_ip:5433 |      demote_timeout |      demote_timeout
18:18:00 | new_primary_ip |     5 | new_primary_ip:5433 |    stop_replication |    stop_replication
18:18:00 | new_primary_ip |     5 | new_primary_ip:5433 |    stop_replication |        wait_primary
18:18:00 |  original_primary_ip |     3 |  original_primary_ip:5433 |      demote_timeout |             demoted
18:18:00 | new_primary_ip |     5 | new_primary_ip:5433 |        wait_primary |        wait_primary
18:18:00 |  original_primary_ip |     3 |  original_primary_ip:5433 |             demoted |             demoted
18:18:00 |  original_primary_ip |     3 |  original_primary_ip:5433 |             demoted |          catchingup
18:18:05 |  original_primary_ip |     3 |  original_primary_ip:5433 |             demoted |          catchingup
18:18:53 |  original_primary_ip |     3 |  original_primary_ip:5433 |          catchingup |          catchingup
18:18:55 |  original_primary_ip |     3 |  original_primary_ip:5433 |          catchingup |           secondary
18:18:55 |  original_primary_ip |     3 |  original_primary_ip:5433 |           secondary |           secondary
18:18:55 | new_primary_ip |     5 | new_primary_ip:5433 |        wait_primary |             primary
18:18:55 |  original_primary_ip |     3 |  original_primary_ip:5433 |           secondary |           secondary
18:18:55 | new_primary_ip |     5 | new_primary_ip:5433 |             primary |             primary

postgres@prodpgmon02 ~ $ pg_autoctl show state
         Name |  Node |          Host:Port |           TLI: LSN |   Connection |      Reported State |      Assigned State
--------------+-------+--------------------+--------------------+--------------+---------------------+--------------------
original_primary_ip |     3 |  original_primary_ip:5433 |   4: 1A92/762D75D0 |    read-only |           secondary |           secondary
new_primary_ip |     5 | new_primary_ip:5433 |   4: 1A92/762D75D0 |   read-write |             primary |             primary

[dimitri]

Thanks a lot for the very complete report, including logs from both nodes and the monitor — that made this much easier to pin down.

This is fixed by #1141. NodeIsHealthy() in src/monitor/node_metadata.c only handled the GOOD and BAD health values explicitly. There's also a "fresh report" override meant to keep a node considered healthy when it's marked BAD by the health-check worker but is still actively reporting via node_active (exactly your case: the new primary was reachable and reporting, just intermittently failing the monitor's own health check). That override was being masked by the missing handling of NODE_HEALTH_UNKNOWN, so the health state kept flapping between healthy/unhealthy as you saw in the monitor logs, without the fresh-report logic ever kicking in to stabilize it or trigger a clean action.

PR #1141 adds the missing UNKNOWN branch (trusting the keeper's own pgIsRunning report, same as the existing BAD-with-fresh-report path) and adds test_002 in the new node_active_protocol.sql regression test, which asserts a primary with BAD health and a fresh report stays primary instead of flapping or triggering a spurious failover.