View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0000274 | Pgpool-II | Bug | public | 2016-12-19 21:28 | 2021-10-08 17:07 |
| Reporter | amitkindia | Assigned To | t-ishii | ||
| Priority | high | Severity | major | Reproducibility | N/A |
| Status | closed | Resolution | open | ||
| Product Version | 3.5.4 | ||||
| Summary | 0000274: PgPool showing all the nodes as standby even though pg_is_in_recovery() shows correctly as master/standby? | ||||
| Description | I have a set up where I have 1 pgpool, 1 primary postgres and 2 standby postgres. And I am seeing following issues: Issue 1 : Pgpool is not able to detect primary and says all are standby. Issue 2 : Pgpool creates persistent connection with only one of the standby with status 2 | ||||
| Steps To Reproduce | Here below Pgpool is not able to detect primary and says all are standby: [root@ip-172-22-3-228 data]# sudo -u postgres psql -h 172.21.3.41 -p 5432 -x -c "show pool_nodes;" Password: -[ RECORD 1 ]------------ node_id | 0 hostname | 172.21.3.229 port | 5432 status | 3 lb_weight | 0.333333 role | standby select_cnt | 0 -[ RECORD 2 ]------------ node_id | 1 hostname | 172.21.2.88 port | 5432 status | 2 lb_weight | 0.333333 role | standby select_cnt | 0 -[ RECORD 3 ]------------ node_id | 2 hostname | 172.22.3.228 port | 5432 status | 0 lb_weight | 0.333333 role | standby select_cnt | 0 Here's the output for pg_is_in_recovery() on all the nodes where it correctly says which is primary'f' and which is standby't': [root@ip-172-22-3-228 data]# sudo -u postgres psql -h 172.21.3.229 -p 5432 -x -c "select pg_is_in_recovery();" Password: -[ RECORD 1 ]-----+-- pg_is_in_recovery | f [root@ip-172-22-3-228 data]# sudo -u postgres psql -h 172.21.2.88 -p 5432 -x -c "select pg_is_in_recovery();" Password: -[ RECORD 1 ]-----+-- pg_is_in_recovery | t [root@ip-172-22-3-228 data]# sudo -u postgres psql -h 172.22.3.228 -p 5432 -x -c "select pg_is_in_recovery();" Password: -[ RECORD 1 ]-----+-- pg_is_in_recovery | t | ||||
| Additional Information | Here's the log from pgpool, it also creates connection only to 2nd backend out of 3. 2016-12-18 17:16:41: pid 24793: DEBUG: loading hba configuration 2016-12-18 17:16:41: pid 24793: DETAIL: loading file :"/etc/pgpool-II/pool_hba.conf" for client authentication configuration file 2016-12-18 17:16:41: pid 24793: LOG: reading status file: 0 th backend is set to down status 2016-12-18 17:16:41: pid 24793: LOG: reading status file: 2 th backend is set to down status 2016-12-18 17:16:41: pid 24793: DEBUG: pool_coninfo_size: num_init_children (20) * max_pool (10) * MAX_NUM_BACKENDS (128) * sizeof(ConnectionInfo) (136) = 3481600 bytes requested for shared memory 2016-12-18 17:16:41: pid 24793: DEBUG: ProcessInfo: num_init_children (20) * sizeof(ProcessInfo) (32) = 640 bytes requested for shared memory 2016-12-18 17:16:41: pid 24793: DEBUG: Request info are: sizeof(POOL_REQUEST_INFO) 5224 bytes requested for shared memory 2016-12-18 17:16:41: pid 24793: DEBUG: Recovery management area: sizeof(int) 4 bytes requested for shared memory 2016-12-18 17:16:41: pid 24793: LOG: Setting up socket for 0.0.0.0:5432 2016-12-18 17:16:41: pid 24793: LOG: Setting up socket for :::5432 2016-12-18 17:16:41: pid 24794: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24793: LOG: pgpool-II successfully started. version 3.5.4 (ekieboshi) 2016-12-18 17:16:41: pid 24793: LOG: find_primary_node: checking backend no 0 2016-12-18 17:16:41: pid 24793: LOG: find_primary_node: checking backend no 1 2016-12-18 17:16:41: pid 24795: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24796: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24797: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24798: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24799: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24793: DEBUG: pool_read: read 13 bytes from backend 0 2016-12-18 17:16:41: pid 24793: DEBUG: authenticate kind = 5 2016-12-18 17:16:41: pid 24793: DEBUG: pool_write: to backend: 0 kind:p 2016-12-18 17:16:41: pid 24800: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24801: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24802: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24793: DEBUG: pool_read: read 326 bytes from backend 0 2016-12-18 17:16:41: pid 24793: DEBUG: authenticate kind = 0 2016-12-18 17:16:41: pid 24793: DEBUG: authenticate backend: key data received 2016-12-18 17:16:41: pid 24793: DEBUG: authenticate backend: transaction state: I 2016-12-18 17:16:41: pid 24793: DEBUG: do_query: extended:0 query:"SELECT pg_is_in_recovery()" 2016-12-18 17:16:41: pid 24793: DEBUG: pool_write: to backend: 0 kind:Q 2016-12-18 17:16:41: pid 24803: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24793: DEBUG: pool_read: read 75 bytes from backend 0 2016-12-18 17:16:41: pid 24793: DEBUG: do_query: kind: 'T' 2016-12-18 17:16:41: pid 24793: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-12-18 17:16:41: pid 24793: DEBUG: do_query: row description: num_fileds: 1 2016-12-18 17:16:41: pid 24793: DEBUG: do_query: kind: 'D' 2016-12-18 17:16:41: pid 24793: DEBUG: do_query: received DATA ROW ('D') 2016-12-18 17:16:41: pid 24793: DEBUG: do_query: kind: 'C' 2016-12-18 17:16:41: pid 24793: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-12-18 17:16:41: pid 24793: DEBUG: do_query: kind: 'Z' 2016-12-18 17:16:41: pid 24793: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-12-18 17:16:41: pid 24793: DEBUG: pool_write: to backend: 0 kind:X 2016-12-18 17:16:41: pid 24793: DEBUG: find_primary_node: 1 node is standby 2016-12-18 17:16:41: pid 24793: LOG: find_primary_node: checking backend no 2 2016-12-18 17:16:41: pid 24793: DEBUG: find_primary_node: no primary node found 2016-12-18 17:16:41: pid 24804: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24793: DEBUG: starting health check 2016-12-18 17:16:41: pid 24793: DEBUG: health check: clearing alarm 2016-12-18 17:16:41: pid 24793: DEBUG: doing health check against database:postgres user:postgres 2016-12-18 17:16:41: pid 24793: DEBUG: Backend DB node 0 status is 3 2016-12-18 17:16:41: pid 24793: DEBUG: Backend DB node 1 status is 2 2016-12-18 17:16:41: pid 24793: DEBUG: Trying to make persistent DB connection to backend node 1 having status 2 2016-12-18 17:16:41: pid 24805: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24806: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24807: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24808: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24809: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24810: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24793: DEBUG: pool_read: read 13 bytes from backend 0 2016-12-18 17:16:41: pid 24793: DEBUG: authenticate kind = 5 2016-12-18 17:16:41: pid 24793: DEBUG: pool_write: to backend: 0 kind:p 2016-12-18 17:16:41: pid 24811: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24812: DEBUG: initializing backend status 2016-12-18 17:16:41: pid 24793: DEBUG: pool_read: read 318 bytes from backend 0 2016-12-18 17:16:41: pid 24793: DEBUG: authenticate kind = 0 2016-12-18 17:16:41: pid 24793: DEBUG: authenticate backend: key data received 2016-12-18 17:16:41: pid 24793: DEBUG: authenticate backend: transaction state: I 2016-12-18 17:16:41: pid 24793: DEBUG: persistent DB connection to backend node 1 having status 2 is successful 2016-12-18 17:16:41: pid 24793: DEBUG: pool_write: to backend: 0 kind:X 2016-12-18 17:16:41: pid 24793: DEBUG: Backend DB node 2 status is 3 | ||||
| Tags | streaming replication | ||||
|
|
|
|
|
2016-12-18 17:16:41: pid 24793: LOG: reading status file: 0 th backend is set to down status 2016-12-18 17:16:41: pid 24793: LOG: reading status file: 2 th backend is set to down status This indicates that Pgpool-II reads the previous status file and thinks that node 0 and 2 are in down status. So Pgpool-II skips to issue pg_is_in_recovery() to those backends. You could either restart Pgpool-II with -D option (which ignores the status file) or remove the status before restarting Pgpool-II. |
|
|
Thanks. It was using pgpool_status in the logdir. When I restart a node it goes to status 3 and remains in that status. Does it automatically updates this status in pgpool_status as an when postgres nodes comes up and down? What does different status codes in show pool_nodes means? |
|
|
> Does it automatically updates this status in pgpool_status as an when postgres nodes comes up and down? If a node is already in down (3) or unused (0) state, Pgpool-II skips the node availability check. So the node will remain in the down or unused status. On the other hand, if a node which is recognized in state "online but client not connected" (1) or "online and client connected" (2) goes down, Pgpool-II will automatically detects it. |
|
|
Why is it taking almost 20 minutes for the state of backend nodes to change from "1" to "2"? //Status is "1" when pgpool starts 2016-12-26 15:23:54: pid 17325: DEBUG: starting health check 2016-12-26 15:23:54: pid 17325: DEBUG: health check: clearing alarm 2016-12-26 15:23:54: pid 17325: DEBUG: doing health check against database:postgres user:postgres 2016-12-26 15:23:54: pid 17325: DEBUG: Backend DB node 0 status is 1 2016-12-26 15:23:54: pid 17325: DEBUG: Trying to make persistent DB connection to backend node 0 having status 1 2016-12-26 15:23:54: pid 17325: DEBUG: pool_read: read 13 bytes from backend 0 2016-12-26 15:23:54: pid 17325: DEBUG: authenticate kind = 5 2016-12-26 15:23:54: pid 17325: DEBUG: pool_write: to backend: 0 kind:p 2016-12-26 15:23:54: pid 17325: DEBUG: pool_read: read 318 bytes from backend 0 2016-12-26 15:23:54: pid 17325: DEBUG: authenticate kind = 0 2016-12-26 15:23:54: pid 17325: DEBUG: authenticate backend: key data received 2016-12-26 15:23:54: pid 17325: DEBUG: authenticate backend: transaction state: I 2016-12-26 15:23:54: pid 17325: DEBUG: persistent DB connection to backend node 0 having status 1 is successful 2016-12-26 15:23:54: pid 17325: DEBUG: pool_write: to backend: 0 kind:X 2016-12-26 15:23:54: pid 17325: DEBUG: Backend DB node 1 status is 1 2016-12-26 15:23:54: pid 17325: DEBUG: Trying to make persistent DB connection to backend node 1 having status 1 2016-12-26 15:23:54: pid 17325: DEBUG: pool_read: read 13 bytes from backend 0 2016-12-26 15:23:54: pid 17325: DEBUG: authenticate kind = 5 2016-12-26 15:23:54: pid 17325: DEBUG: pool_write: to backend: 0 kind:p 2016-12-26 15:23:54: pid 17325: DEBUG: pool_read: read 318 bytes from backend 0 2016-12-26 15:23:54: pid 17325: DEBUG: authenticate kind = 0 2016-12-26 15:23:54: pid 17325: DEBUG: authenticate backend: key data received 2016-12-26 15:23:54: pid 17325: DEBUG: authenticate backend: transaction state: I 2016-12-26 15:23:54: pid 17325: DEBUG: persistent DB connection to backend node 1 having status 1 is successful 2016-12-26 15:23:54: pid 17325: DEBUG: pool_write: to backend: 0 kind:X 2016-12-26 15:23:54: pid 17325: DEBUG: Backend DB node 2 status is 1 2016-12-26 15:23:54: pid 17325: DEBUG: Trying to make persistent DB connection to backend node 2 having status 1 2016-12-26 15:23:54: pid 17325: DEBUG: pool_read: read 13 bytes from backend 0 2016-12-26 15:23:54: pid 17325: DEBUG: authenticate kind = 5 2016-12-26 15:23:54: pid 17325: DEBUG: pool_write: to backend: 0 kind:p 2016-12-26 15:23:54: pid 17325: DEBUG: pool_read: read 318 bytes from backend 0 2016-12-26 15:23:54: pid 17325: DEBUG: authenticate kind = 0 2016-12-26 15:23:54: pid 17325: DEBUG: authenticate backend: key data received 2016-12-26 15:23:54: pid 17325: DEBUG: authenticate backend: transaction state: I 2016-12-26 15:23:54: pid 17325: DEBUG: persistent DB connection to backend node 2 having status 1 is successful 2016-12-26 15:23:54: pid 17325: DEBUG: pool_write: to backend: 0 kind:X 2016-12-26 15:23:54: pid 17325: DEBUG: health check: clearing alarm 2016-12-26 15:23:54: pid 17325: DEBUG: health check: clearing alarm //Status becomes "2" now after almost 20 minutes 2016-12-26 15:44:08: pid 17345: DEBUG: I am 17345 accept fd 8 2016-12-26 15:44:08: pid 17345: LOG: new connection received 2016-12-26 15:44:08: pid 17345: DETAIL: connecting host=ip-172-22-3-228.us-west-1.compute.internal port=50018 2016-12-26 15:44:08: pid 17345: DEBUG: reading startup packet 2016-12-26 15:44:08: pid 17345: DETAIL: Protocol Major: 1234 Minor: 5679 database: user: 2016-12-26 15:44:08: pid 17345: DEBUG: selecting backend connection 2016-12-26 15:44:08: pid 17345: DETAIL: SSLRequest from client 2016-12-26 15:44:08: pid 17345: DEBUG: reading startup packet 2016-12-26 15:44:08: pid 17345: DETAIL: application_name: psql 2016-12-26 15:44:08: pid 17345: DEBUG: reading startup packet 2016-12-26 15:44:08: pid 17345: DETAIL: Protocol Major: 3 Minor: 0 database: postgres user: postgres 2016-12-26 15:44:08: pid 17345: DEBUG: creating new connection to backend 2016-12-26 15:44:08: pid 17345: DETAIL: connecting 0 backend 2016-12-26 15:44:08: pid 17345: DEBUG: creating new connection to backend 2016-12-26 15:44:08: pid 17345: DETAIL: connecting 1 backend 2016-12-26 15:44:08: pid 17345: DEBUG: creating new connection to backend 2016-12-26 15:44:08: pid 17345: DETAIL: connecting 2 backend 2016-12-26 15:44:08: pid 17345: DEBUG: pool_read: read 13 bytes from backend 0 2016-12-26 15:44:08: pid 17345: DEBUG: pool_read: read 13 bytes from backend 1 2016-12-26 15:44:08: pid 17345: DEBUG: pool_read: read 13 bytes from backend 2 2016-12-26 15:44:08: pid 17345: DEBUG: reading message length 2016-12-26 15:44:08: pid 17345: DETAIL: slot: 0 length: 12 2016-12-26 15:44:08: pid 17345: DEBUG: reading message length 2016-12-26 15:44:08: pid 17345: DETAIL: slot: 1 length: 12 2016-12-26 15:44:08: pid 17345: DEBUG: reading message length 2016-12-26 15:44:08: pid 17345: DETAIL: slot: 2 length: 12 2016-12-26 15:44:08: pid 17345: DEBUG: authentication backend 2016-12-26 15:44:08: pid 17345: DETAIL: auth kind:5 2016-12-26 15:44:08: pid 17345: DEBUG: authentication backend 2016-12-26 15:44:08: pid 17345: DETAIL: trying md5 authentication 2016-12-26 15:44:11: pid 17325: DEBUG: starting health check 2016-12-26 15:44:11: pid 17325: DEBUG: health check: clearing alarm 2016-12-26 15:44:11: pid 17325: DEBUG: doing health check against database:postgres user:postgres 2016-12-26 15:44:11: pid 17325: DEBUG: Backend DB node 0 status is 2 2016-12-26 15:44:11: pid 17325: DEBUG: Trying to make persistent DB connection to backend node 0 having status 2 2016-12-26 15:44:11: pid 17325: DEBUG: pool_read: read 13 bytes from backend 0 2016-12-26 15:44:11: pid 17325: DEBUG: authenticate kind = 5 2016-12-26 15:44:11: pid 17325: DEBUG: pool_write: to backend: 0 kind:p 2016-12-26 15:44:11: pid 17325: DEBUG: pool_read: read 318 bytes from backend 0 2016-12-26 15:44:11: pid 17325: DEBUG: authenticate kind = 0 2016-12-26 15:44:11: pid 17325: DEBUG: authenticate backend: key data received 2016-12-26 15:44:11: pid 17325: DEBUG: authenticate backend: transaction state: I 2016-12-26 15:44:11: pid 17325: DEBUG: persistent DB connection to backend node 0 having status 2 is successful 2016-12-26 15:44:11: pid 17325: DEBUG: pool_write: to backend: 0 kind:X 2016-12-26 15:44:11: pid 17325: DEBUG: Backend DB node 1 status is 2 2016-12-26 15:44:11: pid 17325: DEBUG: Trying to make persistent DB connection to backend node 1 having status 2 2016-12-26 15:44:11: pid 17325: DEBUG: pool_read: read 13 bytes from backend 0 2016-12-26 15:44:11: pid 17325: DEBUG: authenticate kind = 5 2016-12-26 15:44:11: pid 17325: DEBUG: pool_write: to backend: 0 kind:p 2016-12-26 15:44:11: pid 17325: DEBUG: pool_read: read 318 bytes from backend 0 2016-12-26 15:44:11: pid 17325: DEBUG: authenticate kind = 0 2016-12-26 15:44:11: pid 17325: DEBUG: authenticate backend: key data received 2016-12-26 15:44:11: pid 17325: DEBUG: authenticate backend: transaction state: I 2016-12-26 15:44:11: pid 17325: DEBUG: persistent DB connection to backend node 1 having status 2 is successful 2016-12-26 15:44:11: pid 17325: DEBUG: pool_write: to backend: 0 kind:X 2016-12-26 15:44:11: pid 17325: DEBUG: Backend DB node 2 status is 2 2016-12-26 15:44:11: pid 17325: DEBUG: Trying to make persistent DB connection to backend node 2 having status 2 2016-12-26 15:44:11: pid 17325: DEBUG: pool_read: read 13 bytes from backend 0 2016-12-26 15:44:11: pid 17325: DEBUG: authenticate kind = 5 2016-12-26 15:44:11: pid 17325: DEBUG: pool_write: to backend: 0 kind:p 2016-12-26 15:44:11: pid 17325: DEBUG: pool_read: read 318 bytes from backend 0 2016-12-26 15:44:11: pid 17325: DEBUG: authenticate kind = 0 2016-12-26 15:44:11: pid 17325: DEBUG: authenticate backend: key data received 2016-12-26 15:44:11: pid 17325: DEBUG: authenticate backend: transaction state: I 2016-12-26 15:44:11: pid 17325: DEBUG: persistent DB connection to backend node 2 having status 2 is successful |
|
|
Because no client connected to the backend via Pgpool-II last 20 minutes. After a client connects to the backend via Pgpool-II, the status is changed from 1 to 2. |
|
|
From the logs I see that for: Status 1: persistent DB connection to backend node 1 having status 1 is successful Status 2: persistent DB connection to backend node 1 having status 2 is successful It looks in both the cases they are connected. Isn't this confusing? |
|
|
No. These logs come from the health checking of Pgpool-II main process. Health checking does not change the status from 1 to 2. Changing status 1 to 2 is done only by Pgpool-II child process which is responsible for each client session. |
|
|
Can we close this issue? If you have further questions, please send it to the Pgpool-II mailing list. This is a bug forum. |
|
|
Yes, Please close this. And thanks for taking out time to clarify my doubts. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2016-12-19 21:28 | amitkindia | New Issue | |
| 2016-12-19 21:28 | amitkindia | File Added: pgpool.conf | |
| 2016-12-19 21:28 | amitkindia | Tag Attached: streaming replication | |
| 2016-12-20 09:36 | t-ishii | Assigned To | => t-ishii |
| 2016-12-20 09:36 | t-ishii | Status | new => assigned |
| 2016-12-21 11:36 | t-ishii | Note Added: 0001251 | |
| 2016-12-21 11:36 | t-ishii | Status | assigned => feedback |
| 2016-12-21 12:34 | amitkindia | Note Added: 0001252 | |
| 2016-12-21 12:34 | amitkindia | Status | feedback => assigned |
| 2016-12-21 13:36 | t-ishii | Note Added: 0001253 | |
| 2016-12-21 13:38 | t-ishii | Status | assigned => feedback |
| 2016-12-27 20:03 | amitkindia | Note Added: 0001266 | |
| 2016-12-27 20:03 | amitkindia | Status | feedback => assigned |
| 2016-12-27 21:55 | t-ishii | Note Added: 0001267 | |
| 2016-12-27 22:08 | amitkindia | Note Added: 0001268 | |
| 2016-12-27 22:13 | t-ishii | Note Added: 0001269 | |
| 2016-12-28 13:36 | t-ishii | Note Added: 0001270 | |
| 2016-12-28 22:13 | amitkindia | Note Added: 0001272 | |
| 2017-01-06 09:47 | t-ishii | Status | assigned => closed |
