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

Fri May 16 15:38:30 JST 2014

Oh, you are using AWS.

Maybe 1 second time out for select(2) in AWS is not long enough?

Can you please try to make the 1 second time out longer?

It's a really subtle change. Around line of 520 in
pool_connection_pool.c there's a line:

#define CONNECT_TIMEOUT_MSEC 1000		/* specify select(2) timeout in milliseconds */

If you want to change it to, say 10 seconds, you change 1000 to 10000.

For a long term solution, it would be better to have new swicth to
control the variable, rather than fixed constant.
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese: http://www.sraoss.co.jp

> Hi,
> 
> Thanks, now I see why it is not honouring the timeout. I am trying to solve an issue in our production (in AWS) where we had 5 failovers during the last 2 months and every time we believe the DB was working properly. So our guess is it had some glitch in the network so it timed out. 
> I believe we should try increasing the retry delay so that the 2nd check would return as healthy.
> 
> Thanks & Regards,
> Shyalika
> 
> -----Original Message-----
> From: Tatsuo Ishii [mailto:ishii at postgresql.org] 
> Sent: Friday, 16 May 2014 12:24 PM
> To: Shyalika Benthotage
> Cc: pgpool-general at pgpool.net; ishii at postgresql.org
> Subject: Re: [pgpool-general: 2835] Issue with pgpool health check timeout
> 
> Because select(2) time out is counted as an error.
> --
> Tatsuo Ishii
> SRA OSS, Inc. Japan
> English: http://www.sraoss.co.jp/index_en.php
> Japanese: http://www.sraoss.co.jp
> 
>> 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
>> 
>>>>