From: Tom Lane <tgl@sss.pgh.pa.us>
To: pgsql-hackers@lists.postgresql.org
Subject: Why is subscription/t/031_column_list.pl failing so much?
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <3307254.1706911634.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable
Date: Fri, 02 Feb 2024 17:07:14 -0500
Message-ID: <3307255.1706911634@sss.pgh.pa.us>
Archived-At: <https://www.postgresql.org/message-id/3307255.1706911634%40sss.pgh.pa.us>
Precedence: bulk

If you look at the buildfarm's failures page and filter down to
just subscriptionCheck failures, what you find is that all of the
last 6 such failures are in 031_column_list.pl:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dtamandua&dt=3D20=
24-02-02%2019%3A33%3A16
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dcalliphoridae&dt=
=3D2024-02-02%2011%3A21%3A44
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dflaviventris&dt=3D=
2024-02-01%2020%3A34%3A29
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dflaviventris&dt=3D=
2024-02-01%2016%3A57%3A14
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dkestrel&dt=3D202=
4-01-31%2022%3A18%3A24
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dcalliphoridae&dt=
=3D2024-01-30%2011%3A29%3A23

There are some further back too:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dmylodon&dt=3D202=
3-11-17%2018%3A28%3A24

but this definitely got way more common in the last few days.

Digging down into the logs, these all look pretty similar.  Somehow
things get into a state where replication connections fail with
the publisher reporting "publication does not exist":

2024-02-02 19:42:23.187 UTC [1631708][not initialized][:0] LOG:  connectio=
n received: host=3D[local]
2024-02-02 19:42:23.189 UTC [1631708][walsender][4/287:0] LOG:  connection=
 authenticated: user=3D"bf" method=3Dtrust (/home/bf/bf-build/tamandua/HEA=
D/pgsql.build/testrun/subscription/031_column_list/data/t_031_column_list_=
publisher_data/pgdata/pg_hba.conf:117)
2024-02-02 19:42:23.189 UTC [1631708][walsender][4/287:0] LOG:  replicatio=
n connection authorized: user=3Dbf application_name=3Dsub1
2024-02-02 19:42:23.214 UTC [1631708][walsender][4/288:0] LOG:  statement:=
 SELECT pg_catalog.set_config('search_path', '', false);
2024-02-02 19:42:23.226 UTC [1631708][walsender][4/0:0] LOG:  received rep=
lication command: IDENTIFY_SYSTEM
2024-02-02 19:42:23.226 UTC [1631708][walsender][4/0:0] STATEMENT:  IDENTI=
FY_SYSTEM
2024-02-02 19:42:23.226 UTC [1631708][walsender][4/0:0] LOG:  received rep=
lication command: START_REPLICATION SLOT "sub1" LOGICAL 0/15BCDD0 (proto_v=
ersion '4', origin 'any', publication_names '"pub7"')
2024-02-02 19:42:23.226 UTC [1631708][walsender][4/0:0] STATEMENT:  START_=
REPLICATION SLOT "sub1" LOGICAL 0/15BCDD0 (proto_version '4', origin 'any'=
, publication_names '"pub7"')
2024-02-02 19:42:23.226 UTC [1631708][walsender][4/0:0] LOG:  acquired log=
ical replication slot "sub1"
2024-02-02 19:42:23.226 UTC [1631708][walsender][4/0:0] STATEMENT:  START_=
REPLICATION SLOT "sub1" LOGICAL 0/15BCDD0 (proto_version '4', origin 'any'=
, publication_names '"pub7"')
2024-02-02 19:42:23.242 UTC [1631708][walsender][4/0:0] LOG:  starting log=
ical decoding for slot "sub1"
2024-02-02 19:42:23.242 UTC [1631708][walsender][4/0:0] DETAIL:  Streaming=
 transactions committing after 0/15BCDD0, reading WAL from 0/15BCDD0.
2024-02-02 19:42:23.242 UTC [1631708][walsender][4/0:0] STATEMENT:  START_=
REPLICATION SLOT "sub1" LOGICAL 0/15BCDD0 (proto_version '4', origin 'any'=
, publication_names '"pub7"')
2024-02-02 19:42:23.243 UTC [1631708][walsender][4/0:0] LOG:  logical deco=
ding found consistent point at 0/15BCDD0
2024-02-02 19:42:23.243 UTC [1631708][walsender][4/0:0] DETAIL:  There are=
 no running transactions.
2024-02-02 19:42:23.243 UTC [1631708][walsender][4/0:0] STATEMENT:  START_=
REPLICATION SLOT "sub1" LOGICAL 0/15BCDD0 (proto_version '4', origin 'any'=
, publication_names '"pub7"')
2024-02-02 19:42:23.244 UTC [1631708][walsender][4/0:0] ERROR:  publicatio=
n "pub7" does not exist
2024-02-02 19:42:23.244 UTC [1631708][walsender][4/0:0] CONTEXT:  slot "su=
b1", output plugin "pgoutput", in the change callback, associated LSN 0/15=
C7698
2024-02-02 19:42:23.244 UTC [1631708][walsender][4/0:0] STATEMENT:  START_=
REPLICATION SLOT "sub1" LOGICAL 0/15BCDD0 (proto_version '4', origin 'any'=
, publication_names '"pub7"')
2024-02-02 19:42:23.244 UTC [1631708][walsender][4/0:0] LOG:  released log=
ical replication slot "sub1"
2024-02-02 19:42:23.834 UTC [1631708][walsender][:0] LOG:  disconnection: =
session time: 0:00:00.647 user=3Dbf database=3Dpostgres host=3D[local]

and then we just repeat that until the test times out.  It fails at
different points in the test script (hence, different publication
names), but the pattern looks about the same.

I don't see anything that 031_column_list.pl is doing that is much
different from other subscription tests, so why is it the only one
failing?  And more to the point, what's going wrong exactly?

I am suspicious that this somehow represents a failure of the
historical catalog decoding logic, but I don't see how that theory
explains this only breaking in one test script.

			regards, tom lane