Subject: Re: Race conditions in 019_replslot_limit.pl

From: Masahiko Sawada <[email-masked]>
Date: Wed, 16 Feb 2022 14:58:23 +0900

On Wed, Feb 16, 2022 at 2:26 PM Kyotaro Horiguchi
<[email-masked]> wrote:
>
> At Tue, 15 Feb 2022 15:51:57 -0800, Andres Freund <[email-masked]> wrote in
> > I think what happened is that there was no WAL to receive between the start of
> > the primary and the $node_primary3->wait_for_catchup($node_standby3);
> >
> > Because the slot is created without reserving WAL that allows the primary to
> > remove the WAL segments without ever creating a slot based conflict. I think
> > that should be fixable by reserving the slot at creation time?
>
> Agreed.  Doing this att all slot creation seems fine.
>
> > > and:
> > >
> > > https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=serinus&dt=2022-02-15%2011%3A00%3A08
> > >
> > > #   Failed test 'have walsender pid 3682154
> > > # 3682136'
> > > #   at t/019_replslot_limit.pl line 335.
> > > #                   '3682154
> > > # 3682136'
> > > #     doesn't match '(?^:^[0-9]+$)'
> > >
> > > The latter looks like there are two walsenders active, which confuses the
> > > test.
> >
> > Too bad there's no plain pid in the log_line_prefix. Looks like that used to be the
> > buildfarm default, and I haven't fixed that animals configuration...
> >
> > %c apparently is hex(process startup time).hex(pid) in hex, so we're looking
> > for 382f58... Confirmed by the slot name:
> > 2022-02-15 12:10:20.874 CET [620b8a1c.382f58:5] LOG:  received replication command: CREATE_REPLICATION_SLOT "pg_basebackup_3682136" TEMPORARY PHYSICAL ( RESERVE_WAL)
> > which pg_basebackup builds using the backend pid:
> >               replication_slot = psprintf("pg_basebackup_%d", (int) PQbackendPID(param->bgconn));
> >
> > The logs for that pid are:
> > 2022-02-15 12:10:20.873 CET [620b8a1c.382f58:1] LOG:  connection received: host=[local]
> > 2022-02-15 12:10:20.874 CET [620b8a1c.382f58:2] LOG:  replication connection authorized: user=bf application_name=019_replslot_limit.pl
> > 2022-02-15 12:10:20.874 CET [620b8a1c.382f58:3] LOG:  received replication command: SHOW data_directory_mode
> > 2022-02-15 12:10:20.874 CET [620b8a1c.382f58:4] STATEMENT:  SHOW data_directory_mode
> > 2022-02-15 12:10:20.874 CET [620b8a1c.382f58:5] LOG:  received replication command: CREATE_REPLICATION_SLOT "pg_basebackup_3682136" TEMPORARY PHYSICAL ( RESERVE_WAL)
> > 2022-02-15 12:10:20.874 CET [620b8a1c.382f58:6] STATEMENT:  CREATE_REPLICATION_SLOT "pg_basebackup_3682136" TEMPORARY PHYSICAL ( RESERVE_WAL)
> > 2022-02-15 12:10:20.875 CET [620b8a1c.382f58:7] LOG:  received replication command: IDENTIFY_SYSTEM
> > 2022-02-15 12:10:20.875 CET [620b8a1c.382f58:8] STATEMENT:  IDENTIFY_SYSTEM
> > 2022-02-15 12:10:20.875 CET [620b8a1c.382f58:9] LOG:  received replication command: START_REPLICATION SLOT "pg_basebackup_3682136" 0/600000 TIMELINE 1
> > 2022-02-15 12:10:20.875 CET [620b8a1c.382f58:10] STATEMENT:  START_REPLICATION SLOT "pg_basebackup_3682136" 0/600000 TIMELINE 1
> >
> > Even though the node has log_disconnect = true, and other processes indeed log
> > their disconnection, there's no disconnect for the above session until the
> > server is shut down.  Even though pg_basebackup clearly finished? Uh, huh?
>
> It seems to me so, too.
>
> > I guess it's conceivable that the backend was still working through process
> > shutdown? But it doesn't seem too likely, given that several other connections
> > manage to get through entire connect / disconnect cycles?
>
> Yes, but since postmaster seems thinking that process is gone.

Or it's possible that the process took a time to clean up the
temporary replication slot?

Regards,

-- 
Masahiko Sawada
EDB:  https://www.enterprisedb.com/

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Wed, 16 Feb 2022 15:09:38 +0900 (JST)

At Wed, 16 Feb 2022 14:58:23 +0900, Masahiko Sawada <[email-masked]> wrote in 
> temporary replication slot?

Ugg, it's immediate shutdown.  So postmaster kills the walsender no
matter what state the waldender is under, nd leaves no log about the
end ofwalsender.

Sorry for the confusion.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Wed, 16 Feb 2022 15:22:27 +0900 (JST)

> temporary replication slot?

Checkpointer may take ReplicationSlotControlLock. Dead lock between
ReplicationSlotCleanup and InvalidateObsoleteReplicationSlots
happened?

regards.

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Wed, 16 Feb 2022 16:12:24 +0900 (JST)

At Wed, 16 Feb 2022 15:22:27 +0900 (JST), Kyotaro Horiguchi <[email-masked]> wrote in 
> ReplicationSlotCleanup and InvalidateObsoleteReplicationSlots

Or missing CV broadcast?  Anyway I haven't find a scenario of
interfering between checkpointer and walsender.

regards.

---

From: Masahiko Sawada <[email-masked]>
Date: Wed, 16 Feb 2022 18:04:14 +0900

> ReplicationSlotCleanup and InvalidateObsoleteReplicationSlots

That's possible. Whatever the exact cause of this failure, I think we
can stabilize this test by adding a condition of application_name to
the query.

Regards,

---

From: Andres Freund <[email-masked]>
Date: Wed, 16 Feb 2022 09:26:25 -0800

Hi,

> > ReplicationSlotCleanup and InvalidateObsoleteReplicationSlots

A deadlock requires some form of incorrected lock (or lock like) nesting. Do
you have an idea what that could be?

> can stabilize this test by adding a condition of application_name to

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.

It'd be good try to reproduce this locally...

- Andres

---

From: Tom Lane <[email-masked]>
Date: Wed, 16 Feb 2022 20:22:23 -0500

> 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 = '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=[local]
2022-02-16 23:06:29.596 CET [620d7565.38dd62:2] LOG:  replication connection authorized: user=bf application_name=019_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_directory_mode
2022-02-16 23:06:29.596 CET [620d7565.38dd62:5] LOG:  received replication command: CREATE_REPLICATION_SLOT "pg_basebackup_3726690" TEMPORARY PHYSICAL ( RESERVE_WAL)
2022-02-16 23:06:29.596 CET [620d7565.38dd62:6] STATEMENT:  CREATE_REPLICATION_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_SYSTEM
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_REPLICATION 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=[local]
2022-02-16 23:06:29.687 CET [620d7565.38dd6f:2] LOG:  replication connection authorized: user=bf application_name=standby_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_SYSTEM
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_REPLICATION 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=standby_3?

			regards, tom lane

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