View Issue Details

IDProjectCategoryView StatusLast Update
0000508Pgpool-IIBugpublic2020-02-25 11:22
ReportermnievaAssigned Tohoshiai 
PriorityhighSeveritymajorReproducibilityrandom
Status closedResolutionfixed 
Product Version3.7.4 
Target VersionFixed in Version 
Summary0000508: received degenerate backend request for node_id: 0 write on backend 0 failed with error :"Success"
DescriptionOur 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 InformationThis 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.
Tagspgpool-II

Activities

hoshiai

2019-05-08 15:47

developer   ~0002589

Last edited: 2019-05-08 15:47

View 2 revisions

> 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.

mnieva

2019-06-11 02:12

reporter   ~0002647

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"' ?

mnieva

2019-06-12 02:03

reporter   ~0002649

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

hoshiai

2019-06-18 14:20

developer   ~0002664

Sorry, late for reply.
Could you show me more pgpool.log around it, and pgpool.conf ?
I want to see previous log messages.

mnieva

2019-06-19 02:39

reporter   ~0002667

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

pgpool.conf (32,498 bytes)
pgpool.zip (610,938 bytes)

mnieva

2019-06-25 23:29

reporter   ~0002678

Any feedback on this?

hoshiai

2019-06-27 16:07

developer   ~0002682

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.

mnieva

2019-06-27 23:36

reporter   ~0002683

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 ?

hoshiai

2019-07-11 09:32

developer   ~0002705

> 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.

Dgeliko

2019-08-27 22:37

reporter   ~0002804

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)

hoshiai

2019-09-27 14:37

developer   ~0002888

Hi Dgeliko,

> WARNING: write on backend 1 failed with error :"Success"

This warning message is apeared is not problem during failover is exucuting.

hoshiai

2020-02-05 09:46

developer   ~0003136

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.

hoshiai

2020-02-25 11:22

developer   ~0003225

I closed this ticket.
If you have a new question, Please email pgpool-general or pgpool-hackers.

Issue History

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 View Revisions
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