Re: Inadequate failure reporting from poll_query_until

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