From: Samuel VISCAPI <samuel.viscapi@xelians.fr>
To: Alvaro Herrera <alvherre@alvh.no-ip.org>
CC: "pgsql-admin@lists.postgresql.org" <pgsql-admin@lists.postgresql.org>
Subject: RE: 2nd PostgreSQL server in WAL shipping cluster fails to start
Thread-Topic: 2nd PostgreSQL server in WAL shipping cluster fails to start
Thread-Index: AdtifmqCI/mjxc4zTd6+dTy4ZYsnWQACMquABBvf7qAACGHu4A==
Date: Thu, 30 Jan 2025 14:14:32 +0000
Message-ID: 
 <MR2P264MB014725DBCD35E59B6F77CB07FEE92@MR2P264MB0147.FRAP264.PROD.OUTLOOK.COM>
References: 
 <MR2P264MB0147200E004CB5C9FC761ACCFE132@MR2P264MB0147.FRAP264.PROD.OUTLOOK.COM>
 <202501091111.ds3gg5ae7kyc@alvherre.pgsql>
 <MR2P264MB014775B1000AD1C59C5EA584FEE92@MR2P264MB0147.FRAP264.PROD.OUTLOOK.COM>
In-Reply-To: 
 <MR2P264MB014775B1000AD1C59C5EA584FEE92@MR2P264MB0147.FRAP264.PROD.OUTLOOK.COM>
Accept-Language: fr-FR, en-US
Content-Language: fr-FR
x-ms-exchange-antispam-messagedata-chunkcount: 1
x-ms-exchange-antispam-messagedata-0: 
 =?iso-8859-1?Q?eyXWHpZtk59niSAZPbKZinUZfQGYRiqW1fIghvaP9ZzmkYBhvz+wqxPJtl?=
 =?iso-8859-1?Q?BelVgZNgP1askrth02AYzAXeSiIRY7a05NqhUI3hFxHkbJAvGXmb4HqZHu?=
 =?iso-8859-1?Q?oRUNooTJf6A27Vg80yqXPfXxjTMOdEEuiv2+cBCiQmosSZWr2qxtbNaYqT?=
 =?iso-8859-1?Q?ee/uDo8T/YWzfoV7ENA1xI9nCPTmt6iVZ+ZnEIeF/HGUCJJbZUjDKXU4yr?=
 =?iso-8859-1?Q?qUDWEBehpG+DcGWO87QkvxiajvLeNH7AZuiaYhe6nNr4MbpuUtJkra8FQV?=
 =?iso-8859-1?Q?Bo6WDWxaCtR2oK9ZTlPGWTOpevCho/BtqcdN2UL+rZVmZ6pAHuORVBIG9C?=
 =?iso-8859-1?Q?qXKwO+0Ptf374ZSf1S/Wl3S7F0mrVW9TSc47hu2fmyLzVgTEAzy+h90mgG?=
 =?iso-8859-1?Q?jYsPmPiuENsDlWkGpI/Io6l+zTRJMyUdM8fzxd+qk+CXKWZGo5+8jWzC1k?=
 =?iso-8859-1?Q?rJDWzr/+diAh5pV6XEsGxOhtv+16VZdsUiZ2IJqYbg7xk4PH+jzc0k5HG/?=
 =?iso-8859-1?Q?5Q2oKcuSlXnKXwkwNeadsf1D5TZBjge3bIMzMr2TL3vnHcniZr7d3T+wxw?=
 =?iso-8859-1?Q?GeCSUwYp0w80Lg04f9bXYqLPcp8iQ0OUkj5m6tzRFsMOHHOpoUJ96+j3IU?=
 =?iso-8859-1?Q?8srroEJuCWIxqK9NZAR6p1H6aM/1dB/kvC+12IQpJvFc2Z/LFZjUMRkWUR?=
 =?iso-8859-1?Q?o/SD8zXqYQhdNo4eJt86zrfX4f9xUgOiVPpzYkbogY3X/ytaltoDaQw2VY?=
 =?iso-8859-1?Q?HoU2YiufpvsymiSFau510ZDIRuivyboljIosoWLCC+H3ynz58V24x2XTUo?=
 =?iso-8859-1?Q?FIee2YYN3+lWa7jCaruBIi/6lb6mB8prcRj0so2y8V5nqS2PnsxfWCL1br?=
 =?iso-8859-1?Q?SCPDR1lh8lgJ+JkiFPl4YzWoXp2YqVx0io79wcmpQaU/IJQxjwO3kBOYVs?=
 =?iso-8859-1?Q?b68sSY583esKGFlMmh6B7WO0GofkK6qmtCnsZzFWPapKjMFKHIB8KGn5z4?=
 =?iso-8859-1?Q?Qvm11JnjrGjC9I0N5YE0J4CwRJgvvv2ONU9EiOpJpETu5jMWfdRfuFequa?=
 =?iso-8859-1?Q?eHzT/5pc1BqjjAGuV0uS3WMNeYg19CRQ7EUK/pUMnymJC6LUdEjRERp7Eh?=
 =?iso-8859-1?Q?yKRX9iSEKDXrpzqLHHDfgLti69+NF1NMfeOvKwwvdlLvq2xy1WeAKbyZxj?=
 =?iso-8859-1?Q?+7w77WEajKoOQXyUvjuuCdUOqdIyNk1ma4KD31enG0gLJ9cCQwRB8waMwm?=
 =?iso-8859-1?Q?8l5DxSMsuF8ps9kn+ytfrWAUuJpcm5us/yyfOkJ4wx7+n5cusgSphBsPI7?=
 =?iso-8859-1?Q?kLVp4T4IlGZGWK1gxfC+2hMGXb2VAtZ1XKgtBgF9MNlRPkQNZkmBc/jPaA?=
 =?iso-8859-1?Q?fpJvyLU9EkKaDVyar194+qeJOKTwtsR5E2kJACwQ7LADw3z7el7rlKFf0Z?=
 =?iso-8859-1?Q?K9wxbY/z68CH2Tc4MsnlNQ6lPL27HF2zgDvyHyi2llX0Ktzcca9TQq16q+?=
 =?iso-8859-1?Q?dB1wkyKD/jpyXCiZ+HmMgeomYCT9/+NbY84vsLJuexsQ+cZp7kNlM8tm9r?=
 =?iso-8859-1?Q?PrMZfzDlTBDcSEer7kFdsJSRBxQ22f4KNgtwjg9zX70nqrzSuUTQXr/QGq?=
 =?iso-8859-1?Q?/OYoqcFK6pHva16nukc5NCJ8cdj8s7p1sW3SWDDVv3+dEDQuM50Ju863T/?=
 =?iso-8859-1?Q?KgDdgNXLyAKsv/aOWDyDxcel8oM2b0ebId4gyj7b?=
Content-Type: text/plain; charset="iso-8859-1"
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-OriginatorOrg: xelians.fr
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-AuthSource: MR2P264MB0147.FRAP264.PROD.OUTLOOK.COM
X-MS-Exchange-CrossTenant-Network-Message-Id: 
 226eee97-e080-43b4-dff9-08dd41386ae5
X-MS-Exchange-CrossTenant-originalarrivaltime: 30 Jan 2025 14:14:32.3315
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Hosted
X-MS-Exchange-CrossTenant-id: 6fc1c04c-4bce-498f-bdd2-4a407cbd7dcd
X-MS-Exchange-CrossTenant-mailboxtype: HOSTED
X-MS-Exchange-CrossTenant-userprincipalname: 
 6csK8iGYAPt18VfxLH8OZYtl4fyelGnkXZixODXW+J3+81Qiqp/Z3kaCN/S/MrPTOFG6GUsehKMS+7pSpakgl6Yeh8kgfEOxoyT0JUfWFYc=
X-MS-Exchange-Transport-CrossTenantHeadersStamped: PR0P264MB2344
List-Id: <pgsql-admin.lists.postgresql.org>
List-Help: <https://lists.postgresql.org/manage/>
List-Subscribe: <https://lists.postgresql.org/manage/>
List-Post: <mailto:pgsql-admin@lists.postgresql.org>
List-Owner: <mailto:pgsql-admin-owner@lists.postgresql.org>
List-Archive: <https://www.postgresql.org/list/pgsql-admin>
Archived-At: 
 <https://www.postgresql.org/message-id/MR2P264MB014725DBCD35E59B6F77CB07FEE92%40MR2P264MB0147.FRAP264.PROD.OUTLOOK.COM>
Precedence: bulk

Dear all,

A quick follow-up message :

Files were indeed removed from the primary server in order to make some roo=
m. The directory /some_app/data/mnt/server/archivedir/ used in the "archive=
_command" eventually almost filled up the whole partition (118GB) where the=
 application data is kept. So it's been decided to remove those files in or=
der to keep the application running. That directory is growing again on the=
 primary server though, with 506 files now (7.9GB). For comparison, on the =
stand-by server that same directory contains only 1 file of 17MB. That file=
 is from ~2 years ago (February 2023). I think this is when the stand-by se=
rver stopped running. As of today, that server is still down.

Regarding the "pg_wal" directories on both nodes:

- Stand-by server : 5 files + "archive_status" directory. Among the files t=
here is one 000000010000000D000000D6, as per the original error message.
- Primary server : 8 files + "archive_status" directory. The file 000000010=
000000D000000D6 is missing there.

I still believe "pg_basebackup" to be the most promising lead to solve the =
issue at hand and recreate the replica from scratch.

What do you think ? Finally, since storage size can be an issue, I understa=
nd one can configure PostgreSQL to compress the archive logs, as per : http=
s://www.postgresql.org/docs/13/continuous-archiving.html#BACKUP-TIPS . Woul=
d you have any prior experience with that setting ?

Many thanks again for your help.

Best regards,

Samuel

-----Message d'origine-----
De=A0: Samuel VISCAPI=20
Envoy=E9=A0: jeudi 30 janvier 2025 10:54
=C0=A0: Alvaro Herrera <alvherre@alvh.no-ip.org>
Cc=A0: pgsql-admin@lists.postgresql.org
Objet=A0: RE: 2nd PostgreSQL server in WAL shipping cluster fails to start

Dear Alvaro and Anton,

Thank you for your quick replies, really appreciated. I ran some more tests=
 today and the results are as follows:

Available disk space on primary server : 101GB free in the data directory. =
I believe some cleaning up has been done, I need to check with my colleague=
s about that.
Wal_sender_timeout : #wal_sender_timeout =3D 60s Wal_keep_segments : not pr=
esent in postgresql.conf Networking issues : none at the moment, the primar=
y server can ping the server in standby mode by its IP address. Name resolu=
tion doesn't work though.
Monitor replication lag between the two nodes:
- Primary node :=20

SELECT pg_current_wal_lsn();
 pg_current_wal_lsn
--------------------
 18/B6C404B8

- Standby node : TODO when the node is up again

I'm tempted to give the pgbasebackup command a go: https://www.postgresql.o=
rg/docs/13/app-pgbasebackup.html

pg_basebackup -h primary_host -D /some_app/data -U postgres -v -P

@Alvaro Herrera : the archive_command is indeed set in the primary server, =
as follows:

archive_command =3D 'test ! -f /some_app/data/mnt/server/archivedir/%f && c=
p %p /some_app/data/mnt/server/archivedir/%f'

There are some files in the pg_wal directory but they only amount to 289MB.=
 If I need to rebuild the replica from scratch, could I use the pg_baseback=
up command above for that purpose ?

And you are obviously right about the error message in French. Please find =
it below:

2025-01-09 09:46:35.742 CET [3147382] FATAL:  n'a pas pu recevoir des donn=
=E9es du flux de WAL : ERREUR:  le segment demand=E9 du journal de transact=
ion, 000000010000000D000000D6, a d=E9j=E0 =E9t=E9 supprim=E9
2025-01-09 09:46:40.745 CET [3147395] LOG:  d=E9marr=E9 le flux des journau=
x depuis le principal =E0 D/D6000000 sur la timeline 1
2025-01-09 09:46:40.745 CET [3147395] FATAL:  n'a pas pu recevoir des donn=
=E9es du flux de WAL : ERREUR:  le segment demand=E9 du journal de transact=
ion, 000000010000000D000000D6, a d=E9j=E0 =E9t=E9 supprim=E9
2025-01-09 09:46:45.749 CET [3147397] LOG:  d=E9marr=E9 le flux des journau=
x depuis le principal =E0 D/D6000000 sur la timeline 1
2025-01-09 09:46:45.749 CET [3147397] FATAL:  n'a pas pu recevoir des donn=
=E9es du flux de WAL : ERREUR:  le segment demand=E9 du journal de transact=
ion, 000000010000000D000000D6, a d=E9j=E0 =E9t=E9 supprim=E9
2025-01-09 09:46:50.753 CET [3147424] LOG:  d=E9marr=E9 le flux des journau=
x depuis le principal =E0 D/D6000000 sur la timeline 1
2025-01-09 09:46:50.753 CET [3147424] FATAL:  n'a pas pu recevoir des donn=
=E9es du flux de WAL : ERREUR:  le segment demand=E9 du journal de transact=
ion, 000000010000000D000000D6, a d=E9j=E0 =E9t=E9 supprim=E9

Thanks again for your help.

Best regards,

Samuel

-----Message d'origine-----
De=A0: Alvaro Herrera <alvherre@alvh.no-ip.org> Envoy=E9=A0: jeudi 9 janvie=
r 2025 12:11 =C0=A0: Samuel VISCAPI <samuel.viscapi@xelians.fr> Cc=A0: pgsq=
l-admin@lists.postgresql.org Objet=A0: Re: 2nd PostgreSQL server in WAL shi=
pping cluster fails to start

On 2025-Jan-09, Samuel VISCAPI wrote:

> Dear all,
>=20
> Some years ago I set up a two PostgreSQL 13 nodes cluster on Debian 11. T=
his cluster uses the Write-Ahead Log Shipping method. I've just been told t=
he second server (in standby mode) is down and refuses to start again with =
the following error message (roughly translated from French) :
>=20
> 2025-01-09 09:46:35.742 CET [3147382] FATAL:  could not receive data=20
> from WAL stream: ERROR:  segment requested from transaction journal,=20
> 000000010000000D000000D6, has already been removed
> 2025-01-09 09:46:40.745 CET [3147395] LOG:  journal flow started from=20
> primary at D/D6000000 on timeline 1
> 2025-01-09 09:46:40.745 CET [3147395] FATAL:  could not receive data=20
> from WAL stream : ERROR:  segment requested from transaction journal,=20
> 000000010000000D000000D6, has already been removed
> 2025-01-09 09:46:45.749 CET [3147397] LOG: journal flow started from=20
> primary at D/D6000000 on timeline 1
> 2025-01-09 09:46:45.749 CET [3147397] FATAL:  could not receive data=20
> from WAL stream : ERROR:  segment requested from transaction journal,=20
> 000000010000000D000000D6, has already been removed
> 2025-01-09 09:46:50.753 CET [3147424] LOG:  journal flow started from=20
> primary at D/D6000000 on timeline 1
> 2025-01-09 09:46:50.753 CET [3147424] FATAL:  could not receive data=20
> from WAL stream : ERROR:  segment requested from transaction journal,=20
> 000000010000000D000000D6, has already been removed

This means the standby is requesting a segment that was already removed.
You may be able to find those files in a WAL archive, if you have archive_c=
ommand set in the primary.  If you do, then it would work to copy those to =
the standby's pg_wal/ subdirectory.  If you don't have them, then the repli=
ca must be rebuilt.


Note that it's not a good idea to translate the error messages when posting=
 -- that is, it's better to post exactly what the log file has.
For helpfulness you could post a translation for the lines separately.
But the developers can find the translated messages in the source code, if =
they need them ... but if you translate them yourself, there's no way to kn=
ow exactly which ones they are.  Sometimes subtle differences are important=
 cues.

--=20
=C1lvaro Herrera               48=B001'N 7=B057'E  -  https://www.Enterpris=
eDB.com/