From: Andrew Dunstan <andrew.dunstan@2ndquadrant.com>
Subject: Re: Inadequate failure reporting from poll_query_until
To: Tom Lane <tgl@sss.pgh.pa.us>, pgsql-hackers@lists.postgresql.org
References: <17913.1539634756@sss.pgh.pa.us>
Message-ID: <91ec0b8e-4dbf-aa07-eb68-875de46807f3@2ndQuadrant.com>
Date: Mon, 15 Oct 2018 16:23:29 -0400
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101
 Thunderbird/52.4.0
MIME-Version: 1.0
In-Reply-To: <17913.1539634756@sss.pgh.pa.us>
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 7bit
Content-Language: en-MW
Precedence: bulk


On 10/15/2018 04:19 PM, Tom Lane wrote:
> I just spent some time puzzling over why we've seen so many recoveryCheck
> failures in the buildfarm recently --- excluding failures with known
> causes, such as the pg_verify_checksums business, that's basically all
> we've seen for the last week.  I am suspicious that there's some
> timing-dependent problems in WAL streaming startup and shutdown, but
> can't prove anything yet.  However, one case catches my eye:
>
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=snapper&dt=2018-10-15%2016%3A01%3A59
>
> This is the sum total of the visible logged information:
>
>      #
>      not ok 2 - asterisk in synchronous_standby_names
>      
>      #   Failed test 'asterisk in synchronous_standby_names'
>      #   at t/007_sync_rep.pl line 26.
>
> The failing test is evidently this one:
>
>      test_sync_state(
>              $node_master, qq(standby1|1|sync
>      standby2|1|potential
>      standby3|1|potential),
>              'asterisk in synchronous_standby_names',
>              '*');
>
> and when you drill down, you find that PostgresNode.pm's poll_query_until
> must have timed out, and that blank line there is as much as it felt like
> telling us about it.  Evidently what we were getting back from the server
> did not match the expected output, but good luck guessing what it was.
>
> I think we ought to fix poll_query_until so that upon failure, you get
> a much more complete and intelligible report, along the lines of
>
> poll_query_until timed out executing this query:
> $query
> expecting this output:
> $expected
> last actual query output:
> $stdout
> with stderr:
> $stderr
>
> Objections?  Thoughts about better formatting?


WFM.

cheers

andrew


-- 
Andrew Dunstan                https://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services