Date: Mon, 13 Dec 2021 09:45:51 +0000
From: Alex Enachioaie <alex@altmetric.com>
Subject: Re: BUG #17327: Postgres server does not correctly emit error for
 max_slot_wal_keep_size being breached
To: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
Cc: pgsql-bugs@lists.postgresql.org
Message-Id: <FGS14R.K3L8GOS0U6ZQ1@altmetric.com>
In-Reply-To: <20211213.144442.1533332056665514669.horikyota.ntt@gmail.com>
References: <17327-89d0efa8b9ae6271@postgresql.org>
	<CAD21AoAQtdXm_ijArUew69X178fWp5HoTF8+CQksWuxZSCeHWg@mail.gmail.com>
	<Z4PW3R.84TE92O82TFQ@altmetric.com>
	<20211213.144442.1533332056665514669.horikyota.ntt@gmail.com>
MIME-Version: 1.0
Content-Type: multipart/alternative; boundary="=-orfQ6kmTasK4xoE5xA0n"
Archived-At: 
 <https://www.postgresql.org/message-id/FGS14R.K3L8GOS0U6ZQ1%40altmetric.com>
Precedence: bulk

--=-orfQ6kmTasK4xoE5xA0n
Content-Type: text/plain; charset=us-ascii; format=flowed

Hello Kyotaro,

Understood, that makes sense re: invalidation and what I assumed might 
be happening.

I think I'm happy to leave the method of resolution up to you, I think 
the main point for me would be that when a
replication process gets terminated as a consequence of the underlying 
temporary replication slot reaching max_slot_wal_keep_size
that we log a specific message to indicate to the user the cause of the 
termination rather than leave it ambiguous.

Thank you

King regards

Alex E
Senior Site Reliability Engineer
Altmetric

On Mon, Dec 13 2021 at 14:44:42 +0900, Kyotaro Horiguchi 
<horikyota.ntt@gmail.com> wrote:
> At Fri, 10 Dec 2021 15:46:11 +0000, Alex Enachioaie 
> <alex@altmetric.com <mailto:alex@altmetric.com>> wrote in
>>  So, essentially the server side log emmitted on a temporary
>>  replication breaching max_slot_wal_keep_size limit is only:
>> 
>>  2021-12-03 16:21:54 UTC [29724-2647] LOG: terminating process 42601 
>> to
>>  release replication slot "pg_basebackup_42601"
>> 
>>  whereas for a persistent replication slot we get an additional line
>>  that clearly states _why_ the replication process was terminated:
>> 
>>  2021-12-03 00:57:16 UTC [29724-2645] LOG: terminating process 3899 
>> to
>>  release replication slot "backup"
>>  2021-12-03 00:57:16 UTC [29724-2646] LOG: invalidating slot "backup"
>>  because its restart_lsn 47198/1E000000 exceeds 
>> max_slot_wal_keep_size
>> 
>>  I'm not sure if this means that in the case of a temporary slot it
>>  does not get invalidated at all (I've not looked at the code), or 
>> it's
>>  simply that we don't emit a log message when it does because the 
>> slot
>>  would be discarded anyway, but such a message would be very useful 
>> for
>>  diagnostic purposes imo.
> 
> The "invalidating slot" message is emitted when the slot needs to be
> invalidated, that is, when the slot persists after the user process is
> terminated.  Thus the message cannot be seen for temporary slots since
> they are removed at process termination and no longer exist after
> that.
> 
> At Wed, 08 Dec 2021 11:23:35 +0000, PG Bug reporting form 
> <noreply@postgresql.org <mailto:noreply@postgresql.org>> wrote in
>>  The core issue here then in our opinion is that Postgres server 
>> should log
>>  an error when the max_slot_wal_keep_size limit is reached for 
>> temporary
>>  replication slots as well as for permanent ones as otherwise
>>  users/administrators are presented only with non-descript connection
>>  termination errors which do not point to the actual cause of the 
>> problem.
> 
> If you mean the "invalidating slot" message by "an error", that
> wouldn't happen since invalidation is actually doesn't happen.  Or, we
> could change the message like this.  Does this make sense for you?
> 
>>  LOG:  terminating process 42601 to release temporary replication 
>> slot "pg_basebackup_42601"
>>  DETAIL:  The slot will be dropped by the process termination.
> 
> 
>>  LOG:  terminating process 3899 to release persistent replication 
>> slot "backup"
> ...
>>  LOG:  invalidating slot "backup" because its restart_lsn 
>> 47198/1E000000 exceeds max_slot_wal_keep_size
> 
> regards.
> 
> --
> Kyotaro Horiguchi
> NTT Open Source Software Center


--=-orfQ6kmTasK4xoE5xA0n
Content-Type: text/html; charset=us-ascii
Content-Transfer-Encoding: quoted-printable

<div id=3D"geary-body" dir=3D"auto"><div>Hello Kyotaro,</div><div><br></div=
><div>Understood, that makes sense re: invalidation and what I assumed migh=
t be happening.</div><div><br></div><div>I think I'm happy to leave the met=
hod of resolution up to you, I think the main point for me would be that wh=
en a&nbsp;</div><div>replication process gets terminated as a consequence o=
f the underlying temporary replication slot reaching max_slot_wal_keep_size=
</div><div>that we log a specific message to indicate to the user the cause=
 of the termination rather than leave it ambiguous.</div><div><br></div><di=
v>Thank you</div><div><br></div><div>King regards</div><div><br></div><div>=
Alex E</div><div>Senior Site Reliability Engineer</div><div>Altmetric</div>=
</div><div id=3D"geary-quote" dir=3D"auto"><br>On Mon, Dec 13 2021 at 14:44=
:42 +0900, Kyotaro Horiguchi &lt;horikyota.ntt@gmail.com&gt; wrote:<br><blo=
ckquote type=3D"cite"><div class=3D"plaintext" style=3D"white-space: break-=
spaces;">At Fri, 10 Dec 2021 15:46:11 +0000, Alex Enachioaie &lt;<a href=3D=
"mailto:alex@altmetric.com">alex@altmetric.com</a>&gt; wrote in=20
<blockquote> So, essentially the server side log emmitted on a temporary
 replication breaching max_slot_wal_keep_size limit is only:
=20
 2021-12-03 16:21:54 UTC [29724-2647] LOG: terminating process 42601 to
 release replication slot "pg_basebackup_42601"
=20
 whereas for a persistent replication slot we get an additional line
 that clearly states _why_ the replication process was terminated:
=20
 2021-12-03 00:57:16 UTC [29724-2645] LOG: terminating process 3899 to
 release replication slot "backup"
 2021-12-03 00:57:16 UTC [29724-2646] LOG: invalidating slot "backup"
 because its restart_lsn 47198/1E000000 exceeds max_slot_wal_keep_size
=20
 I'm not sure if this means that in the case of a temporary slot it
 does not get invalidated at all (I've not looked at the code), or it's
 simply that we don't emit a log message when it does because the slot
 would be discarded anyway, but such a message would be very useful for
 diagnostic purposes imo.
</blockquote>
The "invalidating slot" message is emitted when the slot needs to be
invalidated, that is, when the slot persists after the user process is
terminated.  Thus the message cannot be seen for temporary slots since
they are removed at process termination and no longer exist after
that.

At Wed, 08 Dec 2021 11:23:35 +0000, PG Bug reporting form &lt;<a href=3D"ma=
ilto:noreply@postgresql.org">noreply@postgresql.org</a>&gt; wrote in=20
<blockquote> The core issue here then in our opinion is that Postgres serve=
r should log
 an error when the max_slot_wal_keep_size limit is reached for temporary
 replication slots as well as for permanent ones as otherwise
 users/administrators are presented only with non-descript connection
 termination errors which do not point to the actual cause of the problem.
</blockquote>
If you mean the "invalidating slot" message by "an error", that
wouldn't happen since invalidation is actually doesn't happen.  Or, we
could change the message like this.  Does this make sense for you?

<blockquote> LOG:  terminating process 42601 to release temporary replicati=
on slot "pg_basebackup_42601"
 DETAIL:  The slot will be dropped by the process termination.
</blockquote>

<blockquote> LOG:  terminating process 3899 to release persistent replicati=
on slot "backup"=20
</blockquote>...
<blockquote> LOG:  invalidating slot "backup" because its restart_lsn 47198=
/1E000000 exceeds max_slot_wal_keep_size
</blockquote>
regards.

<div>--=20
</div>Kyotaro Horiguchi
NTT Open Source Software Center
</div></blockquote></div>
--=-orfQ6kmTasK4xoE5xA0n--