Re: WAL segments removed from primary despite the fact that logical replication slot needs it.

On Fri, Nov 11, 2022 at 8:20 PM hubert depesz lubaczewski
<depesz(at)depesz(dot)com> wrote:
>
> On Thu, Oct 20, 2022 at 01:55:16PM +0200, hubert depesz lubaczewski wrote:
> > Hi,
> > just an update. Due to procedures we will upgrade to 12.12 at the
> > beginning of November. Then, I'll try to replicate the problem again,
> > and we'll see how this will pan out.
> > For next test will do my best to use debug2 log level.
>
> So. I have an update.
>
> Out of 8 servers that we prepared upgrade for, one failed with the
> same/similar problem.
> Unfortunately I don't know if this is the same server as before. Sorry.
>
> Specifically, I see now, in logs on focal/pg14 side:
>
> #v+
> 2022-11-11 12:45:26.432 UTC,,,994963,,636e43e6.f2e93,2,,2022-11-11 12:45:26 UTC,6/0,0,ERROR,08P01,"could not receive data from WAL stream: ERROR: requested WAL segment 000000010001039D00000083 has already been removed",,,,,,,,,"","logical replication worker",,0
> #v-
>
> On source (bionic/pg12), I see:
>
> #v+
> =# select * from pg_replication_slots ;
> slot_name │ plugin │ slot_type │ datoid │ database │ temporary │ active │ active_pid │ xmin │ catalog_xmin │ restart_lsn │ confirmed_flush_lsn
> ═══════════╪══════════╪═══════════╪════════╪══════════╪═══════════╪════════╪════════════╪════════╪══════════════╪════════════════╪═════════════════════
> focal14 │ pgoutput │ logical │ 16607 │ canvas │ f │ f │ [null] │ [null] │ 3241443528 │ 1039D/83825958 │ 1039D/96453F38
> (1 row)
> #v-
>
> but pg, like previously, lost some wal files, this time 8 of them:
>
> #v+
> =$ sudo ls -l ~postgres/12/main/pg_wal | head
> total 224403644
> -rw------- 1 postgres postgres 349 Feb 11 2022 000000010000BDEF000000FF.00045F68.backup
> -rw------- 1 postgres postgres 16777216 Nov 10 19:08 000000010001039D0000008B
> -rw------- 1 postgres postgres 16777216 Nov 10 19:08 000000010001039D0000008C
> -rw------- 1 postgres postgres 16777216 Nov 10 19:08 000000010001039D0000008D
> ...
> #v-
>
> This time we had debug2 enabled on both sides.
>
> Looks like we lost segments:
> 000000010001039D00000083, 000000010001039D00000084,
> 000000010001039D00000085, 000000010001039D00000086,
> 000000010001039D00000087, 000000010001039D00000088,
> 000000010001039D00000089, and 000000010001039D0000008A.
>
> It looks that first time replica logged the error was:
>
> #v+
> 2022-11-10 21:06:16.427 UTC,,,572364,,636d67c8.8bbcc,2,,2022-11-10 21:06:16 UTC,6/0,0,ERROR,08P01,"could not receive data from WAL stream: ERROR: requested WAL segment 000000010001039D00000083 has already been removed",,,,,,,,,"","logical replication worker",,0
> #v-
>
> In Pg logs on source I see:
>
> #v+
> 2022-11-10 21:01:07.531 UTC,,,28925,,636378d6.70fd,4586739,,2022-11-03 08:16:22 UTC,,0,DEBUG,00000,"recycled write-ahead log file ""000000010001039D00000082""",,,,,,,,,""
> 2022-11-10 21:06:07.523 UTC,,,28925,,636378d6.70fd,4594903,,2022-11-03 08:16:22 UTC,,0,DEBUG,00000,"recycled write-ahead log file ""000000010001039D00000083""",,,,,,,,,""
> 2022-11-10 21:06:07.524 UTC,,,28925,,636378d6.70fd,4594904,,2022-11-03 08:16:22 UTC,,0,DEBUG,00000,"recycled write-ahead log file ""000000010001039D00000084""",,,,,,,,,""
> 2022-11-10 21:06:07.525 UTC,,,28925,,636378d6.70fd,4594905,,2022-11-03 08:16:22 UTC,,0,DEBUG,00000,"recycled write-ahead log file ""000000010001039D00000085""",,,,,,,,,""
> 2022-11-10 21:06:07.526 UTC,,,28925,,636378d6.70fd,4594906,,2022-11-03 08:16:22 UTC,,0,DEBUG,00000,"recycled write-ahead log file ""000000010001039D00000086""",,,,,,,,,""
> 2022-11-10 21:06:07.527 UTC,,,28925,,636378d6.70fd,4594907,,2022-11-03 08:16:22 UTC,,0,DEBUG,00000,"recycled write-ahead log file ""000000010001039D00000087""",,,,,,,,,""
> 2022-11-10 21:06:07.528 UTC,,,28925,,636378d6.70fd,4594908,,2022-11-03 08:16:22 UTC,,0,DEBUG,00000,"recycled write-ahead log file ""000000010001039D00000088""",,,,,,,,,""
> 2022-11-10 21:06:07.529 UTC,,,28925,,636378d6.70fd,4594909,,2022-11-03 08:16:22 UTC,,0,DEBUG,00000,"recycled write-ahead log file ""000000010001039D00000089""",,,,,,,,,""
> 2022-11-10 21:06:07.530 UTC,,,28925,,636378d6.70fd,4594910,,2022-11-03 08:16:22 UTC,,0,DEBUG,00000,"recycled write-ahead log file ""000000010001039D0000008A""",,,,,,,,,""
> 2022-11-10 21:06:16.426 UTC,"upgrayedd","canvas",28608,"10.1.238.101:45328",636d67c8.6fc0,8,"idle",2022-11-10 21:06:16 UTC,147/0,0,ERROR,58P01,"requested WAL segment 000000010001039D00000083 has already been removed",,,,,,"START_REPLICATION SLOT ""focal14"" LOGICAL 1039D/9754F6F8 (proto_version '1', publication_names '""focal14""')",,,"focal14"
> 2022-11-10 21:06:21.456 UTC,"upgrayedd","canvas",28815,"10.1.238.101:52316",636d67cd.708f,8,"idle",2022-11-10 21:06:21 UTC,147/0,0,ERROR,58P01,"requested WAL segment 000000010001039D00000083 has already been removed",,,,,,"START_REPLICATION SLOT ""focal14"" LOGICAL 1039D/9754F6F8 (proto_version '1', publication_names '""focal14""')",,,"focal14"
> 2022-11-10 21:06:26.488 UTC,"upgrayedd","canvas",28962,"10.1.238.101:52320",636d67d2.7122,8,"idle",2022-11-10 21:06:26 UTC,148/0,0,ERROR,58P01,"requested WAL segment 000000010001039D00000083 has already been removed",,,,,,"START_REPLICATION SLOT ""focal14"" LOGICAL 1039D/9754F6F8 (proto_version '1', publication_names '""focal14""')",,,"focal14"
> #v-
>
> So, the whole set of missing files was recycled at the same time.
>
> One more thing that I have is copy of pg_replication_slots info. This data is taken periodically, around every 1 minute. Each line, aside from pg_replication_slots slots data has also output of pg_current_wal_lsn() and timestamp. Looks like this:
>
> #v+
> timestamp pg_current_wal_lsn slot_name plugin slot_type datoid database temporary active active_pid xmin catalog_xmin restart_lsn confirmed_flush_lsn
...
...
> 2022-11-10 21:02:52 UTC 103A7/B45ECEA8 focal14 pgoutput logical 16607 canvas f f \N \N 3241434855 1039D/83825958 1039D/911A8DB0
> 2022-11-10 21:03:52 UTC 103A7/C4355F60 focal14 pgoutput logical 16607 canvas f t 21748 \N 3241443528 1039D/83825958 1039D/955633D0
...

I think from the above two it is clear that the slot with restart_lsn
1039D/83825958 is active and we seem to have recycled corresponding
segment.

>
> Now, I can keep this situation up for some time, if more debug will be helpful,
> but I don't know how long (disk space issues).
>
> Is there anything in here that helps? Any other info I can dig out?
>

You may have the LOG for "attempting to remove WAL segments older than
log file %s", if so, please share. Also on similar lines, I think we
need to add some LOGs before calling RemoveOldXlogFiles() to know
where our computation to remove files goes off. Something, like the
attached, would be helpful but note I have added this quickly on my
working branch to show you what I have in mind. You may need small
changes based on the branch you are working on.

--
With Regards,
Amit Kapila.