<div dir="ltr"><div dir="ltr">I have already put that check in place.<div><br></div><div>Thank you for confirming.</div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Sat, Feb 23, 2019 at 11:56 PM Tatsuo Ishii <<a href="mailto:ishii@sraoss.co.jp">ishii@sraoss.co.jp</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Sorry, I was wrong. A follow_master_command will be executed against<br>
the down node as well. So you need to check whether target PostgreSQL<br>
node is running in the follow_master_commdn. If it's not, you can skip<br>
the node.<br>
<br>
Best regards,<br>
--<br>
Tatsuo Ishii<br>
SRA OSS, Inc. Japan<br>
English: <a href="http://www.sraoss.co.jp/index_en.php" rel="noreferrer" target="_blank">http://www.sraoss.co.jp/index_en.php</a><br>
Japanese:<a href="http://www.sraoss.co.jp" rel="noreferrer" target="_blank">http://www.sraoss.co.jp</a><br>
<br>
> I have added pg_ctl status check to ensure no action is taken when node is<br>
> down but I'll check 3.7.8 version.<br>
> <br>
> Here's the Pgpool log from the time node2 is shutdown to time node1(already<br>
> dead old primary) received follow master command.<br>
> Sorry for double date logging. I'm also including self-explanatory<br>
> failover.log that I my failover and follow_master scripts generated.<br>
> <br>
> Arguments passed to scripts for your reference.<br>
> failover.sh %d %h %p %D %M %P %m %H %r %R<br>
> follow_master.sh %d %h %p %D %M %P %m %H %r %R<br>
> <br>
> Pool status before shutdown of node 2:<br>
> postgres=> show pool_nodes;<br>
> node_id | hostname | port | status | lb_weight | role<br>
> | select_cnt | load_balance_node | replication_delay<br>
> ---------+----------------------------+------+--------+-----------+---------+------------+-------------------+-------------------<br>
> 0 | pg-hdp-node1.kitchen.local | 5432 | down | 0.333333 | standby<br>
> | 0 | false | 0<br>
> 1 | pg-hdp-node2.kitchen.local | 5432 | up | 0.333333 | primary<br>
> | 0 | false | 0<br>
> 2 | pg-hdp-node3.kitchen.local | 5432 | up | 0.333333 | standby<br>
> | 0 | true | 0<br>
> (3 rows)<br>
> <br>
> Pgpool log<br>
> Feb 22 10:43:27 pg-hdp-node3 pgpool[12437]: [126-1] 2019-02-22 10:43:27:<br>
> pid 12437: LOG: failed to connect to PostgreSQL server on<br>
> "pg-hdp-node2.kitchen.local:5432", getsockopt() detected error "Connection<br>
> refused"<br>
> Feb 22 10:43:27 pg-hdp-node3 pgpool[12437]: [127-1] 2019-02-22 10:43:27:<br>
> pid 12437: ERROR: failed to make persistent db connection<br>
> Feb 22 10:43:27 pg-hdp-node3 pgpool[12437]: [127-2] 2019-02-22 10:43:27:<br>
> pid 12437: DETAIL: connection to host:"pg-hdp-node2.kitchen.local:5432"<br>
> failed<br>
> Feb 22 10:43:37 pg-hdp-node3 pgpool[12437]: [128-1] 2019-02-22 10:43:37:<br>
> pid 12437: ERROR: Failed to check replication time lag<br>
> Feb 22 10:43:37 pg-hdp-node3 pgpool[12437]: [128-2] 2019-02-22 10:43:37:<br>
> pid 12437: DETAIL: No persistent db connection for the node 1<br>
> Feb 22 10:43:37 pg-hdp-node3 pgpool[12437]: [128-3] 2019-02-22 10:43:37:<br>
> pid 12437: HINT: check sr_check_user and sr_check_password<br>
> Feb 22 10:43:37 pg-hdp-node3 pgpool[12437]: [128-4] 2019-02-22 10:43:37:<br>
> pid 12437: CONTEXT: while checking replication time lag<br>
> Feb 22 10:43:37 pg-hdp-node3 pgpool[12437]: [129-1] 2019-02-22 10:43:37:<br>
> pid 12437: LOG: failed to connect to PostgreSQL server on<br>
> "pg-hdp-node2.kitchen.local:5432", getsockopt() detected error "Connection<br>
> refused"<br>
> Feb 22 10:43:37 pg-hdp-node3 pgpool[12437]: [130-1] 2019-02-22 10:43:37:<br>
> pid 12437: ERROR: failed to make persistent db connection<br>
> Feb 22 10:43:37 pg-hdp-node3 pgpool[12437]: [130-2] 2019-02-22 10:43:37:<br>
> pid 12437: DETAIL: connection to host:"pg-hdp-node2.kitchen.local:5432"<br>
> failed<br>
> Feb 22 10:43:45 pg-hdp-node3 pgpool[7786]: [6-1] 2019-02-22 10:43:45: pid<br>
> 7786: LOG: failed to connect to PostgreSQL server on<br>
> "pg-hdp-node2.kitchen.local:5432", getsockopt() detected error "Connection<br>
> refused"<br>
> Feb 22 10:43:45 pg-hdp-node3 pgpool[7786]: [7-1] 2019-02-22 10:43:45: pid<br>
> 7786: ERROR: failed to make persistent db connection<br>
> Feb 22 10:43:45 pg-hdp-node3 pgpool[7786]: [7-2] 2019-02-22 10:43:45: pid<br>
> 7786: DETAIL: connection to host:"pg-hdp-node2.kitchen.local:5432" failed<br>
> Feb 22 10:43:45 pg-hdp-node3 pgpool[7786]: [8-1] 2019-02-22 10:43:45: pid<br>
> 7786: LOG: health check retrying on DB node: 1 (round:1)<br>
> Feb 22 10:43:47 pg-hdp-node3 pgpool[12437]: [131-1] 2019-02-22 10:43:47:<br>
> pid 12437: ERROR: Failed to check replication time lag<br>
> Feb 22 10:43:47 pg-hdp-node3 pgpool[12437]: [131-2] 2019-02-22 10:43:47:<br>
> pid 12437: DETAIL: No persistent db connection for the node 1<br>
> Feb 22 10:43:47 pg-hdp-node3 pgpool[12437]: [131-3] 2019-02-22 10:43:47:<br>
> pid 12437: HINT: check sr_check_user and sr_check_password<br>
> Feb 22 10:43:47 pg-hdp-node3 pgpool[12437]: [131-4] 2019-02-22 10:43:47:<br>
> pid 12437: CONTEXT: while checking replication time lag<br>
> Feb 22 10:43:47 pg-hdp-node3 pgpool[12437]: [132-1] 2019-02-22 10:43:47:<br>
> pid 12437: LOG: failed to connect to PostgreSQL server on<br>
> "pg-hdp-node2.kitchen.local:5432", getsockopt() detected error "Connection<br>
> refused"<br>
> Feb 22 10:43:47 pg-hdp-node3 pgpool[12437]: [133-1] 2019-02-22 10:43:47:<br>
> pid 12437: ERROR: failed to make persistent db connection<br>
> Feb 22 10:43:47 pg-hdp-node3 pgpool[12437]: [133-2] 2019-02-22 10:43:47:<br>
> pid 12437: DETAIL: connection to host:"pg-hdp-node2.kitchen.local:5432"<br>
> failed<br>
> Feb 22 10:43:48 pg-hdp-node3 pgpool[7786]: [9-1] 2019-02-22 10:43:48: pid<br>
> 7786: LOG: failed to connect to PostgreSQL server on<br>
> "pg-hdp-node2.kitchen.local:5432", getsockopt() detected error "Connection<br>
> refused"<br>
> Feb 22 10:43:48 pg-hdp-node3 pgpool[7786]: [10-1] 2019-02-22 10:43:48: pid<br>
> 7786: ERROR: failed to make persistent db connection<br>
> Feb 22 10:43:48 pg-hdp-node3 pgpool[7786]: [10-2] 2019-02-22 10:43:48: pid<br>
> 7786: DETAIL: connection to host:"pg-hdp-node2.kitchen.local:5432" failed<br>
> Feb 22 10:43:48 pg-hdp-node3 pgpool[7786]: [11-1] 2019-02-22 10:43:48: pid<br>
> 7786: LOG: health check retrying on DB node: 1 (round:2)<br>
> Feb 22 10:43:51 pg-hdp-node3 pgpool[7786]: [12-1] 2019-02-22 10:43:51: pid<br>
> 7786: LOG: failed to connect to PostgreSQL server on<br>
> "pg-hdp-node2.kitchen.local:5432", getsockopt() detected error "Connection<br>
> refused"<br>
> Feb 22 10:43:51 pg-hdp-node3 pgpool[7786]: [13-1] 2019-02-22 10:43:51: pid<br>
> 7786: ERROR: failed to make persistent db connection<br>
> Feb 22 10:43:51 pg-hdp-node3 pgpool[7786]: [13-2] 2019-02-22 10:43:51: pid<br>
> 7786: DETAIL: connection to host:"pg-hdp-node2.kitchen.local:5432" failed<br>
> Feb 22 10:43:51 pg-hdp-node3 pgpool[7786]: [14-1] 2019-02-22 10:43:51: pid<br>
> 7786: LOG: health check retrying on DB node: 1 (round:3)<br>
> Feb 22 10:43:54 pg-hdp-node3 pgpool[7786]: [15-1] 2019-02-22 10:43:54: pid<br>
> 7786: LOG: failed to connect to PostgreSQL server on<br>
> "pg-hdp-node2.kitchen.local:5432", getsockopt() detected error "Connection<br>
> refused"<br>
> Feb 22 10:43:54 pg-hdp-node3 pgpool[7786]: [16-1] 2019-02-22 10:43:54: pid<br>
> 7786: ERROR: failed to make persistent db connection<br>
> Feb 22 10:43:54 pg-hdp-node3 pgpool[7786]: [16-2] 2019-02-22 10:43:54: pid<br>
> 7786: DETAIL: connection to host:"pg-hdp-node2.kitchen.local:5432" failed<br>
> Feb 22 10:43:54 pg-hdp-node3 pgpool[7786]: [17-1] 2019-02-22 10:43:54: pid<br>
> 7786: LOG: health check failed on node 1 (timeout:0)<br>
> Feb 22 10:43:54 pg-hdp-node3 pgpool[7786]: [18-1] 2019-02-22 10:43:54: pid<br>
> 7786: LOG: received degenerate backend request for node_id: 1 from pid<br>
> [7786]<br>
> Feb 22 10:43:54 pg-hdp-node3 pgpool[7746]: [253-1] 2019-02-22 10:43:54: pid<br>
> 7746: LOG: Pgpool-II parent process has received failover request<br>
> Feb 22 10:43:54 pg-hdp-node3 pgpool[7746]: [254-1] 2019-02-22 10:43:54: pid<br>
> 7746: LOG: starting degeneration. shutdown host<br>
> pg-hdp-node2.kitchen.local(5432)<br>
> Feb 22 10:43:54 pg-hdp-node3 pgpool[7746]: [255-1] 2019-02-22 10:43:54: pid<br>
> 7746: LOG: Restart all children<br>
> Feb 22 10:43:54 pg-hdp-node3 pgpool[7746]: [256-1] 2019-02-22 10:43:54: pid<br>
> 7746: LOG: execute command: /etc/pgpool-II/failover.sh 1<br>
> pg-hdp-node2.kitchen.local 5432 /var/lib/pgsql/10/data 1 1 2<br>
> pg-hdp-node3.kitchen.local 5432 /var/lib/pgsql/10/data<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[7746]: [257-1] 2019-02-22 10:43:55: pid<br>
> 7746: LOG: find_primary_node_repeatedly: waiting for finding a primary node<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[7746]: [258-1] 2019-02-22 10:43:55: pid<br>
> 7746: LOG: find_primary_node: checking backend no 0<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[7746]: [259-1] 2019-02-22 10:43:55: pid<br>
> 7746: LOG: find_primary_node: checking backend no 1<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[7746]: [260-1] 2019-02-22 10:43:55: pid<br>
> 7746: LOG: find_primary_node: checking backend no 2<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[7746]: [261-1] 2019-02-22 10:43:55: pid<br>
> 7746: LOG: find_primary_node: primary node id is 2<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[7746]: [262-1] 2019-02-22 10:43:55: pid<br>
> 7746: LOG: starting follow degeneration. shutdown host<br>
> pg-hdp-node1.kitchen.local(5432)<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[7746]: [263-1] 2019-02-22 10:43:55: pid<br>
> 7746: LOG: starting follow degeneration. shutdown host<br>
> pg-hdp-node2.kitchen.local(5432)<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[7746]: [264-1] 2019-02-22 10:43:55: pid<br>
> 7746: LOG: failover: 2 follow backends have been degenerated<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[7746]: [265-1] 2019-02-22 10:43:55: pid<br>
> 7746: LOG: failover: set new primary node: 2<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[7746]: [266-1] 2019-02-22 10:43:55: pid<br>
> 7746: LOG: failover: set new master node: 2<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[7746]: [267-1] 2019-02-22 10:43:55: pid<br>
> 7746: LOG: failover done. shutdown host pg-hdp-node2.kitchen.local(5432)<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[12437]: [134-1] 2019-02-22 10:43:55:<br>
> pid 12437: ERROR: Failed to check replication time lag<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[12437]: [134-2] 2019-02-22 10:43:55:<br>
> pid 12437: DETAIL: No persistent db connection for the node 1<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[12437]: [134-3] 2019-02-22 10:43:55:<br>
> pid 12437: HINT: check sr_check_user and sr_check_password<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[12437]: [134-4] 2019-02-22 10:43:55:<br>
> pid 12437: CONTEXT: while checking replication time lag<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[12437]: [135-1] 2019-02-22 10:43:55:<br>
> pid 12437: LOG: worker process received restart request<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[12774]: [267-1] 2019-02-22 10:43:55:<br>
> pid 12774: LOG: failback event detected<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[12774]: [267-2] 2019-02-22 10:43:55:<br>
> pid 12774: DETAIL: restarting myself<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[12742]: [265-1] 2019-02-22 10:43:55:<br>
> pid 12742: LOG: start triggering follow command.<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[12742]: [266-1] 2019-02-22 10:43:55:<br>
> pid 12742: LOG: execute command: /etc/pgpool-II/follow_master.sh 0<br>
> pg-hdp-node1.kitchen.local 5432 /var/lib/pgsql/10/data 1 1 2<br>
> pg-hdp-node3.kitchen.local 5432 /var/lib/pgsql/10/data<br>
> Feb 22 10:43:55 pg-hdp-node3 pgpool[12742]: [267-1] 2019-02-22 10:43:55:<br>
> pid 12742: LOG: execute command: /etc/pgpool-II/follow_master.sh 1<br>
> pg-hdp-node2.kitchen.local 5432 /var/lib/pgsql/10/data 1 1 2<br>
> pg-hdp-node3.kitchen.local 5432 /var/lib/pgsql/10/data<br>
> Feb 22 10:43:56 pg-hdp-node3 pgpool[12436]: [60-1] 2019-02-22 10:43:56: pid<br>
> 12436: LOG: restart request received in pcp child process<br>
> Feb 22 10:43:56 pg-hdp-node3 pgpool[7746]: [268-1] 2019-02-22 10:43:56: pid<br>
> 7746: LOG: PCP child 12436 exits with status 0 in failover()<br>
> <br>
> Pgpool self-explanatory failover.log<br>
> <br>
> 2019-02-22 10:43:54.893 PST Executing failover script ...<br>
> 2019-02-22 10:43:54.895 PST Script arguments:<br>
> failed_node_id 1<br>
> failed_node_host pg-hdp-node2.kitchen.local<br>
> failed_node_port 5432<br>
> failed_node_pgdata /var/lib/pgsql/10/data<br>
> old_primary_node_id 1<br>
> old_master_node_id 1<br>
> new_master_node_id 2<br>
> new_master_node_host pg-hdp-node3.kitchen.local<br>
> new_master_node_port 5432<br>
> new_master_node_pgdata /var/lib/pgsql/10/data<br>
> 2019-02-22 10:43:54.897 PST Primary node running on<br>
> pg-hdp-node2.kitchen.local host is unresponsive or have died<br>
> 2019-02-22 10:43:54.898 PST Attempting to stop primary node running on<br>
> pg-hdp-node2.kitchen.local host before promoting slave as the new primary<br>
> 2019-02-22 10:43:54.899 PST ssh -o StrictHostKeyChecking=no -i<br>
> /var/lib/pgsql/.ssh/id_rsa postgres@pg-hdp-node2.kitchen.local -T<br>
> /usr/pgsql-10/bin/pg_ctl -D /var/lib/pgsql/10/data stop -m fast<br>
> 2019-02-22 10:43:55.151 PST Promoting pg-hdp-node3.kitchen.local host as<br>
> the new primary<br>
> 2019-02-22 10:43:55.153 PST ssh -o StrictHostKeyChecking=no -i<br>
> /var/lib/pgsql/.ssh/id_rsa postgres@pg-hdp-node3.kitchen.local -T<br>
> /usr/pgsql-10/bin/pg_ctl -D /var/lib/pgsql/10/data promote<br>
> waiting for server to promote.... done<br>
> server promoted<br>
> 2019-02-22 10:43:55.532 PST Completed executing failover<br>
> <br>
> 2019-02-22 10:43:55.564 PST Executing follow master script ...<br>
> 2019-02-22 10:43:55.566 PST Script arguments<br>
> detached_node_id 0<br>
> detached_node_host pg-hdp-node1.kitchen.local<br>
> detached_node_port 5432<br>
> detached_node_pgdata /var/lib/pgsql/10/data<br>
> old_primary_node_id 1<br>
> old_master_node_id 1<br>
> new_master_node_id 2<br>
> new_master_node_host pg-hdp-node3.kitchen.local<br>
> new_master_node_port 5432<br>
> new_master_node_pgdata /var/lib/pgsql/10/data<br>
> 2019-02-22 10:43:55.567 PST Checking if server is running on<br>
> pg-hdp-node1.kitchen.local host<br>
> 2019-02-22 10:43:55.569 PST ssh -o StrictHostKeyChecking=no -i<br>
> /var/lib/pgsql/.ssh/id_rsa postgres@pg-hdp-node1.kitchen.local -T<br>
> /usr/pgsql-10/bin/pg_ctl -D /var/lib/pgsql/10/data status<br>
> <br>
> <br>
> pg_ctl: no server running<br>
> 2019-02-22 10:43:55.823 PST Node on pg-hdp-node1.kitchen.local host is not<br>
> running. It could be old slave or primary that needs to be recovered.<br>
> 2019-02-22 10:43:55.824 PST Completed executing follow master script<br>
> <br>
> 2019-02-22 10:43:55.829 PST Executing follow master script ...<br>
> 2019-02-22 10:43:55.830 PST Script arguments<br>
> detached_node_id 1<br>
> detached_node_host pg-hdp-node2.kitchen.local<br>
> detached_node_port 5432<br>
> detached_node_pgdata /var/lib/pgsql/10/data<br>
> old_primary_node_id 1<br>
> old_master_node_id 1<br>
> new_master_node_id 2<br>
> new_master_node_host pg-hdp-node3.kitchen.local<br>
> new_master_node_port 5432<br>
> new_master_node_pgdata /var/lib/pgsql/10/data<br>
> 2019-02-22 10:43:55.831 PST Detached node on pg-hdp-node2.kitchen.local<br>
> host is the the old primary node<br>
> 2019-02-22 10:43:55.833 PST Slave can be created from old primary node by<br>
> deleting PG_DATA directory under /var/lib/pgsql/10/data on<br>
> pg-hdp-node2.kitchen.local host and re-running Chef client<br>
> 2019-02-22 10:43:55.834 PST Slave can be recovered from old primary node by<br>
> running /usr/pgsql-10/bin/pg_rewind -D /var/lib/pgsql/10/data<br>
> --source-server="port=5432 host=pg-hdp-node3.kitchen.local" command on<br>
> pg-hdp-node2.kitchen.local host as postgres user<br>
> 2019-02-22 10:43:55.835 PST After successful pg_rewind run cp<br>
> /var/lib/pgsql/10/data/recovery.done /var/lib/pgsql/10/data/recovery.conf,<br>
> ensure host connection string points to pg-hdp-node3.kitchen.local, start<br>
> PostgreSQL and attach it to pgpool<br>
> 2019-02-22 10:43:55.836 PST Completed executing follow master script<br>
> <br>
> On Thu, Feb 21, 2019 at 4:47 PM Tatsuo Ishii <<a href="mailto:ishii@sraoss.co.jp" target="_blank">ishii@sraoss.co.jp</a>> wrote:<br>
> <br>
>> > Is this correct behavior?<br>
>> ><br>
>> > In 3-node setup, node1(primary) is shutdown, failover is executed and<br>
>> node2<br>
>> > becomes new primary and node3 follows new primary on node2.<br>
>> > Now, node2(new primary) is shutdown, failover is executed and node3<br>
>> becomes<br>
>> > new primary but fallow_master_command is executed on node1 even though it<br>
>> > is reported as down.<br>
>><br>
>> No. follow master command should not be executed on an already-down<br>
>> node (in this case node1).<br>
>><br>
>> > It happens that my script repoints node1 and restarts it which breaks<br>
>> hell<br>
>> > because node1 was never recovered after being shutdown.<br>
>> ><br>
>> > I'm on PgPool 3.7.4.<br>
>><br>
>> Can you share the log from when node2 was shutdown to when node1 was<br>
>> recovered by your follow master command?<br>
>><br>
>> In the mean time 3.7.4 is not the latest one. Can you try with the<br>
>> latest one? (3.7.8).<br>
>><br>
>> Best regards,<br>
>> --<br>
>> Tatsuo Ishii<br>
>> SRA OSS, Inc. Japan<br>
>> English: <a href="http://www.sraoss.co.jp/index_en.php" rel="noreferrer" target="_blank">http://www.sraoss.co.jp/index_en.php</a><br>
>> Japanese:<a href="http://www.sraoss.co.jp" rel="noreferrer" target="_blank">http://www.sraoss.co.jp</a><br>
>><br>
> <br>
> <br>
> -- <br>
> <br>
> *Andre Piwoni*<br><br></blockquote></div></div>