From: Tom Lane <tgl@sss.pgh.pa.us>
To: Andres Freund <andres@anarazel.de>
cc: Masahiko Sawada <sawada.mshk@gmail.com>,
        Kyotaro Horiguchi <horikyota.ntt@gmail.com>, hlinnaka@iki.fi,
        pgsql-hackers@postgresql.org
Subject: Re: Race conditions in 019_replslot_limit.pl
In-reply-to: <20220216172625.4q5ziexufyw45lyf@alap3.anarazel.de>
References: <20220215235157.jknqi73c5scietxe@alap3.anarazel.de> <20220216.142637.1918987197255698649.horikyota.ntt@gmail.com> <CAD21AoCmphWmVNWHa3uPDF=12z3z8yqQnBMpfSGVb+kGkvux2A@mail.gmail.com> <20220216.152227.2011857448174448615.horikyota.ntt@gmail.com> <CAD21AoAFZAD5kzR3M8mmziQo1x94n4Jv3ZBKTPfv6k7BWDCNjA@mail.gmail.com> <20220216172625.4q5ziexufyw45lyf@alap3.anarazel.de>
Comments: In-reply-to Andres Freund <andres@anarazel.de>
	message dated "Wed, 16 Feb 2022 09:26:25 -0800"
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <3518070.1645060943.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable
Date: Wed, 16 Feb 2022 20:22:23 -0500
Message-ID: <3518071.1645060943@sss.pgh.pa.us>
Archived-At: <https://www.postgresql.org/message-id/3518071.1645060943%40sss.pgh.pa.us>
Precedence: bulk

Andres Freund <andres@anarazel.de> writes:
> I think the test is telling us that something may be broken. We shouldn'=
t
> silence that without at least some understanding what it is.

I looked at the recent failure on komodoensis [1], and I think what is
happening is just that the walsender for the basebackup run (launched
at 019_replslot_limit.pl line 325) hasn't exited yet at the point where
we do a blind
"SELECT pid FROM pg_stat_activity WHERE backend_type =3D 'walsender'"
and expect that we're only going to see the walsender launched for
the standby at line 331.  The two PIDs reported in the failure
correspond to this postmaster log trace:

2022-02-16 23:06:29.596 CET [620d7565.38dd62:1] LOG:  connection received:=
 host=3D[local]
2022-02-16 23:06:29.596 CET [620d7565.38dd62:2] LOG:  replication connecti=
on authorized: user=3Dbf application_name=3D019_replslot_limit.pl
2022-02-16 23:06:29.596 CET [620d7565.38dd62:3] LOG:  received replication=
 command: SHOW data_directory_mode
2022-02-16 23:06:29.596 CET [620d7565.38dd62:4] STATEMENT:  SHOW data_dire=
ctory_mode
2022-02-16 23:06:29.596 CET [620d7565.38dd62:5] LOG:  received replication=
 command: CREATE_REPLICATION_SLOT "pg_basebackup_3726690" TEMPORARY PHYSIC=
AL ( RESERVE_WAL)
2022-02-16 23:06:29.596 CET [620d7565.38dd62:6] STATEMENT:  CREATE_REPLICA=
TION_SLOT "pg_basebackup_3726690" TEMPORARY PHYSICAL ( RESERVE_WAL)
2022-02-16 23:06:29.597 CET [620d7565.38dd62:7] LOG:  received replication=
 command: IDENTIFY_SYSTEM
2022-02-16 23:06:29.597 CET [620d7565.38dd62:8] STATEMENT:  IDENTIFY_SYSTE=
M
2022-02-16 23:06:29.597 CET [620d7565.38dd62:9] LOG:  received replication=
 command: START_REPLICATION SLOT "pg_basebackup_3726690" 0/600000 TIMELINE=
 1
2022-02-16 23:06:29.597 CET [620d7565.38dd62:10] STATEMENT:  START_REPLICA=
TION SLOT "pg_basebackup_3726690" 0/600000 TIMELINE 1

and this one:

2022-02-16 23:06:29.687 CET [620d7565.38dd6f:1] LOG:  connection received:=
 host=3D[local]
2022-02-16 23:06:29.687 CET [620d7565.38dd6f:2] LOG:  replication connecti=
on authorized: user=3Dbf application_name=3Dstandby_3
2022-02-16 23:06:29.687 CET [620d7565.38dd6f:3] LOG:  received replication=
 command: IDENTIFY_SYSTEM
2022-02-16 23:06:29.687 CET [620d7565.38dd6f:4] STATEMENT:  IDENTIFY_SYSTE=
M
2022-02-16 23:06:29.687 CET [620d7565.38dd6f:5] LOG:  received replication=
 command: START_REPLICATION SLOT "rep3" 0/700000 TIMELINE 1
2022-02-16 23:06:29.687 CET [620d7565.38dd6f:6] STATEMENT:  START_REPLICAT=
ION SLOT "rep3" 0/700000 TIMELINE 1

There's no disconnection log entry for either, which I suppose means
that somebody didn't bother logging disconnection for walsenders ...
shouldn't we fix that?  But in any case, I don't see anything
interesting here, just a query that needs to be more selective.
Perhaps we can look for application_name=3Dstandby_3?

			regards, tom lane

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dkomodoensis&=
dt=3D2022-02-16%2021%3A16%3A04