[pgpool-general: 2840] Re: Issue with pgpool health check timeout

Fri May 16 11:19:53 JST 2014

So my question is, why did it timeout too soon without waiting for 10 seconds? Please check my log below

2014-05-13 12:14:43 DEBUG: pid 15822: health_check: 0 th DB node status: 1

2014-05-13 12:14:44 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

2014-05-13 12:14:44 ERROR: pid 15822: connect_inet_domain_socket: select() timed out

2014-05-13 12:14:44 ERROR: pid 15822: make_persistent_db_connection: connection to 10.0.0.5(5432) failed

2014-05-13 12:14:44 DEBUG: pid 15822: health_check: 0 th DB node status: 1

2014-05-13 12:14:45 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

2014-05-13 12:14:45 ERROR: pid 15822: connect_inet_domain_socket: select() timed out

2014-05-13 12:14:45 ERROR: pid 15822: make_persistent_db_connection: connection to 10.0.0.5(5432) failed

2014-05-13 12:14:45 ERROR: pid 15822: health check failed. 0 th host 10.0.0.5 at port 5432 is down

2014-05-13 12:14:45 DEBUG: pid 15822: health check: clearing alarm

2014-05-13 12:14:45 DEBUG: pid 15822: health check: clearing alarm

2014-05-13 12:14:45 LOG: pid 15822: health check retry sleep time: 2 second(s)

2014-05-13 12:14:46 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

2014-05-13 12:14:47 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

2014-05-13 12:14:47 DEBUG: pid 15822: retrying 1 th health checking

2014-05-13 12:14:47 DEBUG: pid 15822: health check: clearing alarm

2014-05-13 12:14:47 DEBUG: pid 15822: health_check: 0 th DB node status: 1

2014-05-13 12:14:48 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

2014-05-13 12:14:48 ERROR: pid 15822: connect_inet_domain_socket: select() timed out

2014-05-13 12:14:48 ERROR: pid 15822: make_persistent_db_connection: connection to 10.0.0.5(5432) failed

2014-05-13 12:14:48 ERROR: pid 15822: health check failed. 0 th host 10.0.0.5 at port 5432 is down

2014-05-13 12:14:48 DEBUG: pid 15822: health check: clearing alarm

2014-05-13 12:14:48 DEBUG: pid 15822: health check: clearing alarm

2014-05-13 12:14:48 LOG: pid 15822: health check retry sleep time: 2 second(s)

2014-05-13 12:14:49 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

2014-05-13 12:14:50 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

2014-05-13 12:14:50 DEBUG: pid 15822: retrying 2 th health checking

2014-05-13 12:14:50 DEBUG: pid 15822: health check: clearing alarm

2014-05-13 12:14:50 DEBUG: pid 15822: health_check: 0 th DB node status: 1

2014-05-13 12:14:51 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

2014-05-13 12:14:51 ERROR: pid 15822: connect_inet_domain_socket: select() timed out

2014-05-13 12:14:51 ERROR: pid 15822: make_persistent_db_connection: connection to 10.0.0.5(5432) failed

2014-05-13 12:14:51 ERROR: pid 15822: health check failed. 0 th host 10.0.0.5 at port 5432 is down

2014-05-13 12:14:51 DEBUG: pid 15822: health check: clearing alarm

2014-05-13 12:14:51 DEBUG: pid 15822: health check: clearing alarm

2014-05-13 12:14:51 LOG: pid 15822: set 0 th backend down status

2014-05-13 12:14:51 DEBUG: pid 15822: failover_handler called

2014-05-13 12:14:51 DEBUG: pid 15822: failover_handler: starting to select new master node

Thanks & Regards,

Shyalika

-----Original Message-----
From: Tatsuo Ishii [mailto:ishii at postgresql.org]
Sent: Friday, 16 May 2014 12:16 PM
To: Shyalika Benthotage
Cc: pgpool-general at pgpool.net
Subject: Re: [pgpool-general: 2835] Issue with pgpool health check timeout

From: Shyalika Benthotage <shyalika_benthotage at dialog.com.au<mailto:shyalika_benthotage at dialog.com.au>>

Subject: RE: [pgpool-general: 2835] Issue with pgpool health check timeout

Date: Fri, 16 May 2014 02:11:27 +0000

Message-ID: <0C34193B8C9D1249A95AD902CCF181CF14CB66AD at otwdgmxbox01.dialoggroup.internal<mailto:0C34193B8C9D1249A95AD902CCF181CF14CB66AD at otwdgmxbox01.dialoggroup.internal>>

> Hi Ishii,

>

> Thanks for the quick reply. I tested the pgpool settings using a DROP rule in iptables. I.e. the DROP rule will silently drop data packets without sending a response to the sender, making the sender to wait and then the request to time out. So I believe in this case the network related system call does not actually return so it should time out. Am I correct?

Yes,correct. More precisely,

non blocking connect(2) issued then select(2) waits for something comes in:

>> 2014-05-13 12:14:43 DEBUG: pid 15822: health_check: 0 th DB node

Then select(2) timed out because there is 1 second time out set in the select(2) parameter.

>> 2014-05-13 12:14:44 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

> Thanks & Regards,

> Shyalika

>

> -----Original Message-----

> From: Tatsuo Ishii [mailto:ishii at postgresql.org]

> Sent: Friday, 16 May 2014 10:17 AM

> To: Shyalika Benthotage

> Cc: pgpool-general at pgpool.net<mailto:pgpool-general at pgpool.net>

> Subject: Re: [pgpool-general: 2835] Issue with pgpool health check

> timeout

>

>> Hi,

>>

>> We have configured pgpool 3.3 for our PostgreSQL db in aws. And using the healthcheck parameters as below.

>>

>> health_check_period = 40

>> health_check_timeout = 10

>> health_check_max_retries = 2

>> health_check_retry_delay = 2

>>

>> I am trying to test this by using an iptables rule in the active server. When I add a drop rule to the PostgreSQL db port it does trigger a timeout but I think it timeout too soon. I.e. according to my understanding it should wait for the time period specified in "health_check_timeout " in this case, but actually times out in less than a second.(Please see the log below). Shouldn't it wait for 10 secs before time out or is my understanding incorrect.

>

> No. health_check_timeout is a timeout before network related system calls returns. If any of system calls returns error immediately, it is possible that it detects error less than 10 seconds.

>

>> Please note that I checked my DROP rule with telnet and it takes 60 seconds to time out.

>> I have restarted pgpool every time I tested this (I know just

>> reloading would do)

>>

>> I have enabled debug mode just to check this.

>>

>> 2014-05-13 12:14:43 DEBUG: pid 15822: health_check: 0 th DB node

>> status: 1

>> 2014-05-13 12:14:44 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

>> 2014-05-13 12:14:44 ERROR: pid 15822: connect_inet_domain_socket:

>> select() timed out

>> 2014-05-13 12:14:44 ERROR: pid 15822: make_persistent_db_connection:

>> connection to 10.0.0.5(5432) failed

>> 2014-05-13 12:14:44 DEBUG: pid 15822: health_check: 0 th DB node

>> status: 1

>> 2014-05-13 12:14:45 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

>> 2014-05-13 12:14:45 ERROR: pid 15822: connect_inet_domain_socket:

>> select() timed out

>> 2014-05-13 12:14:45 ERROR: pid 15822: make_persistent_db_connection:

>> connection to 10.0.0.5(5432) failed

>> 2014-05-13 12:14:45 ERROR: pid 15822: health check failed. 0 th host

>> 10.0.0.5 at port 5432 is down

>> 2014-05-13 12:14:45 DEBUG: pid 15822: health check: clearing alarm

>> 2014-05-13 12:14:45 DEBUG: pid 15822: health check: clearing alarm

>> 2014-05-13 12:14:45 LOG: pid 15822: health check retry sleep time: 2

>> second(s)

>> 2014-05-13 12:14:46 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

>> 2014-05-13 12:14:47 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

>> 2014-05-13 12:14:47 DEBUG: pid 15822: retrying 1 th health checking

>> 2014-05-13 12:14:47 DEBUG: pid 15822: health check: clearing alarm

>> 2014-05-13 12:14:47 DEBUG: pid 15822: health_check: 0 th DB node

>> status: 1

>> 2014-05-13 12:14:48 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

>> 2014-05-13 12:14:48 ERROR: pid 15822: connect_inet_domain_socket:

>> select() timed out

>> 2014-05-13 12:14:48 ERROR: pid 15822: make_persistent_db_connection:

>> connection to 10.0.0.5(5432) failed

>> 2014-05-13 12:14:48 ERROR: pid 15822: health check failed. 0 th host

>> 10.0.0.5 at port 5432 is down

>> 2014-05-13 12:14:48 DEBUG: pid 15822: health check: clearing alarm

>> 2014-05-13 12:14:48 DEBUG: pid 15822: health check: clearing alarm

>> 2014-05-13 12:14:48 LOG: pid 15822: health check retry sleep time: 2

>> second(s)

>> 2014-05-13 12:14:49 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

>> 2014-05-13 12:14:50 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

>> 2014-05-13 12:14:50 DEBUG: pid 15822: retrying 2 th health checking

>> 2014-05-13 12:14:50 DEBUG: pid 15822: health check: clearing alarm

>> 2014-05-13 12:14:50 DEBUG: pid 15822: health_check: 0 th DB node

>> status: 1

>> 2014-05-13 12:14:51 LOG: pid 15857: connect_inet_domain_socket: select() timed out. retrying...

>> 2014-05-13 12:14:51 ERROR: pid 15822: connect_inet_domain_socket:

>> select() timed out

>> 2014-05-13 12:14:51 ERROR: pid 15822: make_persistent_db_connection:

>> connection to 10.0.0.5(5432) failed

>> 2014-05-13 12:14:51 ERROR: pid 15822: health check failed. 0 th host

>> 10.0.0.5 at port 5432 is down

>> 2014-05-13 12:14:51 DEBUG: pid 15822: health check: clearing alarm

>> 2014-05-13 12:14:51 DEBUG: pid 15822: health check: clearing alarm

>> 2014-05-13 12:14:51 LOG: pid 15822: set 0 th backend down status

>> 2014-05-13 12:14:51 DEBUG: pid 15822: failover_handler called

>> 2014-05-13 12:14:51 DEBUG: pid 15822: failover_handler: starting to

>> select new master node

>>

>> I even tried setting health_check_timeout to 0 to see whether it defaults to TCP/IP timeout. No difference.

>>

>> Regards,

>> Shyalika

>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.sraoss.jp/pipermail/pgpool-general/attachments/20140516/5c449d74/attachment-0001.html>