View Issue Details

IDProjectCategoryView StatusLast Update
0000576Pgpool-IIBugpublic2020-01-19 11:43
ReporterdcvythoulkasAssigned Tot-ishii 
PrioritynormalSeveritytrivialReproducibilityalways
Status resolvedResolutionopen 
PlatformPostgresql 12OSDebianOS Version10.2
Product Version4.1.0 
Target VersionFixed in Version 
Summary0000576: getsockopt() detected error "Connection refused"
DescriptionI install pgpool-II version 4.1.0 (karasukiboshi) from http://apt.postgresql.org/pub/repos/apt repo. I also install Postgresql 12.
I configured a 3 node streaming replication cluster with physical replication slots (no archiving) and used modified versions of the failover, followmaster, etc, from the example here https://www.pgpool.net/docs/latest/en/html/example-cluster.html#EXAMPLE-CLUSTER-PGPOOL-CONFIG.

The setup works. Replication, healthchecks, watchdog, failover, online recovery, loadbalancing everything I tested (pg_rewind not yet because I am still using the initdb from Debian, so I use the pg_basebackup way).

The only thing I cannot explain is why the following appears in the syslog of all servers. It appears for every server for its own local database:

Jan 16 17:28:42 debian10 pgpool[10477]: 2020-01-16 17:28:42: pid 10523: LOG: failed to connect to PostgreSQL server on "pg2:5433", getsockopt() detected error "Connection refused"
Jan 16 17:28:42 debian10 pgpool[10477]: 2020-01-16 17:28:42: pid 10523: LOCATION: pool_connection_pool.c:680

Both the intervals and the PID mentioned point to the healtheck as the culprit, however healthcheck appears to be working properly and instantly detects any problem that I manually create.

Is it something that I can ignore? Is there something I miss configured?
I have attached the pool_hba.conf (same for everyone) and every pgpool.conf from each node.
Tagslogs, pgpool health check, settings

Activities

dcvythoulkas

2020-01-17 02:50

reporter  

pgpool3.conf (44,432 bytes)
pgpool2.conf (44,432 bytes)
pool_hba.conf (3,413 bytes)
pgpool.conf (44,432 bytes)

t-ishii

2020-01-17 16:35

developer   ~0003067

I guess health check succeeds after some retries because you said the heath check feature seems to be working. I need to confirm this by looking at the health check log in syslog. Can we share the log?

dcvythoulkas

2020-01-17 17:31

reporter   ~0003068

Thanks for the rapid reply. I've attached extracts from syslog and postgresql log of the same time from 1 of the nodes. The whole setup is configured from my custom ansible roles. Equivalent logs exist on the other two nodes. The following is what i think to be the issue from the postgres log. The unknown@unknown login attempt followed by the proper pgpool@postgres

2020-01-17 07:57:11.319 UTC [7980] pg1(55164)[unknown][unknown]@[unknown] LOG: 00000: connection received: host=pg1 port=55164
2020-01-17 07:57:11.319 UTC [7980] pg1(55164)[unknown][unknown]@[unknown] LOCATION: BackendInitialize, postmaster.c:4296
2020-01-17 07:57:11.328 UTC [7980] pg1(55164)[unknown]pgpool@postgres LOG: 00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:11.328 UTC [7980] pg1(55164)[unknown]pgpool@postgres LOCATION: PerformAuthentication, postinit.c:303
2020-01-17 07:57:11.370 UTC [7980] pg1(55164)[unknown]pgpool@postgres LOG: 00000: disconnection: session time: 0:00:00.050 user=pgpool database=postgres host=pg1 port=55164
2020-01-17 07:57:11.370 UTC [7980] pg1(55164)[unknown]pgpool@postgres LOCATION: log_disconnections, postgres.c:4666

pg1_syslog (21,055 bytes)
Jan 17 07:57:01 debian10 systemd[1]: Started pgpool-II.
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7898: LOG:  Backend status file /var/log/postgresql/pgpool_status discarded
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7898: LOCATION:  pgpool_main.c:3747
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7898: LOG:  memory cache initialized
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7898: DETAIL:  memcache blocks :64
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7898: LOCATION:  pool_memqcache.c:1931
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7898: LOG:  pool_discard_oid_maps: discarded memqcache oid maps
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7898: LOCATION:  pgpool_main.c:3682
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7898: LOG:  waiting for watchdog to initialize
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7898: LOCATION:  pgpool_main.c:314
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOG:  setting the local watchdog node name to "pg1:5432 Linux pg1"
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOCATION:  watchdog.c:740
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOG:  watchdog cluster is configured with 2 remote nodes
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOCATION:  watchdog.c:748
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOG:  watchdog remote node:0 on pg2:9000
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOCATION:  watchdog.c:761
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOG:  watchdog remote node:1 on pg3:9000
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOCATION:  watchdog.c:761
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOG:  interface monitoring is disabled in watchdog
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOCATION:  watchdog.c:638
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOG:  watchdog node state changed from [DEAD] to [LOADING]
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOCATION:  watchdog.c:6900
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOG:  new watchdog node connection is received from "10.10.10.12:58594"
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOCATION:  watchdog.c:3273
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOG:  new node joined the cluster hostname:"pg2" port:9000 pgpool_port:5432
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: DETAIL:  Pgpool-II version:"4.1.0" watchdog messaging version: 1.1
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOCATION:  watchdog.c:1594
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOG:  new watchdog node connection is received from "10.10.10.13:11979"
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOCATION:  watchdog.c:3273
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOG:  new node joined the cluster hostname:"pg3" port:9000 pgpool_port:5432
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: DETAIL:  Pgpool-II version:"4.1.0" watchdog messaging version: 1.1
Jan 17 07:57:01 debian10 pgpool[7898]: 2020-01-17 07:57:01: pid 7902: LOCATION:  watchdog.c:1594
Jan 17 07:57:01 debian10 ansible-systemd: Invoked with no_block=False force=None name=postgresql daemon_reexec=False enabled=None daemon_reload=False state=restarted masked=None scope=None user=None
Jan 17 07:57:01 debian10 systemd[1]: postgresql.service: Succeeded.
Jan 17 07:57:01 debian10 systemd[1]: Stopped PostgreSQL RDBMS.
Jan 17 07:57:01 debian10 systemd[1]: Stopping PostgreSQL RDBMS...
Jan 17 07:57:01 debian10 systemd[1]: Stopping PostgreSQL Cluster 12-main...
Jan 17 07:57:01 debian10 systemd[1]: postgresql@12-main.service: Succeeded.
Jan 17 07:57:01 debian10 systemd[1]: Stopped PostgreSQL Cluster 12-main.
Jan 17 07:57:01 debian10 systemd[1]: Starting PostgreSQL Cluster 12-main...
Jan 17 07:57:03 debian10 systemd[1]: Started PostgreSQL Cluster 12-main.
Jan 17 07:57:03 debian10 systemd[1]: Starting PostgreSQL RDBMS...
Jan 17 07:57:03 debian10 systemd[1]: Started PostgreSQL RDBMS.
Jan 17 07:57:06 debian10 pgpool[7898]: 2020-01-17 07:57:06: pid 7902: LOG:  watchdog node state changed from [LOADING] to [JOINING]
Jan 17 07:57:06 debian10 pgpool[7898]: 2020-01-17 07:57:06: pid 7902: LOCATION:  watchdog.c:6900
Jan 17 07:57:06 debian10 pgpool[7898]: 2020-01-17 07:57:06: pid 7902: LOG:  watchdog node state changed from [JOINING] to [INITIALIZING]
Jan 17 07:57:06 debian10 pgpool[7898]: 2020-01-17 07:57:06: pid 7902: LOCATION:  watchdog.c:6900
Jan 17 07:57:07 debian10 pgpool[7898]: 2020-01-17 07:57:07: pid 7902: LOG:  watchdog node state changed from [INITIALIZING] to [STANDING FOR MASTER]
Jan 17 07:57:07 debian10 pgpool[7898]: 2020-01-17 07:57:07: pid 7902: LOCATION:  watchdog.c:6900
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOG:  watchdog node state changed from [STANDING FOR MASTER] to [MASTER]
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOCATION:  watchdog.c:6900
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOG:  I am announcing my self as master/coordinator watchdog node
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOCATION:  watchdog.c:5716
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOG:  I am the cluster leader node
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: DETAIL:  our declare coordinator message is accepted by all nodes
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOCATION:  watchdog.c:5752
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOG:  setting the local node "pg1:5432 Linux pg1" as watchdog cluster master
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOCATION:  watchdog.c:7636
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOG:  I am the cluster leader node but we do not have enough nodes in cluster
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: DETAIL:  waiting for the quorum to start escalation process
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOCATION:  watchdog.c:5766
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOG:  watchdog process is initialized
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: DETAIL:  watchdog messaging data version: 1.1
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOCATION:  pgpool_main.c:329
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOG:  new IPC connection received
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOCATION:  watchdog.c:3308
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOG:  Setting up socket for 0.0.0.0:5432
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOCATION:  pgpool_main.c:791
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOG:  Setting up socket for :::5432
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOCATION:  pgpool_main.c:791
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOG:  new IPC connection received
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7902: LOCATION:  watchdog.c:3308
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7943: LOG:  3 watchdog nodes are configured for lifecheck
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7943: LOCATION:  wd_lifecheck.c:493
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7943: LOG:  watchdog nodes ID:0 Name:"pg1:5432 Linux pg1"
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7943: DETAIL:  Host:"pg1" WD Port:9000 pgpool-II port:5432
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7943: LOCATION:  wd_lifecheck.c:501
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7943: LOG:  watchdog nodes ID:1 Name:"pg2:5432 Linux pg2"
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7943: DETAIL:  Host:"pg2" WD Port:9000 pgpool-II port:5432
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7943: LOCATION:  wd_lifecheck.c:501
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7943: LOG:  watchdog nodes ID:2 Name:"pg3:5432 Linux pg3"
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7943: DETAIL:  Host:"pg3" WD Port:9000 pgpool-II port:5432
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7943: LOCATION:  wd_lifecheck.c:501
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOG:  find_primary_node_repeatedly: waiting for finding a primary node
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOCATION:  pgpool_main.c:3540
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOCATION:  pool_connection_pool.c:680
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOG:  find_primary_node: primary node is 0
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOCATION:  pgpool_main.c:3474
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOG:  find_primary_node: standby node is 1
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOCATION:  pgpool_main.c:3480
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOG:  find_primary_node: standby node is 2
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOCATION:  pgpool_main.c:3480
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7981: LOG:  PCP process: 7981 started
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7981: LOCATION:  pcp_child.c:151
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOG:  pgpool-II successfully started. version 4.1.0 (karasukiboshi)
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOCATION:  pgpool_main.c:471
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOG:  node status[0]: 1
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOCATION:  pgpool_main.c:482
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOG:  node status[1]: 2
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOCATION:  pgpool_main.c:482
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOG:  node status[2]: 2
Jan 17 07:57:11 debian10 pgpool[7898]: 2020-01-17 07:57:11: pid 7898: LOCATION:  pgpool_main.c:482
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOG:  adding watchdog node "pg3:5432 Linux pg3" to the standby list
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOCATION:  watchdog.c:7666
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOG:  quorum found
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: DETAIL:  starting escalation process
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOCATION:  watchdog.c:5846
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOG:  escalation process started with PID:7987
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOCATION:  watchdog.c:6427
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7898: LOG:  Pgpool-II parent process received watchdog quorum change signal from watchdog
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7898: LOCATION:  pgpool_main.c:1554
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7987: LOG:  watchdog: escalation started
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7987: LOCATION:  wd_escalation.c:93
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOG:  new IPC connection received
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOCATION:  watchdog.c:3308
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOG:  new outbound connection to pg2:9000
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOCATION:  watchdog.c:3352
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOG:  new outbound connection to pg3:9000
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOCATION:  watchdog.c:3352
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOG:  adding watchdog node "pg2:5432 Linux pg2" to the standby list
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOCATION:  watchdog.c:7666
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7898: LOG:  watchdog cluster now holds the quorum
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7898: DETAIL:  updating the state of quarantine backend nodes
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7898: LOCATION:  pgpool_main.c:1561
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOG:  new IPC connection received
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7902: LOCATION:  watchdog.c:3308
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7977: LOG:  set SO_REUSEPORT option to the socket
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7977: LOCATION:  wd_heartbeat.c:690
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7977: LOG:  creating socket for sending heartbeat
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7977: DETAIL:  set SO_REUSEPORT
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7977: LOCATION:  wd_heartbeat.c:145
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7978: LOG:  set SO_REUSEPORT option to the socket
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7978: LOCATION:  wd_heartbeat.c:690
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7978: LOG:  creating watchdog heartbeat receive socket.
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7978: DETAIL:  set SO_REUSEPORT
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7978: LOCATION:  wd_heartbeat.c:228
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7979: LOG:  set SO_REUSEPORT option to the socket
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7979: LOCATION:  wd_heartbeat.c:690
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7979: LOG:  creating socket for sending heartbeat
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7979: DETAIL:  set SO_REUSEPORT
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7979: LOCATION:  wd_heartbeat.c:145
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7976: LOG:  set SO_REUSEPORT option to the socket
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7976: LOCATION:  wd_heartbeat.c:690
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7976: LOG:  creating watchdog heartbeat receive socket.
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7976: DETAIL:  set SO_REUSEPORT
Jan 17 07:57:12 debian10 pgpool[7898]: 2020-01-17 07:57:12: pid 7976: LOCATION:  wd_heartbeat.c:228
Jan 17 07:57:13 debian10 pgpool[7898]: 2020-01-17 07:57:13: pid 7987: LOG:  failed to acquire the delegate IP address
Jan 17 07:57:13 debian10 pgpool[7898]: 2020-01-17 07:57:13: pid 7987: DETAIL:  'if_up_cmd' failed
Jan 17 07:57:13 debian10 pgpool[7898]: 2020-01-17 07:57:13: pid 7987: LOCATION:  wd_if.c:184
Jan 17 07:57:13 debian10 pgpool[7898]: 2020-01-17 07:57:13: pid 7987: WARNING:  watchdog escalation failed to acquire delegate IP
Jan 17 07:57:13 debian10 pgpool[7898]: 2020-01-17 07:57:13: pid 7987: LOCATION:  wd_escalation.c:140
Jan 17 07:57:13 debian10 pgpool[7898]: 2020-01-17 07:57:13: pid 7902: LOG:  watchdog escalation process with pid: 7987 exit with SUCCESS.
Jan 17 07:57:13 debian10 pgpool[7898]: 2020-01-17 07:57:13: pid 7902: LOCATION:  watchdog.c:3137
Jan 17 07:57:16 debian10 pgpool[7898]: 2020-01-17 07:57:16: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:57:16 debian10 pgpool[7898]: 2020-01-17 07:57:16: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:57:21 debian10 pgpool[7898]: 2020-01-17 07:57:21: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:57:21 debian10 pgpool[7898]: 2020-01-17 07:57:21: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:57:26 debian10 pgpool[7898]: 2020-01-17 07:57:26: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:57:26 debian10 pgpool[7898]: 2020-01-17 07:57:26: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:57:31 debian10 pgpool[7898]: 2020-01-17 07:57:31: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:57:31 debian10 pgpool[7898]: 2020-01-17 07:57:31: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:57:36 debian10 pgpool[7898]: 2020-01-17 07:57:36: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:57:36 debian10 pgpool[7898]: 2020-01-17 07:57:36: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:57:41 debian10 pgpool[7898]: 2020-01-17 07:57:41: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:57:41 debian10 pgpool[7898]: 2020-01-17 07:57:41: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:57:46 debian10 pgpool[7898]: 2020-01-17 07:57:46: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:57:46 debian10 pgpool[7898]: 2020-01-17 07:57:46: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:57:51 debian10 pgpool[7898]: 2020-01-17 07:57:51: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:57:51 debian10 pgpool[7898]: 2020-01-17 07:57:51: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:57:56 debian10 pgpool[7898]: 2020-01-17 07:57:56: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:57:56 debian10 pgpool[7898]: 2020-01-17 07:57:56: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:58:01 debian10 pgpool[7898]: 2020-01-17 07:58:01: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:58:01 debian10 pgpool[7898]: 2020-01-17 07:58:01: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:58:04 debian10 systemd[1]: session-10.scope: Succeeded.
Jan 17 07:58:06 debian10 pgpool[7898]: 2020-01-17 07:58:06: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:58:06 debian10 pgpool[7898]: 2020-01-17 07:58:06: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:58:11 debian10 pgpool[7898]: 2020-01-17 07:58:11: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:58:11 debian10 pgpool[7898]: 2020-01-17 07:58:11: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:58:16 debian10 pgpool[7898]: 2020-01-17 07:58:16: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:58:16 debian10 pgpool[7898]: 2020-01-17 07:58:16: pid 7983: LOCATION:  pool_connection_pool.c:680
Jan 17 07:58:21 debian10 pgpool[7898]: 2020-01-17 07:58:21: pid 7983: LOG:  failed to connect to PostgreSQL server on "pg1:5433", getsockopt() detected error "Connection refused"
Jan 17 07:58:21 debian10 pgpool[7898]: 2020-01-17 07:58:21: pid 7983: LOCATION:  pool_connection_pool.c:680
pg1_syslog (21,055 bytes)
pg1_postgres_log (41,923 bytes)
2020-01-17 07:57:01.739 UTC [7921] LOG:  00000: starting PostgreSQL 12.1 (Debian 12.1-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit
2020-01-17 07:57:01.739 UTC [7921] LOCATION:  PostmasterMain, postmaster.c:998
2020-01-17 07:57:01.739 UTC [7921] LOG:  00000: listening on IPv4 address "127.0.0.1", port 5433
2020-01-17 07:57:01.739 UTC [7921] LOCATION:  StreamServerPort, pqcomm.c:593
2020-01-17 07:57:01.740 UTC [7921] LOG:  XX000: could not bind IPv6 address "::1": Cannot assign requested address
2020-01-17 07:57:01.740 UTC [7921] HINT:  Is another postmaster already running on port 5433? If not, wait a few seconds and retry.
2020-01-17 07:57:01.740 UTC [7921] LOCATION:  StreamServerPort, pqcomm.c:546
2020-01-17 07:57:01.741 UTC [7921] LOG:  00000: listening on IPv4 address "10.10.10.11", port 5433
2020-01-17 07:57:01.741 UTC [7921] LOCATION:  StreamServerPort, pqcomm.c:593
2020-01-17 07:57:01.741 UTC [7921] LOG:  00000: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5433"
2020-01-17 07:57:01.741 UTC [7921] LOCATION:  StreamServerPort, pqcomm.c:587
2020-01-17 07:57:01.754 UTC [7922] LOG:  00000: database system was shut down at 2020-01-17 07:57:01 UTC
2020-01-17 07:57:01.754 UTC [7922] LOCATION:  StartupXLOG, xlog.c:6244
2020-01-17 07:57:01.759 UTC [7921] LOG:  00000: database system is ready to accept connections
2020-01-17 07:57:01.759 UTC [7921] LOCATION:  reaper, postmaster.c:2995
2020-01-17 07:57:01.762 UTC [7929] pg3(43354)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43354
2020-01-17 07:57:01.762 UTC [7929] pg3(43354)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:01.768 UTC [7930] pg2(43294)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43294
2020-01-17 07:57:01.768 UTC [7930] pg2(43294)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:01.771 UTC [7929] pg3(43354)[unknown]repuser@[unknown] LOG:  00000: replication connection authorized: user=repuser application_name=12/main SSL enabled (protocol=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384, bits=256, compression=off)
2020-01-17 07:57:01.771 UTC [7929] pg3(43354)[unknown]repuser@[unknown] LOCATION:  PerformAuthentication, postinit.c:267
2020-01-17 07:57:01.777 UTC [7930] pg2(43294)[unknown]repuser@[unknown] LOG:  00000: replication connection authorized: user=repuser application_name=12/main SSL enabled (protocol=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384, bits=256, compression=off)
2020-01-17 07:57:01.777 UTC [7930] pg2(43294)[unknown]repuser@[unknown] LOCATION:  PerformAuthentication, postinit.c:267
2020-01-17 07:57:02.333 UTC [7931] [local][unknown][unknown]@[unknown] LOG:  00000: connection received: host=[local]
2020-01-17 07:57:02.333 UTC [7931] [local][unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4300
2020-01-17 07:57:02.856 UTC [7934] [local][unknown][unknown]@[unknown] LOG:  00000: connection received: host=[local]
2020-01-17 07:57:02.856 UTC [7934] [local][unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4300
2020-01-17 07:57:02.857 UTC [7934] [local][unknown]postgres@template1 LOG:  00000: connection authorized: user=postgres database=template1 application_name=psql
2020-01-17 07:57:02.857 UTC [7934] [local][unknown]postgres@template1 LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:02.870 UTC [7934] [local]psqlpostgres@template1 LOG:  00000: disconnection: session time: 0:00:00.015 user=postgres database=template1 host=[local]
2020-01-17 07:57:02.870 UTC [7934] [local]psqlpostgres@template1 LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:03.401 UTC [7937] [local][unknown][unknown]@[unknown] LOG:  00000: connection received: host=[local]
2020-01-17 07:57:03.401 UTC [7937] [local][unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4300
2020-01-17 07:57:03.403 UTC [7937] [local][unknown]postgres@template1 LOG:  00000: connection authorized: user=postgres database=template1 application_name=psql
2020-01-17 07:57:03.403 UTC [7937] [local][unknown]postgres@template1 LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:03.407 UTC [7937] [local]psqlpostgres@template1 LOG:  00000: disconnection: session time: 0:00:00.006 user=postgres database=template1 host=[local]
2020-01-17 07:57:03.407 UTC [7937] [local]psqlpostgres@template1 LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:03.933 UTC [7940] [local][unknown][unknown]@[unknown] LOG:  00000: connection received: host=[local]
2020-01-17 07:57:03.933 UTC [7940] [local][unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4300
2020-01-17 07:57:03.936 UTC [7940] [local][unknown]postgres@template1 LOG:  00000: connection authorized: user=postgres database=template1 application_name=psql
2020-01-17 07:57:03.936 UTC [7940] [local][unknown]postgres@template1 LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:03.939 UTC [7940] [local]psqlpostgres@template1 LOG:  00000: disconnection: session time: 0:00:00.006 user=postgres database=template1 host=[local]
2020-01-17 07:57:03.939 UTC [7940] [local]psqlpostgres@template1 LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:11.319 UTC [7980] pg1(55164)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55164
2020-01-17 07:57:11.319 UTC [7980] pg1(55164)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:11.328 UTC [7980] pg1(55164)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:11.328 UTC [7980] pg1(55164)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:11.370 UTC [7980] pg1(55164)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.050 user=pgpool database=postgres host=pg1 port=55164
2020-01-17 07:57:11.370 UTC [7980] pg1(55164)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:11.380 UTC [7986] pg1(55174)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55174
2020-01-17 07:57:11.380 UTC [7986] pg1(55174)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:11.387 UTC [7986] pg1(55174)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:11.387 UTC [7986] pg1(55174)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:11.388 UTC [7986] pg1(55174)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.007 user=pgpool database=postgres host=pg1 port=55174
2020-01-17 07:57:11.388 UTC [7986] pg1(55174)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:12.348 UTC [7991] pg3(43358)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43358
2020-01-17 07:57:12.348 UTC [7991] pg3(43358)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:12.357 UTC [7993] pg2(43300)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43300
2020-01-17 07:57:12.357 UTC [7993] pg2(43300)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:12.365 UTC [7991] pg3(43358)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:12.365 UTC [7991] pg3(43358)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:12.366 UTC [7991] pg3(43358)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.018 user=pgpool database=postgres host=pg3 port=43358
2020-01-17 07:57:12.366 UTC [7991] pg3(43358)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:12.367 UTC [7993] pg2(43300)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:12.367 UTC [7993] pg2(43300)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:12.373 UTC [7993] pg2(43300)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.016 user=pgpool database=postgres host=pg2 port=43300
2020-01-17 07:57:12.373 UTC [7993] pg2(43300)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:16.398 UTC [7994] pg1(55184)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55184
2020-01-17 07:57:16.398 UTC [7994] pg1(55184)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:16.406 UTC [7994] pg1(55184)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:16.406 UTC [7994] pg1(55184)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:16.407 UTC [7994] pg1(55184)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.010 user=pgpool database=postgres host=pg1 port=55184
2020-01-17 07:57:16.407 UTC [7994] pg1(55184)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:17.370 UTC [7995] pg3(43370)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43370
2020-01-17 07:57:17.370 UTC [7995] pg3(43370)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:17.376 UTC [7996] pg2(43306)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43306
2020-01-17 07:57:17.376 UTC [7996] pg2(43306)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:17.382 UTC [7995] pg3(43370)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:17.382 UTC [7995] pg3(43370)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:17.383 UTC [7995] pg3(43370)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.013 user=pgpool database=postgres host=pg3 port=43370
2020-01-17 07:57:17.383 UTC [7995] pg3(43370)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:17.384 UTC [7996] pg2(43306)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:17.384 UTC [7996] pg2(43306)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:17.389 UTC [7996] pg2(43306)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.014 user=pgpool database=postgres host=pg2 port=43306
2020-01-17 07:57:17.389 UTC [7996] pg2(43306)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:21.416 UTC [7997] pg1(55192)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55192
2020-01-17 07:57:21.416 UTC [7997] pg1(55192)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:21.440 UTC [7997] pg1(55192)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:21.440 UTC [7997] pg1(55192)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:21.442 UTC [7997] pg1(55192)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.027 user=pgpool database=postgres host=pg1 port=55192
2020-01-17 07:57:21.442 UTC [7997] pg1(55192)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:22.390 UTC [7998] pg3(43378)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43378
2020-01-17 07:57:22.390 UTC [7998] pg3(43378)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:22.395 UTC [7999] pg2(43314)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43314
2020-01-17 07:57:22.395 UTC [7999] pg2(43314)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:22.424 UTC [7998] pg3(43378)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:22.424 UTC [7998] pg3(43378)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:22.426 UTC [7999] pg2(43314)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:22.426 UTC [7999] pg2(43314)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:22.427 UTC [7998] pg3(43378)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.039 user=pgpool database=postgres host=pg3 port=43378
2020-01-17 07:57:22.427 UTC [7998] pg3(43378)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:22.429 UTC [7999] pg2(43314)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.034 user=pgpool database=postgres host=pg2 port=43314
2020-01-17 07:57:22.429 UTC [7999] pg2(43314)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:26.449 UTC [8000] pg1(55200)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55200
2020-01-17 07:57:26.449 UTC [8000] pg1(55200)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:26.484 UTC [8000] pg1(55200)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:26.484 UTC [8000] pg1(55200)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:26.485 UTC [8000] pg1(55200)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.037 user=pgpool database=postgres host=pg1 port=55200
2020-01-17 07:57:26.485 UTC [8000] pg1(55200)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:27.433 UTC [8001] pg3(43386)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43386
2020-01-17 07:57:27.433 UTC [8001] pg3(43386)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:27.437 UTC [8002] pg2(43328)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43328
2020-01-17 07:57:27.437 UTC [8002] pg2(43328)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:27.466 UTC [8001] pg3(43386)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:27.466 UTC [8001] pg3(43386)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:27.467 UTC [8002] pg2(43328)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:27.467 UTC [8002] pg2(43328)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:27.468 UTC [8001] pg3(43386)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.035 user=pgpool database=postgres host=pg3 port=43386
2020-01-17 07:57:27.468 UTC [8001] pg3(43386)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:27.469 UTC [8002] pg2(43328)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.033 user=pgpool database=postgres host=pg2 port=43328
2020-01-17 07:57:27.469 UTC [8002] pg2(43328)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:31.497 UTC [8003] pg1(55210)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55210
2020-01-17 07:57:31.497 UTC [8003] pg1(55210)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:31.531 UTC [8003] pg1(55210)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:31.531 UTC [8003] pg1(55210)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:31.532 UTC [8003] pg1(55210)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.035 user=pgpool database=postgres host=pg1 port=55210
2020-01-17 07:57:31.532 UTC [8003] pg1(55210)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:32.471 UTC [8005] pg3(43392)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43392
2020-01-17 07:57:32.471 UTC [8005] pg3(43392)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:32.479 UTC [8006] pg2(43336)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43336
2020-01-17 07:57:32.479 UTC [8006] pg2(43336)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:32.500 UTC [8005] pg3(43392)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:32.500 UTC [8005] pg3(43392)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:32.501 UTC [8005] pg3(43392)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.031 user=pgpool database=postgres host=pg3 port=43392
2020-01-17 07:57:32.501 UTC [8005] pg3(43392)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:32.504 UTC [8006] pg2(43336)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:32.504 UTC [8006] pg2(43336)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:32.507 UTC [8006] pg2(43336)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.030 user=pgpool database=postgres host=pg2 port=43336
2020-01-17 07:57:32.507 UTC [8006] pg2(43336)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:36.535 UTC [8007] pg1(55220)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55220
2020-01-17 07:57:36.535 UTC [8007] pg1(55220)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:36.541 UTC [8007] pg1(55220)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:36.541 UTC [8007] pg1(55220)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:36.542 UTC [8007] pg1(55220)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.007 user=pgpool database=postgres host=pg1 port=55220
2020-01-17 07:57:36.542 UTC [8007] pg1(55220)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:37.506 UTC [8008] pg3(43400)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43400
2020-01-17 07:57:37.506 UTC [8008] pg3(43400)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:37.510 UTC [8009] pg2(43342)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43342
2020-01-17 07:57:37.510 UTC [8009] pg2(43342)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:37.519 UTC [8008] pg3(43400)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:37.519 UTC [8008] pg3(43400)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:37.520 UTC [8008] pg3(43400)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.014 user=pgpool database=postgres host=pg3 port=43400
2020-01-17 07:57:37.520 UTC [8008] pg3(43400)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:37.523 UTC [8009] pg2(43342)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:37.523 UTC [8009] pg2(43342)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:37.526 UTC [8009] pg2(43342)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.015 user=pgpool database=postgres host=pg2 port=43342
2020-01-17 07:57:37.526 UTC [8009] pg2(43342)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:41.550 UTC [8010] pg1(55226)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55226
2020-01-17 07:57:41.550 UTC [8010] pg1(55226)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:41.562 UTC [8010] pg1(55226)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:41.562 UTC [8010] pg1(55226)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:41.563 UTC [8010] pg1(55226)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.014 user=pgpool database=postgres host=pg1 port=55226
2020-01-17 07:57:41.563 UTC [8010] pg1(55226)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:42.523 UTC [8011] pg3(43404)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43404
2020-01-17 07:57:42.523 UTC [8011] pg3(43404)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:42.531 UTC [8012] pg2(43350)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43350
2020-01-17 07:57:42.531 UTC [8012] pg2(43350)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:42.535 UTC [8011] pg3(43404)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:42.535 UTC [8011] pg3(43404)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:42.536 UTC [8011] pg3(43404)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.014 user=pgpool database=postgres host=pg3 port=43404
2020-01-17 07:57:42.536 UTC [8011] pg3(43404)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:42.543 UTC [8012] pg2(43350)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:42.543 UTC [8012] pg2(43350)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:42.544 UTC [8012] pg2(43350)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.012 user=pgpool database=postgres host=pg2 port=43350
2020-01-17 07:57:42.544 UTC [8012] pg2(43350)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:46.565 UTC [8013] pg1(55234)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55234
2020-01-17 07:57:46.565 UTC [8013] pg1(55234)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:46.579 UTC [8013] pg1(55234)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:46.579 UTC [8013] pg1(55234)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:46.580 UTC [8013] pg1(55234)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.015 user=pgpool database=postgres host=pg1 port=55234
2020-01-17 07:57:46.580 UTC [8013] pg1(55234)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:47.540 UTC [8014] pg3(43412)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43412
2020-01-17 07:57:47.540 UTC [8014] pg3(43412)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:47.549 UTC [8015] pg2(43358)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43358
2020-01-17 07:57:47.549 UTC [8015] pg2(43358)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:47.581 UTC [8014] pg3(43412)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:47.581 UTC [8014] pg3(43412)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:47.582 UTC [8015] pg2(43358)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:47.582 UTC [8015] pg2(43358)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:47.583 UTC [8015] pg2(43358)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.034 user=pgpool database=postgres host=pg2 port=43358
2020-01-17 07:57:47.583 UTC [8015] pg2(43358)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:47.585 UTC [8014] pg3(43412)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.045 user=pgpool database=postgres host=pg3 port=43412
2020-01-17 07:57:47.585 UTC [8014] pg3(43412)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:51.583 UTC [8016] pg1(55240)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55240
2020-01-17 07:57:51.583 UTC [8016] pg1(55240)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:51.596 UTC [8016] pg1(55240)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:51.596 UTC [8016] pg1(55240)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:51.597 UTC [8016] pg1(55240)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.014 user=pgpool database=postgres host=pg1 port=55240
2020-01-17 07:57:51.597 UTC [8016] pg1(55240)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:52.588 UTC [8017] pg2(43366)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43366
2020-01-17 07:57:52.588 UTC [8017] pg2(43366)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:52.588 UTC [8018] pg3(43424)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43424
2020-01-17 07:57:52.588 UTC [8018] pg3(43424)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:52.595 UTC [8018] pg3(43424)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:52.595 UTC [8018] pg3(43424)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:52.595 UTC [8017] pg2(43366)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:52.595 UTC [8017] pg2(43366)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:52.600 UTC [8018] pg3(43424)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.013 user=pgpool database=postgres host=pg3 port=43424
2020-01-17 07:57:52.600 UTC [8018] pg3(43424)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:52.600 UTC [8017] pg2(43366)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.013 user=pgpool database=postgres host=pg2 port=43366
2020-01-17 07:57:52.600 UTC [8017] pg2(43366)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:56.601 UTC [8019] pg1(55252)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55252
2020-01-17 07:57:56.601 UTC [8019] pg1(55252)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:56.635 UTC [8019] pg1(55252)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:56.635 UTC [8019] pg1(55252)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:56.636 UTC [8019] pg1(55252)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.037 user=pgpool database=postgres host=pg1 port=55252
2020-01-17 07:57:56.636 UTC [8019] pg1(55252)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:57.599 UTC [8020] pg3(43428)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43428
2020-01-17 07:57:57.599 UTC [8020] pg3(43428)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:57.603 UTC [8021] pg2(43370)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43370
2020-01-17 07:57:57.603 UTC [8021] pg2(43370)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:57:57.638 UTC [8020] pg3(43428)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:57.638 UTC [8020] pg3(43428)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:57.640 UTC [8021] pg2(43370)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:57:57.640 UTC [8021] pg2(43370)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:57:57.641 UTC [8020] pg3(43428)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.042 user=pgpool database=postgres host=pg3 port=43428
2020-01-17 07:57:57.641 UTC [8020] pg3(43428)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:57:57.642 UTC [8021] pg2(43370)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.039 user=pgpool database=postgres host=pg2 port=43370
2020-01-17 07:57:57.642 UTC [8021] pg2(43370)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:01.641 UTC [8022] pg1(55260)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55260
2020-01-17 07:58:01.641 UTC [8022] pg1(55260)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:01.648 UTC [8022] pg1(55260)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:01.648 UTC [8022] pg1(55260)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:01.649 UTC [8022] pg1(55260)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.008 user=pgpool database=postgres host=pg1 port=55260
2020-01-17 07:58:01.649 UTC [8022] pg1(55260)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:02.644 UTC [8024] pg3(43436)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43436
2020-01-17 07:58:02.644 UTC [8024] pg3(43436)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:02.649 UTC [8025] pg2(43384)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43384
2020-01-17 07:58:02.649 UTC [8025] pg2(43384)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:02.654 UTC [8024] pg3(43436)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:02.654 UTC [8024] pg3(43436)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:02.655 UTC [8024] pg3(43436)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.011 user=pgpool database=postgres host=pg3 port=43436
2020-01-17 07:58:02.655 UTC [8024] pg3(43436)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:02.665 UTC [8025] pg2(43384)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:02.665 UTC [8025] pg2(43384)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:02.666 UTC [8025] pg2(43384)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.016 user=pgpool database=postgres host=pg2 port=43384
2020-01-17 07:58:02.666 UTC [8025] pg2(43384)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:06.653 UTC [8026] pg1(55264)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55264
2020-01-17 07:58:06.653 UTC [8026] pg1(55264)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:06.662 UTC [8026] pg1(55264)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:06.662 UTC [8026] pg1(55264)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:06.663 UTC [8026] pg1(55264)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.010 user=pgpool database=postgres host=pg1 port=55264
2020-01-17 07:58:06.663 UTC [8026] pg1(55264)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:07.660 UTC [8027] pg3(43444)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43444
2020-01-17 07:58:07.660 UTC [8027] pg3(43444)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:07.667 UTC [8028] pg2(43390)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43390
2020-01-17 07:58:07.667 UTC [8028] pg2(43390)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:07.668 UTC [8027] pg3(43444)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:07.668 UTC [8027] pg3(43444)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:07.669 UTC [8027] pg3(43444)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.009 user=pgpool database=postgres host=pg3 port=43444
2020-01-17 07:58:07.669 UTC [8027] pg3(43444)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:07.676 UTC [8028] pg2(43390)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:07.676 UTC [8028] pg2(43390)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:07.677 UTC [8028] pg2(43390)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.010 user=pgpool database=postgres host=pg2 port=43390
2020-01-17 07:58:07.677 UTC [8028] pg2(43390)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:11.665 UTC [8034] pg1(55272)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55272
2020-01-17 07:58:11.665 UTC [8034] pg1(55272)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:11.675 UTC [8034] pg1(55272)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:11.675 UTC [8034] pg1(55272)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:11.680 UTC [8034] pg1(55272)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.015 user=pgpool database=postgres host=pg1 port=55272
2020-01-17 07:58:11.680 UTC [8034] pg1(55272)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:12.673 UTC [8040] pg3(43452)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43452
2020-01-17 07:58:12.673 UTC [8040] pg3(43452)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:12.680 UTC [8041] pg2(43400)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43400
2020-01-17 07:58:12.680 UTC [8041] pg2(43400)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:12.685 UTC [8040] pg3(43452)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:12.685 UTC [8040] pg3(43452)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:12.686 UTC [8040] pg3(43452)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.014 user=pgpool database=postgres host=pg3 port=43452
2020-01-17 07:58:12.686 UTC [8040] pg3(43452)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:12.692 UTC [8041] pg2(43400)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:12.692 UTC [8041] pg2(43400)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:12.693 UTC [8041] pg2(43400)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.012 user=pgpool database=postgres host=pg2 port=43400
2020-01-17 07:58:12.693 UTC [8041] pg2(43400)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:16.685 UTC [8049] pg1(55282)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55282
2020-01-17 07:58:16.685 UTC [8049] pg1(55282)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:16.697 UTC [8049] pg1(55282)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:16.697 UTC [8049] pg1(55282)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:16.698 UTC [8049] pg1(55282)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.014 user=pgpool database=postgres host=pg1 port=55282
2020-01-17 07:58:16.698 UTC [8049] pg1(55282)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:17.690 UTC [8050] pg3(43460)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43460
2020-01-17 07:58:17.690 UTC [8050] pg3(43460)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:17.697 UTC [8051] pg2(43402)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43402
2020-01-17 07:58:17.697 UTC [8051] pg2(43402)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:17.699 UTC [8050] pg3(43460)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:17.699 UTC [8050] pg3(43460)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:17.700 UTC [8050] pg3(43460)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.010 user=pgpool database=postgres host=pg3 port=43460
2020-01-17 07:58:17.700 UTC [8050] pg3(43460)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:17.706 UTC [8051] pg2(43402)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:17.706 UTC [8051] pg2(43402)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:17.707 UTC [8051] pg2(43402)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.010 user=pgpool database=postgres host=pg2 port=43402
2020-01-17 07:58:17.707 UTC [8051] pg2(43402)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:21.704 UTC [8052] pg1(55292)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg1 port=55292
2020-01-17 07:58:21.704 UTC [8052] pg1(55292)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:21.714 UTC [8052] pg1(55292)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:21.714 UTC [8052] pg1(55292)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:21.715 UTC [8052] pg1(55292)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.010 user=pgpool database=postgres host=pg1 port=55292
2020-01-17 07:58:21.715 UTC [8052] pg1(55292)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:22.704 UTC [8053] pg3(43468)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg3 port=43468
2020-01-17 07:58:22.704 UTC [8053] pg3(43468)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:22.714 UTC [8053] pg3(43468)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:22.714 UTC [8053] pg3(43468)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:22.715 UTC [8053] pg3(43468)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.011 user=pgpool database=postgres host=pg3 port=43468
2020-01-17 07:58:22.715 UTC [8053] pg3(43468)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
2020-01-17 07:58:22.718 UTC [8054] pg2(43414)[unknown][unknown]@[unknown] LOG:  00000: connection received: host=pg2 port=43414
2020-01-17 07:58:22.718 UTC [8054] pg2(43414)[unknown][unknown]@[unknown] LOCATION:  BackendInitialize, postmaster.c:4296
2020-01-17 07:58:22.730 UTC [8054] pg2(43414)[unknown]pgpool@postgres LOG:  00000: connection authorized: user=pgpool database=postgres
2020-01-17 07:58:22.730 UTC [8054] pg2(43414)[unknown]pgpool@postgres LOCATION:  PerformAuthentication, postinit.c:303
2020-01-17 07:58:22.733 UTC [8054] pg2(43414)[unknown]pgpool@postgres LOG:  00000: disconnection: session time: 0:00:00.015 user=pgpool database=postgres host=pg2 port=43414
2020-01-17 07:58:22.733 UTC [8054] pg2(43414)[unknown]pgpool@postgres LOCATION:  log_disconnections, postgres.c:4666
pg1_postgres_log (41,923 bytes)

t-ishii

2020-01-18 07:12

developer   ~0003069

I looked into pg1syslog and found a strange thing. It seems pgpool's health check process behaves as if it successfully connected to backend despite the getsockopt() error. Moreover, PostgreSQL backend accept the connection from health check process and does the authentication negotiation. I expected health check retry after getsockopt() error in this situation, and is also expected from the source code.
Is it possible that in your debian package the source code is modified? Especially I suspect this(src/protocol/pool_connection_pool.c line 676):
                    /* Non Solaris case */
                    if (error != 0)
                    {
                        ereport(LOG,
                                (errmsg("failed to connect to PostgreSQL server on \"%s:%d\", getsockopt() detected error \"%s\"", host, port, strerror(error))));
                        return false; <--- maybe replaced with "return true;"?
                    }

dcvythoulkas

2020-01-18 07:47

reporter   ~0003070

If you check the pg1_postres_log you will that PostgreSQL did actually accepted a login connection, so healthcheck did actually manage to successfully connect.
Now regarding the source, as I mentioned in the initial report, I used binary packages from http://apt.postgresql.org/pub/repos/apt . I did not compile anything from source, nor do I have the knowledge to do so.

Also if I try stopping the backend, the healthcheck immediately notices and proceeds with quarantine, etc.
If the code had changed as you suggest, then I think that healthcheck would fail to notice the change.

t-ishii

2020-01-18 09:16

developer   ~0003071

Yes, I know you used binary packages. My guess was debian packagers patched the source code then created the binary package. I am not familiar with debian packages but there's should be a way to get the actual source code to be used to build debian packages (like source packages provided in RPM). If so, I could be able to confirm my speculation.

> Also if I try stopping the backend, the healthcheck immediately notices and proceeds with quarantine, etc.
If the code had changed as you suggest, then I think that healthcheck would fail to notice the change.

If you stop PostgreSQL by using pg_ctl or other way and you connect to pgpool at the time, pgpool detects it by receiving a notice message from PostgreSQL. The health check process is not involved here. Also please note that there are multiple code path that detects failure in connecting to backend in health check and it is possible that health check detects the connection error in different ways.

t-ishii

2020-01-18 10:34

developer   ~0003072

Last edited: 2020-01-18 11:00

View 2 revisions

I found this page:
https://sources.debian.org/patches/pgpool2/4.1.0-1/
It seems there's no patch for pool_connection_pool.c. So my theory fails:-<

Another theory is, getaddrinfo() for "pg1" returns multiple network address info, e.g. IPV4 and IPV6 address. In this case health check first tries IPV4 address. If it fails with the error you are seeing, then it tries IPV6 address. If it succeeds, health check succeeds. This theory explains the situation.

If my theory is correct, you could avoid the error by enabling both IPV4 and IPV6 address of PostgreSQL.

dcvythoulkas

2020-01-19 02:43

reporter   ~0003073

Your theory is correct. But it was not the IPv6, it was name resolution in the /etc/hosts file and the postgresql.conf.

Specifically, the /etc/hosts was like this:
vagrant@pg1:~$ cat /etc/hosts
127.0.0.1 localhost
127.0.1.1 pg1
....
10.10.20.11 pg1
....

And postgresql.conf like this:
....
listen_addresses = 'localhost,10.10.20.11' # what IP address(es) to listen on;
....

So when healthcheck tried to reach the local node on every machine, it would check via hostname (pg1, pg2, etc). With the hosts file above that leeds to 127.0.1.1 that postgresql doesn't listen, so it would fail, hence the error, and then try with the 10.10.20.11 which would be successful. That also explains why there was no error from healthchecks of remote hosts.

I changed the hosts file to the following:
vagrant@pg1:~$ cat /etc/hosts
127.0.0.1 localhost
127.0.1.1 pg1-local
....
10.10.20.11 pg1
....

And the logs are clear.
Thank you for your quick response and support. You can close this issue.

t-ishii

2020-01-19 08:24

developer   ~0003074

Thanks for the feedback. I am going to close this issue.

Issue History

Date Modified Username Field Change
2020-01-17 02:50 dcvythoulkas New Issue
2020-01-17 02:50 dcvythoulkas File Added: pgpool.conf
2020-01-17 02:50 dcvythoulkas File Added: pool_hba.conf
2020-01-17 02:50 dcvythoulkas File Added: pgpool2.conf
2020-01-17 02:50 dcvythoulkas File Added: pgpool3.conf
2020-01-17 02:50 dcvythoulkas Tag Attached: logs
2020-01-17 02:50 dcvythoulkas Tag Attached: pgpool health check
2020-01-17 02:50 dcvythoulkas Tag Attached: settings
2020-01-17 16:35 t-ishii Note Added: 0003067
2020-01-17 16:35 t-ishii Assigned To => t-ishii
2020-01-17 16:35 t-ishii Status new => feedback
2020-01-17 17:31 dcvythoulkas File Added: pg1_postgres_log
2020-01-17 17:31 dcvythoulkas File Added: pg1_syslog
2020-01-17 17:31 dcvythoulkas Note Added: 0003068
2020-01-17 17:31 dcvythoulkas Status feedback => assigned
2020-01-18 07:12 t-ishii Note Added: 0003069
2020-01-18 07:13 t-ishii Status assigned => feedback
2020-01-18 07:47 dcvythoulkas Note Added: 0003070
2020-01-18 07:47 dcvythoulkas Status feedback => assigned
2020-01-18 09:16 t-ishii Note Added: 0003071
2020-01-18 09:17 t-ishii Status assigned => feedback
2020-01-18 10:34 t-ishii Note Added: 0003072
2020-01-18 11:00 t-ishii Note Edited: 0003072 View Revisions
2020-01-19 02:43 dcvythoulkas Note Added: 0003073
2020-01-19 02:43 dcvythoulkas Status feedback => assigned
2020-01-19 08:24 t-ishii Note Added: 0003074
2020-01-19 11:43 t-ishii Status assigned => resolved