View Issue Details

IDProjectCategoryView StatusLast Update
0000597Pgpool-IIBugpublic2020-05-15 10:43
ReporterdcvythoulkasAssigned ToMuhammad Usama 
PriorityhighSeveritymajorReproducibilityalways
Status assignedResolutionopen 
PlatformPostgreSQL 12OSDebianOS Version10.3
Product Version4.1.0 
Target VersionFixed in Version 
Summary0000597: pgpool2 fails to run the if_down_cmd and arping_cmd
DescriptionThis a two node installation using watchdog with the gateway as the trusted server.

When pgpool2 shuts down on the master node, the secondary succsessfully gets promoted to master and raises the delegated IP. However the former master never releases the IP, so both nodes hold the IP. The only choice is to use 'ip addr del DELEGATED_IP/NETMASK dev NIC' to release the IP.
Also the new master node does not notify the local network about acquiring the delegated IP and therefore clients cannot connect.
Steps To Reproduce- Node1 master & Node2 standby
- Shutdown pgpool2 process on node1. pgpool2 on node2 promotes to master and raises delagated IP
- Node1 still has the delegated IP. Use ip addr dell command to remove
- Node2 has not announced taking the delegated ip and client cannot connect
Tagsvirtual ip, watchdog

Activities

Muhammad Usama

2020-03-13 23:31

developer   ~0003269

Can you please share the pgpool config and log files.

dcvythoulkas

2020-03-16 20:22

reporter   ~0003271

pgpool.conf is from node ...cn1, node cn2 has an equivalent configuration. The setup is deployed by Ansible.
Initially, cn2 was master and cn1 was standby. cn2 pgpool2 process was shut down and cn1 took over and raised the virtual IP.
However, cn2 never released the virtual IP and the local network was never notified about the change.

pgpool-cn1.log (23,214 bytes)
pgpool-cn2.log (18,328 bytes)
pgpool.conf (44,216 bytes)

tito052879

2020-04-10 06:23

reporter   ~0003312

Might be wrong but in your pgpool.conf file, if_up_cmd is assigning delegate IP to eth0.153:0 but if_down_cmd is trying to delete eth0.153 instead.

tito052879

2020-04-10 14:15

reporter   ~0003313

i take that back. your conf is right. but that tells me my conf was wrong. hmm

Muhammad Usama

2020-04-17 02:43

developer   ~0003331

Hi

Despite my best efforts, I am not able to replicate the issue. I am using centos 7 docker environment.

^C2020-04-16 17:14:53: pid 29543: LOG: Watchdog is shutting down
2020-04-16 17:14:53: pid 29673: LOG: watchdog: de-escalation started
2020-04-16 17:14:53: pid 29673: LOG: successfully released the delegate IP:"172.17.0.5"
2020-04-16 17:14:53: pid 29673: DETAIL: 'if_down_cmd' returned with success

Can you confirm did you get same behaviour every time you shutdown Pgpool.
Also, can you provide information on how are you running and stoping Pgpool-II. (service or from terminal)

dcvythoulkas

2020-04-21 22:26

reporter   ~0003339

@tito052879 thnx for your effort :)

@Muhammad Usama, I am starting/stopping pgpool-II via systemd.
I am attaching 4 files terminal commands/output and corresponding pgpool.logs. Where I failover the pgpool master. The VIP changes once, and but after that it stays attached on both nodes.

cn2-pgpool.log (20,547 bytes)
cn1-pgpool.log (14,038 bytes)
cn1-terminal.log (7,174 bytes)
cn2-terminal.log (9,269 bytes)

dcvythoulkas

2020-04-23 20:09

reporter   ~0003340

I tried the same configuration (deployed via ansible for consistency) on Debian testing(bullseye) and noticed similar behavior. The attached log is from syslog with pgpool logs combined. The pg2 node is the only pgpool node configured with trusted server. So it achieves quorum by itself.

 If I am not mistaken, it seems as if the watchdog process fails to acknowledge the 'if_up_cmd' ran successfully (it always does) and then completely fails to run the 'if_down_cmd' (which fails 90% of the times).

The pgpool process runs as the 'postgres' OS. The 'postgres' user also sudo permissions on the ip and arping commands. When I run the 'if_up_cmd' and 'if_down_cmd' command from a postgres session, the IP is acquired and released without any problems.

I have attached the syslog and the sudoer file in case there is an issue with the sudo permissions given.

pg2-sudoers (110 bytes)
Cmnd_Alias PGPOOL_UTILS = /sbin/ip, /usr/sbin/arping, /usr/sbin/pg_enc

postgres ALL = NOPASSWD: PGPOOL_UTILS
pg2-sudoers (110 bytes)
bullseye-pg2-syslog (21,695 bytes)
Apr 23 13:19:18 pg2 systemd[1]: Started pgpool-II.
Apr 23 13:19:18 pg2 pgpool[1553]: 2020-04-23 13:19:18: pid 1553: LOG:  Backend status file /var/log/postgresql/pgpool_status discarded
Apr 23 13:19:18 pg2 pgpool[1553]: 2020-04-23 13:19:18: pid 1553: LOCATION:  pgpool_main.c:3749
Apr 23 13:19:18 pg2 pgpool[1553]: 2020-04-23 13:19:18: pid 1553: LOG:  memory cache initialized
Apr 23 13:19:18 pg2 pgpool[1553]: 2020-04-23 13:19:18: pid 1553: DETAIL:  memcache blocks :64
Apr 23 13:19:18 pg2 pgpool[1553]: 2020-04-23 13:19:18: pid 1553: LOCATION:  pool_memqcache.c:1929
Apr 23 13:19:18 pg2 pgpool[1553]: 2020-04-23 13:19:18: pid 1553: LOG:  pool_discard_oid_maps: discarded memqcache oid maps
Apr 23 13:19:18 pg2 pgpool[1553]: 2020-04-23 13:19:18: pid 1553: LOCATION:  pgpool_main.c:3684
Apr 23 13:19:18 pg2 pgpool[1553]: 2020-04-23 13:19:18: pid 1553: LOG:  waiting for watchdog to initialize
Apr 23 13:19:18 pg2 pgpool[1553]: 2020-04-23 13:19:18: pid 1553: LOCATION:  pgpool_main.c:313
Apr 23 13:19:18 pg2 pgpool[1556]: 2020-04-23 13:19:18: pid 1556: LOG:  setting the local watchdog node name to "pg2:5432 Linux pg2"
Apr 23 13:19:18 pg2 pgpool[1556]: 2020-04-23 13:19:18: pid 1556: LOCATION:  watchdog.c:739
Apr 23 13:19:18 pg2 pgpool[1556]: 2020-04-23 13:19:18: pid 1556: LOG:  watchdog cluster is configured with 1 remote nodes
Apr 23 13:19:18 pg2 pgpool[1556]: 2020-04-23 13:19:18: pid 1556: LOCATION:  watchdog.c:747
Apr 23 13:19:18 pg2 pgpool[1556]: 2020-04-23 13:19:18: pid 1556: LOG:  watchdog remote node:0 on pg1:9000
Apr 23 13:19:18 pg2 pgpool[1556]: 2020-04-23 13:19:18: pid 1556: LOCATION:  watchdog.c:760
Apr 23 13:19:18 pg2 pgpool[1556]: 2020-04-23 13:19:18: pid 1556: LOG:  interface monitoring is disabled in watchdog
Apr 23 13:19:18 pg2 pgpool[1556]: 2020-04-23 13:19:18: pid 1556: LOCATION:  watchdog.c:637
Apr 23 13:19:18 pg2 pgpool[1556]: 2020-04-23 13:19:18: pid 1556: LOG:  watchdog node state changed from [DEAD] to [LOADING]
Apr 23 13:19:18 pg2 pgpool[1556]: 2020-04-23 13:19:18: pid 1556: LOCATION:  watchdog.c:6899
Apr 23 13:19:23 pg2 pgpool[1556]: 2020-04-23 13:19:23: pid 1556: LOG:  watchdog node state changed from [LOADING] to [JOINING]
Apr 23 13:19:23 pg2 pgpool[1556]: 2020-04-23 13:19:23: pid 1556: LOCATION:  watchdog.c:6899
Apr 23 13:19:27 pg2 pgpool[1556]: 2020-04-23 13:19:27: pid 1556: LOG:  watchdog node state changed from [JOINING] to [INITIALIZING]
Apr 23 13:19:27 pg2 pgpool[1556]: 2020-04-23 13:19:27: pid 1556: LOCATION:  watchdog.c:6899
Apr 23 13:19:28 pg2 pgpool[1556]: 2020-04-23 13:19:28: pid 1556: LOG:  I am the only alive node in the watchdog cluster
Apr 23 13:19:28 pg2 pgpool[1556]: 2020-04-23 13:19:28: pid 1556: HINT:  skipping stand for coordinator state
Apr 23 13:19:28 pg2 pgpool[1556]: 2020-04-23 13:19:28: pid 1556: LOCATION:  watchdog.c:5522
Apr 23 13:19:28 pg2 pgpool[1556]: 2020-04-23 13:19:28: pid 1556: LOG:  watchdog node state changed from [INITIALIZING] to [MASTER]
Apr 23 13:19:28 pg2 pgpool[1556]: 2020-04-23 13:19:28: pid 1556: LOCATION:  watchdog.c:6899
Apr 23 13:19:28 pg2 pgpool[1556]: 2020-04-23 13:19:28: pid 1556: LOG:  I am announcing my self as master/coordinator watchdog node
Apr 23 13:19:28 pg2 pgpool[1556]: 2020-04-23 13:19:28: pid 1556: LOCATION:  watchdog.c:5715
Apr 23 13:19:32 pg2 pgpool[1556]: 2020-04-23 13:19:32: pid 1556: LOG:  I am the cluster leader node
Apr 23 13:19:32 pg2 pgpool[1556]: 2020-04-23 13:19:32: pid 1556: DETAIL:  our declare coordinator message is accepted by all nodes
Apr 23 13:19:32 pg2 pgpool[1556]: 2020-04-23 13:19:32: pid 1556: LOCATION:  watchdog.c:5750
Apr 23 13:19:32 pg2 pgpool[1556]: 2020-04-23 13:19:32: pid 1556: LOG:  setting the local node "pg2:5432 Linux pg2" as watchdog cluster master
Apr 23 13:19:32 pg2 pgpool[1556]: 2020-04-23 13:19:32: pid 1556: LOCATION:  watchdog.c:7633
Apr 23 13:19:32 pg2 pgpool[1556]: 2020-04-23 13:19:32: pid 1556: LOG:  I am the cluster leader node. Starting escalation process
Apr 23 13:19:32 pg2 pgpool[1556]: 2020-04-23 13:19:32: pid 1556: LOCATION:  watchdog.c:5770
Apr 23 13:19:32 pg2 pgpool[1556]: 2020-04-23 13:19:32: pid 1556: LOG:  escalation process started with PID:1564
Apr 23 13:19:32 pg2 pgpool[1556]: 2020-04-23 13:19:32: pid 1556: LOCATION:  watchdog.c:6426
Apr 23 13:19:32 pg2 pgpool[1564]: 2020-04-23 13:19:32: pid 1564: LOG:  watchdog: escalation started
Apr 23 13:19:32 pg2 pgpool[1564]: 2020-04-23 13:19:32: pid 1564: LOCATION:  wd_escalation.c:92
Apr 23 13:19:32 pg2 pgpool[1553]: 2020-04-23 13:19:32: pid 1553: LOG:  watchdog process is initialized
Apr 23 13:19:32 pg2 pgpool[1553]: 2020-04-23 13:19:32: pid 1553: DETAIL:  watchdog messaging data version: 1.1
Apr 23 13:19:32 pg2 pgpool[1553]: 2020-04-23 13:19:32: pid 1553: LOCATION:  pgpool_main.c:327
Apr 23 13:19:32 pg2 pgpool[1556]: 2020-04-23 13:19:32: pid 1556: LOG:  new IPC connection received
Apr 23 13:19:32 pg2 pgpool[1556]: 2020-04-23 13:19:32: pid 1556: LOCATION:  watchdog.c:3307
Apr 23 13:19:32 pg2 pgpool[1553]: 2020-04-23 13:19:32: pid 1553: LOG:  Setting up socket for 0.0.0.0:5432
Apr 23 13:19:32 pg2 pgpool[1553]: 2020-04-23 13:19:32: pid 1553: LOCATION:  pgpool_main.c:790
Apr 23 13:19:32 pg2 pgpool[1553]: 2020-04-23 13:19:32: pid 1553: LOG:  Setting up socket for :::5432
Apr 23 13:19:32 pg2 pgpool[1553]: 2020-04-23 13:19:32: pid 1553: LOCATION:  pgpool_main.c:790
Apr 23 13:19:32 pg2 pgpool[1556]: 2020-04-23 13:19:32: pid 1556: LOG:  new IPC connection received
Apr 23 13:19:32 pg2 pgpool[1556]: 2020-04-23 13:19:32: pid 1556: LOCATION:  watchdog.c:3307
Apr 23 13:19:32 pg2 pgpool[1566]: 2020-04-23 13:19:32: pid 1566: LOG:  2 watchdog nodes are configured for lifecheck
Apr 23 13:19:32 pg2 pgpool[1566]: 2020-04-23 13:19:32: pid 1566: LOCATION:  wd_lifecheck.c:492
Apr 23 13:19:32 pg2 pgpool[1566]: 2020-04-23 13:19:32: pid 1566: LOG:  watchdog nodes ID:0 Name:"pg2:5432 Linux pg2"
Apr 23 13:19:32 pg2 pgpool[1566]: 2020-04-23 13:19:32: pid 1566: DETAIL:  Host:"pg2" WD Port:9000 pgpool-II port:5432
Apr 23 13:19:32 pg2 pgpool[1566]: 2020-04-23 13:19:32: pid 1566: LOCATION:  wd_lifecheck.c:496
Apr 23 13:19:32 pg2 pgpool[1566]: 2020-04-23 13:19:32: pid 1566: LOG:  watchdog nodes ID:1 Name:"Not_Set"
Apr 23 13:19:32 pg2 pgpool[1566]: 2020-04-23 13:19:32: pid 1566: DETAIL:  Host:"pg1" WD Port:9000 pgpool-II port:5432
Apr 23 13:19:32 pg2 pgpool[1566]: 2020-04-23 13:19:32: pid 1566: LOCATION:  wd_lifecheck.c:496
Apr 23 13:19:32 pg2 pgpool[1566]: 2020-04-23 13:19:32: pid 1566: LOG:  watchdog lifecheck trusted server "10.10.20.1" added for the availability check
Apr 23 13:19:32 pg2 pgpool[1566]: 2020-04-23 13:19:32: pid 1566: LOCATION:  wd_lifecheck.c:1082
Apr 23 13:19:32 pg2 pgpool[1553]: 2020-04-23 13:19:32: pid 1553: LOG:  find_primary_node_repeatedly: waiting for finding a primary node
Apr 23 13:19:32 pg2 pgpool[1553]: 2020-04-23 13:19:32: pid 1553: LOCATION:  pgpool_main.c:3542
Apr 23 13:19:33 pg2 pgpool[1553]: 2020-04-23 13:19:33: pid 1553: LOG:  find_primary_node: primary node is 0
Apr 23 13:19:33 pg2 pgpool[1553]: 2020-04-23 13:19:33: pid 1553: LOCATION:  pgpool_main.c:3476
Apr 23 13:19:33 pg2 pgpool[1553]: 2020-04-23 13:19:33: pid 1553: LOG:  find_primary_node: standby node is 1
Apr 23 13:19:33 pg2 pgpool[1553]: 2020-04-23 13:19:33: pid 1553: LOCATION:  pgpool_main.c:3482
Apr 23 13:19:33 pg2 pgpool[1553]: 2020-04-23 13:19:33: pid 1553: LOG:  pgpool-II successfully started. version 4.1.1 (karasukiboshi)
Apr 23 13:19:33 pg2 pgpool[1553]: 2020-04-23 13:19:33: pid 1553: LOCATION:  pgpool_main.c:470
Apr 23 13:19:33 pg2 pgpool[1553]: 2020-04-23 13:19:33: pid 1553: LOG:  node status[0]: 1
Apr 23 13:19:33 pg2 pgpool[1553]: 2020-04-23 13:19:33: pid 1553: LOCATION:  pgpool_main.c:481
Apr 23 13:19:33 pg2 pgpool[1553]: 2020-04-23 13:19:33: pid 1553: LOG:  node status[1]: 2
Apr 23 13:19:33 pg2 pgpool[1553]: 2020-04-23 13:19:33: pid 1553: LOCATION:  pgpool_main.c:481
Apr 23 13:19:33 pg2 pgpool[1605]: 2020-04-23 13:19:33: pid 1605: LOG:  PCP process: 1605 started
Apr 23 13:19:33 pg2 pgpool[1605]: 2020-04-23 13:19:33: pid 1605: LOCATION:  pcp_child.c:150
Apr 23 13:19:33 pg2 pgpool[1574]: 2020-04-23 13:19:33: pid 1574: LOG:  set SO_REUSEPORT option to the socket
Apr 23 13:19:33 pg2 pgpool[1574]: 2020-04-23 13:19:33: pid 1574: LOCATION:  wd_heartbeat.c:689
Apr 23 13:19:33 pg2 pgpool[1574]: 2020-04-23 13:19:33: pid 1574: LOG:  creating watchdog heartbeat receive socket.
Apr 23 13:19:33 pg2 pgpool[1574]: 2020-04-23 13:19:33: pid 1574: DETAIL:  set SO_REUSEPORT
Apr 23 13:19:33 pg2 pgpool[1574]: 2020-04-23 13:19:33: pid 1574: LOCATION:  wd_heartbeat.c:226
Apr 23 13:19:33 pg2 pgpool[1577]: 2020-04-23 13:19:33: pid 1577: LOG:  set SO_REUSEPORT option to the socket
Apr 23 13:19:33 pg2 pgpool[1577]: 2020-04-23 13:19:33: pid 1577: LOCATION:  wd_heartbeat.c:689
Apr 23 13:19:33 pg2 pgpool[1577]: 2020-04-23 13:19:33: pid 1577: LOG:  creating socket for sending heartbeat
Apr 23 13:19:33 pg2 pgpool[1577]: 2020-04-23 13:19:33: pid 1577: DETAIL:  set SO_REUSEPORT
Apr 23 13:19:33 pg2 pgpool[1577]: 2020-04-23 13:19:33: pid 1577: LOCATION:  wd_heartbeat.c:143
Apr 23 13:19:34 pg2 ntpd[439]: Listen normally on 9 eth1:0 10.10.20.20:123
Apr 23 13:19:34 pg2 ntpd[439]: new interface(s) found: waking up resolver
Apr 23 13:19:34 pg2 pgpool[1564]: 2020-04-23 13:19:34: pid 1564: LOG:  failed to acquire the delegate IP address
Apr 23 13:19:34 pg2 pgpool[1564]: 2020-04-23 13:19:34: pid 1564: DETAIL:  'if_up_cmd' failed
Apr 23 13:19:34 pg2 pgpool[1564]: 2020-04-23 13:19:34: pid 1564: LOCATION:  wd_if.c:182
Apr 23 13:19:34 pg2 pgpool[1564]: 2020-04-23 13:19:34: pid 1564: WARNING:  watchdog escalation failed to acquire delegate IP
Apr 23 13:19:34 pg2 pgpool[1564]: 2020-04-23 13:19:34: pid 1564: LOCATION:  wd_escalation.c:139
Apr 23 13:19:34 pg2 pgpool[1556]: 2020-04-23 13:19:34: pid 1556: LOG:  watchdog escalation process with pid: 1564 exit with SUCCESS.
Apr 23 13:19:34 pg2 pgpool[1556]: 2020-04-23 13:19:34: pid 1556: LOCATION:  watchdog.c:3136
Apr 23 13:20:43 pg2 pgpool[1556]: 2020-04-23 13:20:43: pid 1556: LOG:  Watchdog is shutting down
Apr 23 13:20:43 pg2 pgpool[1556]: 2020-04-23 13:20:43: pid 1556: LOCATION:  watchdog.c:3161
Apr 23 13:20:43 pg2 systemd[1]: Stopping pgpool-II...
Apr 23 13:20:43 pg2 systemd[1]: pgpool2.service: Succeeded.
Apr 23 13:20:43 pg2 systemd[1]: Stopped pgpool-II.
GGG  Apr 23 13:23:47 pg2 repmgrd[492]: node "pg2" (ID: 2) monitoring upstream node "pg1" (ID: 1) in normal state
Apr 23 13:23:48 pg2 ntpd[439]: Deleting interface #9 eth1:0, 10.10.20.20#123, interface stats: received=0, sent=0, dropped=0, active_time=254 secs
Apr 23 13:25:01 pg2 CRON[1830]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Apr 23 13:25:17 pg2 systemd[1]: Started pgpool-II.
Apr 23 13:25:17 pg2 pgpool[1843]: 2020-04-23 13:25:17: pid 1843: LOG:  Backend status file /var/log/postgresql/pgpool_status discarded
Apr 23 13:25:17 pg2 pgpool[1843]: 2020-04-23 13:25:17: pid 1843: LOCATION:  pgpool_main.c:3749
Apr 23 13:25:17 pg2 pgpool[1843]: 2020-04-23 13:25:17: pid 1843: LOG:  memory cache initialized
Apr 23 13:25:17 pg2 pgpool[1843]: 2020-04-23 13:25:17: pid 1843: DETAIL:  memcache blocks :64
Apr 23 13:25:17 pg2 pgpool[1843]: 2020-04-23 13:25:17: pid 1843: LOCATION:  pool_memqcache.c:1929
Apr 23 13:25:17 pg2 pgpool[1843]: 2020-04-23 13:25:17: pid 1843: LOG:  pool_discard_oid_maps: discarded memqcache oid maps
Apr 23 13:25:17 pg2 pgpool[1843]: 2020-04-23 13:25:17: pid 1843: LOCATION:  pgpool_main.c:3684
Apr 23 13:25:17 pg2 pgpool[1843]: 2020-04-23 13:25:17: pid 1843: LOG:  waiting for watchdog to initialize
Apr 23 13:25:17 pg2 pgpool[1843]: 2020-04-23 13:25:17: pid 1843: LOCATION:  pgpool_main.c:313
Apr 23 13:25:17 pg2 pgpool[1846]: 2020-04-23 13:25:17: pid 1846: LOG:  setting the local watchdog node name to "pg2:5432 Linux pg2"
Apr 23 13:25:17 pg2 pgpool[1846]: 2020-04-23 13:25:17: pid 1846: LOCATION:  watchdog.c:739
Apr 23 13:25:17 pg2 pgpool[1846]: 2020-04-23 13:25:17: pid 1846: LOG:  watchdog cluster is configured with 1 remote nodes
Apr 23 13:25:17 pg2 pgpool[1846]: 2020-04-23 13:25:17: pid 1846: LOCATION:  watchdog.c:747
Apr 23 13:25:17 pg2 pgpool[1846]: 2020-04-23 13:25:17: pid 1846: LOG:  watchdog remote node:0 on pg1:9000
Apr 23 13:25:17 pg2 pgpool[1846]: 2020-04-23 13:25:17: pid 1846: LOCATION:  watchdog.c:760
Apr 23 13:25:17 pg2 pgpool[1846]: 2020-04-23 13:25:17: pid 1846: LOG:  interface monitoring is disabled in watchdog
Apr 23 13:25:17 pg2 pgpool[1846]: 2020-04-23 13:25:17: pid 1846: LOCATION:  watchdog.c:637
Apr 23 13:25:17 pg2 pgpool[1846]: 2020-04-23 13:25:17: pid 1846: LOG:  watchdog node state changed from [DEAD] to [LOADING]
Apr 23 13:25:17 pg2 pgpool[1846]: 2020-04-23 13:25:17: pid 1846: LOCATION:  watchdog.c:6899
Apr 23 13:25:22 pg2 pgpool[1846]: 2020-04-23 13:25:22: pid 1846: LOG:  watchdog node state changed from [LOADING] to [JOINING]
Apr 23 13:25:22 pg2 pgpool[1846]: 2020-04-23 13:25:22: pid 1846: LOCATION:  watchdog.c:6899
Apr 23 13:25:26 pg2 pgpool[1846]: 2020-04-23 13:25:26: pid 1846: LOG:  watchdog node state changed from [JOINING] to [INITIALIZING]
Apr 23 13:25:26 pg2 pgpool[1846]: 2020-04-23 13:25:26: pid 1846: LOCATION:  watchdog.c:6899
Apr 23 13:25:27 pg2 pgpool[1846]: 2020-04-23 13:25:27: pid 1846: LOG:  I am the only alive node in the watchdog cluster
Apr 23 13:25:27 pg2 pgpool[1846]: 2020-04-23 13:25:27: pid 1846: HINT:  skipping stand for coordinator state
Apr 23 13:25:27 pg2 pgpool[1846]: 2020-04-23 13:25:27: pid 1846: LOCATION:  watchdog.c:5522
Apr 23 13:25:27 pg2 pgpool[1846]: 2020-04-23 13:25:27: pid 1846: LOG:  watchdog node state changed from [INITIALIZING] to [MASTER]
Apr 23 13:25:27 pg2 pgpool[1846]: 2020-04-23 13:25:27: pid 1846: LOCATION:  watchdog.c:6899
Apr 23 13:25:27 pg2 pgpool[1846]: 2020-04-23 13:25:27: pid 1846: LOG:  I am announcing my self as master/coordinator watchdog node
Apr 23 13:25:27 pg2 pgpool[1846]: 2020-04-23 13:25:27: pid 1846: LOCATION:  watchdog.c:5715
Apr 23 13:25:31 pg2 pgpool[1846]: 2020-04-23 13:25:31: pid 1846: LOG:  I am the cluster leader node
Apr 23 13:25:31 pg2 pgpool[1846]: 2020-04-23 13:25:31: pid 1846: DETAIL:  our declare coordinator message is accepted by all nodes
Apr 23 13:25:31 pg2 pgpool[1846]: 2020-04-23 13:25:31: pid 1846: LOCATION:  watchdog.c:5750
Apr 23 13:25:31 pg2 pgpool[1846]: 2020-04-23 13:25:31: pid 1846: LOG:  setting the local node "pg2:5432 Linux pg2" as watchdog cluster master
Apr 23 13:25:31 pg2 pgpool[1846]: 2020-04-23 13:25:31: pid 1846: LOCATION:  watchdog.c:7633
Apr 23 13:25:31 pg2 pgpool[1846]: 2020-04-23 13:25:31: pid 1846: LOG:  I am the cluster leader node. Starting escalation process
Apr 23 13:25:31 pg2 pgpool[1846]: 2020-04-23 13:25:31: pid 1846: LOCATION:  watchdog.c:5770
Apr 23 13:25:31 pg2 pgpool[1846]: 2020-04-23 13:25:31: pid 1846: LOG:  escalation process started with PID:1853
Apr 23 13:25:31 pg2 pgpool[1846]: 2020-04-23 13:25:31: pid 1846: LOCATION:  watchdog.c:6426
Apr 23 13:25:31 pg2 pgpool[1853]: 2020-04-23 13:25:31: pid 1853: LOG:  watchdog: escalation started
Apr 23 13:25:31 pg2 pgpool[1853]: 2020-04-23 13:25:31: pid 1853: LOCATION:  wd_escalation.c:92
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOG:  watchdog process is initialized
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: DETAIL:  watchdog messaging data version: 1.1
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOCATION:  pgpool_main.c:327
Apr 23 13:25:31 pg2 pgpool[1846]: 2020-04-23 13:25:31: pid 1846: LOG:  new IPC connection received
Apr 23 13:25:31 pg2 pgpool[1846]: 2020-04-23 13:25:31: pid 1846: LOCATION:  watchdog.c:3307
Apr 23 13:25:31 pg2 pgpool[1846]: 2020-04-23 13:25:31: pid 1846: LOG:  new IPC connection received
Apr 23 13:25:31 pg2 pgpool[1846]: 2020-04-23 13:25:31: pid 1846: LOCATION:  watchdog.c:3307
Apr 23 13:25:31 pg2 pgpool[1855]: 2020-04-23 13:25:31: pid 1855: LOG:  2 watchdog nodes are configured for lifecheck
Apr 23 13:25:31 pg2 pgpool[1855]: 2020-04-23 13:25:31: pid 1855: LOCATION:  wd_lifecheck.c:492
Apr 23 13:25:31 pg2 pgpool[1855]: 2020-04-23 13:25:31: pid 1855: LOG:  watchdog nodes ID:0 Name:"pg2:5432 Linux pg2"
Apr 23 13:25:31 pg2 pgpool[1855]: 2020-04-23 13:25:31: pid 1855: DETAIL:  Host:"pg2" WD Port:9000 pgpool-II port:5432
Apr 23 13:25:31 pg2 pgpool[1855]: 2020-04-23 13:25:31: pid 1855: LOCATION:  wd_lifecheck.c:496
Apr 23 13:25:31 pg2 pgpool[1855]: 2020-04-23 13:25:31: pid 1855: LOG:  watchdog nodes ID:1 Name:"Not_Set"
Apr 23 13:25:31 pg2 pgpool[1855]: 2020-04-23 13:25:31: pid 1855: DETAIL:  Host:"pg1" WD Port:9000 pgpool-II port:5432
Apr 23 13:25:31 pg2 pgpool[1855]: 2020-04-23 13:25:31: pid 1855: LOCATION:  wd_lifecheck.c:496
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOG:  Setting up socket for 0.0.0.0:5432
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOCATION:  pgpool_main.c:790
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOG:  Setting up socket for :::5432
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOCATION:  pgpool_main.c:790
Apr 23 13:25:31 pg2 pgpool[1855]: 2020-04-23 13:25:31: pid 1855: LOG:  watchdog lifecheck trusted server "10.10.20.1" added for the availability check
Apr 23 13:25:31 pg2 pgpool[1855]: 2020-04-23 13:25:31: pid 1855: LOCATION:  wd_lifecheck.c:1082
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOG:  find_primary_node_repeatedly: waiting for finding a primary node
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOCATION:  pgpool_main.c:3542
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOG:  find_primary_node: primary node is 0
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOCATION:  pgpool_main.c:3476
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOG:  find_primary_node: standby node is 1
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOCATION:  pgpool_main.c:3482
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOG:  pgpool-II successfully started. version 4.1.1 (karasukiboshi)
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOCATION:  pgpool_main.c:470
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOG:  node status[0]: 1
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOCATION:  pgpool_main.c:481
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOG:  node status[1]: 2
Apr 23 13:25:31 pg2 pgpool[1843]: 2020-04-23 13:25:31: pid 1843: LOCATION:  pgpool_main.c:481
Apr 23 13:25:31 pg2 pgpool[1894]: 2020-04-23 13:25:31: pid 1894: LOG:  PCP process: 1894 started
Apr 23 13:25:31 pg2 pgpool[1894]: 2020-04-23 13:25:31: pid 1894: LOCATION:  pcp_child.c:150
Apr 23 13:25:32 pg2 pgpool[1858]: 2020-04-23 13:25:32: pid 1858: LOG:  set SO_REUSEPORT option to the socket
Apr 23 13:25:32 pg2 pgpool[1858]: 2020-04-23 13:25:32: pid 1858: LOCATION:  wd_heartbeat.c:689
Apr 23 13:25:32 pg2 pgpool[1856]: 2020-04-23 13:25:32: pid 1856: LOG:  set SO_REUSEPORT option to the socket
Apr 23 13:25:32 pg2 pgpool[1856]: 2020-04-23 13:25:32: pid 1856: LOCATION:  wd_heartbeat.c:689
Apr 23 13:25:32 pg2 pgpool[1856]: 2020-04-23 13:25:32: pid 1856: LOG:  creating watchdog heartbeat receive socket.
Apr 23 13:25:32 pg2 pgpool[1856]: 2020-04-23 13:25:32: pid 1856: DETAIL:  set SO_REUSEPORT
Apr 23 13:25:32 pg2 pgpool[1856]: 2020-04-23 13:25:32: pid 1856: LOCATION:  wd_heartbeat.c:226
Apr 23 13:25:32 pg2 pgpool[1858]: 2020-04-23 13:25:32: pid 1858: LOG:  creating socket for sending heartbeat
Apr 23 13:25:32 pg2 pgpool[1858]: 2020-04-23 13:25:32: pid 1858: DETAIL:  set SO_REUSEPORT
Apr 23 13:25:32 pg2 pgpool[1858]: 2020-04-23 13:25:32: pid 1858: LOCATION:  wd_heartbeat.c:143
Apr 23 13:25:32 pg2 pgpool[1853]: 2020-04-23 13:25:32: pid 1853: LOG:  failed to acquire the delegate IP address
Apr 23 13:25:32 pg2 pgpool[1853]: 2020-04-23 13:25:32: pid 1853: DETAIL:  'if_up_cmd' failed
Apr 23 13:25:32 pg2 pgpool[1853]: 2020-04-23 13:25:32: pid 1853: LOCATION:  wd_if.c:182
Apr 23 13:25:32 pg2 pgpool[1853]: 2020-04-23 13:25:32: pid 1853: WARNING:  watchdog escalation failed to acquire delegate IP
Apr 23 13:25:32 pg2 pgpool[1853]: 2020-04-23 13:25:32: pid 1853: LOCATION:  wd_escalation.c:139
Apr 23 13:25:32 pg2 pgpool[1846]: 2020-04-23 13:25:32: pid 1846: LOG:  watchdog escalation process with pid: 1853 exit with SUCCESS.
Apr 23 13:25:32 pg2 pgpool[1846]: 2020-04-23 13:25:32: pid 1846: LOCATION:  watchdog.c:3136
Apr 23 13:25:33 pg2 ntpd[439]: Listen normally on 10 eth1:0 10.10.20.20:123
Apr 23 13:25:33 pg2 ntpd[439]: new interface(s) found: waking up resolver
Apr 23 13:26:59 pg2 pgpool[1846]: 2020-04-23 13:26:59: pid 1846: LOG:  Watchdog is shutting down
Apr 23 13:26:59 pg2 pgpool[1846]: 2020-04-23 13:26:59: pid 1846: LOCATION:  watchdog.c:3161
Apr 23 13:26:59 pg2 systemd[1]: Stopping pgpool-II...
Apr 23 13:26:59 pg2 systemd[1]: pgpool2.service: Succeeded.
Apr 23 13:26:59 pg2 systemd[1]: Stopped pgpool-II.
Apr 23 13:27:36 pg2 ntpd[439]: Deleting interface #10 eth1:0, 10.10.20.20#123, interface stats: received=0, sent=0, dropped=0, active_time=123 secs
Apr 23 13:28:27 pg2 ntpd[439]: Listen normally on 11 eth1:0 10.10.20.20:123
Apr 23 13:28:27 pg2 ntpd[439]: new interface(s) found: waking up resolver
Apr 23 13:28:48 pg2 repmgrd[492]: node "pg2" (ID: 2) monitoring upstream node "pg1" (ID: 1) in normal state
Apr 23 13:32:01 pg2 ntpd[439]: Deleting interface #11 eth1:0, 10.10.20.20#123, interface stats: received=0, sent=0, dropped=0, active_time=214 secs
Apr 23 13:33:49 pg2 repmgrd[492]: node "pg2" (ID: 2) monitoring upstream node "pg1" (ID: 1) in normal state
Apr 23 13:35:01 pg2 CRON[2243]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
bullseye-pg2-syslog (21,695 bytes)

Issue History

Date Modified Username Field Change
2020-03-13 02:11 dcvythoulkas New Issue
2020-03-13 02:11 dcvythoulkas Tag Attached: virtual ip
2020-03-13 02:11 dcvythoulkas Tag Attached: watchdog
2020-03-13 23:31 Muhammad Usama Note Added: 0003269
2020-03-16 20:22 dcvythoulkas File Added: pgpool-cn2.log
2020-03-16 20:22 dcvythoulkas File Added: pgpool-cn1.log
2020-03-16 20:22 dcvythoulkas File Added: pgpool.conf
2020-03-16 20:22 dcvythoulkas Note Added: 0003271
2020-04-10 06:23 tito052879 Note Added: 0003312
2020-04-10 14:15 tito052879 Note Added: 0003313
2020-04-17 02:43 Muhammad Usama Note Added: 0003331
2020-04-21 22:26 dcvythoulkas File Added: cn2-pgpool.log
2020-04-21 22:26 dcvythoulkas File Added: cn1-pgpool.log
2020-04-21 22:26 dcvythoulkas File Added: cn2-terminal.log
2020-04-21 22:26 dcvythoulkas File Added: cn1-terminal.log
2020-04-21 22:26 dcvythoulkas Note Added: 0003339
2020-04-23 20:09 dcvythoulkas File Added: bullseye-pg2-syslog
2020-04-23 20:09 dcvythoulkas File Added: pg2-sudoers
2020-04-23 20:09 dcvythoulkas Note Added: 0003340
2020-05-15 10:43 administrator Assigned To => Muhammad Usama
2020-05-15 10:43 administrator Status new => assigned