Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1t8ab8-004z0K-Id for pgsql-hackers@arkaria.postgresql.org; Wed, 06 Nov 2024 07:37:02 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1t8ab5-004Hti-74 for pgsql-hackers@arkaria.postgresql.org; Wed, 06 Nov 2024 07:36:59 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1t8ab4-004Hta-HC for pgsql-hackers@lists.postgresql.org; Wed, 06 Nov 2024 07:36:59 +0000 Received: from zcsmtaf02-pub.meteo.fr ([137.129.63.6]) by makus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1t8ab0-000QvC-Bg for pgsql-hackers@lists.postgresql.org; Wed, 06 Nov 2024 07:36:57 +0000 Received: from localhost (localhost.localdomain [127.0.0.1]) by zcsmtaf02-pub.meteo.fr (Postfix) with ESMTP id 7FE444000C54 for ; Wed, 6 Nov 2024 07:36:51 +0000 (GMT) Received: from zcsmtaf02-pub.meteo.fr ([127.0.0.1]) by localhost (zcsmtaf02.meteo.fr [127.0.0.1]) (amavis, port 10032) with ESMTP id O8H_7T-qI2es for ; Wed, 6 Nov 2024 07:36:51 +0000 (GMT) Received: from localhost (localhost.localdomain [127.0.0.1]) by zcsmtaf02-pub.meteo.fr (Postfix) with ESMTP id 6650C4000C5D for ; Wed, 6 Nov 2024 07:36:51 +0000 (GMT) X-Virus-Scanned: amavis at meteo.fr Received: from zcsmtaf02-pub.meteo.fr ([127.0.0.1]) by localhost (zcsmtaf02.meteo.fr [127.0.0.1]) (amavis, port 10026) with ESMTP id cg4z9M-92JLT for ; Wed, 6 Nov 2024 07:36:51 +0000 (GMT) Received: from zcsmsm01.meteo.fr (zcsmsm01.meteo.fr [172.24.3.121]) by zcsmtaf02-pub.meteo.fr (Postfix) with ESMTP id 5157B4000C54 for ; Wed, 6 Nov 2024 07:36:51 +0000 (GMT) Date: Wed, 6 Nov 2024 07:36:51 +0000 (GMT) From: =?utf-8?Q?RECHT=C3=89?= Marc To: pgsql-hackers@lists.postgresql.org Message-ID: <638764862.181008636.1730878611279.JavaMail.zimbra@meteo.fr> Subject: Logical replication timeout MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="=_66ceaccb-a068-44ef-8616-91d89f740551" X-Originating-IP: [172.24.2.156] X-Mailer: Zimbra 9.0.0_GA_4583 (ZimbraWebClient - GC130 (Linux)/9.0.0_GA_4583) Thread-Index: 848lO3ZBpxJC8yKOFRBlJK2vymsFUg== Thread-Topic: Logical replication timeout List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --=_66ceaccb-a068-44ef-8616-91d89f740551 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable Hello,=20 For some unknown reason (probably a very big transaction at the source), we= experienced a logical decoding breakdown,=20 due to a timeout from the subscriber side (either wal_receiver_timeout or c= onnexion drop by network equipment due to inactivity).=20 The problem is, that due to that failure, the wal_receiver process stops. W= hen the wal_sender is ready to send some data, it finds the connexion broke= n and exits.=20 A new wal_sender process is created that restarts from the beginning (resta= rt LSN). This is an endless loop.=20 Checking the network connexion between wal_sender and wal_receiver, we foun= d that no traffic occurs for hours.=20 We first increased wal_receiver_timeout up to 12h and still got a disconnec= tion on the receiver party:=20 2024-10-17 16:31:58.645 GMT [1356203:2] user=3D,db=3D,app=3D,client=3D ERRO= R: terminating logical replication worker due to timeout=20 2024-10-17 16:31:58.648 GMT [849296:212] user=3D,db=3D,app=3D,client=3D LOG= : background worker "logical replication worker" (PID 1356203) exited with = exit code 1=20 Then put this parameter to 0, but got then disconnected by the network (not= e the slight difference in message):=20 2024-10-21 11:45:42.867 GMT [1697787:2] user=3D,db=3D,app=3D,client=3D ERRO= R: could not receive data from WAL stream: could not receive data from serv= er: Connection timed out=20 2024-10-21 11:45:42.869 GMT [849296:40860] user=3D,db=3D,app=3D,client=3D L= OG: background worker "logical replication worker" (PID 1697787) exited wit= h exit code 1=20 The message is generated in libpqrcv_receive function (replication/libpqwal= receiver/libpqwalreceiver.c) which calls pqsecure_raw_read (interfaces/libp= q/fe-secure.c)=20 The last message "Connection timed out" is the errno translation from the r= ecv system function:=20 ETIMEDOUT Connection timed out (POSIX.1-2001)=20 When those timeout occurred, the sender was still busy deleting files from = data/pg_replslot/bdcpb21_sene, accumulating more than 6 millions small ".sp= ill" files.=20 It seems this very long pause is at cleanup stage were PG is blindly trying= to delete those files.=20 strace on wal sender show tons of calls like:=20 unlink("pg_replslot/bdcpb21_sene/xid-2 721 821 917-lsn-439C-0.spill") =3D -= 1 ENOENT (Aucun fichier ou dossier de ce type)=20 unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-1000000.spill") = =3D -1 ENOENT (Aucun fichier ou dossier de ce type)=20 unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-2000000.spill") = =3D -1 ENOENT (Aucun fichier ou dossier de ce type)=20 unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-3000000.spill") = =3D -1 ENOENT (Aucun fichier ou dossier de ce type)=20 unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-4000000.spill") = =3D -1 ENOENT (Aucun fichier ou dossier de ce type)=20 unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-5000000.spill") = =3D -1 ENOENT (Aucun fichier ou dossier de ce type)=20 This occurs in ReorderBufferRestoreCleanup (backend/replication/logical/reo= rderbuffer.c).=20 The call stack presumes this may probably occur in DecodeCommit or DecodeAb= ort (backend/replication/logical/decode.c):=20 unlink("pg_replslot/bdcpb21_sene/xid-2730444214-lsn-43A6-88000000.spill") = =3D -1 ENOENT (Aucun fichier ou dossier de ce type)=20 > /usr/lib64/libc-2.17.so(unlink+0x7) [0xf12e7]=20 > /usr/pgsql-15/bin/postgres(ReorderBufferRestoreCleanup.isra.17+0x5d) [0x7= 69e3d]=20 > /usr/pgsql-15/bin/postgres(ReorderBufferCleanupTXN+0x166) [0x76aec6] <=3D= =3D=3D replication/logical/reorderbuff.c:1480 (mais cette fonction (static)= n'est utili=C3=A9e qu'au sein de ce module ...)=20 > /usr/pgsql-15/bin/postgres(xact_decode+0x1e7) [0x75f217] <=3D=3D=3D repli= cation/logical/decode.c:175=20 > /usr/pgsql-15/bin/postgres(LogicalDecodingProcessRecord+0x73) [0x75eee3] = <=3D=3D=3D replication/logical/decode.c:90, appelle la fonction rmgr.rm_dec= ode(ctx, &buf) =3D 1 des 6 m=C3=A9thodes du resource manager=20 > /usr/pgsql-15/bin/postgres(XLogSendLogical+0x4e) [0x78294e]=20 > /usr/pgsql-15/bin/postgres(WalSndLoop+0x151) [0x785121]=20 > /usr/pgsql-15/bin/postgres(exec_replication_command+0xcba) [0x785f4a]=20 > /usr/pgsql-15/bin/postgres(PostgresMain+0xfa8) [0x7d0588]=20 > /usr/pgsql-15/bin/postgres(ServerLoop+0xa8a) [0x493b97]=20 > /usr/pgsql-15/bin/postgres(PostmasterMain+0xe6c) [0x74d66c]=20 > /usr/pgsql-15/bin/postgres(main+0x1c5) [0x494a05]=20 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf4) [0x22554]=20 > /usr/pgsql-15/bin/postgres(_start+0x28) [0x494fb8]=20 We did not find any other option than deleting the subscription to stop tha= t loop and start a new one (thus loosing transactions).=20 The publisher is PostgreSQL 15.6=20 The subscriber is PostgreSQL 14.5=20 Thanks=20 --=_66ceaccb-a068-44ef-8616-91d89f740551 Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: quoted-printable
Hello,

For some= unknown reason (probably a very big transaction at the source), we experie= nced a logical decoding breakdown, 
due to a timeout from th= e subscriber side (either wal_receiver_timeout or connexion drop by network= equipment due to inactivity).

The problem is, tha= t due to that failure, the wal_receiver process stops. When the wal_sender = is ready to send some data, it finds the connexion broken and exits. <= /div>
A new wal_sender process is created that restarts from the beginn= ing (restart LSN). This is an endless loop.

Checki= ng the network connexion between wal_sender and wal_receiver, we found that= no traffic occurs for hours.

We first increased w= al_receiver_timeout up to 12h and still got a disconnection on the receiver= party:

2024-10-17 16:31:58.645 GMT [1356203:2] us= er=3D,db=3D,app=3D,client=3D ERROR:  terminating logical replication w= orker due to timeout
2024-10-17 16:31:58.648 GMT [849296:212] use= r=3D,db=3D,app=3D,client=3D LOG:  background worker "logical replicati= on worker" (PID 1356203) exited with exit code 1

T= hen put this parameter to 0, but got then disconnected by the network (note= the slight difference in message):

2024-10-21 11:= 45:42.867 GMT [1697787:2] user=3D,db=3D,app=3D,client=3D ERROR:  could= not receive data from WAL stream: could not receive data from server: Conn= ection timed out
2024-10-21 11:45:42.869 GMT [849296:40860] user= =3D,db=3D,app=3D,client=3D LOG:  background worker "logical replicatio= n worker" (PID 1697787) exited with exit code 1

Th= e message is generated in libpqrcv_receive function (replication/libpqwalre= ceiver/libpqwalreceiver.c) which calls pqsecure_raw_read (interfaces/libpq/= fe-secure.c)

The last message "Connection timed ou= t" is the errno translation from the recv system function:

ETIMEDOUT       Connection timed out (POSIX.1-= 2001)

When those timeout occurred, the sender was = still busy deleting files from data/pg_replslot/bdcpb21_sene, accumulating = more than 6 millions small ".spill" files.
It seems this very lon= g pause is at cleanup stage were PG is blindly trying to delete those files= .

strace on wal sender show tons of calls like:

unlink("pg_replslot/bdcpb21_sene/xid-2 721 821 917-l= sn-439C-0.spill") =3D -1 ENOENT (Aucun fichier ou dossier de ce type)
=
unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-1000000.spill= ") =3D -1 ENOENT (Aucun fichier ou dossier de ce type)
unlink("pg= _replslot/bdcpb21_sene/xid-2721821917-lsn-439C-2000000.spill") =3D -1 ENOEN= T (Aucun fichier ou dossier de ce type)
unlink("pg_replslot/bdcpb= 21_sene/xid-2721821917-lsn-439C-3000000.spill") =3D -1 ENOENT (Aucun fichie= r ou dossier de ce type)
unlink("pg_replslot/bdcpb21_sene/xid-272= 1821917-lsn-439C-4000000.spill") =3D -1 ENOENT (Aucun fichier ou dossier de= ce type)
unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439= C-5000000.spill") =3D -1 ENOENT (Aucun fichier ou dossier de ce type)
=

This occurs in ReorderBufferRestoreCleanup (backend/rep= lication/logical/reorderbuffer.c). 
The call stack presumes = this may probably occur in DecodeCommit or DecodeAbort (backend/replication= /logical/decode.c):

unlink("pg_replslot/bdcpb21_se= ne/xid-2730444214-lsn-43A6-88000000.spill") =3D -1 ENOENT (Aucun fichier ou= dossier de ce type)
 > /usr/lib64/libc-2.17.so(unlink+0x= 7) [0xf12e7]
 > /usr/pgsql-15/bin/postgres(ReorderBufferR= estoreCleanup.isra.17+0x5d) [0x769e3d]
 > /usr/pgsql-15/b= in/postgres(ReorderBufferCleanupTXN+0x166) [0x76aec6] <=3D=3D=3D replica= tion/logical/reorderbuff.c:1480 (mais cette fonction (static) n'est utili= =C3=A9e qu'au sein de ce module ...)
 > /usr/pgsql-15/bin= /postgres(xact_decode+0x1e7) [0x75f217] <=3D=3D=3D replication/logical/d= ecode.c:175 
 > /usr/pgsql-15/bin/postgres(LogicalDe= codingProcessRecord+0x73) [0x75eee3] <=3D=3D=3D replication/logical/deco= de.c:90, appelle la fonction rmgr.rm_decode(ctx, &buf) =3D 1 des 6 m=C3= =A9thodes du resource manager
 > /usr/pgsql-15/bin/postgr= es(XLogSendLogical+0x4e) [0x78294e]
 > /usr/pgsql-15/bin/= postgres(WalSndLoop+0x151) [0x785121]
 > /usr/pgsql-15/bi= n/postgres(exec_replication_command+0xcba) [0x785f4a]
 > = /usr/pgsql-15/bin/postgres(PostgresMain+0xfa8) [0x7d0588]
 &= gt; /usr/pgsql-15/bin/postgres(ServerLoop+0xa8a) [0x493b97]
 = ;> /usr/pgsql-15/bin/postgres(PostmasterMain+0xe6c) [0x74d66c]
 > /usr/pgsql-15/bin/postgres(main+0x1c5) [0x494a05]
&nb= sp;> /usr/lib64/libc-2.17.so(__libc_start_main+0xf4) [0x22554]
 > /usr/pgsql-15/bin/postgres(_start+0x28) [0x494fb8]
We did not find any other option than deleting the subscriptio= n to stop that loop and start a new one (thus loosing transactions).
<= div>
The publisher is PostgreSQL 15.6
The subscribe= r is PostgreSQL 14.5

Thanks
--=_66ceaccb-a068-44ef-8616-91d89f740551--