Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1njWmg-000410-JX for pgsql-hackers@arkaria.postgresql.org; Wed, 27 Apr 2022 01:48:02 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1njWme-0006yC-SX for pgsql-hackers@arkaria.postgresql.org; Wed, 27 Apr 2022 01:48:00 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1njWme-0006xw-J2 for pgsql-hackers@lists.postgresql.org; Wed, 27 Apr 2022 01:48:00 +0000 Received: from sss.pgh.pa.us ([66.207.139.130]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1njWmZ-0004ZF-Ah for pgsql-hackers@lists.postgresql.org; Wed, 27 Apr 2022 01:47:56 +0000 Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1]) by sss.pgh.pa.us (8.15.2/8.15.2) with ESMTP id 23R1lrf9295869; Tue, 26 Apr 2022 21:47:53 -0400 From: Tom Lane To: Thomas Munro cc: Michael Paquier , Noah Misch , Jeff Davis , Postgres hackers Subject: Re: pgsql: Add contrib/pg_walinspect. In-reply-to: References: <171769.1650950714@sss.pgh.pa.us> <287795.1651019129@sss.pgh.pa.us> Comments: In-reply-to Thomas Munro message dated "Wed, 27 Apr 2022 13:10:50 +1200" MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0" Content-ID: <295825.1651024041.0@sss.pgh.pa.us> Date: Tue, 26 Apr 2022 21:47:53 -0400 Message-ID: <295868.1651024073@sss.pgh.pa.us> List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk ------- =_aaaaaaaaaa0 Content-Type: text/plain; charset="us-ascii" Content-ID: <295825.1651024041.1@sss.pgh.pa.us> Thomas Munro writes: > Hrmph... Are you sure you rebuilt the contrib module? Assuming so, > maybe it's failing in a different way for you and me. For me, it > always fails after this break is reached in xlogutil.c: > /* If asked, let's not wait for future WAL. */ > if (!wait_for_wal) > break; Hmm. For me, that statement is not reached at all in successful (make installcheck) runs. In a failing run, it's reached with wait_for_wal = false, after which we get the "could not read WAL" failure. Usually that happens twice, as per attached. regards, tom lane ------- =_aaaaaaaaaa0 Content-Type: text/x-diff; name="debug.patch"; charset="us-ascii" Content-ID: <295825.1651024041.2@sss.pgh.pa.us> Content-Description: debug.patch Content-Transfer-Encoding: quoted-printable diff --git a/contrib/pg_walinspect/Makefile b/contrib/pg_walinspect/Makefi= le index 960530e..85dcb3a 100644 --- a/contrib/pg_walinspect/Makefile +++ b/contrib/pg_walinspect/Makefile @@ -15,7 +15,6 @@ REGRESS_OPTS =3D --temp-config $(top_srcdir)/contrib/pg_= walinspect/walinspect.conf = # Disabled because these tests require "wal_level=3Dreplica", which # some installcheck users do not have (e.g. buildfarm clients). -NO_INSTALLCHECK =3D 1 = ifdef USE_PGXS PG_CONFIG =3D pg_config diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/= transam/xlogreader.c index cf5db23..33d2c73 100644 --- a/src/backend/access/transam/xlogreader.c +++ b/src/backend/access/transam/xlogreader.c @@ -373,6 +373,9 @@ XLogNextRecord(XLogReaderState *state, char **errormsg= ) */ Assert(!XLogRecPtrIsInvalid(state->EndRecPtr)); = + if(!*errormsg) + *errormsg =3D "decode_queue_head is null"; + = return NULL; } = diff --git a/src/backend/access/transam/xlogutils.c b/src/backend/access/t= ransam/xlogutils.c index 4257026..4089efd 100644 --- a/src/backend/access/transam/xlogutils.c +++ b/src/backend/access/transam/xlogutils.c @@ -955,6 +955,8 @@ read_local_xlog_page_guts(XLogReaderState *state, XLog= RecPtr targetPagePtr, if (loc <=3D read_upto) break; = + elog(LOG, "let's wait for wal: %d", wait_for_wal); + /* If asked, let's not wait for future WAL. */ if (!wait_for_wal) break; ------- =_aaaaaaaaaa0 Content-Type: text/plain; name="fail.log"; charset="us-ascii" Content-ID: <295825.1651024041.3@sss.pgh.pa.us> Content-Description: fail.log Content-Transfer-Encoding: quoted-printable 2022-04-27 03:40:09.253 CEST postmaster[32569] LOG: starting PostgreSQL 1= 5devel on mipsel-unknown-linux-gnu, compiled by gcc (Debian 4.9.2-10+deb8u= 1) 4.9.2, 32-bit 2022-04-27 03:40:09.254 CEST postmaster[32569] LOG: listening on Unix soc= ket "/tmp/pg_regress-g0HWzi/.s.PGSQL.51696" 2022-04-27 03:40:09.284 CEST startup[32574] LOG: database system was shut= down at 2022-04-27 03:40:09 CEST 2022-04-27 03:40:09.314 CEST postmaster[32569] LOG: database system is re= ady to accept connections 2022-04-27 03:40:12.073 CEST client backend[32598] pg_regress/pg_walinspec= t ERROR: WAL start LSN must be less than end LSN 2022-04-27 03:40:12.073 CEST client backend[32598] pg_regress/pg_walinspec= t STATEMENT: SELECT COUNT(*) >=3D 0 AS ok FROM pg_get_wal_records_info('0= /1903EE8', '0/1903E40'); 2022-04-27 03:40:12.075 CEST client backend[32598] pg_regress/pg_walinspec= t ERROR: WAL start LSN must be less than end LSN 2022-04-27 03:40:12.075 CEST client backend[32598] pg_regress/pg_walinspec= t STATEMENT: SELECT COUNT(*) >=3D 0 AS ok FROM pg_get_wal_stats('0/1903EE= 8', '0/1903E40'); 2022-04-27 03:40:12.085 CEST client backend[32598] pg_regress/pg_walinspec= t LOG: let's wait for wal: 0 2022-04-27 03:40:12.085 CEST client backend[32598] pg_regress/pg_walinspec= t STATEMENT: SELECT COUNT(*) >=3D 0 AS ok FROM pg_get_wal_records_info_ti= ll_end_of_wal('0/1903E40'); 2022-04-27 03:40:12.085 CEST client backend[32598] pg_regress/pg_walinspec= t ERROR: could not read WAL at 0/1903E40: decode_queue_head is null 2022-04-27 03:40:12.085 CEST client backend[32598] pg_regress/pg_walinspec= t STATEMENT: SELECT COUNT(*) >=3D 0 AS ok FROM pg_get_wal_records_info_ti= ll_end_of_wal('0/1903E40'); 2022-04-27 03:40:12.091 CEST client backend[32598] pg_regress/pg_walinspec= t LOG: let's wait for wal: 0 2022-04-27 03:40:12.091 CEST client backend[32598] pg_regress/pg_walinspec= t STATEMENT: SELECT COUNT(*) >=3D 0 AS ok FROM pg_get_wal_stats_till_end_= of_wal('0/1903E40'); 2022-04-27 03:40:12.091 CEST client backend[32598] pg_regress/pg_walinspec= t ERROR: could not read WAL at 0/1903E40: decode_queue_head is null 2022-04-27 03:40:12.091 CEST client backend[32598] pg_regress/pg_walinspec= t STATEMENT: SELECT COUNT(*) >=3D 0 AS ok FROM pg_get_wal_stats_till_end_= of_wal('0/1903E40'); 2022-04-27 03:40:12.198 CEST postmaster[32569] LOG: received fast shutdow= n request 2022-04-27 03:40:12.299 CEST postmaster[32569] LOG: aborting any active t= ransactions 2022-04-27 03:40:12.304 CEST postmaster[32569] LOG: background worker "lo= gical replication launcher" (PID 32577) exited with exit code 1 2022-04-27 03:40:12.306 CEST checkpointer[32572] LOG: shutting down 2022-04-27 03:40:12.310 CEST checkpointer[32572] LOG: checkpoint starting= : shutdown immediate 2022-04-27 03:40:12.524 CEST checkpointer[32572] LOG: checkpoint complete= : wrote 784 buffers (4.8%); 0 WAL file(s) added, 0 removed, 0 recycled; wr= ite=3D0.199 s, sync=3D0.001 s, total=3D0.218 s; sync files=3D0, longest=3D= 0.000 s, average=3D0.000 s; distance=3D4197 kB, estimate=3D4197 kB 2022-04-27 03:40:12.838 CEST postmaster[32569] LOG: database system is sh= ut down ------- =_aaaaaaaaaa0--