View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0000508 | Pgpool-II | Bug | public | 2019-05-07 23:55 | 2020-02-25 11:22 |
| Reporter | mnieva | Assigned To | hoshiai | ||
| Priority | high | Severity | major | Reproducibility | random |
| Status | closed | Resolution | fixed | ||
| Product Version | 3.7.4 | ||||
| Summary | 0000508: received degenerate backend request for node_id: 0 write on backend 0 failed with error :"Success" | ||||
| Description | Our current environment uses postgres 10.4 with master and 2 slaves streaming replication. We use repmgr to manage the replication. The application uses pgpool to connect to postgres. node_id | hostname | port | status | lb_weight | role ------------+--------------------------+-------+-----------+---------------+--------- 0 | pgsql04-pgw-prd.vz | 5432 | up | 0.333333 | standby 1 | pgsql03-ops-prd.vz | 5432 | up | 0.333333 | primary 2 | pgsql01-ops-prd.pr1 5432 | up | 0.333333 | standby We often see this in the pgpool logs. LOG: received degenerate backend request for node_id: 0 from pid [11725] WARNING: write on backend 0 failed with error :"Success" DETAIL: while trying to write data from offset: 0 wlen: 5 LOG: Pgpool-II parent process has received failover request LOG: starting degeneration. shutdown host pgsql04-pgw-prd.vz(5432) LOG: Do not restart children because we are switching over node id 0 host: pgsql04-pgw-prd.vz port: 5432 and we are in streaming replication mode LOG: child pid 6370 needs to restart because pool 0 uses backend 0 LOG: child pid 9160 needs to restart because pool 0 uses backend 0 LOG: child pid 10905 needs to restart because pool 0 uses backend 0 LOG: child pid 2784 needs to restart because pool 0 uses backend 0 LOG: child pid 5985 needs to restart because pool 0 uses backend 0 LOG: child pid 11725 needs to restart because pool 0 uses backend 0 LOG: child pid 9401 needs to restart because pool 0 uses backend 0 LOG: child pid 10026 needs to restart because pool 0 uses backend 0 LOG: child pid 7683 needs to restart because pool 0 uses backend 0 LOG: child pid 8857 needs to restart because pool 0 uses backend 0 LOG: execute command: /home/postgres/dba_scripts/failover.sh pgsql04-pgw-prd.vz pgsql03-ops-prd.vz The slaves are accessible and was wondering why are we getting this. Furthermore, no failover happened as the primary node remain the same. I know pgpool handles load balancing, where queries are redirected to the standby and data inserts,updates are directed to the primary. We see some of the transactions are not created in the database. The timestamp error on the application side syncs with the timestamp error in pgpool. The error application is getting is 'The connection attempt failed' and 'An I/O error occurred while sending to the backend.' How does pgpool handle load balancing? This is a major concern to us. How does pgpool handle load balancing? This is related to https://www.pgpool.net/mantisbt/view.php?id=488 and https://www.pgpool.net/mantisbt/view.php?id=395. In these links, it was recommended to use write.diff. It also says that it has been integrated in release 3.7. I would like to know if we still need to compile write.diff on later release? Is the error fixed in version 4.0.4? Hope you can help us on this. | ||||
| Additional Information | This is what is shown in the application logs SEVERE [org.postgresql.Driver] (JCA PoolFiller) Connection error: : org.postgresql.util.PSQLException: The connection attempt failed. ERROR [com.points.services.payment.dao.SQLOrdersDAO] (default task-50) org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend. | ||||
| Tags | pgpool-II | ||||
|
|
> This is related to https://www.pgpool.net/mantisbt/view.php?id=488 and https://www.pgpool.net/mantisbt/view.php?id=395. I think too. There's a possibility that this bug is ralated its problem. This bug is that pgpool decide an error by mistake. so maybe pgpool did to degenerate backend . > In these links, it was recommended to use write.diff. It also says that it has been integrated in release 3.7. > I would like to know if we still need to compile write.diff on later release? Is the error fixed in version 4.0.4? Sure, this fix was contained for release 3.7.5 and after, and 4.0.x. So these version don't need to compile a patch. |
|
|
Hi, we recently upgraded pgpool to 4.0.4. I still see the same issue in the logs. 2019-06-10 12:54:53: db: paysvc pid 26815: user: dst_app client [unknown]: 4 LOG: received degenerate backend request for node_id: 0 from pid [26815] 2019-06-10 12:54:53: db: paysvc pid 26815: user: dst_app client [unknown]: 5 WARNING: write on backend 0 failed with error :"Success" 2019-06-10 12:54:53: db: paysvc pid 26815: user: dst_app client [unknown]: 6 DETAIL: while trying to write data from offset: 0 wlen: 5 2019-06-10 12:54:53: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 4848 LOG: Pgpool-II parent process has received failover request 2019-06-10 12:54:53: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 4849 LOG: starting degeneration. shutdown host pgsql04-pgw-prd.vz.points.com(5432) 2019-06-10 12:54:53: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 4850 LOG: Do not restart children because we are switching over node id 0 host: pgsql04-pgw-prd.vz.points.com port: 5432 and we are in streaming replication mode Does anyone what's triggering 'received degenerate backend request' and 'WARNING: write on backend 0 failed with error :"Success"' ? |
|
|
Can some one please help me out. My understanding is that, once I do the pgpool upgrade, I will be seeing less of the WARNING: write on backend 0 failed with error :"Success" on the logs. On the contrary, I am still getting the same error. The logs show it is still happening. Furthermore, the failover command is executed even when no actual failover happened. Here are the entries from the logs today 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8056 LOG: fork a new worker child process with pid: 11710 2019-06-11 12:04:37: db: paysvc pid 20934: user: dst_app client [unknown]: 6 LOG: received degenerate backend request for node_id: 2 from pid [20934] 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8057 LOG: Pgpool-II parent process has received failover request 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8058 LOG: starting degeneration. shutdown host pgsql01-ops-prd.pr1.points.com(5432) 2019-06-11 12:04:37: db: paysvc pid 20934: user: dst_app client [unknown]: 7 WARNING: write on backend 2 failed with error :"Success" 2019-06-11 12:04:37: db: paysvc pid 20934: user: dst_app client [unknown]: 8 DETAIL: while trying to write data from offset: 0 wlen: 5 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8059 LOG: Do not restart children because we are switching over node id 2 host: pgsql01-ops-prd.pr1.points.com port: 5432 and we are in streaming replication mode 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8060 LOG: child pid 29987 needs to restart because pool 0 uses backend 2 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8061 LOG: child pid 28485 needs to restart because pool 0 uses backend 2 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8062 LOG: child pid 20937 needs to restart because pool 0 uses backend 2 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8063 LOG: child pid 20938 needs to restart because pool 0 uses backend 2 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8064 LOG: child pid 27614 needs to restart because pool 0 uses backend 2 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8065 LOG: child pid 11555 needs to restart because pool 0 uses backend 2 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8066 LOG: child pid 26964 needs to restart because pool 0 uses backend 2 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8067 LOG: child pid 28545 needs to restart because pool 0 uses backend 2 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8068 LOG: child pid 30028 needs to restart because pool 0 uses backend 2 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8069 LOG: child pid 28847 needs to restart because pool 0 uses backend 2 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8070 LOG: child pid 20934 needs to restart because pool 0 uses backend 2 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8071 LOG: child pid 28468 needs to restart because pool 0 uses backend 2 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8072 LOG: child pid 29166 needs to restart because pool 0 uses backend 2 2019-06-11 12:04:37: db: [No Connection] pid 16184: user: [No Connection] client [No Connection]: 8073 LOG: execute command: /home/postgres/dba_scripts/failover.sh pgsql01-ops-prd.pr1.points.com pgsql03-ops-prd.vz.points.com >> /local/opt/points/pgpoolII/9999/log/pgpool_failover.log |
|
|
Sorry, late for reply. Could you show me more pgpool.log around it, and pgpool.conf ? I want to see previous log messages. |
|
|
I have attached the files pgpool.conf and pgpool.log. The log is from the time we upgraded pgpool to the version 4.0.4 |
|
|
Any feedback on this? |
|
|
I saw your log. The following warning messages is output with failover executed. So this message is no problem. WARNING: write on backend 0 failed with error :"Success" > Furthermore, the failover command is executed even when no actual failover happened. No, failover actually happened. The failback was happend after that, so you saw wrong it. Your problem may be resolved, if you use health_check instead of failover_on_backend_error. |
|
|
You mentioned that disabling failover_on_backend_error will resolve the issue. The slave nodes are detached whenever this happens. We need to reattach the slave nodes. The application gets connection attempt failed and 'An I/O error occurred while sending to the backend.' error message. Will this issue be resolved too? I have set health_check parameters. What particular health check parameter are you referring? Are you able to look into the pgpool.conf ? |
|
|
> The slave nodes are detached whenever this happens. We need to reattach the slave nodes. > The application gets connection attempt failed and 'An I/O error occurred while sending to the backend.' error message. Will this issue be resolved too? I probablly think that its message will decrease, bacause maybe its messages was outputted execution of failover. |
|
|
Hello! We have pgpool 4.0.5 and Postgresql 9.4.5 and same problems. May be exist workaround? Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 28539: LOG: received degenerate backend request for node_id: 1 from pid [28539] Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 28539: WARNING: write on backend 1 failed with error :"Success" Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 28539: DETAIL: while trying to write data from offset: 0 wlen: 5 Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 31263: LOG: Pgpool-II parent process has received failover request Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 31263: LOG: starting degeneration. shutdown host 10.12.124.32(5432) Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 31263: LOG: Do not restart children because we are switching over node id 1 host: 10.12.124.32 port: 5432 and we are in streaming replication mode Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 31263: LOG: find_primary_node_repeatedly: waiting for finding a primary node Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 13619: WARNING: failover/failback is in progress Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 13619: DETAIL: executing failover or failback on backend Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 13619: HINT: In a moment you should be able to reconnect to the database Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 13619: WARNING: failover/failback is in progress Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 13619: DETAIL: executing failover or failback on backend Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 13619: HINT: In a moment you should be able to reconnect to the database Aug 26 17:43:47 pgpool[31263]: 2019-08-26 17:43:47: pid 31263: LOG: find_primary_node: standby node is 0 Aug 26 17:43:48 pgpool[31263]: 2019-08-26 17:43:48: pid 31263: LOG: find_primary_node: standby node is 0 Aug 26 17:43:49 pgpool[31263]: 2019-08-26 17:43:49: pid 2302: WARNING: failover/failback is in progress Aug 26 17:43:49 pgpool[31263]: 2019-08-26 17:43:49: pid 2302: DETAIL: executing failover or failback on backend Aug 26 17:43:49 pgpool[31263]: 2019-08-26 17:43:49: pid 2302: HINT: In a moment you should be able to reconnect to the database Aug 26 17:43:49 pgpool[31263]: 2019-08-26 17:43:49: pid 2302: WARNING: failover/failback is in progress Aug 26 17:43:49 pgpool[31263]: 2019-08-26 17:43:49: pid 2302: DETAIL: executing failover or failback on backend Aug 26 17:43:49 pgpool[31263]: 2019-08-26 17:43:49: pid 2302: HINT: In a moment you should be able to reconnect to the database Aug 26 17:43:49 pgpool[31263]: 2019-08-26 17:43:49: pid 31263: LOG: find_primary_node: standby node is 0 Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 14941: WARNING: failover/failback is in progress Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 14941: DETAIL: executing failover or failback on backend Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 14941: HINT: In a moment you should be able to reconnect to the database Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 14941: WARNING: failover/failback is in progress Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 14941: DETAIL: executing failover or failback on backend Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 14941: HINT: In a moment you should be able to reconnect to the database Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 14928: LOG: md5 authentication successful with frontend Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 14928: WARNING: failover/failback is in progress Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 14928: DETAIL: executing failover or failback on backend Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 14928: HINT: In a moment you should be able to reconnect to the database Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 14928: WARNING: failover/failback is in progress Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 14928: DETAIL: executing failover or failback on backend Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 14928: HINT: In a moment you should be able to reconnect to the database Aug 26 17:43:50 pgpool[31263]: 2019-08-26 17:43:50: pid 31263: LOG: find_primary_node: standby node is 0 Aug 26 17:43:51 pgpool[31263]: 2019-08-26 17:43:51: pid 31263: LOG: find_primary_node: standby node is 0 Aug 26 17:43:52 pgpool[31263]: 2019-08-26 17:43:52: pid 31263: LOG: find_primary_node: standby node is 0 Aug 26 17:43:53 pgpool[31263]: 2019-08-26 17:43:53: pid 31263: LOG: find_primary_node: standby node is 0 Aug 26 17:43:54 pgpool[31263]: 2019-08-26 17:43:54: pid 31263: LOG: find_primary_node: standby node is 0 Aug 26 17:43:55 pgpool[31263]: 2019-08-26 17:43:55: pid 31263: LOG: find_primary_node: standby node is 0 Aug 26 17:43:56 pgpool[31263]: 2019-08-26 17:43:56: pid 31263: LOG: find_primary_node: standby node is 0 Aug 26 17:43:57 pgpool[31263]: 2019-08-26 17:43:57: pid 31263: LOG: failover: set new primary node: -1 Aug 26 17:43:57 pgpool[31263]: 2019-08-26 17:43:57: pid 31263: LOG: failover: set new master node: 0 Aug 26 17:43:57 pgpool[31263]: failover done. shutdown host 10.12.124.32(5432)2019-08-26 17:43:57: pid 31263: LOG: failover done. shutdown host 10.12.124.32(5432) |
|
|
Hi Dgeliko, > WARNING: write on backend 1 failed with error :"Success" This warning message is apeared is not problem during failover is exucuting. |
|
|
I couldn't see correct logs. Do you have any questions? If you don't have any problems, I would like to close this issue. |
|
|
I closed this ticket. If you have a new question, Please email pgpool-general or pgpool-hackers. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2019-05-07 23:55 | mnieva | New Issue | |
| 2019-05-07 23:55 | mnieva | Tag Attached: pgpool-II | |
| 2019-05-08 14:20 | hoshiai | Assigned To | => hoshiai |
| 2019-05-08 14:20 | hoshiai | Status | new => assigned |
| 2019-05-08 15:47 | hoshiai | Note Added: 0002589 | |
| 2019-05-08 15:47 | hoshiai | Note Edited: 0002589 | |
| 2019-05-08 15:48 | hoshiai | Status | assigned => feedback |
| 2019-06-11 02:12 | mnieva | Note Added: 0002647 | |
| 2019-06-11 02:12 | mnieva | Status | feedback => assigned |
| 2019-06-12 02:03 | mnieva | Note Added: 0002649 | |
| 2019-06-18 14:20 | hoshiai | Note Added: 0002664 | |
| 2019-06-18 14:20 | hoshiai | Status | assigned => feedback |
| 2019-06-19 02:39 | mnieva | File Added: pgpool.zip | |
| 2019-06-19 02:39 | mnieva | File Added: pgpool.conf | |
| 2019-06-19 02:39 | mnieva | Note Added: 0002667 | |
| 2019-06-19 02:39 | mnieva | Status | feedback => assigned |
| 2019-06-25 23:29 | mnieva | Note Added: 0002678 | |
| 2019-06-27 16:07 | hoshiai | Note Added: 0002682 | |
| 2019-06-27 16:07 | hoshiai | Status | assigned => feedback |
| 2019-06-27 23:36 | mnieva | Note Added: 0002683 | |
| 2019-06-27 23:36 | mnieva | Status | feedback => assigned |
| 2019-07-11 09:32 | hoshiai | Note Added: 0002705 | |
| 2019-08-27 22:37 | Dgeliko | Note Added: 0002804 | |
| 2019-09-27 14:37 | hoshiai | Note Added: 0002888 | |
| 2019-09-27 14:37 | hoshiai | Status | assigned => feedback |
| 2020-02-05 09:46 | hoshiai | Note Added: 0003136 | |
| 2020-02-25 11:22 | hoshiai | Status | feedback => closed |
| 2020-02-25 11:22 | hoshiai | Resolution | open => fixed |
| 2020-02-25 11:22 | hoshiai | Note Added: 0003225 |
