Build-farm - intermittent error in 031_column_list.pl - Mailing list pgsql-hackers

Hi hackers.

FYI, I saw that there was a recent Build-farm error on the "grison" machine [1]
[1] https://buildfarm.postgresql.org/cgi-bin/show_history.pl?nm=grison&br=HEAD

The error happened during "subscriptionCheck" phase in the TAP test
t/031_column_list.pl
This test file was added by this [2] commit.
[2] https://github.com/postgres/postgres/commit/923def9a533a7d986acfb524139d8b9e5466d0a5

~~

I checked the history of fails for that TAP test t/031_column_list.pl
and found that this same error seems to have been happening
intermittently for at least the last 50 days.

Details of similar previous errors from the BF are listed below.

~~~

1. Details for system "grison" failure at stage subscriptionCheck,
snapshot taken 2022-05-18 18:11:45
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=grison&dt=2022-05-18%2018%3A11%3A45

[22:02:08] t/029_on_error.pl .................. ok    25475 ms ( 0.01
usr  0.00 sys + 15.39 cusr  5.59 csys = 20.99 CPU)
# poll_query_until timed out executing this query:
# SELECT '0/1530588' <= replay_lsn AND state = 'streaming'
#          FROM pg_catalog.pg_stat_replication
#          WHERE application_name IN ('sub1', 'walreceiver')
# expecting this output:
# t
# last actual query output:
#
# with stderr:
# Tests were run but no plan was declared and done_testing() was not seen.
# Looks like your test exited with 29 just after 22.
[22:09:25] t/031_column_list.pl ...............
...
[22:02:47.887](1.829s) ok 22 - partitions with different replica
identities not replicated correctly Waiting for replication conn
sub1's replay_lsn to pass 0/1530588 on publisher
[22:09:25.395](397.508s) # poll_query_until timed out executing this query:
# SELECT '0/1530588' <= replay_lsn AND state = 'streaming'
#          FROM pg_catalog.pg_stat_replication
#          WHERE application_name IN ('sub1', 'walreceiver')
# expecting this output:
# t
# last actual query output:
#
# with stderr:
timed out waiting for catchup at t/031_column_list.pl line 728.
### Stopping node "publisher" using mode immediate

~~~

2. Details for system "xenodermus" failure at stage subscriptionCheck,
snapshot taken 2022-04-16 21:00:04
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=xenodermus&dt=2022-04-16%2021%3A00%3A04

[00:15:32] t/029_on_error.pl .................. ok     8278 ms ( 0.00
usr  0.00 sys +  1.33 cusr  0.55 csys =  1.88 CPU)
# poll_query_until timed out executing this query:
# SELECT '0/1543648' <= replay_lsn AND state = 'streaming'
#          FROM pg_catalog.pg_stat_replication
#          WHERE application_name IN ('sub1', 'walreceiver')
# expecting this output:
# t
# last actual query output:
#
# with stderr:
# Tests were run but no plan was declared and done_testing() was not seen.
# Looks like your test exited with 29 just after 25.
[00:22:30] t/031_column_list.pl ...............
...
[00:16:04.100](0.901s) ok 25 - partitions with different replica
identities not replicated correctly Waiting for replication conn
sub1's replay_lsn to pass 0/1543648 on publisher
[00:22:29.923](385.823s) # poll_query_until timed out executing this query:
# SELECT '0/1543648' <= replay_lsn AND state = 'streaming'
#          FROM pg_catalog.pg_stat_replication
#          WHERE application_name IN ('sub1', 'walreceiver')
# expecting this output:
# t
# last actual query output:
#
# with stderr:
timed out waiting for catchup at t/031_column_list.pl line 818.

~~~

3. Details for system "phycodurus" failure at stage subscriptionCheck,
snapshot taken 2022-04-05 17:30:04
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=phycodurus&dt=2022-04-05%2017%3A30%3A04

# poll_query_until timed out executing this query:
# SELECT '0/1528640' <= replay_lsn AND state = 'streaming'
#          FROM pg_catalog.pg_stat_replication
#          WHERE application_name IN ('sub1', 'walreceiver')
# expecting this output:
# t
# last actual query output:
#
# with stderr:
# Tests were run but no plan was declared and done_testing() was not seen.
# Looks like your test exited with 29 just after 22.
[20:50:25] t/031_column_list.pl ...............
...
ok 22 - partitions with different replica identities not replicated
correctly Waiting for replication conn sub1's replay_lsn to pass
0/1528640 on publisher # poll_query_until timed out executing this
query:
# SELECT '0/1528640' <= replay_lsn AND state = 'streaming'
#          FROM pg_catalog.pg_stat_replication
#          WHERE application_name IN ('sub1', 'walreceiver')
# expecting this output:
# t
# last actual query output:
#
# with stderr:
timed out waiting for catchup at t/031_column_list.pl line 667.

~~~

4. Details for system "phycodurus" failure at stage subscriptionCheck,
snapshot taken 2022-04-05 17:30:04
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=phycodurus&dt=2022-04-05%2017%3A30%3A04

[20:43:04] t/030_sequences.pl ................. ok    11108 ms ( 0.00
usr  0.00 sys +  1.49 cusr  0.40 csys =  1.89 CPU)
# poll_query_until timed out executing this query:
# SELECT '0/1528640' <= replay_lsn AND state = 'streaming'
#          FROM pg_catalog.pg_stat_replication
#          WHERE application_name IN ('sub1', 'walreceiver')
# expecting this output:
# t
# last actual query output:
#
# with stderr:
# Tests were run but no plan was declared and done_testing() was not seen.
# Looks like your test exited with 29 just after 22.
[20:50:25] t/031_column_list.pl ...............
...
ok 22 - partitions with different replica identities not replicated
correctly Waiting for replication conn sub1's replay_lsn to pass
0/1528640 on publisher # poll_query_until timed out executing this
query:
# SELECT '0/1528640' <= replay_lsn AND state = 'streaming'
#          FROM pg_catalog.pg_stat_replication
#          WHERE application_name IN ('sub1', 'walreceiver')
# expecting this output:
# t
# last actual query output:
#
# with stderr:
timed out waiting for catchup at t/031_column_list.pl line 667.

~~~

5. Details for system "grison" failure at stage subscriptionCheck,
snapshot taken 2022-04-03 18:11:39
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=grison&dt=2022-04-03%2018%3A11%3A39

[22:28:00] t/030_sequences.pl ................. ok    22970 ms ( 0.01
usr  0.00 sys + 14.93 cusr  5.14 csys = 20.08 CPU)
# poll_query_until timed out executing this query:
# SELECT '0/1528CF0' <= replay_lsn AND state = 'streaming'
#          FROM pg_catalog.pg_stat_replication
#          WHERE application_name IN ('sub1', 'walreceiver')
# expecting this output:
# t
# last actual query output:
#
# with stderr:
# Tests were run but no plan was declared and done_testing() was not seen.
# Looks like your test exited with 29 just after 22.
[22:35:11] t/031_column_list.pl ...............
....
ok 22 - partitions with different replica identities not replicated
correctly Waiting for replication conn sub1's replay_lsn to pass
0/1528CF0 on publisher # poll_query_until timed out executing this
query:
# SELECT '0/1528CF0' <= replay_lsn AND state = 'streaming'
#          FROM pg_catalog.pg_stat_replication
#          WHERE application_name IN ('sub1', 'walreceiver')
# expecting this output:
# t
# last actual query output:
#
# with stderr:
timed out waiting for catchup at t/031_column_list.pl line 667.

----
Kind Regards,
Peter Smith.
Fujitsu Australia