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 1rcU6G-000Mx1-IL for pgsql-bugs@arkaria.postgresql.org; Tue, 20 Feb 2024 17:40:13 +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 1rcU5F-000zVI-2G for pgsql-bugs@arkaria.postgresql.org; Tue, 20 Feb 2024 17:39:09 +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 1rcU5E-000zV9-Fs for pgsql-bugs@lists.postgresql.org; Tue, 20 Feb 2024 17:39:09 +0000 Received: from mx0a-00134001.pphosted.com ([205.220.160.129]) by makus.postgresql.org with esmtps (TLS1.2) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1rcU55-0001hx-M9 for pgsql-bugs@lists.postgresql.org; Tue, 20 Feb 2024 17:39:07 +0000 Received: from pps.filterd (m0267959.ppops.net [127.0.0.1]) by mx0a-00134001.pphosted.com (8.17.1.24/8.17.1.24) with ESMTP id 41K9XrF3026109 for ; Tue, 20 Feb 2024 17:38:59 GMT DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=optiver.com; h= from:to:subject:date:message-id:content-type:mime-version; s= mail; bh=WOEC5Ae6Y+eXe/4TrXiARhpT9wwXgMrKmZdo+4BWf7w=; b=QyhhSPY vrUB65znoZrrQNuxjRBI1v0z76+adPpIvnQZntHTMHjIrwm6tgZqUj7Jlo+IL2jU CKVxYO0YlsQyDio1RB5pAPleH/SkN0ObGnn9kxAAoTetEpsV7rjTVFojbaayrLEN zym+pb0Exm+OkBzKh3+DnlJ1EPkLcqdjtNYF9XXjqKUjSaoHqW5P2zOM0J0J+acy coSQ8kPfvDomJ7mYJXajUk3t+l/1yNgGpCb2mr4qW9ouh5+cC/vY2l38UcBRuzPE BsIAcyuPyVFVbWBN2LDNKzNG27mEiiPvDRivtn8lFZI/UIeI2uzNPFnXDA34Aj88 Nq6Vp6oOzdKbzkg== Received: from opammb1266.comp.optiver.com ([195.246.114.78]) by mx0a-00134001.pphosted.com (PPS) with ESMTPS id 3wajss376t-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Tue, 20 Feb 2024 17:38:59 +0000 (GMT) Received: from opammb1267.comp.optiver.com (100.68.11.12) by opammb1266.comp.optiver.com (100.68.11.26) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.2.1118.26; Tue, 20 Feb 2024 18:38:57 +0100 Received: from opammb1267.comp.optiver.com ([fe80::5b6f:1976:98cd:68a7]) by opammb1267.comp.optiver.com ([fe80::5b6f:1976:98cd:68a7%13]) with mapi id 15.02.1118.026; Tue, 20 Feb 2024 18:38:57 +0100 From: Floris Van Nee To: "pgsql-bugs@lists.postgresql.org" Subject: error "can only drop stats once" brings down database Thread-Topic: error "can only drop stats once" brings down database Thread-Index: AdpkITkvvWn2BJ6LSeem21xvsvJqVw== Date: Tue, 20 Feb 2024 17:38:57 +0000 Message-ID: Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: x-originating-ip: [100.68.31.121] Content-Type: multipart/alternative; boundary="_000_b14ae28029f64757bb64613be2549a74Optivercom_" MIME-Version: 1.0 X-Proofpoint-Virus-Version: vendor=baseguard engine=ICAP:2.0.272,Aquarius:18.0.1011,Hydra:6.0.619,FMLib:17.11.176.26 definitions=2024-02-20_06,2024-02-20_01,2023-05-22_02 List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --_000_b14ae28029f64757bb64613be2549a74Optivercom_ Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable Hi, On a database we have we've recently seen a fatal error occur twice. The er= ror happened on two different physical replicas (of the same cluster) durin= g a WAL redo action in the recovery process. They're running Postgres 15.5. Occurrence 1: 2024-02-01 06:55:54.476 CET,,,70290,,65a29b60.11292,6,,2024-01-13 15:17:04 = CET,1/0,0,FATAL,XX000,"can only drop stats once",,,,,"WAL redo at A7BD1/D6F= 9B6C0 for Transaction/COMMIT: 2024-02-01 06:55:54.395851+01; dropped stats:= 2/16405/2991517839 2/16405/2991517838 2/16405/2991517835; inval msgs: catc= ache 80 catcache 79 catcache 80 catcache 79 catcache 55 catcache 54 catcach= e 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catca= che 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 cat= cache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 c= atcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6= catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache= 55 catcache 54 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catc= ache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 ca= tcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 55= catcache 54 catcache 7 catcache 6 catcache 7 catcache 6 catcache 32 catcac= he 55 catcache 54 catcache 55 catcache 54 catcache 55 catcache 54 catcache = 32 catcache 7 catcache 6 catcache 7 catcache 6 catcache 55 catcache 54 catc= ache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 ca= tcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 = catcache 7 catcache 6 catcache 7 catcache 6 catcache 55 catcache 54 catcach= e 80 catcache 79 catcache 80 catcache 79 catcache 7 catcache 6 catcache 7 c= atcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6= catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache= 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcac= he 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catc= ache 7 catcache 6 catcache 7 catcache 6 catcache 55 catcache 54 snapshot 26= 08 relcache 2991517835 snapshot 1214 relcache 2991517838 relcache 299151783= 9 relcache 2991517838 snapshot 2608 relcache 2991517838 relcache 2991517839= relcache 2991517835 snapshot 2608 relcache 2991517839 relcache 2991517838 = snapshot 2608 relcache 2991517838 snapshot 2608 snapshot 2608 snapshot 2608= relcache 2991517835 snapshot 2608 snapshot 1214",,,,"","startup",,0 2024-02-01 06:55:56.793 CET,,,70282,,65a29b5f.1128a,8,,2024-01-13 15:17:03 = CET,,0,LOG,00000,"startup process (PID 70290) exited with exit code 1",,,,,= ,,,,"","postmaster",,0 2024-02-01 06:55:56.793 CET,,,70282,,65a29b5f.1128a,= 9,,2024-01-13 15:17:03 CET,,0,LOG,00000,"terminating any other active serve= r processes",,,,,,,,,"","postmaster",,0 2024-02-01 06:55:57.145 CET,,,26624= ,"100.104.20.59:37478",65bb326d.6800,1,"",2024-02-01 06:55:57 Occurrence 2: 2024-02-09 19:15:41.353 CET,,,88714,,65a29b5e.15a8a,6,,2024-01-13 15:17:02 = CET,1/0,0,FATAL,XX000,"can only drop stats once",,,,,"WAL redo at A95F1/3C9= D3D88 for Transaction/COMMIT: 2024-02-09 19:15:41.33755+01; dropped stats: = 2/16405/3843195112 2/16405/3843195111 2/16405/3843195107; inval msgs: catca= che 80 catcache 79 catcache 80 catcache 79 catcache 55 catcache 54 catcache= 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcac= he 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catc= ache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 ca= tcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 = catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache = 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcach= e 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catca= che 7 catcache 6 catcache 55 catcache 54 catcache 7 catcache 6 catcache 7 c= atcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6= catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache= 7 catcache 6 catcache 55 catcache 54 catcache 7 catcache 6 catcache 7 catc= ache 6 catcache 32 catcache 55 catcache 54 catcache 55 catcache 54 catcache= 55 catcache 54 catcache 7 catcache 6 catcache 7 catcache 6 catcache 32 cat= cache 7 catcache 6 catcache 7 catcache 6 catcache 55 catcache 54 catcache 7= catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache= 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcac= he 7 catcache 6 catcache 7 catcache 6 catcache 55 catcache 54 catcache 80 c= atcache 79 catcache 80 catcache 79 catcache 7 catcache 6 catcache 7 catcach= e 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catca= che 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 cat= cache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 c= atcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7= catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache= 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcac= he 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 55 cat= cache 54 snapshot 2608 relcache 3843195107 snapshot 1214 relcache 384319511= 1 relcache 3843195112 relcache 3843195111 snapshot 2608 relcache 3843195111= relcache 3843195112 relcache 3843195107 snapshot 2608 relcache 3843195107 = snapshot 2608 relcache 3843195107 snapshot 2608 relcache 3843195112 relcach= e 3843195111 snapshot 2608 relcache 3843195111 snapshot 2608 snapshot 2608 = snapshot 2608 relcache 3843195107 snapshot 2608 snapshot 1214",,,,"","start= up",,0 Googling the error only shows one conversation from last year: https://www.= postgresql.org/message-id/flat/17947-b9554521ad963c9c%40postgresql.org However, in that thread it is caused by logical replication slots, which th= is cluster does not have. Does anyone have an idea what may be causing this? Separately, it seems like Postgres did not restart by itself when this erro= r occurred (normally if a backend crashes Postgres would kill all connectio= ns and initiate a restart), but in this case because it's the recovery proc= ess that stops, the whole database just shuts down and needs to be manually= restarted. Is that intended? After manually starting the database again, recovery would continue as norm= al. The database would be in normal operation again. -Floris --_000_b14ae28029f64757bb64613be2549a74Optivercom_ Content-Type: text/html; charset="us-ascii" Content-Transfer-Encoding: quoted-printable

Hi,

 

On a database we have we’ve recently seen a fa= tal error occur twice. The error happened on two different physical replica= s (of the same cluster) during a WAL redo action in the recovery process. T= hey’re running Postgres 15.5.

 

Occurrence 1:

2024-02-01 06:55:54.476 CET,,,70290,,65a29b60.11292,= 6,,2024-01-13 15:17:04 CET,1/0,0,FATAL,XX000,"can only drop stats once= ",,,,,"WAL redo at A7BD1/D6F9B6C0 for Transaction/COMMIT: 2024-02= -01 06:55:54.395851+01; dropped stats: 2/16405/2991517839 2/16405/2991517838 2/16405/2991517835; inval msgs: catcache 80 catcache 79= catcache 80 catcache 79 catcache 55 catcache 54 catcache 7 catcache 6 catc= ache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 ca= tcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcac= he 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catc= ache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 ca= tcache 6 catcache 55 catcache 54 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache= 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcac= he 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 55 catcache 54 ca= tcache 7 catcache 6 catcache 7 catcache 6 catcache 32 catcache 55 catcache 54 catcache 55 catcache 54 catcache 55 = catcache 54 catcache 32 catcache 7 catcache 6 catcache 7 catcache 6 catcach= e 55 catcache 54 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 cat= cache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcac= he 6 catcache 7 catcache 6 catcache 55 catcache 54 catcache 80 catcache 79 = catcache 80 catcache 79 catcache 7 catcache 6 catcache 7 catcache 6 catcach= e 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcac= he 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catc= ache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 ca= tcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 55 catcache 54 snapshot 2608 relcache 299= 1517835 snapshot 1214 relcache 2991517838 relcache 2991517839 relcache 2991= 517838 snapshot 2608 relcache 2991517838 relcache 2991517839 relcache 29915= 17835 snapshot 2608 relcache 2991517839 relcache 2991517838 snapshot 2608 relcache 2991517838 snapshot 2608 snapsh= ot 2608 snapshot 2608 relcache 2991517835 snapshot 2608 snapshot 1214"= ,,,,"","startup",,0

2024-02-01 06:55:56.793 CET,,,70282,,65a29b5f.1128a,= 8,,2024-01-13 15:17:03 CET,,0,LOG,00000,"startup process (PID 70290) e= xited with exit code 1",,,,,,,,,"","postmaster",,0= 2024-02-01 06:55:56.793 CET,,,70282,,65a29b5f.1128a,9,,2024-01-13 15:17:03 CET,,0,LOG,00000,"terminating any other active server proces= ses",,,,,,,,,"","postmaster",,0 2024-02-01 06:55:5= 7.145 CET,,,26624,"100.104.20.59:37478",65bb326d.6800,1,"&qu= ot;,2024-02-01 06:55:57

 

Occurrence 2:

2024-02-09 19:15:41.353 CET,,,88714,,65a29b5e.15a8a,= 6,,2024-01-13 15:17:02 CET,1/0,0,FATAL,XX000,"can only drop stats once= ",,,,,"WAL redo at A95F1/3C9D3D88 for Transaction/COMMIT: 2024-02= -09 19:15:41.33755+01; dropped stats: 2/16405/3843195112 2/16405/3843195111 2/16405/3843195107; inval msgs: catcache 80 catcache 79= catcache 80 catcache 79 catcache 55 catcache 54 catcache 7 catcache 6 catc= ache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 ca= tcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcac= he 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catc= ache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 ca= tcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcac= he 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catc= ache 55 catcache 54 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 = catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache= 7 catcache 6 catcache 7 catcache 6 catcache 55 catcache 54 catcache 7 catc= ache 6 catcache 7 catcache 6 catcache 32 catcache 55 catcache 54 catcache 5= 5 catcache 54 catcache 55 catcache 54 catcache 7 catcache 6 catcache 7 catcache 6 catcache 32 catcache 7 catc= ache 6 catcache 7 catcache 6 catcache 55 catcache 54 catcache 7 catcache 6 = catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache = 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcac= he 55 catcache 54 catcache 80 catcache 79 catcache 80 catcache 79 catcache = 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcach= e 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcac= he 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catc= ache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 ca= tcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcac= he 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catc= ache 7 catcache 6 catcache 55 catcache 54 snapshot 2608 relcache 3843195107= snapshot 1214 relcache 3843195111 relcache 3843195112 relcache 3843195111 snapshot 2608 relcache 3843195111 = relcache 3843195112 relcache 3843195107 snapshot 2608 relcache 3843195107 s= napshot 2608 relcache 3843195107 snapshot 2608 relcache 3843195112 relcache= 3843195111 snapshot 2608 relcache 3843195111 snapshot 2608 snapshot 2608 snapshot 2608 relcache 3843195107 s= napshot 2608 snapshot 1214",,,,"","startup",,0

 

Googling the error only shows one conversation from = last year: https://www.postgresql.org/message-id/flat/17947-b9554521ad963c9c%40postgre= sql.org

However, in that thread it is caused by logical repl= ication slots, which this cluster does not have.

 

Does anyone have an idea what may be causing this?

 

Separately, it seems like Postgres did not restart b= y itself when this error occurred (normally if a backend crashes Postgres w= ould kill all connections and initiate a restart), but in this case because= it’s the recovery process that stops, the whole database just shuts down and needs to be manually restarted. Is = that intended?

 

After manually starting the database again, recovery= would continue as normal. The database would be in normal operation again.=

 

-Floris

 

--_000_b14ae28029f64757bb64613be2549a74Optivercom_--